Regression of failed backup with long file names can result in assertion error

[zjw]

This bug was originally reported here:
http://lists.nongnu.org/archive/html/rdiff-backup-users/2016-08/msg00000.html

The bug can be reproduced with the following script:

#!/bin/bash -v
# Create a long file name -- 211 characters.  This length is chosen to be less
# than the maximum allowed for ext4 filesystems (255 max.), but long enough for
# rdiff-backup to give it special treament (see longname.py).
longName=b
a=0123456789
for (( i = 0; i < 21; i++ )); do
longName=$longName$a
done

# Set up a source directory containing a file with the long name:
mkdir src
echo test1 > src/$longName
ls -l src

# Make a backup:
rdiff-backup src dst
sleep 1

# Keep a copy of the current_mirror file for use later:
cp dst/rdiff-backup-data/current_mirror* .

# Modify the src file:
echo test2 > src/$longName

# Make a 2nd backup:
rdiff-backup src dst

# Notice that the increment file is put in
# dst/rdiff-backup-data/long_filename_data/:
ls -l dst/rdiff-backup-data/long_filename_data

# Copy the saved current_mirror back so as to force rdiff-backup into
# concluding that the last backup failed  (a simulated failure for this test):
cp current_mirror* dst/rdiff-backup-data

# rdiff-backup will now report that there is a problem:
rdiff-backup --list-increments dst

# Perform the usual fix for the problem (regress the repository):
rdiff-backup --check-destination-dir dst

# See that rdiff-backup appears to be happy:
rdiff-backup --list-increments dst

# Here's the problem: regressing the repository failed to remove the increment
# file from the 2nd backup:
ls -l dst/rdiff-backup-data/long_filename_data

# Retry the 2nd backup.  It fails because the old increment file is in the way:
rdiff-backup src dst
rdiff-backup --list-increments dst

# Again, regress the repository to fix the failed backup:
rdiff-backup --check-destination-dir dst
rdiff-backup --list-increments dst

# This time, manually remove the increment file that should not be there (normally, this must
# be done more judiciously than illustrated here):
ls -l dst/rdiff-backup-data/long_filename_data
rm dst/rdiff-backup-data/long_filename_data/1*

# Now we are able to successfully make the 2nd backup:
rdiff-backup src dst
rdiff-backup --list-increments dst

As noted in the script, the problem is that regressing a backup using --check-destination-dir fails to completely clean up the repository when there are increment files stored under rdiff-backup-data/long_filename_data/.

A work-around for the bug is to use --check-destination-dir and then remove the problematic files under rdiff-backup-data/long_filename_data/. This removal needs to be done judiciously, however. The only files removed are ones where the date in the file name matches the date in the current_mirror filename. Here's an example where there is a match:

rdiff-backup-data/current_mirror.2016-08-20T21:30:01-04:00.data
rdiff-backup-data/long_filename_data/1.2016-08-20T21:30:01-04:00.diff.gz

Here is the script output when run:

#!/bin/bash -v
# Create a long file name -- 211 characters.  This length is chosen to be less
# than the maximum allowed for ext4 filesystems (255 max.), but long enough for
# rdiff-backup to give it special treament (see longname.py).
longName=b
a=0123456789
for (( i = 0; i < 21; i++ )); do
longName=$longName$a
done

# Set up a source directory containing a file with the long name:
mkdir src
echo test1 > src/$longName
ls -l src
total 8
-rw-rw-r--  1 joe joe 6 Aug 20 21:17 b012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789

# Make a backup:
rdiff-backup src dst
sleep 1

# Keep a copy of the current_mirror file for use later:
cp dst/rdiff-backup-data/current_mirror* .

# Modify the src file:
echo test2 > src/$longName

# Make a 2nd backup:
rdiff-backup src dst

# Notice that the increment file is put in
# dst/rdiff-backup-data/long_filename_data/:
ls -l dst/rdiff-backup-data/long_filename_data
total 16
-rw-rw-r--  1 joe joe 107 Aug 20 21:17 1.2016-08-20T21:17:56-04:00.diff.gz
-rw-------  1 joe joe   1 Aug 20 21:17 next_free

# Copy the saved current_mirror back so as to force rdiff-backup into
# concluding that the last backup failed (a simulated failure for this test):
cp current_mirror* dst/rdiff-backup-data

# rdiff-backup will now report that there is a problem:
rdiff-backup --list-increments dst
Fatal Error: Previous backup to /lan1/sys/home/joe/tmprdifftest/dst seems to have failed.
Rerun rdiff-backup with --check-destination-dir option to revert directory to state before unsuccessful session.

# Perform the usual fix for the problem (regress the repository):
rdiff-backup --check-destination-dir dst

# See that rdiff-backup appears to be happy:
rdiff-backup --list-increments dst
Found 0 increments:
Current mirror: Sat Aug 20 21:17:56 2016

# Here's the problem: regressing the repository failed to remove the increment
# file from the 2nd backup:
ls -l dst/rdiff-backup-data/long_filename_data
total 16
-rw-rw-r--  1 joe joe 107 Aug 20 21:17 1.2016-08-20T21:17:56-04:00.diff.gz
-rw-------  1 joe joe   1 Aug 20 21:17 next_free

# Retry the 2nd backup.  It fails because the old increment file is in the way:
rdiff-backup src dst
Exception 'Path: dst/rdiff-backup-data/long_filename_data/1.2016-08-20T21:17:56-04:00.diff.gz
Index: ('long_filename_data', '1.2016-08-20T21:17:56-04:00.diff.gz')
Data: {'uid': 500, 'perms': 436, 'type': 'reg', 'gname': 'joe', 'ea': <rdiff_backup.eas_acls.ExtendedAttributes instance at 0xb7c2b4cc>, 'ctime': 1471742278, 'devloc': 64770L, 'uname': 'joe', 'nlink': 1, 'gid': 500, 'mtime': 1471742276, 'atime': 1471742279, 'inode': 9043973L, 'size': 107L}' raised of class 'exceptions.AssertionError':
  File "/usr/lib/python2.3/site-packages/rdiff_backup/robust.py", line 32, in check_common_error
    try: return function(*args)
  File "/usr/lib/python2.3/site-packages/rdiff_backup/increment.py", line 43, in Increment
    incrp = makediff(new, mirror, incpref)
  File "/usr/lib/python2.3/site-packages/rdiff_backup/increment.py", line 79, in makediff
    if compress: diff = get_inc(incpref, "diff.gz")
  File "/usr/lib/python2.3/site-packages/rdiff_backup/increment.py", line 123, in get_inc
    assert not incrp.lstat(), incrp

Exception 'Path: dst/rdiff-backup-data/long_filename_data/1.2016-08-20T21:17:56-04:00.diff.gz
Index: ('long_filename_data', '1.2016-08-20T21:17:56-04:00.diff.gz')
Data: {'uid': 500, 'perms': 436, 'type': 'reg', 'gname': 'joe', 'ea': <rdiff_backup.eas_acls.ExtendedAttributes instance at 0xb7c2b4cc>, 'ctime': 1471742278, 'devloc': 64770L, 'uname': 'joe', 'nlink': 1, 'gid': 500, 'mtime': 1471742276, 'atime': 1471742279, 'inode': 9043973L, 'size': 107L}' raised of class 'exceptions.AssertionError':
  File "/usr/lib/python2.3/site-packages/rdiff_backup/Main.py", line 304, in error_check_Main
    try: Main(arglist)
  File "/usr/lib/python2.3/site-packages/rdiff_backup/Main.py", line 324, in Main
    take_action(rps)
  File "/usr/lib/python2.3/site-packages/rdiff_backup/Main.py", line 280, in take_action
    elif action == "backup": Backup(rps[0], rps[1])
  File "/usr/lib/python2.3/site-packages/rdiff_backup/Main.py", line 343, in Backup
    backup.Mirror_and_increment(rpin, rpout, incdir)
  File "/usr/lib/python2.3/site-packages/rdiff_backup/backup.py", line 51, in Mirror_and_increment
    DestS.patch_and_increment(dest_rpath, source_diffiter, inc_rpath)
  File "/usr/lib/python2.3/site-packages/rdiff_backup/backup.py", line 243, in patch_and_increment
    ITR(diff.index, diff)
  File "/usr/lib/python2.3/site-packages/rdiff_backup/rorpiter.py", line 281, in __call__
    last_branch.fast_process(*args)
  File "/usr/lib/python2.3/site-packages/rdiff_backup/backup.py", line 698, in fast_process
    increment.Increment, (tf, mirror_rp, inc_prefix))
  File "/usr/lib/python2.3/site-packages/rdiff_backup/robust.py", line 32, in check_common_error
    try: return function(*args)
  File "/usr/lib/python2.3/site-packages/rdiff_backup/increment.py", line 43, in Increment
    incrp = makediff(new, mirror, incpref)
  File "/usr/lib/python2.3/site-packages/rdiff_backup/increment.py", line 79, in makediff
    if compress: diff = get_inc(incpref, "diff.gz")
  File "/usr/lib/python2.3/site-packages/rdiff_backup/increment.py", line 123, in get_inc
    assert not incrp.lstat(), incrp

Traceback (most recent call last):
  File "/usr/bin/rdiff-backup", line 30, in ?
    rdiff_backup.Main.error_check_Main(sys.argv[1:])
  File "/usr/lib/python2.3/site-packages/rdiff_backup/Main.py", line 304, in error_check_Main
    try: Main(arglist)
  File "/usr/lib/python2.3/site-packages/rdiff_backup/Main.py", line 324, in Main
    take_action(rps)
  File "/usr/lib/python2.3/site-packages/rdiff_backup/Main.py", line 280, in take_action
    elif action == "backup": Backup(rps[0], rps[1])
  File "/usr/lib/python2.3/site-packages/rdiff_backup/Main.py", line 343, in Backup
    backup.Mirror_and_increment(rpin, rpout, incdir)
  File "/usr/lib/python2.3/site-packages/rdiff_backup/backup.py", line 51, in Mirror_and_increment
    DestS.patch_and_increment(dest_rpath, source_diffiter, inc_rpath)
  File "/usr/lib/python2.3/site-packages/rdiff_backup/backup.py", line 243, in patch_and_increment
    ITR(diff.index, diff)
  File "/usr/lib/python2.3/site-packages/rdiff_backup/rorpiter.py", line 281, in __call__
    last_branch.fast_process(*args)
  File "/usr/lib/python2.3/site-packages/rdiff_backup/backup.py", line 698, in fast_process
    increment.Increment, (tf, mirror_rp, inc_prefix))
  File "/usr/lib/python2.3/site-packages/rdiff_backup/robust.py", line 32, in check_common_error
    try: return function(*args)
  File "/usr/lib/python2.3/site-packages/rdiff_backup/increment.py", line 43, in Increment
    incrp = makediff(new, mirror, incpref)
  File "/usr/lib/python2.3/site-packages/rdiff_backup/increment.py", line 79, in makediff
    if compress: diff = get_inc(incpref, "diff.gz")
  File "/usr/lib/python2.3/site-packages/rdiff_backup/increment.py", line 123, in get_inc
    assert not incrp.lstat(), incrp
AssertionError: Path: dst/rdiff-backup-data/long_filename_data/1.2016-08-20T21:17:56-04:00.diff.gz
Index: ('long_filename_data', '1.2016-08-20T21:17:56-04:00.diff.gz')
Data: {'uid': 500, 'perms': 436, 'type': 'reg', 'gname': 'joe', 'ea': <rdiff_backup.eas_acls.ExtendedAttributes instance at 0xb7c2b4cc>, 'ctime': 1471742278, 'devloc': 64770L, 'uname': 'joe', 'nlink': 1, 'gid': 500, 'mtime': 1471742276, 'atime': 1471742279, 'inode': 9043973L, 'size': 107L}
rdiff-backup --list-increments dst
Fatal Error: Previous backup to /lan1/sys/home/joe/tmprdifftest/dst seems to have failed.
Rerun rdiff-backup with --check-destination-dir option to revert directory to state before unsuccessful session.

# Again, regress the repository to fix the failed backup:
rdiff-backup --check-destination-dir dst
rdiff-backup --list-increments dst
Found 0 increments:
Current mirror: Sat Aug 20 21:17:56 2016

# This time, manually remove the increment file that should not be there (normally, this must
# be done more judiciously than illustrated here):
ls -l dst/rdiff-backup-data/long_filename_data
total 16
-rw-rw-r--  1 joe joe 107 Aug 20 21:17 1.2016-08-20T21:17:56-04:00.diff.gz
-rw-------  1 joe joe   1 Aug 20 21:17 next_free
rm dst/rdiff-backup-data/long_filename_data/1*

# Now we are able to successfully make the 2nd backup:
rdiff-backup src dst
rdiff-backup --list-increments dst
Found 1 increments:
    increments.2016-08-20T21:17:56-04:00.dir   Sat Aug 20 21:17:56 2016
Current mirror: Sat Aug 20 21:18:00 2016

[anomaly256]

Thanks for the repro instructions, I'll test and investigate this today. Sorry for the long delay in responding

[hallyn]

Any update on this?

[schniepp]

I'd also be interested, as I have the same problem.

[ericzolf]

If you could validate that this issue still happens when using the PR #53 that would be really nice.

[ericzolf]

OK, the issue still happens with the master branch. I've already written a regression test script heavily based on the script provided by @zjw (thanks!), available for now from the work-in-progress branch ericzolf-regress-longname-9 (we might want to re-write it in Python like all the other tests but I don't know if it's worth the issue, we should definitely add it though to tox.ini once fixed).

@anomaly256 are you still owning the issue and be available to fix it?