Some months ago, I've installed rsnapshot on my local home-server in order to back up all clients in my home network. Since these clients aren't 24/7 online, rsnapshot does a lot of "roll-backs" of old backups. It worked perfectly until last week.
Here are some logfiles:
This is the last working logfile (worked like that several months)
[There are two clients, both not online, so roll-back the old backups]
/opt/var/log/rsnapshot # cat hourly-2012-01-20_17-00.rlog
Setting locale to POSIX "C"
echo 22570 > /opt/var/desiredrun/rsnapshot.pid
/opt/bin/rm -rf /DataVolume/backup/hourly.5/
mv /DataVolume/backup/hourly.4/ /DataVolume/backup/hourly.5/
mv /DataVolume/backup/hourly.3/ /DataVolume/backup/hourly.4/
mv /DataVolume/backup/hourly.2/ /DataVolume/backup/hourly.3/
mv /DataVolume/backup/hourly.1/ /DataVolume/backup/hourly.2/
mv /DataVolume/backup/hourly.0/ /DataVolume/backup/hourly.1/
mkdir -m 0755 -p /DataVolume/backup/hourly.0/
/opt/bin/rsync -av --delete --numeric-ids --relative --delete-excluded \
--exclude=Recycled/ --exclude=Trash/ --exclude=lost+found/ \
--exclude=.gvfs/ --exclude=Downloads/ --exclude=.cache/ \
--exclude=.thumbnails/ --rsh=/opt/bin/ssh \
--link-dest=/DataVolume/backup/hourly.1/lama/ simon@lama:/home/simon \
/DataVolume/backup/hourly.0/lama/
ssh: connect to host lama port 22: No route to host
rsync: connection unexpectedly closed (0 bytes received so far) [Receiver]
rsync error: unexplained error (code 255) at io.c(601) [Receiver=3.0.8]
----------------------------------------------------------------------------
rsnapshot encountered an error! The program was invoked with these options:
/opt/bin/rsnapshot -V hourly
----------------------------------------------------------------------------
ERROR: /opt/bin/rsync returned 255 while processing simon@lama:/home/simon/
/opt/bin/rsync -av --delete --numeric-ids --relative --delete-excluded \
--exclude=Recycled/ --exclude=Trash/ --exclude=lost+found/ \
--exclude=.gvfs/ --exclude=Downloads/ --exclude=.cache/ \
--exclude=.thumbnails/ --rsh=/opt/bin/ssh \
--link-dest=/DataVolume/backup/hourly.1/zebra/ simon@zebra:/home/simon \
/DataVolume/backup/hourly.0/zebra/
ssh: connect to host zebra port 22: No route to host
rsync: connection unexpectedly closed (0 bytes received so far) [Receiver]
rsync error: error in rsync protocol data stream (code 12) at io.c(601) [Receiver=3.0.8]
ERROR: /opt/bin/rsync returned 12 while processing simon@zebra:/home/simon/
WARNING: Rolling back "lama/"
/opt/bin/cp -al /DataVolume/backup/hourly.1/lama \
/DataVolume/backup/hourly.0/lama
WARNING: Rolling back "zebra/"
/opt/bin/cp -al /DataVolume/backup/hourly.1/zebra \
/DataVolume/backup/hourly.0/zebra
touch /DataVolume/backup/hourly.0/
rm -f /opt/var/run/rsnapshot.pid
I think in the next one is the actual problem: As you can see, at first everything looks good, but then there is a lots of filetransfer(hundreds of lines). And after this transfer, there is nothing. No roll-back, etc. Maybe the filetransfer takes too much time and the next backup cycle cutted the first one?
[those "permission denied" lines are no surprise, since files are owned by root on the client machine. So they shouldn' t be the problem]
/opt/var/log/rsnapshot # vim hourly-2012-01-20_21-00.rlog
Setting locale to POSIX "C"
WARNING: Removing stale lockfile /opt/var/run/rsnapshot.pid
rm -f /opt/var/run/rsnapshot.pid
echo 5859 > /opt/var/run/rsnapshot.pid
/opt/bin/rm -rf /DataVolume/backup/hourly.5/
mv /DataVolume/backup/hourly.4/ /DataVolume/backup/hourly.5/
mv /DataVolume/backup/hourly.3/ /DataVolume/backup/hourly.4/
mv /DataVolume/backup/hourly.2/ /DataVolume/backup/hourly.3/
mv /DataVolume/backup/hourly.1/ /DataVolume/backup/hourly.2/
mv /DataVolume/backup/hourly.0/ /DataVolume/backup/hourly.1/
mkdir -m 0755 -p /DataVolume/backup/hourly.0/
/opt/bin/rsync -av --delete --numeric-ids --relative --delete-excluded \
--exclude=Recycled/ --exclude=Trash/ --exclude=lost+found/ \
--exclude=.gvfs/ --exclude=Downloads/ --exclude=.cache/ \
--exclude=.thumbnails/ --rsh=/opt/bin/ssh \
--link-dest=/DataVolume/backup/hourly.1/lama/ simon@lama:/home/simon \
/DataVolume/backup/hourly.0/lama/
ssh: connect to host lama port 22: No route to host^M
rsync: connection unexpectedly closed (0 bytes received so far) [Receiver]
rsync error: error in rsync protocol data stream (code 12) at io.c(601) [Receiver=3.0.8]
----------------------------------------------------------------------------
rsnapshot encountered an error! The program was invoked with these options:
/opt/bin/rsnapshot -V hourly
----------------------------------------------------------------------------
ERROR: /opt/bin/rsync returned 12 while processing simon@lama:/home/simon/
/opt/bin/rsync -av --delete --numeric-ids --relative --delete-excluded \
--exclude=Recycled/ --exclude=Trash/ --exclude=lost+found/ \
--exclude=.gvfs/ --exclude=Downloads/ --exclude=.cache/ \
--exclude=.thumbnails/ --rsh=/opt/bin/ssh \
--link-dest=/DataVolume/backup/hourly.1/zebra/ simon@zebra:/home/simon \
/DataVolume/backup/hourly.0/zebra/
receiving incremental file list
created directory /DataVolume/backup/hourly.0/zebra
home/simon/
home/simon/.ICEauthority
home/simon/.Xauthority
home/simon/.bash_history
home/simon/.conkyrc
[...LOTS of filetransfer!..]
rsync: send_files failed to open "/home/simon/backup/etc_bu/etc/ssh/ssh_host_rsa_key": Permission denied (13)
rsync: send_files failed to open "/home/simon/backup/etc_bu/etc/sudoers.d/README": Permission denied (13)
rsync: send_files failed to open "/home/simon/backup/etc_bu/etc/ufw/after.rules": Permission denied (13)
rsync: send_files failed to open "/home/simon/backup/etc_bu/etc/ufw/after6.rules": Permission denied (13)
rsync: send_files failed to open "/home/simon/backup/etc_bu/etc/ufw/before.rules": Permission denied (13)
rsync: send_files failed to open "/home/simon/backup/etc_bu/etc/ufw/before6.rules": Permission denied (13)
And here comes the following logfile: As you can see, the machines are both offline again. Zebra gets rolled-back correctly, but lama not. I think this is because of the last backup, which hasn't finished correctly (So lama hasn't rolled-back and never existed for the current backup).
/opt/var/log/rsnapshot # cat hourly-2012-01-21_01-00.rlog
Setting locale to POSIX "C"
WARNING: Removing stale lockfile /opt/var/run/rsnapshot.pid
rm -f /opt/var/run/rsnapshot.pid
echo 7849 > /opt/var/run/rsnapshot.pid
/opt/bin/rm -rf /DataVolume/backup/hourly.5/
mv /DataVolume/backup/hourly.4/ /DataVolume/backup/hourly.5/
mv /DataVolume/backup/hourly.3/ /DataVolume/backup/hourly.4/
mv /DataVolume/backup/hourly.2/ /DataVolume/backup/hourly.3/
mv /DataVolume/backup/hourly.1/ /DataVolume/backup/hourly.2/
mv /DataVolume/backup/hourly.0/ /DataVolume/backup/hourly.1/
mkdir -m 0755 -p /DataVolume/backup/hourly.0/
/opt/bin/rsync -av --delete --numeric-ids --relative --delete-excluded \
--exclude=Recycled/ --exclude=Trash/ --exclude=lost+found/ \
--exclude=.gvfs/ --exclude=Downloads/ --exclude=.cache/ \
--exclude=.thumbnails/ --rsh=/opt/bin/ssh \
--link-dest=/DataVolume/backup/hourly.2/lama/ simon@lama:/home/simon \
/DataVolume/backup/hourly.0/lama/
ssh: connect to host lama port 22: No route to host^M
rsync: connection unexpectedly closed (0 bytes received so far) [Receiver]
rsync error: unexplained error (code 255) at io.c(601) [Receiver=3.0.8]
----------------------------------------------------------------------------
rsnapshot encountered an error! The program was invoked with these options:
/opt/bin/rsnapshot -V hourly
----------------------------------------------------------------------------
ERROR: /opt/bin/rsync returned 255 while processing simon@lama:/home/simon/
/opt/bin/rsync -av --delete --numeric-ids --relative --delete-excluded \
--exclude=Recycled/ --exclude=Trash/ --exclude=lost+found/ \
--exclude=.gvfs/ --exclude=Downloads/ --exclude=.cache/ \
--exclude=.thumbnails/ --rsh=/opt/bin/ssh \
--link-dest=/DataVolume/backup/hourly.1/zebra/ simon@zebra:/home/simon \
/DataVolume/backup/hourly.0/zebra/
ssh: connect to host zebra port 22: No route to host^M
rsync: connection unexpectedly closed (0 bytes received so far) [Receiver]
rsync error: error in rsync protocol data stream (code 12) at io.c(601) [Receiver=3.0.8]
ERROR: /opt/bin/rsync returned 12 while processing simon@zebra:/home/simon/
WARNING: Rolling back "zebra/"
/opt/bin/cp -al /DataVolume/backup/hourly.1/zebra \
/DataVolume/backup/hourly.0/zebra
touch /DataVolume/backup/hourly.0/
rm -f /opt/var/run/rsnapshot.pid
And as a special, there is the "du" command:
(Does this fit to the problem?)
/DataVolume/backup # rsnapshot du
require Lchown
Lchown module not found
/opt/bin/du -csh /DataVolume/backup/hourly.0/ /DataVolume/backup/hourly.1/ \
/DataVolume/backup/hourly.2/ /DataVolume/backup/hourly.3/ \
/DataVolume/backup/hourly.4/ /DataVolume/backup/hourly.5/ \
/DataVolume/backup/daily.0/ /DataVolume/backup/daily.1/ \
/DataVolume/backup/daily.2/ /DataVolume/backup/daily.3/ \
/DataVolume/backup/daily.4/ /DataVolume/backup/daily.5/ \
/DataVolume/backup/daily.6/ /DataVolume/backup/weekly.0/ \
/DataVolume/backup/weekly.1/ /DataVolume/backup/weekly.2/ \
/DataVolume/backup/monthly.0/ /DataVolume/backup/monthly.1/ \
/DataVolume/backup/monthly.2/
33G /DataVolume/backup/hourly.0/
4.3M /DataVolume/backup/hourly.1/
4.3M /DataVolume/backup/hourly.2/
4.3M /DataVolume/backup/hourly.3/
4.3M /DataVolume/backup/hourly.4/
4.3M /DataVolume/backup/hourly.5/
4.3M /DataVolume/backup/daily.0/
4.3M /DataVolume/backup/daily.1/
4.3M /DataVolume/backup/daily.2/
4.3M /DataVolume/backup/daily.3/
4.3M /DataVolume/backup/daily.4/
27G /DataVolume/backup/daily.5/
25G /DataVolume/backup/daily.6/
26G /DataVolume/backup/weekly.0/
679M /DataVolume/backup/weekly.1/
441M /DataVolume/backup/weekly.2/
1.2G /DataVolume/backup/monthly.0/
1003M /DataVolume/backup/monthly.1/
787M /DataVolume/backup/monthly.2/
113G total
PS: If you have any problems with my question regarding my bad english, feel free to ask!
regards, Simon
