Re: [Duplicity-talk] "tarfile.ReadError: unexpected end of data" when restoring

[edgar . soldin]

hey Jerry,

answers inline below

On 31.05.2020 15:21, Jerry Raj via Duplicity-talk wrote:
> On 5/31/20, edgar.soldin--- via Duplicity-talk
> <duplicity-talk@nongnu.org> wrote:
>> On 31.05.2020 14:06, Jerry Raj via Duplicity-talk wrote:
>>> Hello,
>>> I have some files backed up on a B2 bucket. The backup was done in
>>> 2016 and I don't recall seeing any errors when running the backup. A
>>> bunch of incrementals were also run after that. Now, while trying to
>>> restore from the backup, it writes a bunch of files and then prints
>>> this error:
>>>
>>> Writing folder jun 04/19.jpg of type reg
>>> Releasing lockfile b'/root/.cache/duplicity/oldpics/lockfile'
>>> Removing still remembered temporary file
>>> /tmp/duplicity-g54acfp_-tempdir/mkstemp-0q8ek77p-1
>>> Removing still remembered temporary file
>>> /tmp/duplicity-g54acfp_-tempdir/mktemp-c6rtyy0l-15
>>> Removing still remembered temporary file
>>> /tmp/duplicity-g54acfp_-tempdir/mktemp-wvy4ygnk-16
>>> Releasing lockfile b'/root/.cache/duplicity/oldpics/lockfile'
>>> Traceback (innermost last):
>>>   File "/usr/bin/duplicity", line 106, in <module>
>>>     with_tempdir(main)
>>>   File "/usr/bin/duplicity", line 92, in with_tempdir
>>>     fn()
>>>   File "/usr/lib/python3/dist-packages/duplicity/dup_main.py", line
>>> 1538, in main
>>>     do_backup(action)
>>>   File "/usr/lib/python3/dist-packages/duplicity/dup_main.py", line
>>> 1618, in do_backup
>>>     restore(col_stats)
>>>   File "/usr/lib/python3/dist-packages/duplicity/dup_main.py", line
>>> 723, in restore
>>>     if not patchdir.Write_ROPaths(globals.local_path,
>>>   File "/usr/lib/python3/dist-packages/duplicity/patchdir.py", line
>>> 578, in Write_ROPaths
>>>     for ropath in rop_iter:
>>>   File "/usr/lib/python3/dist-packages/duplicity/patchdir.py", line
>>> 541, in integrate_patch_iters
>>>     for patch_seq in collated:
>>>   File "/usr/lib/python3/dist-packages/duplicity/patchdir.py", line
>>> 407, in yield_tuples
>>>     setrorps(overflow, elems)
>>>   File "/usr/lib/python3/dist-packages/duplicity/patchdir.py", line
>>> 396, in setrorps
>>>     elems[i] = next(iter_list[i])
>>>   File "/usr/lib/python3/dist-packages/duplicity/patchdir.py", line
>>> 135, in difftar2path_iter
>>>     multivol_fileobj.close()  # aborting in middle of multivol
>>>   File "/usr/lib/python3/dist-packages/duplicity/patchdir.py", line
>>> 264, in close
>>>     if not self.addtobuffer():
>>>   File "/usr/lib/python3/dist-packages/duplicity/patchdir.py", line
>>> 248, in addtobuffer
>>>     self.buffer += fp.read()
>>>   File "/usr/lib/python3.8/tarfile.py", line 684, in read
>>>     raise ReadError("unexpected end of data")
>>>  tarfile.ReadError: unexpected end of data
>>>
>>> It then just hangs there and does not proceed, I have to ctrl-C to
>>> exit. Is there some way I can recover at least some of the remaining
>>> files? "duplicity list-current-files" returns over 700 files, but only
>>> 240 are written before it errors out.
>>>
>>> FWIW, running restore with -vd provides this summary:
>>>
>>> Collection Status
>>> -----------------
>>> Connecting with backend: BackendWrapper
>>> Archive dir: /root/.cache/duplicity/oldpics
>>>
>>> Found 0 secondary backup chains.
>>>
>>> Found primary backup chain with matching signature chain:
>>> -------------------------
>>> Chain start time: Sat Oct 15 13:36:44 2016
>>> Chain end time: Wed Mar 29 22:10:38 2017
>>> Number of contained backup sets: 13
>>> Total number of contained volumes: 21
>>>  Type of backup set:                            Time:      Num volumes:
>>>                 Full         Sat Oct 15 13:36:44 2016                 5
>>>          Incremental         Sun Jan  8 08:48:27 2017                 5
>>>          Incremental         Sun Jan  8 09:19:42 2017                 1
>>>          Incremental         Mon Jan  9 07:03:47 2017                 1
>>>          Incremental         Mon Jan 16 19:34:53 2017                 1
>>>          Incremental         Thu Jan 19 21:21:56 2017                 1
>>>          Incremental         Tue Feb  7 05:33:27 2017                 1
>>>          Incremental         Tue Feb  7 05:39:58 2017                 1
>>>          Incremental         Tue Feb  7 05:59:27 2017                 1
>>>          Incremental         Sat Feb 11 04:57:12 2017                 1
>>>          Incremental         Wed Mar 29 17:41:50 2017                 1
>>>          Incremental         Wed Mar 29 17:55:07 2017                 1
>>>          Incremental         Wed Mar 29 22:10:38 2017                 1
>>> -------------------------
>>> No orphaned or incomplete backup sets found.
>>>
>>> Any help is appreciated!
>>
>> hey Jerry,
>>
>> for convenience (and speed) you may copy the whole backup from b2 bucket to
>> a local folder just for now.
>>
>> it's unclear if your backup is corrupted or just not restoring properly
>> because of a bug.
>>
>> questions
>> 1. is your backup encrypted or compressed?
>> 2. what is your restore command?
>> 3. when monitoring ram usage during restore until the hanging process, does
>> it get full and starts to swap at any point?
>> 4. what is the output of 'ulimit -n' ?
>> 5. when duplicity hangs, can you check take a 'ps -xfa' and post the
>> duplicity part here to see which process is pausing it?
>>
>> in case of a memory leak (ram running full) it might help to restore only
>> parts of your backup using the '--file-to-restore <file/folder>' parameter.
>>
>> good luck ..ede/duply.net
>>
>> _______________________________________________
>> Duplicity-talk mailing list
>> Duplicity-talk@nongnu.org
>> https://lists.nongnu.org/mailman/listinfo/duplicity-talk
>>
>
> Hi,
> Thanks a lot for your help. Answers below:
>
>> 1. is your backup encrypted or compressed?
> It's encrypted, but I don't think it's compressed. I used a command like:
> duplicity --name oldpics /store/oldpics  <b2url>
> PASSPHRASE was set to a random string

then it should be encrypted. you can check the file names on the backend. if 
they end with .gpg it definitely is.

>> 2. what is your restore command?
> duplicity -vd  --name oldpics
> "b2://$B2_ACCOUNTID:$B2_APPLICATION_KEY@$B2_BUCKET_NAME/oldpics"
> /store/oldpics
> PASSPHRASE is set to the same string as used during backup.
>
>> 3. when monitoring ram usage during restore until the hanging process, does
>> it get full and starts to swap at any point?
> No it doesn't seem to be doing anything at that point. Watching it
> with top doesn't show RES or VIRT increasing.

so there is still plenty of ram available at that point and no oom killing 
logged in kernel.log (check 'dmesg')?

>> 4. what is the output of 'ulimit -n' ?
> 1024

reasonable value

>> 5. when duplicity hangs, can you check take a 'ps -xfa' and post the
>> duplicity part here to see which process is pausing it?
> 30754 pts/2    Sl+    0:14  |       \_ /usr/bin/python3
> /usr/bin/duplicity --force -vd --name oldpics
> b2://<redacted>@<redacted>/oldpics /store/oldpics
>   30812 pts/2    SL+    0:01  |           \_ gpg --passphrase-fd 19
> --status-fd 15 --logger-fd 8 --batch --no-tty --no-secmem-warning
> --ignore-mdc-error --pinentry-mode=loopback --decrypt

for some reason gpg is hanging. so you are definitely encrypted ;)

my guess would be that the b2 backend timed out but did not tell anybody.

is this the latest greatest duplicity 0.8.13? if not, can you try this one and 
which version is it now? ..ede/duply.net