duplicity-team team mailing list archive

Thread
Date
Re: [Question #241395]: 'Full' backup set displayed by 'collection-status' only reports 1287 of 3192 volumes

To: duplicity-team@xxxxxxxxxxxxxxxxxxx
From: Jonathan Elchison <question241395@xxxxxxxxxxxxxxxxxxxxx>
Date: Sun, 29 Dec 2013 02:51:07 -0000
Reply-to: question241395@xxxxxxxxxxxxxxxxxxxxx
Sender: bounces@xxxxxxxxxxxxx
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.

-- 
You received this question notification because you are a member of
duplicity-team, which is an answer contact for Duplicity.