Sftp "Permission denied" - I need debugging help!

Support
#1

I’ve successfully done multiple backups from 2 machines (one osx, one linux) to my ubuntu home server via sftp and I’ve added to the repo from other disks on the server. All went well, deduplication worked very well.

I’m now adding to the repo from a another linux box, a backup of the home folder has worked well but I’ve added a second backup of some more extraneous stuff (/etc, /root and /opt) and its failed twice with this error:

Skipped chunk 3276 size 2318118, 42.19MB/s 00:00:12 97.2%
Failed to upload the chunk ad4cd25bd3e7849b19ce948d7844c94e39b510f9b4f69e8f29e408ab3ced5ae3: sftp: "Permission denied" (SSH_FX_PERMISSION_DENIED)
Incomplete snapshot saved to /duplicacy/.duplicacy/incomplete

This is duplicacy linux cli 2.09 transferring files via sftp over a gigabit wired connection . There is a duplicacy user setup on the server in a chroot that’s only allowed to do sftp. duplicacy is running as root on the client and sftp’ing as duplicacy user on the server. The chroot on the server is in a zfs mirror.

It’s worked well, current repo size is 1.1tb. So it seems unlikely to be a simple permissions issue on the server, which has me wondering what the problem file is that that failed chunk came from - is there a way to find out?

#2

If you run with -d option like duplicacy -d backup it should give you the file that the failed chunk came from by searching for those “Packed file” messages. However, I think this should be a permission issue on the server. Could this be the first chunk to be uploaded by this backup run because all previous chunks already existed on the server?

#3

Thanks. I’ll try -d tomorrow.

It might be the first uploaded chunk, I’ll check that too.

The thing is, I’ve already run one backup from this machine repeatedly, its just a different backup set. I makes little sense to me that backing up different files would cause a permissions issue. The only thing that I changed was the backup id - ssh key and password I kept the same.

Anyway, will investigate more tomorrow, thanks for the prompt answer.

#4

Ok, edited results of running ‘duplicacy -d backup’ for this backup set below.

  • This failing chunk is not the first chunk to be uploaded, there is at least one before.
  • I really don’t need to backup vagrant so my first try at a workaround will be excluding that.

*snip*

Listing chunks/d0/36/
Listing chunks/d0/b4/
Listing chunks/d0/e3/
Skipped 15156 files from previous incomplete backup
Packing etc/mailcap
Packed etc/mailcap (59820)

*snip*

Packing etc/zfs/zpool.cache
Packed etc/zfs/zpool.cache (1112)
Packing opt/vagrant/embedded/gems/gems/vagrant-share-1.1.6/localbin/proxy_windows_amd64.exe
Skipped chunk 296659971b242aed467913d66aa7fa0e1cbc60a2b319965d5185c659a31dcc0b in cache
Skipped chunk 2 size 4704183, 4.49MB/s 00:01:46 0.9%
Packed opt/vagrant/embedded/gems/gems/vagrant-share-1.1.6/localbin/proxy_windows_amd64.exe (12208128)
Packing opt/vagrant/embedded/gems/gems/vagrant-share-1.1.6/locales/en.yml

*snip*

Packing opt/vagrant/embedded/include/lzma.h
Skipped chunk cb4851f3ad36ea52bf4bfd2ebeb6e11cd7f97b884b75f84ad653365511c2ca6a in cache
Skipped chunk 3 size 2318118, 6.70MB/s 00:01:11 1.4%
Packed opt/vagrant/embedded/include/lzma.h (9276)
Packing opt/vagrant/embedded/include/yaml.h

*snip*

Packed opt/vagrant/embedded/include/openssl/modes.h (8260)
Packing opt/vagrant/embedded/include/openssl/obj_mac.h
Chunk 6e3487f0b794551849d5cb8c83548dae1be5ef72d1615ee8a7d9173173550896 has been uploaded
Uploaded chunk 1 size 5088979, 11.55MB/s 00:00:41 2.4%
Packed opt/vagrant/embedded/include/openssl/obj_mac.h (175657)

*snip*

Packing opt/vagrant/embedded/lib/libcrypto.so
Packed opt/vagrant/embedded/lib/libcrypto.so (2588980)
Packing opt/vagrant/embedded/lib/libcrypto.so.1.0.0
Failed to upload the chunk ad4cd25bd3e7849b19ce948d7844c94e39b510f9b4f69e8f29e408ab3ced5ae3: sftp: "Permission denied" (SSH_FX_PERMISSION_DENIED)
Incomplete snapshot saved to /duplicacy/.duplicacy/incomplete
#5

Add me to the list of people that can’t grok duplicacy excludes patterns :slight_smile:

In the end I removed the symlink to /opt and added links to the specific subfolders in /opt that I really wanted to back up. End result was that the troublesome chunk of vagrant was no longer included and the backup proceeded perfectly.

So presumably the sftp permissions error results from the read on the client rather than write on the server - does duplicacy copy a chunk before upload or just read direct from the original file? If that latter, perhaps there’s some on disk corruption. I’ll run fsck later and see what I can find, but out of time for now.

#6

The exclude pattern should be -opt/*.

Duplicacy doesn’t copy a chunk first. It saves snapshot chunks to a local cache and sometimes an error may occur if there is an issue with the local disk. However, this chunk is a file chunk which is never saved locally, and the error message clearly indicates it is sftp related.

I would guess it is a quota issue. The sftp server should return SSH_FX_QUOTA_EXCEEDED in such a case but maybe the sftp server doesn’t implement it correctly (or couldn’t tell if it is a permission issue or a quota issue due to the chroot setup).

#7

Well, I can’t find any disk errors so it does seem like it might be server side.

That said, I set no quota when I set up the chroot. There’s no zfs quota set on the filesystem. There’s circa 680Gb of space left on that zpool. df -i shows only 1% of inodes used. I can’t think of anything else to check.

For now I’ve worked around the problem, so I’m happy to let this go. Thanks for your help.

#8

Just hit this issue again, with a different client machine but same server/repo. This time I figured out how to get some logging working for the chroot user…

Here’s the error when running duplicacy:

Incomplete snapshot loaded from /Volumes/av/.duplicacy/incomplete
Listing all chunks
Skipped 2328 files from previous incomplete backup
Skipped chunk 1 size 1974813, 175KB/s 9 days 10:04:10 0.0%
Skipped chunk 2 size 2962856, 438KB/s 3 days 18:24:51 0.0%
Skipped chunk 3 size 1112192, 537KB/s 3 days 01:47:32 0.0%
Failed to upload the chunk d45db57979316d2df1cc718b9b690159e0c60cdf4f815a483ba823296b1d0b79: sftp: "Permission denied" (SSH_FX_PERMISSION_DENIED)
Skipped chunk 5 size 7951441, 1.21MB/s 1 day 07:53:00 0.0%
Incomplete snapshot saved to /Volumes/av/.duplicacy/incomplete

Here’s the log from the sftp server:

Oct 20 15:44:19 hps internal-sftp[12847]: opendir "repo/chunks/d0/e3"
Oct 20 15:44:19 hps internal-sftp[12847]: closedir "repo/chunks/d0/e3"
Oct 20 15:44:30 hps internal-sftp[12847]: stat name "repo/chunks/d4"
Oct 20 15:44:30 hps internal-sftp[12847]: stat name "repo/chunks/d4/5d"
Oct 20 15:44:30 hps internal-sftp[12847]: stat name "repo/chunks/d4/5d/b57979316d2df1cc718b9b690159e0c60cdf4f815a483ba823296b1d0b79"
Oct 20 15:44:30 hps internal-sftp[12847]: sent status Permission denied
Oct 20 15:44:30 hps internal-sftp[12847]: stat name "repo/chunks/d4/5d/b5"
Oct 20 15:44:30 hps internal-sftp[12847]: sent status Permission denied
Oct 20 15:44:30 hps internal-sftp[12847]: open "repo/chunks/d4/5d/b57979316d2df1cc718b9b690159e0c60cdf4f815a483ba823296b1d0b79.tppypipa.tmp" flags WRITE,CREATE,TRUNCATE mode 0666
Oct 20 15:44:30 hps internal-sftp[12847]: sent status Permission denied
Oct 20 15:44:30 hps internal-sftp[12847]: session closed for local user duplicacy from [192.168.0.x]

Looking at the repo filesystem for that chunk:

drwxrwxr-x 2 duplicacy duplicacy  5 Aug 30 07:01 5b
drwxrwxr-x 2 duplicacy duplicacy  5 Sep 14 17:31 5c
drwxr--r-- 2 root      root       3 Oct 17 13:02 5d
drwxrwxr-x 2 duplicacy duplicacy  5 Oct 19 11:54 5e
drwxrwxr-x 2 duplicacy duplicacy  5 Oct 19 11:21 5f

It’s clear why the permissions error is happening - how that one chunk directory become owned by root is still a mystery. About to correct the ownership (the sftp user is duplicacy) and run the backup again.

Clearly not duplicacy’s fault though, definitely something server side.

#9

Final comment: after correcting permissions on the rogue repo trunk, backup is working as expected.