'Full' backup set displayed by 'collection-status' only reports 1287 of 3192 volumes

On 29.12.2013 03:51, Jonathan Elchison wrote:
> Question #241395 on Duplicity changed:
> https://answers.launchpad.net/duplicity/+question/241395
>
> Description changed to:
> Goal: Use Duplicity to backup user directory on OS X laptop to at-home
> file server, using SSH.
>
> There are two machines in play:
> * Client (MElch2), a laptop running OS X 10.9.1. I used Homebrew to install Duplicity 0.6.22. Logged-in user is 'melissa', but I 'su'ed to user 'jonathan'.
> * Server (JElch4 at 192.168.10.100), a server running Ubuntu Linux with an SSH server. SSH user is also 'jonathan', who has write access to the target directory.
>
> Steps to reproduce:
> 1. Begin from a known state (empty cache and empty backup location)
> bash-3.2$ sudo rm -rf ~/.cache/duplicity/
> 2. Set max open files
> bash-3.2$ ulimit -n 1024
> 3. Start backup
> bash-3.2$ sudo duplicity --no-encryption --ssh-askpass --use-scp --progress --exclude /Users/melissa/Dropbox /Users/melissa ssh://jonathan@192.168.10.100//mnt/raid/bak/Melissa/MElch2/
> 4. Show 'collection-status'
> bash-3.2$ sudo duplicity collection-status --no-encryption --ssh-askpass --use-scp ssh://jonathan@192.168.10.100//mnt/raid/bak/Melissa/MElch2/
> 5. Attempt to list files contained in backup
> bash-3.2$ sudo duplicity list-current-files --no-encryption --ssh-askpass --use-scp ssh://jonathan@192.168.10.100//mnt/raid/bak/Melissa/MElch2/
>
> Expected results (corresponds with step numbers above):
> 1. Cache deleted
> 2. Limit set
> 3. Backup succeeds
> 4. Collection status shows actual number of volumes (in my case, 3192)
> 5. All backed up files are listed
>
> Actual results (corresponds with step numbers above):
> 1. Cache deleted
> 2. Limit set
> 3. Backup succeeds
> 4. Collection status shows only 1287 volumes
> 5. Python exception
>
> Actual output:
> @@@@@@@@@@@@@@@@@@@@ Step 1 @@@@@@@@@@@@@@@@@@@@
> bash-3.2$ sudo rm -rf ~/.cache/duplicity/
> Password:
>
> @@@@@@@@@@@@@@@@@@@@ Step 2 @@@@@@@@@@@@@@@@@@@@
> bash-3.2$ sudo duplicity --no-encryption --ssh-askpass --use-scp --progress --exclude /Users/melissa/Dropbox /Users/melissa ssh://jonathan@192.168.10.100//mnt/raid/bak/Melissa/MElch2/
> Password:
> Import of duplicity.backends.dpbxbackend Failed: No module named dropbox
> Max open files of 256 is too low, should be >= 1024.
> Use 'ulimit -n 1024' or higher to correct.
>
> bash-3.2$ ulimit -n 1024
>
> @@@@@@@@@@@@@@@@@@@@ Step 3 @@@@@@@@@@@@@@@@@@@@
> bash-3.2$ sudo duplicity --no-encryption --ssh-askpass --use-scp --progress --exclude /Users/melissa/Dropbox /Users/melissa ssh://jonathan@192.168.10.100//mnt/raid/bak/Melissa/MElch2/
> Import of duplicity.backends.dpbxbackend Failed: No module named dropbox
> Password for 'jonathan@192.168.10.100':
> Local and Remote metadata are synchronized, no sync needed.
> Last full backup date: none
> No signatures found, switching to full backup.
> 0.0KB 00:00:03 [0.0KB/s] [> ] 0% ETA 3sec
> 0.0KB 00:00:06 [0.0KB/s] [> ] 0% ETA 6sec
> 0.0KB 00:00:09 [0.0B/s] [> ] 0% ETA Stalled!
> 0.0KB 00:00:12 [0.0B/s] [> ] 0% ETA Stalled!
> 0.0KB 00:00:15 [0.0B/s] [> ] 0% ETA Stalled!
> <snip>
> 0.0KB 08:24:40 [0.0B/s] [> ] 0% ETA Stalled!
> 0.0KB 08:24:43 [0.0B/s] [> ] 0% ETA Stalled!
> 0.0KB 08:24:46 [0.0B/s] [> ] 0% ETA Stalled!
> 0.0KB 08:24:49 [0.0KB/s] [========================================>] 100% ETA 0sec
> --------------[ Backup Statistics ]--------------
> StartTime 1388149879.16 (Fri Dec 27 08:11:19 2013)
> EndTime 1388169744.38 (Fri Dec 27 13:42:24 2013)
> ElapsedTime 19865.23 (5 hours 31 minutes 5.23 seconds)
> SourceFiles 74132
> SourceFileSize 86413622259 (80.5 GB)
> NewFiles 74132
> NewFileSize 86413622259 (80.5 GB)
> DeletedFiles 0
> ChangedFiles 0
> ChangedFileSize 0 (0 bytes)
> ChangedDeltaSize 0 (0 bytes)
> DeltaEntries 74132
> RawDeltaSize 86410198462 (80.5 GB)
> TotalDestinationSizeChange 83589125370 (77.8 GB)
> Errors 0
> -------------------------------------------------
>
> @@@@@@@@@@@@@@@@@@@@ Step 4 @@@@@@@@@@@@@@@@@@@@
> bash-3.2$ sudo duplicity collection-status --no-encryption --ssh-askpass --use-scp ssh://jonathan@192.168.10.100//mnt/raid/bak/Melissa/MElch2/
> Password:
> Import of duplicity.backends.dpbxbackend Failed: No module named dropbox
> Password for 'jonathan@192.168.10.100':
> Synchronizing remote metadata to local cache...
> Deleting local /Users/jonathan/.cache/duplicity/2ec9c2c039f0ae90bc592bd5d682fc20/duplicity-full-signatures.20131227T131025Z.sigtar.gz (not authoritative at backend).
> Last full backup date: Fri Dec 27 08:10:25 2013
> Collection Status
> -----------------
> Connecting with backend: SSHParamikoBackend
> Archive dir: /Users/jonathan/.cache/duplicity/2ec9c2c039f0ae90bc592bd5d682fc20
>
> Found 1 secondary backup chain.
> Secondary chain 1 of 1:
> -------------------------
> Chain start time: Fri Dec 27 08:10:25 2013
> Chain end time: Fri Dec 27 08:10:25 2013
> Number of contained backup sets: 1
> Total number of contained volumes: 1287
> Type of backup set: Time: Num volumes:
> Full Fri Dec 27 08:10:25 2013 1287
> -------------------------
>
> No backup chains with active signatures found
> No orphaned or incomplete backup sets found.
> bash-3.2$ sudo duplicity -v9 collection-status --no-encryption --ssh-askpass --use-scp ssh://jonathan@192.168.10.100//mnt/raid/bak/Melissa/MElch2/
> Using archive dir: /Users/jonathan/.cache/duplicity/2ec9c2c039f0ae90bc592bd5d682fc20
> Using backup name: 2ec9c2c039f0ae90bc592bd5d682fc20
> Import of duplicity.backends.botobackend Succeeded
> Import of duplicity.backends.cloudfilesbackend Succeeded
> Import of duplicity.backends.dpbxbackend Failed: No module named dropbox
> Import of duplicity.backends.ftpbackend Succeeded
> Import of duplicity.backends.ftpsbackend Succeeded
> Import of duplicity.backends.gdocsbackend Succeeded
> Import of duplicity.backends.hsibackend Succeeded
> Import of duplicity.backends.imapbackend Succeeded
> Import of duplicity.backends.localbackend Succeeded
> Import of duplicity.backends.megabackend Succeeded
> Import of duplicity.backends.rsyncbackend Succeeded
> Import of duplicity.backends.sshbackend Succeeded
> Import of duplicity.backends.swiftbackend Succeeded
> Import of duplicity.backends.tahoebackend Succeeded
> Import of duplicity.backends.u1backend Succeeded
> Import of duplicity.backends.webdavbackend Succeeded
> Password for 'jonathan@192.168.10.100':
> Main action: collection-status
> ================================================================================
> duplicity 0.6.22 (August 22, 2013)
> Args: /usr/local/Cellar/duplicity/0.6.22/libexec/bin/duplicity -v9 collection-status --no-encryption --ssh-askpass --use-scp ssh://jonathan@192.168.10.100//mnt/raid/bak/Melissa/MElch2/
> Darwin MElch2.local 13.0.0 Darwin Kernel Version 13.0.0: Thu Sep 19 22:22:27 PDT 2013; root:xnu-2422.1.72~6/RELEASE_X86_64 x86_64 i386
> /usr/bin/python 2.7.5 (default, Aug 25 2013, 00:04:04)
> [GCC 4.2.1 Compatible Apple LLVM 5.0 (clang-500.0.68)]
> ================================================================================
> Local and Remote metadata are synchronized, no sync needed.
> 1288 files exist on backend
> 2 files exist in cache
> Extracting backup chains from list of files: ['duplicity-full.20131227T131025Z.manifest', 'duplicity-full.20131227T131025Z.vol1000.difftar.gz', 'duplicity-full.20131227T131025Z.vol1001.difftar.gz', 'duplicity-full.20131227T131025Z.vol1002.difftar.gz',
> <snip>
> 'duplicity-full.20131227T131025Z.vol2156.difftar.gz', 'duplicity-full.20131227T131025Z.vol2157.difftar.gz', 'duplicity-full.20131227T131025Z.vol2158.difftar.gz', 'duplicity-full.20131227T131025Z.vol2159.difftar.']
> File duplicity-full.20131227T131025Z.manifest is not part of a known set; creating new set
> File duplicity-full.20131227T131025Z.vol1000.difftar.gz is part of known set
> File duplicity-full.20131227T131025Z.vol1001.difftar.gz is part of known set
> File duplicity-full.20131227T131025Z.vol1002.difftar.gz is part of known set
> <snip>
> File duplicity-full.20131227T131025Z.vol2156.difftar.gz is part of known set
> File duplicity-full.20131227T131025Z.vol2157.difftar.gz is part of known set
> File duplicity-full.20131227T131025Z.vol2158.difftar.gz is part of known set
> File duplicity-full.20131227T131025Z.vol2159.difftar. is part of known set
> Found backup chain [Fri Dec 27 08:10:25 2013]-[Fri Dec 27 08:10:25 2013]
> Last full backup date: Fri Dec 27 08:10:25 2013
> Collection Status
> -----------------
> Connecting with backend: SSHParamikoBackend
> Archive dir: /Users/jonathan/.cache/duplicity/2ec9c2c039f0ae90bc592bd5d682fc20
>
> Found 1 secondary backup chain.
> Secondary chain 1 of 1:
> -------------------------
> Chain start time: Fri Dec 27 08:10:25 2013
> Chain end time: Fri Dec 27 08:10:25 2013
> Number of contained backup sets: 1
> Total number of contained volumes: 1287
> Type of backup set: Time: Num volumes:
> Full Fri Dec 27 08:10:25 2013 1287
> -------------------------
>
> No backup chains with active signatures found
> No orphaned or incomplete backup sets found.
> Collection Status
> -----------------
> Connecting with backend: SSHParamikoBackend
> Archive dir: /Users/jonathan/.cache/duplicity/2ec9c2c039f0ae90bc592bd5d682fc20
>
> Found 1 secondary backup chain.
> Secondary chain 1 of 1:
> -------------------------
> Chain start time: Fri Dec 27 08:10:25 2013
> Chain end time: Fri Dec 27 08:10:25 2013
> Number of contained backup sets: 1
> Total number of contained volumes: 1287
> Type of backup set: Time: Num volumes:
> Full Fri Dec 27 08:10:25 2013 1287
> -------------------------
>
> No backup chains with active signatures found
> No orphaned or incomplete backup sets found.
> Using temporary directory /tmp/duplicity-pmnb4M-tempdir
>
> @@@@@@@@@@@@@@@@@@@@ Step 5 @@@@@@@@@@@@@@@@@@@@
> bash-3.2$ sudo duplicity list-current-files --no-encryption --ssh-askpass --use-scp ssh://jonathan@192.168.10.100//mnt/raid/bak/Melissa/MElch2/
> Import of duplicity.backends.dpbxbackend Failed: No module named dropbox
> Password for 'jonathan@192.168.10.100':
> Local and Remote metadata are synchronized, no sync needed.
> Last full backup date: Fri Dec 27 08:10:25 2013
> Traceback (most recent call last):
> File "/usr/local/Cellar/duplicity/0.6.22/libexec/bin/duplicity", line 1466, in <module>
> with_tempdir(main)
> File "/usr/local/Cellar/duplicity/0.6.22/libexec/bin/duplicity", line 1459, in with_tempdir
> fn()
> File "/usr/local/Cellar/duplicity/0.6.22/libexec/bin/duplicity", line 1397, in main
> list_current(col_stats)
> File "/usr/local/Cellar/duplicity/0.6.22/libexec/bin/duplicity", line 662, in list_current
> sig_chain = col_stats.get_signature_chain_at_time(time)
> File "/usr/local/Cellar/duplicity/0.6.22/lib/python2.7/site-packages/duplicity/collections.py", line 974, in get_signature_chain_at_time
> raise CollectionsError("No signature chains found")
> CollectionsError: No signature chains found
>
> bash-3.2$ sudo duplicity -v9 list-current-files --no-encryption --ssh-askpass --use-scp ssh://jonathan@192.168.10.100//mnt/raid/bak/Melissa/MElch2/
> Using archive dir: /Users/jonathan/.cache/duplicity/2ec9c2c039f0ae90bc592bd5d682fc20
> Using backup name: 2ec9c2c039f0ae90bc592bd5d682fc20
> Import of duplicity.backends.botobackend Succeeded
> Import of duplicity.backends.cloudfilesbackend Succeeded
> Import of duplicity.backends.dpbxbackend Failed: No module named dropbox
> Import of duplicity.backends.ftpbackend Succeeded
> Import of duplicity.backends.ftpsbackend Succeeded
> Import of duplicity.backends.gdocsbackend Succeeded
> Import of duplicity.backends.hsibackend Succeeded
> Import of duplicity.backends.imapbackend Succeeded
> Import of duplicity.backends.localbackend Succeeded
> Import of duplicity.backends.megabackend Succeeded
> Import of duplicity.backends.rsyncbackend Succeeded
> Import of duplicity.backends.sshbackend Succeeded
> Import of duplicity.backends.swiftbackend Succeeded
> Import of duplicity.backends.tahoebackend Succeeded
> Import of duplicity.backends.u1backend Succeeded
> Import of duplicity.backends.webdavbackend Succeeded
> Password for 'jonathan@192.168.10.100':
> Main action: list-current
> ================================================================================
> duplicity 0.6.22 (August 22, 2013)
> Args: /usr/local/Cellar/duplicity/0.6.22/libexec/bin/duplicity -v9 list-current-files --no-encryption --ssh-askpass --use-scp ssh://jonathan@192.168.10.100//mnt/raid/bak/Melissa/MElch2/
> Darwin MElch2.local 13.0.0 Darwin Kernel Version 13.0.0: Thu Sep 19 22:22:27 PDT 2013; root:xnu-2422.1.72~6/RELEASE_X86_64 x86_64 i386
> /usr/bin/python 2.7.5 (default, Aug 25 2013, 00:04:04)
> [GCC 4.2.1 Compatible Apple LLVM 5.0 (clang-500.0.68)]
> ================================================================================
> Local and Remote metadata are synchronized, no sync needed.
> 1288 files exist on backend
> 2 files exist in cache
> Extracting backup chains from list of files: ['duplicity-full.20131227T131025Z.manifest', 'duplicity-full.20131227T131025Z.vol1000.difftar.gz', 'duplicity-full.20131227T131025Z.vol1001.difftar.gz', 'duplicity-full.20131227T131025Z.vol1002.difftar.gz',
> <snip>
> 'duplicity-full.20131227T131025Z.vol2156.difftar.gz', 'duplicity-full.20131227T131025Z.vol2157.difftar.gz', 'duplicity-full.20131227T131025Z.vol2158.difftar.gz', 'duplicity-full.20131227T131025Z.vol2159.difftar.']
> File duplicity-full.20131227T131025Z.manifest is not part of a known set; creating new set
> File duplicity-full.20131227T131025Z.vol1000.difftar.gz is part of known set
> File duplicity-full.20131227T131025Z.vol1001.difftar.gz is part of known set
> File duplicity-full.20131227T131025Z.vol1002.difftar.gz is part of known set
> <snip>
> File duplicity-full.20131227T131025Z.vol2156.difftar.gz is part of known set
> File duplicity-full.20131227T131025Z.vol2157.difftar.gz is part of known set
> File duplicity-full.20131227T131025Z.vol2158.difftar.gz is part of known set
> File duplicity-full.20131227T131025Z.vol2159.difftar. is part of known set
> Found backup chain [Fri Dec 27 08:10:25 2013]-[Fri Dec 27 08:10:25 2013]
> Last full backup date: Fri Dec 27 08:10:25 2013
> Collection Status
> -----------------
> Connecting with backend: SSHParamikoBackend
> Archive dir: /Users/jonathan/.cache/duplicity/2ec9c2c039f0ae90bc592bd5d682fc20
>
> Found 1 secondary backup chain.
> Secondary chain 1 of 1:
> -------------------------
> Chain start time: Fri Dec 27 08:10:25 2013
> Chain end time: Fri Dec 27 08:10:25 2013
> Number of contained backup sets: 1
> Total number of contained volumes: 1287
> Type of backup set: Time: Num volumes:
> Full Fri Dec 27 08:10:25 2013 1287
> -------------------------
>
> No backup chains with active signatures found
> No orphaned or incomplete backup sets found.
> Using temporary directory /tmp/duplicity-s31btK-tempdir
> Traceback (most recent call last):
> File "/usr/local/Cellar/duplicity/0.6.22/libexec/bin/duplicity", line 1466, in <module>
> with_tempdir(main)
> File "/usr/local/Cellar/duplicity/0.6.22/libexec/bin/duplicity", line 1459, in with_tempdir
> fn()
> File "/usr/local/Cellar/duplicity/0.6.22/libexec/bin/duplicity", line 1397, in main
> list_current(col_stats)
> File "/usr/local/Cellar/duplicity/0.6.22/libexec/bin/duplicity", line 662, in list_current
> sig_chain = col_stats.get_signature_chain_at_time(time)
> File "/usr/local/Cellar/duplicity/0.6.22/lib/python2.7/site-packages/duplicity/collections.py", line 974, in get_signature_chain_at_time
> raise CollectionsError("No signature chains found")
> CollectionsError: No signature chains found
>
> bash-3.2$
>
> @@@@@@@@@@@@@@@@@@@@ Output from server @@@@@@@@@@@@@@@@@@@@
> jonathan@jelch4:/mnt/raid/bak/Melissa/MElch2$ ls -1
> duplicity-full.20131227T131025Z.manifest
> duplicity-full.20131227T131025Z.vol1000.difftar.gz
> duplicity-full.20131227T131025Z.vol1001.difftar.gz
> duplicity-full.20131227T131025Z.vol1002.difftar.gz
> <snip>
> duplicity-full.20131227T131025Z.vol3188.difftar.gz
> duplicity-full.20131227T131025Z.vol3189.difftar.gz
> duplicity-full.20131227T131025Z.vol318.difftar.gz
> duplicity-full.20131227T131025Z.vol3190.difftar.gz
> duplicity-full.20131227T131025Z.vol3191.difftar.gz
> duplicity-full.20131227T131025Z.vol3192.difftar.gz
> duplicity-full.20131227T131025Z.vol319.difftar.gz
> duplicity-full.20131227T131025Z.vol31.difftar.gz
> duplicity-full.20131227T131025Z.vol320.difftar.gz
> duplicity-full.20131227T131025Z.vol321.difftar.gz
> duplicity-full.20131227T131025Z.vol322.difftar.gz
> duplicity-full.20131227T131025Z.vol323.difftar.gz
> duplicity-full.20131227T131025Z.vol324.difftar.gz
> duplicity-full.20131227T131025Z.vol325.difftar.gz
> duplicity-full.20131227T131025Z.vol326.difftar.gz
> duplicity-full.20131227T131025Z.vol327.difftar.gz
> duplicity-full.20131227T131025Z.vol328.difftar.gz
> duplicity-full.20131227T131025Z.vol329.difftar.gz
> duplicity-full.20131227T131025Z.vol32.difftar.gz
> duplicity-full.20131227T131025Z.vol330.difftar.gz
> <snip>
> duplicity-full.20131227T131025Z.vol997.difftar.gz
> duplicity-full.20131227T131025Z.vol998.difftar.gz
> duplicity-full.20131227T131025Z.vol999.difftar.gz
> duplicity-full.20131227T131025Z.vol99.difftar.gz
> duplicity-full.20131227T131025Z.vol9.difftar.gz
> duplicity-full-signatures.20131227T131025Z.sigtar.gz
> jonathan@jelch4:/mnt/raid/bak/Melissa/MElch2$ ls | grep vol | awk -F '.' '{print $3}' | sed 's/vol//' | sort -n | tail -n 1
> 3192
> jonathan@jelch4:/mnt/raid/bak/Melissa/MElch2$ grep -i vol `ls *manifest*`
> Volume 1:
> Volume 2:
> Volume 3:
> <snip>
> Volume 3189:
> Volume 3190:
> Volume 3191:
> Volume 3192:
>
> @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
>
> Anomalies:
> * I'm aware that I don't have a backend module named 'dropbox'. I assume this is an artifact of using Homebrew to install Duplicity.
> * Assume that the 'list-current-files' exception is for the same reason that 'collection-status' shows fewer volumes than it should.
> * I don't think that the ulimit is in play, but it may be. I tried a value much larger than 1024, but it didn't seem to help. However, I didn't attempt a reboot.
>
> Other notable data points
> * 'collection-status' lists 1287 volumes
> * The -v9 output for 'list-current-files' lists 2159 volumes
> * The server (JElch4) actually contains 3192 volumes
> * I tried making this same backup to target URL 'file:///tmp/testbak/', and everything succeeded as expected
> * I tried making a smaller full backup to target URL 'ssh://jonathan@192.168.10.100//mnt/raid/bak/Melissa/MElch2/', and everything succeeded as expected
>
> This issue is deterministically reproducible.
>
> Can anyone help shed some light? Thanks in advance.
>

maybe a defect or missing volume, weird though if reproducable.

pretty clearly your backup is corrupted somehow. e.g. obviously the signatures necessary for file listing do not seem to have been uploaded. this is why it also states that there is only a secondary backup chain.

please send the server folder file list, for me to look at.

please run collection-status with max. verbosity '-v9' and attach the complete console output (zip it if it's big).

..ede

hi edso,

thanks for your time. here are the requested full logs:

client (MElch2) - https://www.dropbox.com/s/vgem0zdjz6gilsy/MElch2.txt
server (JElch4) - https://www.dropbox.com/s/2ckww3kaqfu2exe/JElch4.txt

according to the server directory listing, there is a 986M sized file named duplicity-full-signatures.20131227T131025Z.sigtar.gz

to see the collection-status output, search MElch2.txt for "sudo duplicity -v9 collection-status". the python array printed seems to contain only the first 1288 objects in the directory, and the sigtar appears to be after this boundary.

best,
-je

fyi, i just noticed that the output for the 'collection-status' command includes the following line:

Deleting local /Users/jonathan/.cache/duplicity/2ec9c2c039f0ae90bc592bd5d682fc20/duplicity-full-signatures.20131227T131025Z.sigtar.gz (not authoritative at backend).

this bears similarity to:
* https://bugs.launchpad.net/duplicity/+bug/570586
* https://answers.launchpad.net/duplicity/+question/107074

Thanks edso, that solved my question.

This appears to be an issue specific to paramiko, as the broken commands above succeeded when using '--ssh-backend pexpect'.

My progress is now unblocked, but I'll still pursue this issue with paramiko.

Many thanks,
-je

On 03.01.2014 01:01, Jonathan Elchison wrote:
> Question #241395 on Duplicity changed:
> https://answers.launchpad.net/duplicity/+question/241395
>
> Jonathan Elchison posted a new comment:
> This appears to be an issue specific to paramiko, as the broken commands
> above succeeded when using '--ssh-backend pexpect'.
>
> My progress is now unblocked, but I'll still pursue this issue with
> paramiko.
>
> Many thanks,

no problemo.. would you mind opening a bug on launchpad with a short description, linking the answer ticket? just in case somebody else stumbles over this problem.

.. ede/duply.net

Created Duplicity bug, linked to this question. Direct link here: https://bugs.launchpad.net/duplicity/+bug/1265765