BackupPC

References

rsync

• How Rsync works
• A patch for rsync about computing and caching checksums

Issues

• Backing up a ntfs-3g mount with rsync_bpc keeps transfering all files. See below for details.

Solution: Use tar method instead?

Troubleshooting

Broken pipe

Typical errors:

rsync_bpc: writefd_unbuffered failed to write 426 bytes to message fd [receiver]: Broken pipe (32)

Possible causes and solutions

• Happens more frequently with big files, but some small files fail too. Not always the same file
• Timeout issue
• Firewall
• Lots of packet loss / reject. The following iptable route might help [1]:

iptables -I {line} -p tcp --tcp-flags SYN,RST,ACK,FIN ACK -j ACCEPT

Links

• Interesting discussion on samba.org, with troubleshooting ideas.

  strace -tt -f -o /tmp/rsync-$$.out rsync \
        --verbose \
        --exclude "stor/hosts" \
        --exclude "var/run" \
        --exclude "var/spool" \
        --rsh="ssh -p $backoff_port" \
        --rsync-path="sudo /usr/local/bin/rsync-debug" \
        --recursive \
        --links \
        --perms \
        --times \
        --owner \
        --group \
        --numeric-ids \
        --xattrs \
        --delete \
        --compress \
        --human-readable \
        --stats \
        --exclude='udat/backup*/*' \
        --exclude='udat/migrate/*' \
        /mnt/stor \
        $userid@$backoff_url:$destdir 2>&1

Issues on Lacie-Cloud

Broken pipe, etc

I get failed backup on the lacie-cloud server; I log my findings / tests here.

The current rsync command line is:

/opt/bin/rsync_bpc --bpc-top-dir /shares/backuppc --bpc-host-name zavcxl0005 --bpc-share-name home \
--bpc-bkup-num 1 --bpc-bkup-comp 3 --bpc-bkup-prevnum -1 --bpc-bkup-prevcomp -1 --bpc-bkup-inode0 567 \
--bpc-log-level 3 --super --recursive --protect-args --numeric-ids --perms --owner --group -D --times \
--links --hard-links --delete --partial --log-format=log: %o %i %B %8U,%8G %9l %f%L --stats \
--modify-window=5 --one-file-system --password-file=/shares/backuppc/pc/zavcxl0005/.rsyncdpw6801 \
--exclude=.cache --exclude=.recoll --exclude=.gvfs --exclude=.thumbnails --exclude=.Trash* \
--exclude=*.nobak --exclude=.*.nobak --exclude=.opera/cache --exclude=Snapshots --exclude=Cache \
--exclude=Dropbox --exclude=$RECYCLE.BIN --exclude=$Recycle.Bin --exclude=System Volume Information \
--exclude=lost+found backuppc@zavcxl0005::home /

Notes

• Still use the old parameter --log-format, which has been deprecated and renamed to --out-format in newer rsync version.

Zombie rsync_bpc processes

I have two processes still running on lacie-cloudbox:

[root@LaCie-CloudBox ~]# /opt/bin/ps faux | grep rsync
Unknown HZ value! (73) Assume 100.
root      2249  0.0  0.0   4748     4 ?        Ss   Jun14   0:00 /usr/bin/rsync --daemon --config=/etc/rsyncd.conf --no-detach
root     26783  0.0  0.3   3608   916 pts/0    S+   20:46   0:00          \_ grep rsync
backuppc  5746  1.5  0.0  85764    56 ?        S    10:24   9:41      \_ /opt/bin/rsync_bpc --bpc-top-dir /shares/backuppc --bpc-host-name graphicdaemon --bpc-share-name d --bpc-bkup-num 213 --bpc-bkup-comp 3 --bpc-bkup-prevnum 212 --bpc-bkup-prevcomp 3 --bpc-bkup-inode0 9109 --bpc-log-level 3 --super --recursive --protect-args --numeric-ids --perms --owner --group -D --times --links --hard-links --delete --partial --log-format=log: %o %i %B %8U,%8G %9l %f%L --stats --modify-window=5 --checksum --one-file-system --password-file=/shares/backuppc/pc/graphicdaemon/.rsyncdpw3449 --exclude=.cache --exclude=.recoll --exclude=.gvfs --exclude=.thumbnails --exclude=.Trash* --exclude=*.nobak --exclude=.*.nobak --exclude=.opera/cache --exclude=Cache --exclude=Dropbox --exclude=Snapshots --exclude=$RECYCLE.BIN --exclude=$Recycle.Bin --exclude=System Volume Information --exclude=lost+found backuppc@graphicdaemon::d /
backuppc  5779 12.7  0.0  77872    56 ?        S    10:25  78:57          \_ /opt/bin/rsync_bpc --bpc-top-dir /shares/backuppc --bpc-host-name graphicdaemon --bpc-share-name d --bpc-bkup-num 213 --bpc-bkup-comp 3 --bpc-bkup-prevnum 212 --bpc-bkup-prevcomp 3 --bpc-bkup-inode0 9109 --bpc-log-level 3 --super --recursive --protect-args --numeric-ids --perms --owner --group -D --times --links --hard-links --delete --partial --log-format=log: %o %i %B %8U,%8G %9l %f%L --stats --modify-window=5 --checksum --one-file-system --password-file=/shares/backuppc/pc/graphicdaemon/.rsyncdpw3449 --exclude=.cache --exclude=.recoll --exclude=.gvfs --exclude=.thumbnails --exclude=.Trash* --exclude=*.nobak --exclude=.*.nobak --exclude=.opera/cache --exclude=Cache --exclude=Dropbox --exclude=Snapshots --exclude=$RECYCLE.BIN --exclude=$Recycle.Bin --exclude=System Volume Information --exclude=lost+found backuppc@graphicdaemon::d /

[root@LaCie-CloudBox ~]# netstat -ane | grep 100.117        
netstat: /proc/net/tcp6: No such file or directory
tcp        0      0 172.19.100.98:49947     172.19.100.117:873      ESTABLISHED 
netstat: /proc/net/udp6: No such file or directory
netstat: /proc/net/raw6: No such file or directory

But the rsyncd daemon on the server failed since 10:46 am:

$ sudo netstat -pna|grep 100.98

$ tail /var/log/rsync.log 
2015/06/19 10:04:31 [2917] send lacie-cloudbox [172.19.100.98] d (backuppc) Games/World_of_Tanks/res/packages/hangar_premium_v2.pkg 28914772
2015/06/19 10:04:31 [2917] send lacie-cloudbox [172.19.100.98] d (backuppc) Games/World_of_Tanks/res/packages/hangar_v2.pkg 27720752
2015/06/19 10:07:43 [2917] send lacie-cloudbox [172.19.100.98] d (backuppc) Games/World_of_Tanks/res/packages/misc.pkg 752868269
2015/06/19 10:12:46 [2917] send lacie-cloudbox [172.19.100.98] d (backuppc) Games/World_of_Tanks/res/packages/shaders.pkg 4879357
2015/06/19 10:17:52 [2917] send lacie-cloudbox [172.19.100.98] d (backuppc) Games/World_of_Tanks/res/packages/shared_content.pkg 950719654
2015/06/19 10:17:52 [2917] send lacie-cloudbox [172.19.100.98] d (backuppc) Games/World_of_Tanks/res/packages/shared_content.prefetch 394119
2015/06/19 10:24:52 [2917] send lacie-cloudbox [172.19.100.98] d (backuppc) Games/World_of_Tanks/res/packages/vehicles_level_01.pkg 36603536
2015/06/19 10:27:20 [2917] send lacie-cloudbox [172.19.100.98] d (backuppc) Games/World_of_Tanks/res/packages/vehicles_level_02.pkg 276573347
2015/06/19 10:46:28 [2917] rsync: [sender] write error: Invalid argument (22)
2015/06/19 10:46:28 [2917] rsync error: error in socket IO (code 10) at io.c(837) [sender=3.1.0]

$ ps faux | grep rsync
isma      8126  0.0  0.0  14776   944 pts/0    S+   20:51   0:00              \_ grep rsync

Checking the client log on lacie-cloudbox (using BackupPC_zcat to decompress), we actually observe that the log is truncated much before the rsyncd log. So it seems the client broke but did not exit. So adding param --timeout to rsync client might not help here.

bpc_fileOpen: can't open pool file

I get for each backup the same error message:

     same   recv >f......... rwxrwx---        0,      46       640 Windows/winsxs/FileMaps/$$_ime_fr-fr_0d349902e45b4cea.cdf-ms
 G bpc_fileOpen: can't open pool file /shares/backuppc/cpool/f8/02/f803002e8050e1931403001000000000 (from Windows/winsxs/Manifests/amd64_prnin004.inf-languagepack_31bf3856ad364e35_6.1.7600.16385_en-us_426884f5a0a5f5a4.manifest, 3, 16)
 rsync_bpc: failed to open "/Windows/winsxs/Manifests/amd64_prnin004.inf-languagepack_31bf3856ad364e35_6.1.7600.16385_en-us_426884f5a0a5f5a4.manifest", continuing: No such file or directory (2)
     same   recv >f......... rwxrwx---        0,      46      2136 Windows/winsxs/FileMaps/$$_ime_imejp10_dicts_281006c600450618.cdf-ms

The problem is not solved at next backup. A similar problem is reported by another user on backuppc-users mailing list [2].

Stale transfer

Some troubleshooting commands [3]:

strace -p $PID
lsof -f | grep rsync                          # and the following to confirm)

rsync_bpc keep transfering same file on ntfs-3g mount

/c is a ntfs-3g mount. Content of /etc/fstab:

UUID=445E1B975E1B813A 				/c              ntfs    ro,defaults,nls=utf8,umask=007,gid=46 0       0

To test this, add to /etc/rsyncd.conf:

+[test1]
+comment = Test share 1
+path = /c/Boot

In a separate window, monitor the rsyncd log file:

tail -f /var/log/rsyncd.log

With rsync, the sync is done correctly. Files are no longer transfered on second run. To verify, repeat the command below twice:

mkdir /tmp/rsynctest
sudo rsync --super --recursive --protect-args --numeric-ids --perms --owner --group -D --times \
--links --hard-links --delete --partial --log-format='log: %o %i %B %8U,%8G %9l %f%L' --stats \
--modify-window=5 --one-file-system --password-file=/tmp/rsyncd.secrets \ 
--checksum backuppc@griffin::test1 /tmp/rsynctest

But with rsync_bpc, files are always transfered, and reported as identical after transfer.

i=0
cd /tmp/rsynctest
mkdir cpool

Repeat the command below:

cd /tmp/rsynctest; i=$((i+1)); echo backup $i; sudo cp -ar pc/griffin/$((i-1)) pc/griffin/$i; \
rsync_bpc --bpc-top-dir /tmp/rsynctest --bpc-host-name griffin --bpc-share-name test1 --bpc-bkup-num $i \
--bpc-bkup-comp 3 --bpc-bkup-prevnum $((i-1)) --bpc-bkup-prevcomp 3 --bpc-log-level 9  --super --recursive \
--protect-args --numeric-ids --perms --owner --group -D --times --links --hard-links --delete --partial \
--log-format='log: %o %i %B %8U,%8G %9l %f%L' --stats --modify-window=5 --one-file-system \
--password-file=/tmp/rsyncd.secrets backuppc@griffin::test1 /

This only happens when share test1 is on an ntfs-3g mount point. We can verify this does not happen on other file system by editing /etc/rsyncd.conf. For instance:

 [test1]
 comment = Test share 1
-path = /c/Boot
+path = /boot

And run the rsync_bpc command above twice.

The following works:

cd /tmp/rsynctest; i=$((i+1)); echo backup $i; sudo cp -ar pc/griffin/$((i-1)) pc/griffin/$i; \
sudo rsync_bpc --bpc-top-dir /tmp/rsynctest --bpc-host-name griffin --bpc-share-name test1 --bpc-bkup-num $i \
--bpc-bkup-comp 3 --bpc-bkup-prevnum $((i-1)) --bpc-bkup-prevcomp 3 --bpc-log-level 3  --protect-args --recursive \
--times --one-file-system --password-file=/tmp/rsyncd.secrets backuppc@griffin::test1 /