blog.crox.net

I run a BackupPC instance that is still on Debian 10 / buster. The latest rsync package for Debian 10 has version number 3.1.3-6.

I recently noticed infrequent issues when backing up hosts that are either on Debian 11 / bullseye, or on Ubuntu 22.04 (which both ship rsync 3.2.3). The symptoms are as follows:

- backups take much longer than usual
- XferLog.z starts "normally", but after a certain point contains a lot of binary garbage, and gets much bigger than usual (hundreds of MB, or even in one case up to 12 GB)

After investigating and looking for information online, I came across these bug reports, which contain the explanation as well as a workaround: Debian Bug report #969463 and BackupPC issue #369.

=> The issue is caused by a combination of a change of default behaviour introduced with rsync 3.2.3, and a bug in File::RsyncP.

The solution that works for me (pending an update to Debian 11 and BackupPC 4) is to add the following line in the individual server config for each of the affected hosts:

$Conf{RsyncArgsExtra} = ['--no-msgs2stderr'];

When your backups suddenly takes much longer to complete, it could be because large files that were previously excluded from the backup were renamed or relocated elsewhere. In order to identify those files, or just to sort the list of files by size, I use the following code (bash):

cd /tmp/
BackupPC_zcat /var/lib/backuppc/pc/mypc/XferLOG.99.z > xlog
for S in `cat xlog | sed -e 's/^[^/]*\/[0-9]*[ ]*//' | cut -f1 -d\  | egrep '^[0-9]+$' | egrep '[0-9]{9,}' | sort -n | uniq ` ; do fgrep " $S " xlog ; done

This will show the list of files bigger than 99999999 bytes (100 MB). Remove "| egrep '[0-9]{9,}'" to just list all instead.

Note: on Debian, BackupPC_zcat is in /usr/share/backuppc/bin/. I've added a symlink in /usr/local/bin/ so that I don't need to look for it every time.

It took me some time to figure this out, maybe it can be useful to someone else...

I kept getting "no ping" error for unknown reasons. It turned out that I had enabled DumpPreUserCmd and UserCmdCheckStatus for that specific host to check for an encrypted partition being mounted.

Due to some changes on the host after an upgrade, the script triggered by DumpPreUserCmd was returning an error... And for some reason this showed as a ping error in the web interface.

I eventually figured it out by checking the last lines of the LOG.** file in the pc/[host] directory, which looked like this:

2018-05-08 19:15:45 Output from DumpPreUserCmd: /[partition] is not mounted
2018-05-08 19:15:45 DumpPreUserCmd returned error status 256... exiting

While trying to restore two files with BackupPC I got the following error message:

Remote[1]: Internal hashtable error: illegal key supplied!
Remote[1]: rsync error: errors with program diagnostics (code 13) at hashtable.c(65) [Receiver=3.0.9]
Read EOF: 
Tried again: got 0 bytes
Done: 2 files, 760646 bytes
restore failed: Unable to read 4 bytes

Other restores worked flawlessly. All hosts involved were running the same version of Debian Linux, with the same version of rsync. The same two files could be restored as a zip file from the BackupPC web front-end.

After spending some time on the issue with a colleague we eventually found the explanation, albeit not the solution: one of the files was a hard link. It looks like we hit a bug similar to what is described here: http://sourceforge.net/p/backuppc/mailman/message/20762995/

> This results in one subtle bug that can't be easily fixed: if you
> switch the Xfer method from tar to rsync, old backups that have
> hardlinks stored with tar won't be correctly restored with rsync.
> The workaround is generate a tar file and extract it, or switch
> the Xfer method back to tar before you do the restore.

We did not switch Xfer method (we've always used rsync over ssh). Possibly the issue was caused by attempting to restore two hard links to the same file at once - more testing would be required to confirm this.