Failed to upload the chunk ... operation not supported

Please describe what you are doing to trigger the bug:
On MacOS Catalina, Duplicacy 2.3.0
duplicacy -verbose -debug -log backup -stats

Please describe what you expect to happen (but doesn’t):
Normal backup

Please describe what actually happens (the wrong behaviour):
Backup fails with the error below. I tried a new backup with a new id, removed cache, with or without VSS. Previous version, 2.2.3, works just fine, but without VSS.

2019-11-26 20:51:23.795 DEBUG PATTERN_INCLUDE dotfiles/.zshrc is included
2019-11-26 20:51:23.795 DEBUG PATTERN_INCLUDE dotfiles/CODEOWNERS is included
2019-11-26 20:51:23.795 DEBUG PATTERN_INCLUDE dotfiles/CODE_OF_CONDUCT.md is included
2019-11-26 20:51:23.795 DEBUG PATTERN_INCLUDE dotfiles/CONTRIBUTING.md is included
2019-11-26 20:51:23.795 DEBUG PATTERN_INCLUDE dotfiles/LICENSE is included
2019-11-26 20:51:23.795 DEBUG PATTERN_INCLUDE dotfiles/README.md is included
2019-11-26 20:51:23.795 DEBUG PATTERN_INCLUDE dotfiles/install.sh is included
2019-11-26 20:51:23.795 DEBUG PATTERN_EXCLUDE dotfiles/.git/ is excluded by pattern e:(?i)\.(svn|git|hg)/.*$
2019-11-26 20:51:24.060 TRACE PACK_START Packing .wget-hsts
2019-11-26 20:51:24.060 INFO PACK_END Packed .wget-hsts (262)
2019-11-26 20:51:24.061 TRACE PACK_START Packing .zsh_history
2019-11-26 20:51:24.062 INFO PACK_END Packed .zsh_history (99145)
2019-11-26 20:51:24.062 WARN OPEN_FAILURE Failed to open file for reading: open /Users/vlad/.dropbox/events/1-6cc2-5dddcc8e: no such file or directory
2019-11-26 20:51:24.062 WARN OPEN_FAILURE Failed to open file for reading: open /Users/vlad/.dropbox/events/1-d306-5dddcc8a: no such file or directory
2019-11-26 20:51:24.062 TRACE PACK_START Packing .dropbox/instance1/aggregation.dbx
2019-11-26 20:51:24.062 INFO PACK_END Packed .dropbox/instance1/aggregation.dbx (94208)
2019-11-26 20:51:24.062 TRACE PACK_START Packing .dropbox/instance1/config.dbx
2019-11-26 20:51:24.063 INFO PACK_END Packed .dropbox/instance1/config.dbx (203776)
2019-11-26 20:51:24.063 TRACE PACK_START Packing .dropbox/instance1/home.db
2019-11-26 20:51:24.064 INFO PACK_END Packed .dropbox/instance1/home.db (623616)
2019-11-26 20:51:24.064 TRACE PACK_START Packing .dropbox/instance1/icon.db
2019-11-26 20:51:24.175 DEBUG CHUNK_CACHE Skipped chunk 14a9344868c80dac492160cb88365aebb95f8c53f2b33ca8e4b3ae6cc14065bf in cache
2019-11-26 20:51:24.175 INFO UPLOAD_PROGRESS Skipped chunk 2 size 3123265, 2.98MB/s 00:02:06 0.7%
2019-11-26 20:51:24.184 DEBUG CHUNK_CACHE Skipped chunk d8b41e3212a001582be44e9a8c6b6ba72d8c3c471ddb901051974003a9a585f5 in cache
2019-11-26 20:51:24.184 INFO UPLOAD_PROGRESS Skipped chunk 3 size 1846057, 4.74MB/s 00:01:19 1.2%
2019-11-26 20:51:24.192 DEBUG CHUNK_CACHE Skipped chunk 05bf064217ea17c6e9158beea95cd0a561c2b3a8951a11370193b2989c693e9e in cache
2019-11-26 20:51:24.192 INFO UPLOAD_PROGRESS Skipped chunk 4 size 1651478, 6.31MB/s 00:00:59 1.6%
2019-11-26 20:51:24.201 DEBUG CHUNK_CACHE Skipped chunk d1352c5012e73fa89a3f522aa54fe7b63028189c3e5d79d0208ebac9ef72adc3 in cache
2019-11-26 20:51:24.201 INFO UPLOAD_PROGRESS Skipped chunk 5 size 2037536, 8.26MB/s 00:00:45 2.1%
2019-11-26 20:51:24.265 INFO PACK_END Packed .dropbox/instance1/icon.db (30296064)
2019-11-26 20:51:24.265 TRACE PACK_START Packing .dropbox/instance1/sync/nucleus.sqlite3-wal
2019-11-26 20:51:27.553 ERROR UPLOAD_CHUNK Failed to upload the chunk 42d16542730a704772063fed97f2a5c4b9d3a642aef8ed89cc8934939dbec880: sync /Volumes/BackupV/chunks/42/d16542730a704772063fed97f2a5c4b9d3a642aef8ed89cc8934939dbec880.sggmytcq.tmp: operation not supported

Is the storage a network share? It looks like the sync operation isn’t supported on a network share.

Is it possible for you to use a different protocol to access the network share, like sftp?

Thank you for getting back to me so fast. It is indeed a network share, which works just fine with 2.2.3 (without VSS because Catalina). I did a few tests with a blank new repo, from scratch, only a few GB.

First I tested 2.3.0 with the network share as above (NFS v4):

 ~/Dropbox  duplicacy2.3.0 init -encrypt VMacTest /Volumes/BackupV
Enter storage password for /Volumes/BackupV:****************************************************************
The storage '/Volumes/BackupV' has already been initialized
Compression level: 100
Average chunk size: 4194304
Maximum chunk size: 16777216
Minimum chunk size: 1048576
Chunk seed: 897fe215233abffb006661497326c230eb1428bf36070980af629a7530d69a2f
/Users/vlad/Dropbox will be backed up to /Volumes/BackupV with id VMacTest

 ~/Dropbox  duplicacy2.3.0 -log backup -stats -vss
2019-11-27 21:15:05.471 INFO STORAGE_SET Storage set to /Volumes/BackupV
Enter storage password:****************************************************************
2019-11-27 21:15:11.547 INFO BACKUP_START No previous backup found
2019-11-27 21:15:12.075 INFO VSS_DONE Shadow copy created and mounted at /tmp/snp_064817310
2019-11-27 21:15:12.075 INFO BACKUP_INDEXING Indexing /Users/vlad/Dropbox
2019-11-27 21:15:12.075 INFO SNAPSHOT_FILTER Parsing filter file /Users/vlad/Dropbox/.duplicacy/filters
2019-11-27 21:15:12.075 INFO SNAPSHOT_FILTER Loaded 0 include/exclude pattern(s)
2019-11-27 21:15:14.230 ERROR UPLOAD_CHUNK Failed to upload the chunk 2df7b5a5b8932872c6c2b035c7264f8caf0aa14c6bdf5ec39c16341372028e58: sync /Volumes/BackupV/chunks/2d/f7b5a5b8932872c6c2b035c7264f8caf0aa14c6bdf5ec39c16341372028e58.cmjpxoil.tmp: operation not supported
2019-11-27 21:15:14.231 INFO INCOMPLETE_SAVE Incomplete snapshot saved to /Users/vlad/Dropbox/.duplicacy/incomplete

This failed, so I tested a SFTP connection to the same server hosting the nfs share, and this works just fine. However the speed is very very slow compared to the NFS share (4-5MB/s):

 ~/Dropbox  duplicacy2.3.0 init mywork sftp://vlad@192.168.1.11/test
Enter the path of the private key file:/Users/vlad/.ssh/ansible_rsa
The storage 'sftp://vlad@192.168.1.11/test' has already been initialized
Compression level: 100
Average chunk size: 4194304
Maximum chunk size: 16777216
Minimum chunk size: 1048576
Chunk seed: 6475706c6963616379
/Users/vlad/Dropbox will be backed up to sftp://vlad@192.168.1.11/test with id mywork

 ~/Dropbox  duplicacy2.3.0 -log backup -stats -vss
2019-11-27 21:21:54.647 INFO STORAGE_SET Storage set to sftp://vlad@192.168.1.11/test
2019-11-27 21:21:55.545 INFO BACKUP_START No previous backup found
2019-11-27 21:21:55.914 INFO VSS_DONE Shadow copy created and mounted at /tmp/snp_213689641
2019-11-27 21:21:55.914 INFO BACKUP_INDEXING Indexing /Users/vlad/Dropbox
2019-11-27 21:21:55.914 INFO SNAPSHOT_FILTER Parsing filter file /Users/vlad/Dropbox/.duplicacy/filters
2019-11-27 21:21:55.914 INFO SNAPSHOT_FILTER Loaded 0 include/exclude pattern(s)
2019-11-27 21:21:56.552 INFO BACKUP_LIST Listing all chunks
2019-11-27 21:21:57.217 INFO UPLOAD_PROGRESS Uploaded chunk 1 size 1783321, 1.70MB/s 00:27:40 0.0%
2019-11-27 21:21:57.375 INFO UPLOAD_PROGRESS Uploaded chunk 2 size 1403112, 3.04MB/s 00:15:29 0.1%
2019-11-27 21:21:58.713 INFO UPLOAD_PROGRESS Uploaded chunk 3 size 9941349, 6.26MB/s 00:07:30 0.4%
2019-11-27 21:22:01.014 INFO UPLOAD_PROGRESS Uploaded chunk 4 size 16478452, 5.65MB/s 00:08:16 0.9%
2019-11-27 21:22:02.222 INFO UPLOAD_PROGRESS Uploaded chunk 5 size 6997979, 5.82MB/s 00:08:00 1.2%
2019-11-27 21:22:03.711 INFO UPLOAD_PROGRESS Uploaded chunk 6 size 4435348, 5.59MB/s 00:08:19 1.3%
2019-11-27 21:22:03.907 INFO UPLOAD_PROGRESS Uploaded chunk 7 size 1100142, 5.74MB/s 00:08:05 1.4%
2019-11-27 21:22:04.444 INFO UPLOAD_PROGRESS Uploaded chunk 8 size 3280025, 5.41MB/s 00:08:34 1.5%
2019-11-27 21:22:04.943 INFO UPLOAD_PROGRESS Uploaded chunk 9 size 2192313, 5.68MB/s 00:08:10 1.6%
2019-11-27 21:22:05.766 INFO UPLOAD_PROGRESS Uploaded chunk 10 size 3614789, 5.43MB/s 00:08:32 1.7%
2019-11-27 21:22:07.116 INFO UPLOAD_PROGRESS Uploaded chunk 11 size 5937934, 4.96MB/s 00:09:19 1.9

And lastly, I tested again with the old version (2.2.3) just to get a sense of speed and it is much much faster (25-30MB/s):

 ~/Dropbox  duplicacy2.2.3 init -encrypt VMacTest /Volumes/BackupV
Enter storage password for /Volumes/BackupV:****************************************************************
The storage '/Volumes/BackupV' has already been initialized
Compression level: 100
Average chunk size: 4194304
Maximum chunk size: 16777216
Minimum chunk size: 1048576
Chunk seed: 897fe215233abffb006661497326c230eb1428bf36070980af629a7530d69a2f
/Users/vlad/Dropbox will be backed up to /Volumes/BackupV with id VMacTest
 
 ✘  ~/Dropbox  duplicacy -log backup -stats
2019-11-27 21:25:19.820 INFO STORAGE_SET Storage set to /Volumes/BackupV
2019-11-27 21:25:27.443 INFO BACKUP_START No previous backup found
2019-11-27 21:25:27.443 INFO BACKUP_INDEXING Indexing /Users/vlad/Dropbox
2019-11-27 21:25:27.443 INFO SNAPSHOT_FILTER Parsing filter file /Users/vlad/Dropbox/.duplicacy/filters
2019-11-27 21:25:27.443 INFO SNAPSHOT_FILTER Loaded 0 include/exclude pattern(s)
2019-11-27 21:25:29.288 INFO UPLOAD_PROGRESS Uploaded chunk 1 size 2145302, 1.02MB/s 00:45:59 0.0%
2019-11-27 21:25:29.312 INFO UPLOAD_PROGRESS Skipped chunk 2 size 1212810, 1.60MB/s 00:29:22 0.1%
2019-11-27 21:25:29.328 INFO UPLOAD_PROGRESS Skipped chunk 3 size 2007459, 2.56MB/s 00:18:22 0.1%
2019-11-27 21:25:29.637 INFO UPLOAD_PROGRESS Skipped chunk 4 size 15443875, 9.92MB/s 00:04:43 0.7%
2019-11-27 21:25:29.643 INFO UPLOAD_PROGRESS Skipped chunk 5 size 5817797, 12.70MB/s 00:03:41 0.8%
2019-11-27 21:25:29.701 INFO UPLOAD_PROGRESS Skipped chunk 6 size 4784606, 14.98MB/s 00:03:07 1.0%
2019-11-27 21:25:29.720 INFO UPLOAD_PROGRESS Skipped chunk 7 size 1220246, 15.56MB/s 00:03:00 1.1%
2019-11-27 21:25:29.794 INFO UPLOAD_PROGRESS Skipped chunk 8 size 12561249, 21.55MB/s 00:02:10 1.5%
2019-11-27 21:25:29.799 INFO UPLOAD_PROGRESS Skipped chunk 9 size 1150653, 22.10MB/s 00:02:06 1.5%
2019-11-27 21:25:29.804 INFO UPLOAD_PROGRESS Skipped chunk 10 size 1266680, 22.70MB/s 00:02:03 1.6%
2019-11-27 21:25:29.982 INFO UPLOAD_PROGRESS Skipped chunk 11 size 16777216, 30.70MB/s 00:01:30 2.1%
2019-11-27 21:25:29.998 INFO UPLOAD_PROGRESS Skipped chunk 12 size 2326396, 31.81MB/s 00:01:27 2.2%
2019-11-27 21:25:30.044 INFO UPLOAD_PROGRESS Skipped chunk 13 size 1989702, 21.84MB/s 00:02:07 2.3%
2019-11-27 21:25:30.128 INFO UPLOAD_PROGRESS Skipped chunk 14 size 2426828, 22.61MB/s 00:02:02 2.4%
2019-11-27 21:25:30.179 INFO UPLOAD_PROGRESS Skipped chunk 15 size 1810704, 23.19MB/s 00:01:59 2.4%
2019-11-27 21:25:30.192 INFO UPLOAD_PROGRESS Skipped chunk 16 size 1895979, 23.79MB/s 00:01:56 2.5%
2019-11-27 21:25:32.170 INFO UPLOAD_PROGRESS Uploaded chunk 17 size 10194482, 16.22MB/s 00:02:50 2.8%
2019-11-27 21:25:32.196 INFO UPLOAD_PROGRESS Skipped chunk 18 size 2982936, 16.79MB/s 00:02:44 2.9%
2019-11-27 21:25:32.227 INFO UPLOAD_PROGRESS Skipped chunk 19 size 4684822, 17.68MB/s 00:02:35 3.1%
2019-11-27 21:25:32.276 INFO UPLOAD_PROGRESS Skipped chunk 20 size 3538023, 18.36MB/s 00:02:29 3.2%
2019-11-27 21:25:32.308 INFO UPLOAD_PROGRESS Skipped chunk 21 size 2850091, 18.90MB/s 00:02:25 3.3%

In conclusion, for now I will stick to duplicacy 2.2.3 until 2.3.0 will work on Catalina with a network share.

When it says “Skipped chunk”, the chunk isn’t actually uploaded, but the speed is still calculated as if the chunk were uploaded, so the numbers there do not reflect the actual transfer speed.

The performances of NFS and SFTP should be similar.

1 Like

That I didn’t know. I probably wrongly assumed SFTP is slower due to encryption overhead. But I redid tests and it is actually slightly faster in my case. But there is some error introduced in 2.3.0, right?

There was no code change regarding the file backend (duplicacy_filestorage.c), but version 2.3.0 was built with go 1.12. I’m not sure if that is the reason.