Unable to restore an archive using v1.4.1

[hazzl]

Hi There,

I have an backup archive created with v1.3 which consistently fails to resotre with v1.4.1 at the same point in the archive. The error message is:

Can't open file /mnt/zbackup/15-Feb/bundles/6a/6a9aed9dd043212eeb0637c3111dc1e0809aceea53d8f4dd

However, when I look for the specified file, it clearly exists (and has the same permissions as all others). When restoring with v1.3 everything works like expected. Any hints on how to debug this issue?

[Vlad1mir-D]

Greetings,

try to build zbackup with debug enabled (cmake -DCMAKE_BUILD_TYPE=Debug) and please post full stderr output.

[hazzl]

With current git tip, I can't read the repository.
Can't parse message of type "ExtendedStorageInfo" because it is missing required fields: config.lzma

[hazzl]

v1.4.1 doesn't seem to have debug functionality. Sorry, if I seem a bit lost.

[Vlad1mir-D]

Sorry for being misleading.
Current git tip was fixed now so you could try repeating with latest version but before your second attempt you should remove info_extended from your repo because it was invalid.
Removing info_extended is safe until repo is created by zbackup <= 1.4.1.

For 1.4.1 you could follow those steps to get a debug build:

• Open CMakeLists.txt
• Replace CMAKE_BUILD_TYPE Release to CMAKE_BUILD_TYPE Debug
• Rerun cmake
• Rerun make

I'll much appreciate if you could provide stderr output from both debug versions (current master and 1.4.1).

[hazzl]

I still see the error with current tip 89d6171 Can't parse message of type "ExtendedStorageInfo" because it is missing required fields: config.lzma

[hazzl]

Full Error Log:

hazzl@eressea:~/Projects/git/zbackup$ ./zbackup restore --cache-size 6144mb --non-encrypted /mnt/zbackup/15-Feb/backups/2015-01-29.tar | tar t
[DEBUG] at main( zbackup.cc:18 ): ZBackup version 1.4-66-g89d6171
[DEBUG] at Config( config.cc:151 ): 6Config is instantiated and initialized with default values
--cache-size is deprecated, use -O cache-size instead
[DEBUG] at parseOrValidate( config.cc:204 ): Parsing runtime option "cache-size=6144MiB"...
[DEBUG] at parseOrValidate( config.cc:212 ): runtime option cache-size: 6144MiB
[DEBUG] at parseOrValidate( config.cc:418 ): runtime[cacheSize] = 6442450944
[DEBUG] at load( storage_info_file.cc:33 ): Loading storage info...
[DEBUG] at InputStream( encrypted_file.cc:26 ): Loading /mnt/zbackup/15-Feb/info, hasKey: false
[DEBUG] at load( storage_info_file.cc:75 ): Loading extended storage info, hasKey: false
[DEBUG] at InputStream( encrypted_file.cc:26 ): Loading /mnt/zbackup/15-Feb/info_extended, hasKey: false
[libprotobuf ERROR google/protobuf/message_lite.cc:123] Can't parse message of type "ExtendedStorageInfo" because it is missing required fields: config.lzma
Can't parse message ExtendedStorageInfo

[Vlad1mir-D]

Have you removed info_extended before running restore?

[hazzl]

Oops, sorry. Forgot about that.

[hazzl]

I didn't manage to build a Debug version of 1.4.1. I changed CMakeLists.txt

set( CMAKE_BUILD_TYPE Debug )

However, I still don't get any additional output for the failure just the same

...
home/fuli/.local/share/zeitgeist/activity.sqlite-wal
Can't open file /mnt/zbackup/15-Feb/bundles/6a/6a9aed9dd043212eeb0637c3111dc1e0809aceea53d8f4dd

[Vlad1mir-D]

Have you completed following steps:

• Rerun cmake
• Rerun make

?

If yes then you should remove cmake cache and complete those steps again.

[hazzl]

I did. I'm currently testing git tip again. Looking good...

[hazzl]

Hmm. There is no debug output when the error occurs.

home/fuli/.local/share/zeitgeist/activity.sqlite
[DEBUG] at InputStream( encrypted_file.cc:26 ): Loading /mnt/zbackup/15-Feb/bundles/6a/6a9f93070a677dfb0d9051b2f7d5f74a632d1448e1bb7fef, hasKey: false
home/fuli/.local/share/zeitgeist/activity.sqlite-wal
Can't open file /mnt/zbackup/15-Feb/bundles/6a/6a9aed9dd043212eeb0637c3111dc1e0809aceea53d8f4dd
tar: unexpected EOF of archive.
tar: Error is not recoverable: exiting now
hazzl@eressea:~/Projects/git/zbackup$ ls -l /mnt/zbackup/15-Feb/bundles/6a/6a9aed9dd043212eeb0637c3111dc1e0809aceea53d8f4dd
-rw------- 1 hazzl hazzl 126589 29. Jan 20:35 /mnt/zbackup/15-Feb/bundles/6a/6a9aed9dd043212eeb0637c3111dc1e0809aceea53d8f4dd

[Vlad1mir-D]

Ok, I'll prepare version with extended debug logging based on 1.4.1 tree.
Looks very strange so I want to understand root cause of problem and I'll much appreciate for your help.

[hazzl]

As I see it, you are helping me. So thanks for that ;-)

[Vlad1mir-D]

BTW what OS you are using?

[hazzl]

Arch Linux

[hazzl]

As far as I am concerned, you don't have to base your special debugging build on 1.4.1 (as I still have trouble enabling debugging output in that version) you could equally base it on current HEAD.

[Vlad1mir-D]

I don't understand.
Do you have any troubles with master head version?

[hazzl]

Just the fact that I can't restore my 1.3 repo using git HEAD.

[hazzl]

(Same Error as 1.4.1)

[hazzl]

I just did a fresh backup with 1.4.1. The creation didn't have any problems. However, when testing the repo with zbackup restore, I had the same error. This means, I'm unable to restore any backup using v1.4.1. I adjusted the bug description accordingly.

[Vlad1mir-D]

Ok, please follow those steps with any version your experiencing problems:

1. Build debug version (I've already described how to do that before);
2. run your zbackup in restore mode under strace:
   Say you are running zbackup by
   ./objdir/zbackup restore --password-file /my/private/password /mnt/zbackup/backups/backup_info1
   Then you should run it this way:
   strace -s 0 -f -o zbackup.strace ./objdir/zbackup restore --password-file /my/private/password /mnt/zbackup/backups/backup_info1 > zbackup.stdout 2> zbackup.stderr
3. Post zbackup.stdout, zbackup.stderr and zbackup.strace somewhere.

Please note that no private data will be leaked (because of -s0 flag of strace). You could additionally check zbackup.strace manually.

[hazzl]

zbackup.stderr.xz
zbackup.strace.xz

[hazzl]

zbackup.stdout contains the dump of my backup data. That's 2.2 GiB worth of data. Even if I compress it, it still clocks in at 471 MiB. Also it contains the dump of my backup which I am reluctant to put somewhere publicly accessible.

From inspecting the strace output, it seems as if we're leaking file descriptors. Which is why the open call fails.

[Vlad1mir-D]

Oh, yep, I don't need zbackup.stdout, sorry :)
I'll check out your logs tomorrow.

[hazzl]

Ugh, maybe it's a bad idea to give restore 6 GiB of cache? That way it runs out of file descriptors. With less cache, it runs trhough the restore without problems.

But why did v1.3 deal more gracefully with an extra big cache? And what is a reasonable amount of restore cache?

[hazzl]

It seems that the bundle files only get closed once the bundle falls out of the cache, instead of when it's done being read into the cache.

[Vlad1mir-D]

I've found some other issues that should be fixed before cache handling.

2015-02-17 23:59 GMT+03:00 hazzl notifications@github.com:

It seems that the bundle files only get closed once the bundle falls out
of the cache, instead of when it's done being read into the cache.

—
Reply to this email directly or view it on GitHub
#58 (comment).

Kind regards,
Vladimir.

[Firefishy]

@hazzl what is the output of: ulimit -n

[hazzl]

hazzl@eressea:~$ ulimit -n
1024

[Vlad1mir-D]

This bug was introduced in 0a61cc8, I'll fix it asap.