[Duplicity-talk] Duplicity - hang/choke near the end - on a large directory

[Dirk-Willem van Gulik]

Folks,

I have a setup which has been running well for some 9 years; most recent OS and 
duplicity change from about 6 months ago. Daily incrementals with some 
striping; with every 2 months overlapping full backups. Backend is an sFTP site 
with PKCS#11/#15.

This months quarterly full backup ‘hung’ on what is very likely its last 
partial upload. No sign of any IO issues, diskspace issues or exhaustion of 
some resource.

The only thing special about that last block may be the fact that it has a much 
larger number of files than any of the earlier blocks and that this last block 
contains a single large file. A restart (after clearing the lock) and a restart 
(after clearing lock and cache) did not make things work again. 

The sanitised log file is below. I.e. we see a lot of 

        A /some/file 

getting added; then a 

        AsyncScheduler: task execution done (success: True)

followed by the 

        A /som/file
        <hang>

and then a hang (> 12 hours for a process that should complete in about 3 
normally)

The "AsyncScheduler: task execution done (success: True)” prior to the hang is 
the 953rth — i.e. corresponding to a "Writing 
duplicity-full.20160503T111720Z.vol953.difftar.gpg”.

There is no sign of a 954 starting for the files which are (still) added during 
the hang - so not sure what the task execution refers to.

Attaching (d)truss/ktrace/strace to the hanging process does not give a peep 
(nor does it rack up any cpu cycles); lsof does show an open pipe to a gpg 
process; no open files (for writing, nor any temp files).

The attached gpg process spins in a syscall (very likely a read);  has a temp 
files open, twice,  with what seems to be a gpg encrupted payload - as well as 
a single file from the ‘A’ emitted a few 100 files earlier*. This file happens 
to be large (14Mb); while all other files in this ‘part’ are in the the kBytes 
or smaller.

A kill (or kill -9) does not yield any response either. The machine has done at 
least 1, possibly 2 full backups cycles with the exact same kernel/python/etc.

What is a good way to dive deeper into this ? Or does this ring a bell with 
anyone ? Or what debugging options do I have left ?

Dw.


*: I am a bit confused about it - would have assumed that gpg was just 
processing a stream blindly — why does it see the actual file names ?


Using archive dir: /var/db/duplicity/e39ca70….894946c1
Using backup name: e39ca7...94946c0
...
Import of duplicity.backends.rsyncbackend Succeeded
Import of duplicity.backends.ssh_paramiko_backend Succeeded
Import of duplicity.backends.ssh_pexpect_backend Succeeded
Main action: full
================================================================================
duplicity 0.7.05 (September 15, 2015)
Args: /usr/local/bin/duplicity full --asynchronous-upload --ssh-options 
-oIdentityFile=/some/cnfdir --archive-dir /var/db/duplicity 
--hidden-encrypt-key XX--hidden-encrypt-key XXX --hidden-encrypt-key XXX 
--sign-key XXXX --include /etc —include/stuff --exclude ** -v 7 / 
pexpect+sftp://address@hidden
FreeBSD xxxx.webweaving.org 10.2-RELEASE-p9 FreeBSD 10.2-RELEASE-p9 #0: Thu Jan 
14 01:32:46 UTC 2016     address@hidden:/usr/obj/usr/src/sys/GENERIC amd64 amd64
/usr/local/bin/python2.7 2.7.11 (default, Jan 16 2016, 01:23:17) 
[GCC 4.2.1 Compatible FreeBSD Clang 3.4.1 (tags/RELEASE_34/dot1-final 208032)]
================================================================================
Using temporary directory /tmp/duplicity-HC6yqb-tempdir
Temp has 12101220048384 available, backup will use approx 60293120.
Running 'sftp -oIdentityFile=/some/cnfdir -oServerAliveInterval=15 
-oServerAliveCountMax=2 address@hidden'
sftp command: 'mkdir "."'
sftp command: 'cd "."'
sftp command: 'ls -1'
Synchronizing remote metadata to local cache...
Copying duplicity-full-signatures.20160101T011501Z.sigtar.gpg to local cache.
Running 'sftp -oIdentityFile=/some/cnfdir -oServerAliveInterval=15 
-oServerAliveCountMax=2 address@hidden'
sftp command: 'get "./duplicity-full-signatures.20160101T011501Z.sigtar.gpg" 
"/tmp/duplicity-HC6yqb-tempdir/mktemp-wGp1rN-2"'
Deleting /tmp/duplicity-HC6yqb-tempdir/mktemp-wGp1rN-2
Deleting /tmp/duplicity-HC6yqb-tempdir/mktemp-9EPrVs-3
Copying duplicity-full.20160101T011501Z.manifest.gpg to local cache.

…<repeated for all other files…>

Running 'sftp -oIdentityFile=/some/cnfdir -oServerAliveInterval=15 
-oServerAliveCountMax=2 address@hidden'
sftp command: 'get 
"./duplicity-new-signatures.20160429T002400Z.to.20160430T002400Z.sigtar.gpg" 
"/tmp/duplicity-HC6yqb-tempdir/mktemp-U_FaFN-472"'
Deleting /tmp/duplicity-HC6yqb-tempdir/mktemp-U_FaFN-472
Deleting /tmp/duplicity-HC6yqb-tempdir/mktemp-iq9s8E-473
Running 'sftp -oIdentityFile=/some/cnfdir -oServerAliveInterval=15 
-oServerAliveCountMax=2 address@hidden'
sftp command: 'mkdir "."'
sftp command: 'cd "."'
sftp command: 'ls -1'
Added incremental Backupset (start_time: Fri Jan  1 02:15:01 2016 / end_time: 
Tue Jan  5 02:24:00 2016)
Added incremental Backupset (start_time: Tue Jan  5 02:24:00 2016 / end_time: 
Wed Jan  6 02:24:00 2016)

….<repeated until today>….

Added incremental Backupset (start_time: Fri Apr 29 02:24:00 2016 / end_time: 
Sat Apr 30 02:24:00 2016)
Warning, found incomplete backup sets, probably left from aborted session
Last full backup date: Fri Jan  1 02:15:01 2016
Using temporary directory 
/var/db/duplicity/e39ca701908673c2e81e6c59894946c1/duplicity-QDitlY-tempdir
Using temporary directory 
/var/db/duplicity/e39ca701908673c2e81e6c59894946c1/duplicity-N3YtEw-tempdir
AsyncScheduler: instantiating at concurrency 1

A ...snipped add of 2390 files ..

AsyncScheduler: scheduling task for asynchronous execution
Processed volume 1
Writing duplicity-full.20160503T111720Z.vol1.difftar.gpg
Running 'sftp -oIdentityFile=/some/cnfdir -oServerAliveInterval=15 
-oServerAliveCountMax=2 address@hidden'
sftp command: 'put "/tmp/duplicity-HC6yqb-tempdir/mktemp-WcmH1t-474" 
"./.duplicity-full.20160503T111720Z.vol1.difftar.gpg.part”’

A ...snipped add of 25 files ..

sftp command: 'rename 
"./.duplicity-full.20160503T111720Z.vol1.difftar.gpg.part" 
"./duplicity-full.20160503T111720Z.vol1.difftar.gpg”’

… all well for the next 950 ish difftar uploads…...

sftp command: 'rename 
"./.duplicity-full.20160503T111720Z.vol953.difftar.gpg.part" 
"./duplicity-full.20160503T111720Z.vol953.difftar.gpg"'
A ...snipped add of 197 files ..

Deleting /tmp/duplicity-HC6yqb-tempdir/mktemp-FNlhPm-1426
AsyncScheduler: task execution done (success: True)

A ...snipped add of 852 files ..
— hang —