[Duplicity-talk] Duplicity not continuing and is 'stuck' restarting after interrupted backup

[Scott Hansen]

Hey all,

After a failed backup attempt with this error:

#########################
AsyncScheduler: scheduling task for asynchronous execution                      
                                    [298/4524]
No handlers could be found for logger "paramiko.transport"
AsyncScheduler: a previously scheduled task has failed; propagating the result 
immediately
AsyncScheduler: task execution done (success: False)
Backend error detail: Traceback (most recent call last):
  File "/usr/bin/duplicity", line 1391, in <module>
    with_tempdir(main)
  File "/usr/bin/duplicity", line 1384, in with_tempdir
    fn()
  File "/usr/bin/duplicity", line 1354, in main
    full_backup(col_stats)
  File "/usr/bin/duplicity", line 500, in full_backup
    globals.backend)
  File "/usr/bin/duplicity", line 399, in write_multivol
    (tdp, dest_filename, vol_num)))
  File "/usr/lib/python2.7/site-packages/duplicity/asyncscheduler.py", line 
151, in schedule_task
    return self.__run_asynchronously(fn, params)
  File "/usr/lib/python2.7/site-packages/duplicity/asyncscheduler.py", line 
215, in __run_asynchronously
    with_lock(self.__cv, wait_for_and_register_launch)
  File "/usr/lib/python2.7/site-packages/duplicity/dup_threading.py", line 100, 
in with_lock
    return fn()
  File "/usr/lib/python2.7/site-packages/duplicity/asyncscheduler.py", line 
207, in wait_for_and_register_launch
    check_pending_failure() # raise on fail
  File "/usr/lib/python2.7/site-packages/duplicity/asyncscheduler.py", line 
191, in check_pending_failure
    self.__failed_waiter()
  File "/usr/lib/python2.7/site-packages/duplicity/dup_threading.py", line 201, 
in caller
    value = fn()
  File "/usr/lib/python2.7/site-packages/duplicity/asyncscheduler.py", line 
183, in <lambda>
    (waiter, caller) = async_split(lambda: fn(*params))
  File "/usr/bin/duplicity", line 398, in <lambda>
    async_waiters.append(io_scheduler.schedule_task(lambda tdp, dest_filename, 
vol_num: put(tdp, dest_filename, vol_num),
  File "/usr/bin/duplicity", line 296, in put
    backend.put(tdp, dest_filename)
  File "/usr/lib/python2.7/site-packages/duplicity/backends/sshbackend.py", 
line 191, in put
    raise BackendException("sftp put of %s (as %s) failed: %s" % 
(source_path.name,remote_filename,e))
BackendException: sftp put of /tmp/duplicity-9_jssu-tempdir/mktemp-uqQRIn-42 
(as duplicity-full.20120507T060530Z.vol41.difftar
.gpg) failed: Server connection dropped: 
#########################

When restarting the backup, the process starts and then gets stuck with very
little CPU usage until I ^C to stop it. Here's the output with -vdebug:

#########################
Using archive dir: /root/.cache/duplicity/1498ef4c9557164d69523e5aec4c78ce
Using backup name: 1498ef4c9557164d69523e5aec4c78ce
Import of duplicity.backends.sshbackend Succeeded
Import of duplicity.backends.rsyncbackend Succeeded
Import of duplicity.backends.botobackend Succeeded
Import of duplicity.backends.webdavbackend Succeeded
Import of duplicity.backends.hsibackend Succeeded
Import of duplicity.backends.localbackend Succeeded
Import of duplicity.backends.ftpsbackend Succeeded
Import of duplicity.backends.giobackend Failed: No module named gio
Import of duplicity.backends.ftpbackend Succeeded
Import of duplicity.backends.cloudfilesbackend Succeeded
Import of duplicity.backends.u1backend Succeeded
Import of duplicity.backends.tahoebackend Succeeded
Import of duplicity.backends.imapbackend Succeeded
Import of duplicity.backends.gdocsbackend Succeeded
Main action: inc
================================================================================
duplicity 0.6.18 (February 29, 2012)
Args: /usr/bin/duplicity --use-agent -vdebug --encrypt-key XXXXXXXX --sign-key 
XXXXXXXX --full-if-older-than 60D --exclude /mn
t/backup/bfd-training-data --exclude /mnt/backup/fsarchiver --exclude 
/mnt/backup/media --exclude /mnt/backup/usapparel --asyn
chronous-upload /mnt/backup scp://address@hidden//backups/homeserver
Linux homeserver 3.0.29-1-lts #1 SMP PREEMPT Mon Apr 23 09:41:11 CEST 2012 
x86_64 AMD Sempron(tm) Processor 3400+
/usr/bin/python2 2.7.3 (default, Apr 24 2012, 00:00:54) 
[GCC 4.7.0 20120414 (prerelease)]
================================================================================
Using temporary directory /tmp/duplicity-OjWCPd-tempdir
Registering (mkstemp) temporary file 
/tmp/duplicity-OjWCPd-tempdir/mkstemp-GZ2ieI-1
Temp has 490532864 available, backup will use approx 60293120.
Local and Remote metadata are synchronized, no sync needed.
41 files exist on backend
2 files exist in cache
Extracting backup chains from list of files: 
['duplicity-full.20120507T060530Z.manifest.part', 
'duplicity-full-signatures.2012
0507T060530Z.sigtar.part', 'duplicity-full.20120507T060530Z.vol1.difftar.gpg', 
'duplicity-full.20120507T060530Z.vol2.difftar.g
pg', 'duplicity-full.20120507T060530Z.vol3.difftar.gpg', 
'duplicity-full.20120507T060530Z.vol4.difftar.gpg', 'duplicity-full.2
0120507T060530Z.vol5.difftar.gpg', 
'duplicity-full.20120507T060530Z.vol6.difftar.gpg', 
'duplicity-full.20120507T060530Z.vol7.d
ifftar.gpg', 'duplicity-full.20120507T060530Z.vol8.difftar.gpg', 
'duplicity-full.20120507T060530Z.vol9.difftar.gpg', 'duplicit
y-full.20120507T060530Z.vol10.difftar.gpg', 
'duplicity-full.20120507T060530Z.vol11.difftar.gpg', 
'duplicity-full.20120507T0605
30Z.vol12.difftar.gpg', 'duplicity-full.20120507T060530Z.vol13.difftar.gpg', 
'duplicity-full.20120507T060530Z.vol14.difftar.gp
g', 'duplicity-full.20120507T060530Z.vol15.difftar.gpg', 
'duplicity-full.20120507T060530Z.vol16.difftar.gpg', 'duplicity-full.
20120507T060530Z.vol17.difftar.gpg', 
'duplicity-full.20120507T060530Z.vol18.difftar.gpg', 
'duplicity-full.20120507T060530Z.vol
19.difftar.gpg', 'duplicity-full.20120507T060530Z.vol20.difftar.gpg', 
'duplicity-full.20120507T060530Z.vol21.difftar.gpg', 'du
plicity-full.20120507T060530Z.vol22.difftar.gpg', 
'duplicity-full.20120507T060530Z.vol23.difftar.gpg', 'duplicity-full.2012050
7T060530Z.vol24.difftar.gpg', 
'duplicity-full.20120507T060530Z.vol25.difftar.gpg', 
'duplicity-full.20120507T060530Z.vol26.diff
tar.gpg', 'duplicity-full.20120507T060530Z.vol27.difftar.gpg', 
'duplicity-full.20120507T060530Z.vol28.difftar.gpg', 'duplicity
-full.20120507T060530Z.vol29.difftar.gpg', 
'duplicity-full.20120507T060530Z.vol30.difftar.gpg', 
'duplicity-full.20120507T06053
0Z.vol31.difftar.gpg', 'duplicity-full.20120507T060530Z.vol32.difftar.gpg', 
'duplicity-full.20120507T060530Z.vol33.difftar.gpg
', 'duplicity-full.20120507T060530Z.vol34.difftar.gpg', 
'duplicity-full.20120507T060530Z.vol35.difftar.gpg', 'duplicity-full.2
0120507T060530Z.vol36.difftar.gpg', 
'duplicity-full.20120507T060530Z.vol37.difftar.gpg', 
'duplicity-full.20120507T060530Z.vol3
8.difftar.gpg', 'duplicity-full.20120507T060530Z.vol39.difftar.gpg', 
'duplicity-full.20120507T060530Z.vol40.difftar.gpg', 'dup
licity-full.20120507T060530Z.vol41.difftar.gpg']
File duplicity-full.20120507T060530Z.manifest.part is not part of a known set; 
creating new set
File duplicity-full-signatures.20120507T060530Z.sigtar.part is not part of a 
known set; creating new set             [31/4524]
Ignoring file (rejected by backup set) 
'duplicity-full-signatures.20120507T060530Z.sigtar.part'                      
[30/4524]
File duplicity-full.20120507T060530Z.vol1.difftar.gpg is part of known set      
                                     [29/4524]
File duplicity-full.20120507T060530Z.vol2.difftar.gpg is part of known set      
                                     [28/4524]
File duplicity-full.20120507T060530Z.vol3.difftar.gpg is part of known set      
                                     [27/4524]
File duplicity-full.20120507T060530Z.vol4.difftar.gpg is part of known set      
                                     [26/4524]
File duplicity-full.20120507T060530Z.vol5.difftar.gpg is part of known set      
                                     [25/4524]
File duplicity-full.20120507T060530Z.vol6.difftar.gpg is part of known set      
                                     [24/4524]
File duplicity-full.20120507T060530Z.vol7.difftar.gpg is part of known set      
                                     [23/4524]
File duplicity-full.20120507T060530Z.vol8.difftar.gpg is part of known set      
                                     [22/4524]
File duplicity-full.20120507T060530Z.vol9.difftar.gpg is part of known set      
                                     [21/4524]
File duplicity-full.20120507T060530Z.vol10.difftar.gpg is part of known set     
                                     [20/4524]
File duplicity-full.20120507T060530Z.vol11.difftar.gpg is part of known set
File duplicity-full.20120507T060530Z.vol12.difftar.gpg is part of known set
File duplicity-full.20120507T060530Z.vol13.difftar.gpg is part of known set
File duplicity-full.20120507T060530Z.vol14.difftar.gpg is part of known set
File duplicity-full.20120507T060530Z.vol15.difftar.gpg is part of known set
File duplicity-full.20120507T060530Z.vol16.difftar.gpg is part of known set
File duplicity-full.20120507T060530Z.vol17.difftar.gpg is part of known set
File duplicity-full.20120507T060530Z.vol18.difftar.gpg is part of known set
File duplicity-full.20120507T060530Z.vol19.difftar.gpg is part of known set
File duplicity-full.20120507T060530Z.vol20.difftar.gpg is part of known set
File duplicity-full.20120507T060530Z.vol21.difftar.gpg is part of known set
File duplicity-full.20120507T060530Z.vol22.difftar.gpg is part of known set
File duplicity-full.20120507T060530Z.vol23.difftar.gpg is part of known set
File duplicity-full.20120507T060530Z.vol24.difftar.gpg is part of known set
File duplicity-full.20120507T060530Z.vol25.difftar.gpg is part of known set
File duplicity-full.20120507T060530Z.vol26.difftar.gpg is part of known set
File duplicity-full.20120507T060530Z.vol27.difftar.gpg is part of known set
File duplicity-full.20120507T060530Z.vol28.difftar.gpg is part of known set
File duplicity-full.20120507T060530Z.vol29.difftar.gpg is part of known set
File duplicity-full.20120507T060530Z.vol30.difftar.gpg is part of known set
File duplicity-full.20120507T060530Z.vol31.difftar.gpg is part of known set
File duplicity-full.20120507T060530Z.vol32.difftar.gpg is part of known set
File duplicity-full.20120507T060530Z.vol33.difftar.gpg is part of known set
File duplicity-full.20120507T060530Z.vol34.difftar.gpg is part of known set
File duplicity-full.20120507T060530Z.vol35.difftar.gpg is part of known set
File duplicity-full.20120507T060530Z.vol36.difftar.gpg is part of known set
File duplicity-full.20120507T060530Z.vol37.difftar.gpg is part of known set
File duplicity-full.20120507T060530Z.vol38.difftar.gpg is part of known set
File duplicity-full.20120507T060530Z.vol39.difftar.gpg is part of known set
File duplicity-full.20120507T060530Z.vol40.difftar.gpg is part of known set
File duplicity-full.20120507T060530Z.vol41.difftar.gpg is part of known set
Found backup chain [Sun May  6 23:05:30 2012]-[Sun May  6 23:05:30 2012]
Last full backup left a partial set, restarting.
Last full backup date: Sun May  6 23:05:30 2012
Collection Status
-----------------
Connecting with backend: SftpBackend
Archive dir: /root/.cache/duplicity/1498ef4c9557164d69523e5aec4c78ce

Found 0 secondary backup chains.

Found primary backup chain with matching signature chain:
-------------------------
Chain start time: Sun May  6 23:05:30 2012
Chain end time: Sun May  6 23:05:30 2012
Number of contained backup sets: 1
Total number of contained volumes: 41
 Type of backup set:                            Time:      Num volumes:
                Full         Sun May  6 23:05:30 2012                41
-------------------------
No orphaned or incomplete backup sets found.
RESTART: Volumes 41 to 42 failed to upload before termination.
         Restarting backup at volume 41.
Registering (mktemp) temporary file 
/tmp/duplicity-OjWCPd-tempdir/mktemp-Fx_YTQ-2
^CRemoving still remembered temporary file 
/tmp/duplicity-OjWCPd-tempdir/mktemp-Fx_YTQ-2
Removing still remembered temporary file 
/tmp/duplicity-OjWCPd-tempdir/mkstemp-GZ2ieI-1
INT intercepted...exiting
#########################

Can anyone tell me what's going on here? There doesn't seem to be any useful
info right before it stops working.

Let me know if any further information is needed.

Thanks!
Scott