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 Ubuntu Bugs, which is subscribed to Ubuntu. https://bugs.launchpad.net/bugs/662442 Title: restore fails with "librsync error 103 while in patch cycle" To manage notifications about this bug go to: https://bugs.launchpad.net/duplicity/+bug/662442/+subscriptions -- ubuntu-bugs mailing list [email protected] https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
