rsync: one unreadable file causes backup job to fail completely

[Julian Gilbey]

Here's a backintime run (with the excludes list edited out for clarity):

erdos:~ $ backintime --backup-job
WARNING: import keyring failed

Back In Time
Version: 1.0.34

Back In Time comes with ABSOLUTELY NO WARRANTY.
This is free software, and you are welcome to redistribute it
under certain conditions; type `backintime --license' for details.

INFO: Lock
INFO: [GnomePlugin.Systray.run]
INFO: [UserCallbackPlugin.notify_callback] 1
INFO: [GnomePlugin.Systray.run] begin loop
INFO: on process begins
INFO: Profile_id: 1
INFO: Compare with old snapshot: 20131129-030001-262
INFO: Command "rsync -rtDH --links --no-p --no-g --no-o --delete --delete-excluded -i --dry-run --out-format="BACKINTIME: %i %n%L" --chmod=Du+wx --exclude=[...] --include="/home/jdg/**" --include="/var/mail/jdg" --exclude="*" / "/media/JG-BACKUP/jdg/backintime/erdos/jdg/1/20131129-030001-262/backup/"" returns 0
INFO: Create hard-links
INFO: Command "find "/media/JG-BACKUP/jdg/backintime/erdos/jdg/1/20131129-030001-262/backup/" -type d -exec chmod u+wx "{}" +" returns 0
INFO: Command "cp -aRl "/media/JG-BACKUP/jdg/backintime/erdos/jdg/1/20131129-030001-262/backup/"* "/media/JG-BACKUP/jdg/backintime/erdos/jdg/1/new_snapshot/backup/"" returns 0
INFO: Command "find "/media/JG-BACKUP/jdg/backintime/erdos/jdg/1/20131129-030001-262/backup/" -type d -exec chmod a-w "{}" +" returns 0
INFO: Command "chmod -R a+w "/media/JG-BACKUP/jdg/backintime/erdos/jdg/1/new_snapshot"" returns 0
INFO: Call rsync to take the snapshot
WARNING: Command "rsync -rtDH --links --no-p --no-g --no-o --delete --delete-excluded -v --chmod=Du+wx --exclude=[...] --include="/home/jdg/**" --include="/var/mail/jdg" --exclude="*" / "/media/JG-BACKUP/jdg/backintime/erdos/jdg/1/new_snapshot/backup/" 2>&1" returns 5888
INFO: Command "find "/media/JG-BACKUP/jdg/backintime/erdos/jdg/1/new_snapshot" -type d -exec chmod u+wx "{}" +" returns 0
INFO: Command "rm -rf "/media/JG-BACKUP/jdg/backintime/erdos/jdg/1/new_snapshot"" returns 0
INFO: Command "chmod -R a-w "/media/JG-BACKUP/jdg/backintime/erdos/jdg/1/20131129-030001-262/backup/"" returns 0
INFO: Command "rm -rf "/media/JG-BACKUP/jdg/backintime/erdos/jdg/1/20140102-104338-851"" returns 0
ERROR: Failed to take snapshot !!!
INFO: [UserCallbackPlugin.notify_callback] 2
INFO: [GnomePlugin.Systray.run] end loop
INFO: Unlock

So the effect is that no backup is produced.

Running the listed commands manually revealed the source of the problem:

erdos:~ $ rsync -rtDH --links --no-p --no-g --no-o --delete --delete-excluded -v --chmod=Du+wx --exclude=[...] --include="/home/jdg/**" --include="/var/mail/jdg" --exclude="*" / "/media/JG-BACKUP/jdg/backintime/erdos/jdg/1/new_snapshot/backup/"
sending incremental file list
[...]
home/jdg/.encdir/
rsync: send_files failed to open "/home/jdg/.encdir/.7Fc2v1GRCCi9svpo": Permission denied (13)
[...]

sent 60,328,711 bytes received 17,619 bytes 375,989.60 bytes/sec
total size is 174,071,292,851 speedup is 2,884.54
rsync error: some files/attrs were not transferred (see previous errors) (code 23) at main.c(1183) [sender=3.1.0]
erdos:~ $ echo $?
23

So one single file which was unreadable (it turns out that it was - bizarrely - owned by root with permissions 600) caused the entire backup to fail. (Also, the message that the rsync return code was 5888 - which is 23 * 256 = 0x1700 - is not as helpful as saying that the return code is 23.)

I suggest that in the presence of an rsync error code of 23 (and maybe some others as well), a message is given but the backup process is continued nonetheless; nothing else was backed up in this situation, instead of all but one file.

Julian

[Julian Gilbey (jdg)]

Oh, one other thing about this bug: in spite of the backup failing, backintime still returned with a final exit status of 0, meaning that the failure couldn't be detected without reading the output produced.

[Germar (germar)]

The entire backup only failed because you disabled 'Continue on Errors' in Options. If you enable it again BIT will create a new snapshot and mark it 'WITH ERRORS!'.

The returncode/256 issue bothers me as well. It's caused by the os.system / os.popen functions used to call external commands. I'm not yet sure how to fix this. Either just divide returncode by 256 or change to subprocess.Popen...

For BIT returncode there is already bug #1040995

[Julian Gilbey (jdg)]

That's interesting. I hadn't seen this option, and I have no recollection of having unset it (though maybe I did?). Thanks for the info!