fails when backing up to remote dir w/ lots of files

[Mark A. Hershberger]

I'm trying to use ssh to backup to a remote directory where lots of filess (from duplicity) already exist.

The GUI puts the following on stdout/stderr while running:

  ** (deja-dup:10925): DEBUG: Duplicity.vala:154: Running the following duplicity command: ionice -c3 duplicity --exclude=/home/mah/.cache --exclude=/home/mah/.thumbnails --exclude=/home/mah/.gvfs --exclude=/tmp --exclude=/proc --exclude=/sys --exclude=/home/mah/.local/share/Trash --exclude=/home/mah/.cache --exclude=/home/mah/.beagle/TextCache --exclude=/home/mah/.gvfs --include=/home/mah --exclude=** / ssh://mah@filer:22//mnt/primary/blob/family/mah/backup --ssh-askpass --ssh-options=-oStrictHostKeyChecking=no --dry-run --verbosity=9 --volsize=1 --log-fd=17

  ** (deja-dup:10925): DEBUG: Duplicity.vala:470: duplicity exited with value 30

  ** (deja-dup:10925): DEBUG: Duplicity.vala:154: Running the following duplicity command: ionice -c3 duplicity --exclude=/home/mah/.cache --exclude=/home/mah/.thumbnails --exclude=/home/mah/.gvfs --exclude=/tmp --exclude=/proc --exclude=/sys --exclude=/home/mah/.local/share/Trash --exclude=/home/mah/.cache --exclude=/home/mah/.beagle/TextCache --exclude=/home/mah/.gvfs --include=/home/mah --exclude=** / ssh://mah@filer:22//mnt/primary/blob/family/mah/backup --ssh-askpass --ssh-options=-oStrictHostKeyChecking=no --verbosity=9 --volsize=1 --log-fd=16

  ** (deja-dup:10925): DEBUG: Duplicity.vala:470: duplicity exited with value 30

1. I find it strange that --dry-run failed, but it still tried to do a backup. The GUI displayed "unknown error" after this was done.

2. Running the --dry-run command by hand, I see that duplicity is timing out:

Running 'sftp -oStrictHostKeyChecking=no -oPort=22 mah@filer' (attempt #5)
State = sftp, Before = 'Connecting to filer...'
sftp command: 'mkdir /mnt/primary/blob/family/mah/backup'
State = sftp, Before = 'mkdir /mnt/primary/blob/family/mah/backup
Couldn't create directory: Failure'
sftp command: 'cd /mnt/primary/blob/family/mah/backup'
State = sftp, Before = 'cd /mnt/primary/blob/family/mah/backup'
sftp command: 'ls -1'
State = sftp, Before = 'ls -1'
Timeout waiting for response
Running 'sftp -oStrictHostKeyChecking=no -oPort=22 mah@filer' failed (attempt #5)
Giving up trying to execute 'sftp -oStrictHostKeyChecking=no -oPort=22 mah@filer' after 5 attempts
Using temporary directory /tmp/duplicity-bCTIrl-tempdir
Traceback (most recent call last):
  File "/usr/bin/duplicity", line 579, in <module>
    with_tempdir(main)
  File "/usr/bin/duplicity", line 573, in with_tempdir
    fn()
  File "/usr/bin/duplicity", line 502, in main
    globals.archive_dir).set_values()
  File "/usr/lib/python2.5/site-packages/duplicity/collections.py", line 524, in set_values
    backend_filename_list = self.backend.list()
  File "/usr/lib/python2.5/site-packages/duplicity/backends/sshbackend.py", line 242, in list
    l = self.run_sftp_command(commandline, commands).split('\n')[1:]
  File "/usr/lib/python2.5/site-packages/duplicity/backends/sshbackend.py", line 206, in run_sftp_command
    raise BackendException("Error running '%s'" % commandline)
BackendException: Error running 'sftp -oStrictHostKeyChecking=no -oPort=22 mah@filer'

[Michael Terry (mterry)]

Thanks for the bug report!

You're right that a failure to --dry-run should probably be reported. I'm curious why that would have failed, because it shouldn't do any network connection and thus wouldn't be able to time out.

I see that when you ran duplicity manually, it said:

sftp command: 'mkdir /mnt/primary/blob/family/mah/backup'
State = sftp, Before = 'mkdir /mnt/primary/blob/family/mah/backup
Couldn't create directory: Failure'
sftp command: 'cd /mnt/primary/blob/family/mah/backup'
State = sftp, Before = 'cd /mnt/primary/blob/family/mah/backup'
sftp command: 'ls -1'
State = sftp, Before = 'ls -1'
Timeout waiting for response

Looks like it couldn't create a directory? Are the permissions OK? I assume you can ssh just fine into that machine (i.e. a timeout is certainly unexpected)?

If you want to see exactly what Déjà Dup does when it runs duplicity, run it with the environment variable DEJA_DUP_DEBUG set to 1. This will generate lots of spew, but only the ending exception from duplicity will be of interest. What does that say? (Presumably the same exception as when you ran it manually, but I'm curious what happened when the dry run occurred -- it shouldn't have been the same error, as it never connected).

Thank you!

[Mark A. Hershberger (hexmode)]

Michael Terry <email address hidden> writes:

> You're right that a failure to --dry-run should probably be reported.
> I'm curious why that would have failed, because it shouldn't do any
> network connection and thus wouldn't be able to time out.

I don't know exactly what it is trying to do on --dry-run, but it is
definitely making a network connection.

> Couldn't create directory: Failure'

> Looks like it couldn't create a directory? Are the permissions OK? I
> assume you can ssh just fine into that machine (i.e. a timeout is
> certainly unexpected)?

It couldn't create the directory because it already exists from a
previous backup.

There are, in fact, thousands of files in the directory from the
previous backup. It is timing out because it takes too long to list out
those files.

[Michael Terry (mterry)]

Hmm, OK. I guess a dry run does get the signature file for the backup from the backend. Just no new files are created on the backend.

Regarding the timeout from listing files... I believe a similar issue was reported on the mailing list with the ftp backend recently. I'll look over that thread and see if there was an obvious solution or idea of how to fix it.

[Michael Terry (mterry)]

Hmm, the thread I was thinking of wasn't directly ssh-related: http://lists.gnu.org/archive/html/duplicity-talk/2009-01/msg00039.html

But it seems this kind of problem is known to Ken (the duplicity maintainer). The only workaround is to increase volsize or add an ssh timeout option when calling duplicity. Neither of which are exposed by Deja Dup by default.

[Mark A. Hershberger (hexmode)]

Michael Terry <email address hidden> writes:

> But it seems this kind of problem is known to Ken (the duplicity
> maintainer). The only workaround is to increase volsize or add an ssh
> timeout option when calling duplicity. Neither of which are exposed by
> Deja Dup by default.

The volsize would be especially useful to make accesssible via the GUI.
Perhaps an ssh-timeout as well under “advanced”.

Thanks for your help.

[Michael Terry (mterry)]

I'm not excited about exposing them via the GUI. I feel like I'd rather just get this fixed in duplicity proper, rather than expose such gross details to the user.

Though I sympathise that this does prevent you from using duplicity altogether...

I'll leave this bug open to track fixing it in duplicity. To help avoid this problem in the meantime, I'll bump the volsize up again to its default value of 5 in the next release.

[Michael Terry (mterry)]

I filed a patch to fix this in duplicity's project site: https://savannah.nongnu.org/patch/index.php?6730

[Michael Terry (mterry)]

Patch committed to duplicity HEAD. Will be in next duplicity release.

[Mark A. Hershberger (hexmode)]

just fyi, when you're using sftp (at least on openssh) you're not using /bin/ls, you're using the built-in ls for sftp. For some reason it is much slower than /bin/ls. For large directories "ssh host /bin/ls /full/path" is much faster than the equivilent in sftp. (I was surprised at the speed difference so I checked the sftp source.)

Not sure how feasible it is to use ssh instead of sftp, but it is something to keep in mind.

[Michael Terry (mterry)]

Fixed by the released duplicity 0.5.07.

[Ruben Verweij (ruben-verweij)]

I'm still having this problem..
I'm on karmic with the following versions of duplicity and Déjà Dup:
duplicity:
  Installed: 0.5.18-0ubuntu1
deja-dup:
  Installed: 10.2-0ubuntu1.1

I get the following error code:

** (deja-dup:3411): DEBUG: DuplicityInstance.vala:449: duplicity (3485) exited with value 30

After trying to backup my home directory. Apart from all the --excludes, this is the duplicity command it runs:
** (deja-dup:3411): DEBUG: DuplicityInstance.vala:138: Running the following duplicity (3485) command: nice ionice -c2 -n7 duplicity [all the excludes] file:///media/NAS/Drive D (D)/Ruben/Ruben Backup --verbosity=9 --volsize=5 --archive-dir=/root/.cache/deja-dup --log-fd=18

I am trying to back this up to a cifs mounted NAS disk. I can browse to the destination folder, and Déjà Dup does create a file there of ~120 kb before it crashes. If any additional information is required, I'll be happy to provide it.

[Michael Terry (mterry)]

Thanks for the news, Ruben. But can you please file a new bug, and follow the steps on the bug form? (like provide a log file with debug turned on)

It would help to have a fresh bug-slate to look into your issue.