Tar incremental restore error

[Pierre-Arthur MATHIEU]

We have seen a few report of similar errors:
The signature is:

    A freezer-agent restores an incremental backup.
    Restore of the first level goes okay
    Restore of one of the following level fails with something like:

    Restore error: /bin/tar: Cannot rename ‘<some directory>’ to ‘<some other directory>’: Directory not empty

    or

    Restore error: /bin/tar: Cannot rename ‘<some directory>’ to ‘<some other directory>’: No such file or directory

When this kind of error happens, tar finishes to execute the restore of the current level and reports the error at the end.

The restored directory will be left in the state:

    Level0
    + n non-failed level
    + partial (but mostly complete) failed level
    following levels won't be restored

Full trace of a buggy restore:

2016-04-14 10:10:00,385 root INFO log file at /var/log/freezer-agent/freezer-agent.log
2016-04-14 10:10:00,385 root INFO [*] Creation of swift client
2016-04-14 10:10:00,389 requests.packages.urllib3.connectionpool INFO Starting new HTTPS connection (1): hlm106a-cp1-vip-KEY-API-mgmt
2016-04-14 10:10:00,544 requests.packages.urllib3.connectionpool INFO Starting new HTTPS connection (1): 10.241.226.42
2016-04-14 10:10:00,649 root INFO [*] Job execution Started at: 2016-04-14 10:10:00
2016-04-14 10:10:00,649 root INFO [*] Executing FS restore...
2016-04-14 10:10:00,676 root INFO Creation restore path: /home/stack
2016-04-14 10:10:00,676 root INFO Creation restore path completed
2016-04-14 10:10:00,677 root INFO Restore backup hlm106a-cp1-c1-m1-mgmt_freezer_home_backup_1460487945_0
2016-04-14 10:17:25,459 root INFO [*] Pipe closed as EOF reached. Data transmitted successfully
2016-04-14 10:17:25,552 root INFO Restore backup hlm106a-cp1-c1-m1-mgmt_freezer_home_backup_1460567530_1
2016-04-14 10:17:25,563 root WARNING [SSL: DECRYPTION_FAILED_OR_BAD_RECORD_MAC] decryption failed or bad record mac (_ssl.c:1750)
2016-04-14 10:17:25,563 root INFO [*] Creation of swift client
2016-04-14 10:17:25,568 requests.packages.urllib3.connectionpool INFO Starting new HTTPS connection (1): hlm106a-cp1-vip-KEY-API-mgmt
2016-04-14 10:17:25,708 requests.packages.urllib3.connectionpool INFO Starting new HTTPS connection (1): 10.241.226.42
2016-04-14 10:18:32,511 root INFO [*] Pipe closed as EOF reached. Data transmitted successfully
2016-04-14 10:18:32,689 root ERROR [*] Restore error: /bin/tar: Cannot rename ‘./hos-qa-jobs_template_ci_hlm-106a/hos-qa-ansible/roles/hqe-cinder-multiple-attach-detach-run/tasks’ to ‘./hos-qa-jobs_template_ci_hlm-106a/hos-qa-ansible/roles/hqe-heat-integrationtests-deploy’: Directory not empty
/bin/tar: Exiting with failure status due to previous errors
Traceback (most recent call last):
  File "/opt/stack/venv/freezer_agent-20160411T030610Z/lib/python2.7/site-packages/freezer/engine/tar/tar_engine.py", line 129, in restore_level
    tar_process.stdin.write(read_pipe.recv_bytes())
EOFError
2016-04-14 10:18:32,693 root CRITICAL [*] Critical Error: failed to restore file

[Pierre-Arthur MATHIEU (pi3rra)]

How to reproduce the "Directory not empty" error :

Setup:

    mkdir backupdir
    mkdir backupdir/dir1
    mkdir backupdir/dir2
    echo "aa" > backupdir/dir1/file1_dir1
    echo "aa" > backupdir/dir2/file1_dir2

    freezer-agent --path-to-backup /home/stack/backupdir/ --backup-name plop --storage local --container /tmp/test/ --max-level 15

    rm -rf backupdir/dir2/
    mv backupdir/dir1/ backupdir/dir2

    freezer-agent --path-to-backup /home/stack/backupdir/ --backup-name plop --storage local --container /tmp/test/ --max-level 15

Restore:

    stack@padawan-ccp-c0-m1-mgmt:~$ freezer-agent --restore-abs-path /home/stack/restoredir/ --backup-name plop --storage local --container /tmp/test/ --action restore
    [*] Critical Error: failed to restore file

After restore state:

    stack@padawan-ccp-c0-m1-mgmt:~$ ls -lah restoredir/
    total 16K
    drwxr-xr-x 4 stack stack 4.0K Apr 21 05:20 .
    drwxr-xr-x 14 stack stack 4.0K Apr 21 05:20 ..
    drwxr-xr-x 2 stack stack 4.0K Apr 21 05:19 dir1
    drwxr-xr-x 2 stack stack 4.0K Apr 21 05:19 dir2
    stack@padawan-ccp-c0-m1-mgmt:~$ ls -lah restoredir/dir1/
    total 12K
    drwxr-xr-x 2 stack stack 4.0K Apr 21 05:19 .
    drwxr-xr-x 4 stack stack 4.0K Apr 21 05:20 ..
    -rw-r--r-- 1 stack stack 3 Apr 21 05:19 file1_dir1
    stack@padawan-ccp-c0-m1-mgmt:~$ ls -lah restoredir/dir2
    total 8.0K
    drwxr-xr-x 2 stack stack 4.0K Apr 21 05:19 .
    drwxr-xr-x 4 stack stack 4.0K Apr 21 05:20 ..

Log (separated backup level 1, backup level 2 and restore):

    2016-04-21 05:20:17,738 root INFO log file at /home/stack/.freezer/freezer.log
    2016-04-21 05:20:17,739 root INFO [*] Job execution Started at: 2016-04-21 05:20:17
    2016-04-21 05:20:17,899 root INFO [*] No LVM requested/configured
    2016-04-21 05:20:17,899 root WARNING [*] Directory /home/stack/.freezer found!
    2016-04-21 05:20:17,900 root INFO Tar engine backup stream enter
    2016-04-21 05:20:17,901 root INFO Execution command:
    /bin/tar --create -z --warning=none --no-check-device --one-file-system --preserve-permissions --same-owner --seek --ignore-failed-read --listed-incremental=/home/stack/.freezer/tar_metadata_padawan-ccp-c0-m1-mgmt_plop_1461216017_0 .
    2016-04-21 05:20:17,920 root INFO Tar engine streaming end
    2016-04-21 05:20:17,926 root INFO [*] Job execution Finished, at: 2016-04-21 05:20:17
    2016-04-21 05:20:17,927 root INFO [*] Job time Elapsed: 0:00:00.186618

    2016-04-21 05:20:30,207 root INFO log file at /home/stack/.freezer/freezer.log
    2016-04-21 05:20:30,208 root INFO [*] Job execution Started at: 2016-04-21 05:20:30
    2016-04-21 05:20:30,258 root INFO [*] No LVM requested/configured
    2016-04-21 05:20:30,260 root WARNING [*] Directory /home/stack/.freezer found!
    2016-04-21 05:20:30,262 root INFO Tar engine backup stream enter
    2016-04-21 05:20:30,265 root INFO Execution command:
    /bin/tar --create -z --warning=none --no-check-device --one-file-system --preserve-permissions --same-owner --seek --ignore-failed-read --listed-incremental=/home/stack/.freezer/tar_metadata_padawan-ccp-c0-m1-mgmt_plop_1461216017_0 .
    2016-04-21 05:20:30,277 root INFO Tar eng...

[Pierre-Arthur MATHIEU (pi3rra)]

Reproducing with Tar for the error "Directory not empty":

setup:

  plop@ubuntu:~/testtar$ mkdir bkupdir
  plop@ubuntu:~/testtar$ mkdir bkupdir/dir1
  plop@ubuntu:~/testtar$ mkdir bkupdir/dir2
  plop@ubuntu:~/testtar$ touch bkupdir/dir1/file1
  plop@ubuntu:~/testtar$ touch bkupdir/dir2/file2

Backup level0 :

  cd bkupdir/
  plop@ubuntu:~/testtar/bkupdir$ tar -czv --no-check-device --one-file-system --preserve-permissions --same-owner --seek --ignore-failed-read --listed-incremental=../metadata . -f ../level0
  tar: .: Directory is new
  tar: ./dir1: Directory is new
  tar: ./dir2: Directory is new
  ./
  ./dir1/
  ./dir2/
  ./dir1/file1
  ./dir2/file2

Removing and Renaming:

  plop@ubuntu:~/testtar/bkupdir$ rm -r dir2
  plop@ubuntu:~/testtar/bkupdir$ mv dir1/ dir2

Backup level1:

  plop@ubuntu:~/testtar/bkupdir$ tar -czv --no-check-device --one-file-system --preserve-permissions --same-owner --seek --ignore-failed-read --listed-incremental=../metadata . -f ../level1
  tar: ./dir2: Directory has been renamed from ‘./dir1’
  ./
  ./dir2/

Restore level0:

  plop@ubuntu:~/testtar/bkupdir$ cd ..
  plop@ubuntu:~/testtar$ mkdir restdir
  plop@ubuntu:~/testtar$ cd restdir/
  plop@ubuntu:~/testtar/restdir$ tar -xzv --incremental -f ../level0
  ./
  ./dir1/
  ./dir2/
  ./dir1/file1
  ./dir2/file2

Restore level1:

  plop@ubuntu:~/testtar/restdir$ tar -xzv --incremental -f ../level1
  ./
  tar: Cannot rename ‘./dir1’ to ‘./dir2’: Directory not empty
  ./dir2/
  tar: Deleting ‘./dir2/file2’
  tar: Exiting with failure status due to previous errors

After failed restore state:

  plop@ubuntu:~/testtar/restdir$ ls dir1
  file1
  plop@ubuntu:~/testtar/restdir$ ls dir2
  plop@ubuntu:~/testtar/restdir$

[Pierre-Arthur MATHIEU (pi3rra)]

Re-running the restore of the failed level seems to solve the "Directory not empty" error.

For example, assuming you follow the exact procedure described in the previous comment:

The first restore of level1 gives:

  plop@ubuntu:~/testtar/restdir$ tar -xzv --incremental -f ../level1
  ./
  tar: Cannot rename ‘./dir1’ to ‘./dir2’: Directory not empty
  ./dir2/
  tar: Deleting ‘./dir2/file2’
  tar: Exiting with failure status due to previous errors

With this state:

  plop@ubuntu:~/testtar/restdir$ ls dir1
  file1
  plop@ubuntu:~/testtar/restdir$ ls dir2
  plop@ubuntu:~/testtar/restdir$

After re-running the restore a second time, we get:

  plop@ubuntu:~/testtar/restdir$ tar -xzv --incremental -f ../level1
  ./
  ./dir2/

With this state:

  plop@ubuntu:~/testtar/restdir$ ls dir1
  ls: cannot access dir1: No such file or directory
  plop@ubuntu:~/testtar/restdir$ ls dir2
  file1

[Pierre-Arthur MATHIEU (pi3rra)]

Found a third error case: "Is a directory"

  plop@ubuntu:~/testtar/rr$ tar -xz --incremental -f ../level1
  tar: Cannot rename ‘./1/42/31’ to ‘./1/0’: Is a directory
  tar: Exiting with failure status due to previous errors

I'm still working on a way to reproduce easily this one "Is a directory" and the first one "No such file or directory".

[Henrik Ahlgren (pablo-seestieto)]

@pi3rra, yes re-running works as a workaround, but unfortunately only in this simple test case.

For example, adding another file to dir2 before running the level1 incremental makes even the second extract attempt to fail.

Debian tracks this bug at https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=648048

Upstream discussion: http://lists.gnu.org/archive/html/bug-tar/2016-07/msg00025.html

[Randy Bass (randybass)]

I just encountered this error, so it is still a problem. I am running Linux 4.4.0-140-generic i686, Ubuntu 16.04.5 LTS. I have a tar backup of my os, 6 incrementals, and was trying to restore to another partition. The error message I received is:

tar: Cannot rename ‘mnt/var/lib/app-info/icons/ubuntu-xenial-backports-multiverse/64x64’ to ‘mnt/var/lib/app-info/icons/ubuntu-xenial-security-multiverse’: Directory not empty

I ran tar a second time and got the same error message.

For me, the only solution seems to be to build a new tar without any incrementals, and extract from that, rather than use what I already had. I am lucky that I can do that in my case, but not a solution which is always possible or practical.