A coworker (Steve Magoun) graciously lent me a backup data set of his that reproduces this problem.
What appears to have happened on his data set (and presumably others who are experiencing this) is that a file (say, test.txt) gets backed up in the initial full backup at time A. This initial backup seems fine. Later, the file is included in an incremental backup at time B. But for some reason, the patch that duplicity creates is seemingly against a different basis file than the recorded at time A. So when restoring, the patch does not apply to the stored time A version of the file. When restoring from time B, duplicity will complain but not error out. It will create a half-finished test.txt. If you restore from a later time point, duplicity will error out and create no file. Here is the librsync output from my example data. (original basis file is an xml text file 68664 bytes large) You can see at the end, it tries to read from the basis file past its end. So the patch seems to be against a different (larger) basis file than we have. I'm not sure how this could happen yet, but I figured I'd dump these thoughts here. ---- original call to rs_job_iter here ---- python2.7: (rs_scoop_readahead) got 4 bytes from input buffer python2.7: (rs_scoop_advance) advance over 4 bytes from input buffer python2.7: (rs_patch_s_header) got patch magic 0x72730236 python2.7: (rs_scoop_readahead) got 1 bytes from input buffer python2.7: (rs_scoop_advance) advance over 1 bytes from input buffer python2.7: (rs_patch_s_cmdbyte) got command byte 0x42 (LITERAL), len_1=2 python2.7: (rs_scoop_readahead) got 2 bytes from input buffer python2.7: (rs_scoop_readahead) got 2 bytes from input buffer python2.7: (rs_scoop_advance) advance over 2 bytes from input buffer python2.7: (rs_patch_s_run) running command 0x42, kind 1001 python2.7: (rs_patch_s_literal) LITERAL(len=512) python2.7: (rs_tube_catchup_copy) copied 512 bytes from input buffer, 0 remain to be copied python2.7: (rs_scoop_readahead) got 1 bytes from input buffer python2.7: (rs_scoop_advance) advance over 1 bytes from input buffer python2.7: (rs_patch_s_cmdbyte) got command byte 0x4a (COPY), len_1=2 python2.7: (rs_scoop_readahead) got 4 bytes from input buffer python2.7: (rs_scoop_readahead) got 2 bytes from input buffer python2.7: (rs_scoop_advance) advance over 2 bytes from input buffer python2.7: (rs_scoop_readahead) got 2 bytes from input buffer python2.7: (rs_scoop_advance) advance over 2 bytes from input buffer python2.7: (rs_patch_s_run) running command 0x4a, kind 1003 python2.7: (rs_patch_s_copy) COPY(where=512, len=24064) python2.7: (rs_patch_s_copying) copy 24064 bytes from basis at offset 512 python2.7: (rs_patch_s_copying) copy callback returned OK python2.7: (rs_patch_s_copying) got 24064 bytes back from basis callback python2.7: (rs_scoop_readahead) got 1 bytes from input buffer python2.7: (rs_scoop_advance) advance over 1 bytes from input buffer python2.7: (rs_patch_s_cmdbyte) got command byte 0x42 (LITERAL), len_1=2 python2.7: (rs_scoop_readahead) got 2 bytes from input buffer python2.7: (rs_scoop_readahead) got 2 bytes from input buffer python2.7: (rs_scoop_advance) advance over 2 bytes from input buffer python2.7: (rs_patch_s_run) running command 0x42, kind 1001 python2.7: (rs_patch_s_literal) LITERAL(len=5084) python2.7: (rs_tube_catchup_copy) copied 5084 bytes from input buffer, 0 remain to be copied python2.7: (rs_scoop_readahead) got 1 bytes from input buffer python2.7: (rs_scoop_advance) advance over 1 bytes from input buffer python2.7: (rs_patch_s_cmdbyte) got command byte 0x4a (COPY), len_1=2 python2.7: (rs_scoop_readahead) got 4 bytes from input buffer python2.7: (rs_scoop_readahead) got 2 bytes from input buffer python2.7: (rs_scoop_advance) advance over 2 bytes from input buffer python2.7: (rs_scoop_readahead) got 2 bytes from input buffer python2.7: (rs_scoop_advance) advance over 2 bytes from input buffer python2.7: (rs_patch_s_run) running command 0x4a, kind 1003 python2.7: (rs_patch_s_copy) COPY(where=29696, len=512) python2.7: (rs_patch_s_copying) copy 512 bytes from basis at offset 29696 python2.7: (rs_patch_s_copying) copy callback returned OK python2.7: (rs_patch_s_copying) got 512 bytes back from basis callback python2.7: (rs_scoop_readahead) got 1 bytes from input buffer python2.7: (rs_scoop_advance) advance over 1 bytes from input buffer python2.7: (rs_patch_s_cmdbyte) got command byte 0x42 (LITERAL), len_1=2 python2.7: (rs_scoop_readahead) got 2 bytes from input buffer python2.7: (rs_scoop_readahead) got 2 bytes from input buffer python2.7: (rs_scoop_advance) advance over 2 bytes from input buffer python2.7: (rs_patch_s_run) running command 0x42, kind 1001 python2.7: (rs_patch_s_literal) LITERAL(len=2048) python2.7: (rs_tube_catchup_copy) copied 2048 bytes from input buffer, 0 remain to be copied python2.7: (rs_scoop_readahead) got 1 bytes from input buffer python2.7: (rs_scoop_advance) advance over 1 bytes from input buffer python2.7: (rs_patch_s_cmdbyte) got command byte 0x4a (COPY), len_1=2 python2.7: (rs_scoop_readahead) got 4 bytes from input buffer python2.7: (rs_scoop_readahead) got 2 bytes from input buffer python2.7: (rs_scoop_advance) advance over 2 bytes from input buffer python2.7: (rs_scoop_readahead) got 2 bytes from input buffer python2.7: (rs_scoop_advance) advance over 2 bytes from input buffer python2.7: (rs_patch_s_run) running command 0x4a, kind 1003 python2.7: (rs_patch_s_copy) COPY(where=32256, len=1024) python2.7: (rs_patch_s_copying) copy 1024 bytes from basis at offset 32256 python2.7: (rs_patch_s_copying) copy callback returned OK python2.7: (rs_patch_s_copying) got 1024 bytes back from basis callback python2.7: (rs_scoop_readahead) got 1 bytes from input buffer python2.7: (rs_scoop_advance) advance over 1 bytes from input buffer python2.7: (rs_patch_s_cmdbyte) got command byte 0x42 (LITERAL), len_1=2 python2.7: (rs_scoop_readahead) got 2 bytes from input buffer python2.7: (rs_scoop_readahead) got 2 bytes from input buffer python2.7: (rs_scoop_advance) advance over 2 bytes from input buffer python2.7: (rs_patch_s_run) running command 0x42, kind 1001 python2.7: (rs_patch_s_literal) LITERAL(len=1024) python2.7: (rs_tube_catchup_copy) copied 1024 bytes from input buffer, 0 remain to be copied python2.7: (rs_scoop_readahead) got 1 bytes from input buffer python2.7: (rs_scoop_advance) advance over 1 bytes from input buffer python2.7: (rs_patch_s_cmdbyte) got command byte 0x4a (COPY), len_1=2 python2.7: (rs_scoop_readahead) got 4 bytes from input buffer python2.7: (rs_scoop_readahead) got 2 bytes from input buffer python2.7: (rs_scoop_advance) advance over 2 bytes from input buffer python2.7: (rs_scoop_readahead) got 2 bytes from input buffer python2.7: (rs_scoop_advance) advance over 2 bytes from input buffer python2.7: (rs_patch_s_run) running command 0x4a, kind 1003 python2.7: (rs_patch_s_copy) COPY(where=34304, len=16384) python2.7: (rs_patch_s_copying) copy 16384 bytes from basis at offset 34304 python2.7: (rs_patch_s_copying) copy callback returned OK python2.7: (rs_patch_s_copying) got 16384 bytes back from basis callback python2.7: (rs_scoop_readahead) got 1 bytes from input buffer python2.7: (rs_scoop_advance) advance over 1 bytes from input buffer python2.7: (rs_patch_s_cmdbyte) got command byte 0x42 (LITERAL), len_1=2 python2.7: (rs_scoop_readahead) got 2 bytes from input buffer python2.7: (rs_scoop_readahead) got 2 bytes from input buffer python2.7: (rs_scoop_advance) advance over 2 bytes from input buffer python2.7: (rs_patch_s_run) running command 0x42, kind 1001 python2.7: (rs_patch_s_literal) LITERAL(len=15565) python2.7: (rs_buffers_copy) copy limited to 14884 available output bytes python2.7: (rs_tube_catchup_copy) copied 14884 bytes from input buffer, 681 remain to be copied ---- new call to rs_job_iter here ---- python2.7: (rs_tube_catchup_copy) copied 681 bytes from input buffer, 0 remain to be copied python2.7: (rs_scoop_readahead) got 1 bytes from input buffer python2.7: (rs_scoop_advance) advance over 1 bytes from input buffer python2.7: (rs_patch_s_cmdbyte) got command byte 0x4e (COPY), len_1=4 python2.7: (rs_scoop_readahead) got 6 bytes from input buffer python2.7: (rs_scoop_readahead) got 4 bytes from input buffer python2.7: (rs_scoop_advance) advance over 4 bytes from input buffer python2.7: (rs_scoop_readahead) got 2 bytes from input buffer python2.7: (rs_scoop_advance) advance over 2 bytes from input buffer python2.7: (rs_patch_s_run) running command 0x4e, kind 1003 python2.7: (rs_patch_s_copy) COPY(where=66560, len=1024) python2.7: (rs_patch_s_copying) copy 1024 bytes from basis at offset 66560 python2.7: (rs_patch_s_copying) copy callback returned OK python2.7: (rs_patch_s_copying) got 1024 bytes back from basis callback python2.7: (rs_scoop_readahead) got 1 bytes from input buffer python2.7: (rs_scoop_advance) advance over 1 bytes from input buffer python2.7: (rs_patch_s_cmdbyte) got command byte 0x42 (LITERAL), len_1=2 python2.7: (rs_scoop_readahead) got 2 bytes from input buffer python2.7: (rs_scoop_readahead) got 2 bytes from input buffer python2.7: (rs_scoop_advance) advance over 2 bytes from input buffer python2.7: (rs_patch_s_run) running command 0x42, kind 1001 python2.7: (rs_patch_s_literal) LITERAL(len=1026) python2.7: (rs_tube_catchup_copy) copied 1026 bytes from input buffer, 0 remain to be copied python2.7: (rs_scoop_readahead) got 1 bytes from input buffer python2.7: (rs_scoop_advance) advance over 1 bytes from input buffer python2.7: (rs_patch_s_cmdbyte) got command byte 0x4e (COPY), len_1=4 python2.7: (rs_scoop_readahead) got 6 bytes from input buffer python2.7: (rs_scoop_readahead) got 4 bytes from input buffer python2.7: (rs_scoop_advance) advance over 4 bytes from input buffer python2.7: (rs_scoop_readahead) got 2 bytes from input buffer python2.7: (rs_scoop_advance) advance over 2 bytes from input buffer python2.7: (rs_patch_s_run) running command 0x4e, kind 1003 python2.7: (rs_patch_s_copy) COPY(where=68608, len=364) python2.7: (rs_patch_s_copying) copy 364 bytes from basis at offset 68608 python2.7: (rs_patch_s_copying) copy callback returned OK python2.7: (rs_patch_s_copying) got 56 bytes back from basis callback python2.7: (rs_patch_s_copying) copy 308 bytes from basis at offset 68664 python2.7: ERROR: (rs_file_copy_cb) unexpected eof on fd5 python2.7: ERROR: (rs_job_complete) patch job failed: unexpected end of input -- You received this bug notification because you are a member of Desktop Packages, which is subscribed to duplicity in Ubuntu. https://bugs.launchpad.net/bugs/662442 Title: restore fails with "librsync error 103 while in patch cycle" Status in Duplicity - Bandwidth Efficient Encrypted Backup: Confirmed Status in “duplicity” package in Ubuntu: Confirmed Bug description: I'm doing a trial restore from an sftp backup, and it fails like so: Writing .bazaar/plugins/svn/backup.bzr/repository/packs/5e32df252c6c9b80b70d63cab2a52f1a.pack of type reg Deleting /tmp/duplicity-4I6eKU-tempdir/mktemp-B5f55D-4 Processed volume 2 of 2531 Running 'sftp -oServerAliveInterval=15 -oServerAliveCountMax=2 mbp@grace' (attempt #1) sftp command: 'get "/backup/lithe/home_mbp.duplicity//duplicity-inc.20100210T222519Z.to.20100429T235919Z.vol2.difftar.gz" "/tmp/duplicity-4I6eKU-tempdir/mktemp-7d1sNq-22"' Writing .bazaar/plugins/svn/backup.bzr/repository/upload of type dir ...... Writing .byobu/status of type reg Writing .byobu/windows of type reg python: ERROR: (rs_file_copy_cb) unexpected eof on fd23 python: ERROR: (rs_job_complete) patch job failed: unexpected end of input Traceback (most recent call last): File "/home/mbp/work/duplicity/duplicity-bin", line 1245, in <module> with_tempdir(main) File "/home/mbp/work/duplicity/duplicity-bin", line 1238, in with_tempdir fn() File "/home/mbp/work/duplicity/duplicity-bin", line 1192, in main restore(col_stats) File "/home/mbp/work/duplicity/duplicity-bin", line 539, in restore restore_get_patched_rop_iter(col_stats)): File "/home/mbp/work/duplicity/duplicity/patchdir.py", line 520, in Write_ROPaths for ropath in rop_iter: File "/home/mbp/work/duplicity/duplicity/patchdir.py", line 493, in integrate_patch_iters final_ropath = patch_seq2ropath( normalize_ps( patch_seq ) ) File "/home/mbp/work/duplicity/duplicity/patchdir.py", line 473, in patch_seq2ropath misc.copyfileobj( current_file, tempfp ) File "/home/mbp/work/duplicity/duplicity/misc.py", line 166, in copyfileobj buf = infp.read(blocksize) File "/home/mbp/work/duplicity/duplicity/librsync.py", line 80, in read self._add_to_outbuf_once() File "/home/mbp/work/duplicity/duplicity/librsync.py", line 94, in _add_to_outbuf_once raise librsyncError(str(e)) librsyncError: librsync error 103 while in patch cycle ~/work/duplicity/duplicity-bin -v7 --no-encrypt restore ~/tmp/grace- restore 30.59s user 5.18s system 49% cpu 1:11.81 total Using the tip of the 0.6 branch on Ubuntu Maverick. I think I've seen this once before too. The 'unexpected eof' error suggests that one of the increment files could be truncated, but that doesn't seem likely: I haven't had any filesystem problems, and at the gzip level all of them seem to be ok. To manage notifications about this bug go to: https://bugs.launchpad.net/duplicity/+bug/662442/+subscriptions -- Mailing list: https://launchpad.net/~desktop-packages Post to : [email protected] Unsubscribe : https://launchpad.net/~desktop-packages More help : https://help.launchpad.net/ListHelp
