A few days ago (Dec. 29 at 7 am), everything was working great. (I have been using duplicacy for some years now.)
I was using duplicacy 3.2.0 (on Mac M1); I upgraded to 3.2.3. Same problem.
Here’s the log I have from that last “successful” run:
Command: /Users/gb/bin/duplicacy -background -log backup -stats -threads 8 -vss
2023-12-29 07:05:14.709 INFO STORAGE_SET Storage set to sftp://gb@fileserver3//mnt/hdd5/backups/duplicacy/Guillaumes-MacBook-Pro-gb-gb/
2023-12-29 07:05:18.348 INFO BACKUP_START Last backup at revision 28702 found
2023-12-29 07:05:20.207 INFO VSS_DONE Shadow copy created and mounted at /tmp/snp_2339922623
2023-12-29 07:05:20.223 INFO BACKUP_INDEXING Indexing /Users/gb
2023-12-29 07:05:20.226 INFO SNAPSHOT_FILTER Parsing filter file /Users/gb/.duplicacy/filters
2023-12-29 07:05:20.227 INFO SNAPSHOT_FILTER Loaded 128 include/exclude pattern(s)
2023-12-29 07:07:19.072 INFO PACK_END Packed .DS_Store (67588)
2023-12-29 07:07:19.072 INFO PACK_END Packed crontab (394)
2023-12-29 07:07:19.460 INFO UPLOAD_PROGRESS Uploaded chunk 1 size 5065195, 4.83MB/s 00:06:28 0.2%
2023-12-29 07:07:19.512 INFO UPLOAD_PROGRESS Skipped chunk 15 size 3099196, 7.79MB/s 00:04:01 0.4%
2023-12-29 07:07:19.590 INFO UPLOAD_PROGRESS Skipped chunk 18 size 3008892, 10.66MB/s 00:02:56 0.5%
2023-12-29 07:07:19.705 INFO UPLOAD_PROGRESS Uploaded chunk 3 size 2882307, 13.40MB/s 00:02:20 0.7%
2023-12-29 07:07:19.822 INFO UPLOAD_PROGRESS Uploaded chunk 4 size 2386269, 15.68MB/s 00:01:59 0.8%
...
2023-12-29 07:07:39.039 INFO UPLOAD_PROGRESS Uploaded chunk 336 size 5750847, 89.79MB/s 00:00:01 95.6%
2023-12-29 07:07:39.089 INFO UPLOAD_PROGRESS Uploaded chunk 337 size 10237435, 90.28MB/s 00:00:01 96.1%
2023-12-29 07:07:45.430 INFO BACKUP_END Backup for /Users/gb at revision 28703 completed
2023-12-29 07:07:45.431 INFO BACKUP_STATS Files: 1533907 total, 175,748M bytes; 749 new, 1,805M bytes
2023-12-29 07:07:45.431 INFO BACKUP_STATS File chunks: 214692 total, 1348G bytes; 278 new, 1,579M bytes, 661,641K bytes uploaded
2023-12-29 07:07:45.431 INFO BACKUP_STATS Metadata chunks: 367 total, 437,908K bytes; 39 new, 63,613K bytes, 25,800K bytes uploaded
2023-12-29 07:07:45.431 INFO BACKUP_STATS All chunks: 215059 total, 1348G bytes; 317 new, 1,641M bytes, 687,442K bytes uploaded
2023-12-29 07:07:45.431 INFO BACKUP_STATS Total running time: 00:02:27
2023-12-29 07:07:46.658 INFO VSS_DELETE Shadow copy unmounted and deleted at /tmp/snp_2339922623
Since then, all backups I initiate with the same command (and with the same duplicacy binary) try to re-upload ALL the chunks, skipping all previously uploaded chunks. But that takes about 9 hours total, whereas before, a full backup took less than 3 minutes!
Here’s the log of the first run on Dec. 29 at 8 am that showed that behaviour:
Command: /Users/gb/bin/duplicacy -background -log backup -stats -threads 8 -vss
2023-12-29 08:05:14.431 INFO STORAGE_SET Storage set to sftp://gb@fileserver3//mnt/hdd5/backups/duplicacy/Guillaumes-MacBook-Pro-gb-gb/
2023-12-29 08:05:19.638 INFO BACKUP_START Last backup at revision 28703 found
2023-12-29 08:05:20.664 INFO VSS_DONE Shadow copy created and mounted at /tmp/snp_2522166019
2023-12-29 08:05:20.664 INFO BACKUP_INDEXING Indexing /Users/gb
2023-12-29 08:05:20.665 INFO SNAPSHOT_FILTER Parsing filter file /Users/gb/.duplicacy/filters
2023-12-29 08:05:20.694 INFO SNAPSHOT_FILTER Loaded 128 include/exclude pattern(s)
2023-12-29 08:07:26.925 INFO PACK_END Packed .DS_Store (67588)
2023-12-29 08:07:26.926 INFO PACK_END Packed .bash_history (78316)
2023-12-29 08:07:26.927 INFO PACK_END Packed .profile (249)
2023-12-29 08:07:26.927 INFO PACK_END Packed crontab (394)
2023-12-29 08:07:27.354 INFO UPLOAD_PROGRESS Skipped chunk 10 size 3099196, 2.96MB/s 32 days 21:12:26 0.0%
2023-12-29 08:07:27.368 INFO UPLOAD_PROGRESS Uploaded chunk 0 size 7150961, 9.78MB/s 9 days 22:37:17 0.0%
2023-12-29 08:07:27.413 INFO UPLOAD_PROGRESS Uploaded chunk 1 size 6218829, 15.71MB/s 6 days 04:30:57 0.0%
2023-12-29 08:07:27.479 INFO UPLOAD_PROGRESS Skipped chunk 13 size 3008892, 18.58MB/s 5 days 05:34:25 0.0%
2023-12-29 08:07:27.494 INFO UPLOAD_PROGRESS Skipped chunk 14 size 3566735, 21.98MB/s 4 days 10:08:16 0.0%
...
[after 40 or so chunks, all other chunks are skipped:]
2023-12-29 08:07:44.188 INFO UPLOAD_PROGRESS Skipped chunk 391 size 1048576, 72.71MB/s 1 day 08:04:38 0.0%
2023-12-29 08:07:44.192 INFO UPLOAD_PROGRESS Skipped chunk 392 size 1048576, 72.76MB/s 1 day 08:03:10 0.0%
2023-12-29 08:07:44.196 INFO UPLOAD_PROGRESS Skipped chunk 393 size 1048576, 72.82MB/s 1 day 08:01:42 0.0%
2023-12-29 08:07:44.200 INFO UPLOAD_PROGRESS Skipped chunk 394 size 1048576, 72.87MB/s 1 day 08:00:14 0.0%
2023-12-29 08:07:44.204 INFO UPLOAD_PROGRESS Skipped chunk 395 size 1048576, 72.93MB/s 1 day 07:58:46 0.0%
2023-12-29 08:07:44.208 INFO UPLOAD_PROGRESS Skipped chunk 396 size 1048576, 72.98MB/s 1 day 07:57:19 0.0%
2023-12-29 08:07:44.212 INFO UPLOAD_PROGRESS Skipped chunk 397 size 1048576, 73.04MB/s 1 day 07:55:51 0.0%
2023-12-29 08:07:44.216 INFO UPLOAD_PROGRESS Skipped chunk 398 size 1048576, 73.10MB/s 1 day 07:54:24 0.0%
2023-12-29 08:07:44.220 INFO UPLOAD_PROGRESS Skipped chunk 399 size 1048576, 73.15MB/s 1 day 07:52:56 0.0%
...
[up to chunk 8395835, more than 8 hours later:]
2023-12-29 16:30:19.032 INFO UPLOAD_PROGRESS Skipped chunk 8395831 size 1048576, 278.29MB/s 00:00:02 99.9%
2023-12-29 16:30:19.047 INFO UPLOAD_PROGRESS Skipped chunk 8395832 size 1048576, 278.29MB/s 00:00:02 99.9%
2023-12-29 16:30:19.050 INFO UPLOAD_PROGRESS Skipped chunk 8395833 size 1048576, 278.29MB/s 00:00:02 99.9%
2023-12-29 16:30:19.053 INFO UPLOAD_PROGRESS Skipped chunk 8395834 size 1048576, 278.29MB/s 00:00:02 99.9%
2023-12-29 16:30:19.056 INFO UPLOAD_PROGRESS Skipped chunk 8395835 size 1048576, 278.29MB/s 00:00:02 99.9%
2023-12-29 16:30:19.056 INFO PACK_END Packed .orbstack/data/swap.img (7516192768)
2023-12-29 16:30:19.059 INFO PACK_END Packed .orbstack/log/gui.log (1043)
2023-12-29 16:30:19.060 INFO PACK_END Packed .orbstack/log/vmgr.log (12413)
2023-12-29 16:30:19.060 INFO PACK_END Packed .orbstack/run/vmgr.version (9)
2023-12-29 16:30:19.061 INFO PACK_END Packed .orbstack/shell/init.bash (44)
2023-12-29 16:30:19.061 INFO PACK_END Packed .orbstack/shell/init.fish (38)
2023-12-29 16:30:19.062 INFO PACK_END Packed .orbstack/shell/init.zsh (44)
...
[and the backup completes successfully:]
2023-12-29 16:30:22.956 INFO PACK_END Packed git/fileserver/.idea/workspace.xml (82351)
2023-12-29 16:30:22.958 INFO PACK_END Packed git/fileserver/docker-services/rclone-gdrive-mount/config.inc.php (887)
2023-12-29 16:30:22.982 INFO UPLOAD_PROGRESS Uploaded chunk 8395916 size 16777216, 278.28MB/s 00:00:01 99.9%
2023-12-29 16:30:22.989 INFO UPLOAD_PROGRESS Uploaded chunk 8395915 size 8922989, 278.28MB/s 00:00:01 99.9%
2023-12-29 16:30:23.028 INFO UPLOAD_PROGRESS Uploaded chunk 8395913 size 1918288, 278.27MB/s 00:00:01 99.9%
2023-12-29 16:30:23.249 INFO UPLOAD_PROGRESS Uploaded chunk 8395917 size 4552329, 278.27MB/s 00:00:01 99.9%
2023-12-29 16:30:23.314 INFO UPLOAD_PROGRESS Uploaded chunk 8395918 size 4288548, 278.27MB/s 00:00:01 99.9%
2023-12-29 16:30:23.314 INFO UPLOAD_PROGRESS Uploaded chunk 8395920 size 4158255, 278.27MB/s 00:00:01 99.9%
2023-12-29 16:30:23.320 INFO UPLOAD_PROGRESS Uploaded chunk 8395923 size 9957844, 278.27MB/s 00:00:01 99.9%
2023-12-29 16:30:23.350 INFO UPLOAD_PROGRESS Uploaded chunk 8395921 size 2315118, 278.27MB/s 00:00:01 99.9%
2023-12-29 16:30:23.350 INFO UPLOAD_PROGRESS Uploaded chunk 8395922 size 9142897, 278.27MB/s 00:00:01 99.9%
2023-12-29 16:30:23.352 INFO UPLOAD_PROGRESS Uploaded chunk 8395924 size 625597, 278.27MB/s 00:00:01 99.9%
2023-12-29 16:30:23.404 INFO UPLOAD_PROGRESS Uploaded chunk 8395919 size 10658813, 278.27MB/s 00:00:01 99.9%
2023-12-29 16:30:40.024 INFO BACKUP_END Backup for /Users/gb at revision 28704 completed
2023-12-29 16:30:40.024 INFO BACKUP_STATS Files: 1533933 total, 8370G bytes; 349 new, 8200G bytes
2023-12-29 16:30:40.025 INFO BACKUP_STATS File chunks: 8610407 total, 9549G bytes; 274 new, 1,454M bytes, 601,454K bytes uploaded
2023-12-29 16:30:40.025 INFO BACKUP_STATS Metadata chunks: 758 total, 1,028M bytes; 113 new, 345,123K bytes, 25,220K bytes uploaded
2023-12-29 16:30:40.025 INFO BACKUP_STATS All chunks: 8611165 total, 9550G bytes; 387 new, 1,791M bytes, 626,675K bytes uploaded
2023-12-29 16:30:40.025 INFO BACKUP_STATS Total running time: 08:25:21
2023-12-29 16:30:40.955 INFO VSS_DELETE Shadow copy unmounted and deleted at /tmp/snp_2522166019
Something I noticed: almost all skipped chunks are of size 1048576:
$ cat backup-log-20231229-080514 | grep "Skipped chunk" | grep 1048576 | wc -l
8395591
$ cat backup-log-20231229-080514 | grep "Skipped chunk" | grep -v 1048576 | wc -l
60
What could cause duplicacy to try to re-upload (and skip) all chunks?
(I checked my bash history, and the only thing I saw I was doing at that time, was replacing Docker Desktop with OrbStack. Not sure how that could affect duplicacy, as I am NOT using Docker for anything related to duplicacy.)
Thank you.