Has anyone seen exit code 141 from rsnapshot?
system
----------
ubuntu 10.04 LTS (lucid) server
backup@ubuntu01:~/snapshots$ uname -a
Linux ubuntu01 2.6.32-33-server #72-Ubuntu SMP Fri Jul 29 21:21:55 UTC 2011 x86_64 GNU/Linux
rsnapshot version 1.3.0
rsync version 3.0.7
Lchown perl module loaded
I'm using the sync_first feature and a small shell script to run sync and then the OOB hourly job:
Crontab:
----------
backup@ubuntu01:~$ crontab -l
# m h dom mon dow command
# rsnapshot configuration
# see /etc/rsnapshot.conf for the current interval settings:
# interval hourly 6
# interval daily 7
# interval weekly 6
# interval montly 3
#0 */4 * * * /usr/bin/rsnapshot sync ; /usr/bin/test $? -ne 1 && /usr/bin/rsnapshot hourly
0 */4 * * * /var/backups/rsnapshot_sync_and_hourly.sh
50 23 * * * /usr/bin/rsnapshot daily
#40 23 1,8,15,22 * * /usr/bin/rsnapshot weekly
40 23 * * 6 /usr/bin/rsnapshot weekly
30 23 1 * * /usr/bin/rsnapshot monthly
Backup script:
----------
backup@ubuntu01:~$ cat /var/backups/rsnapshot_sync_and_hourly.sh
#!/bin/sh
# shell script to run rsnapshot sync, and if successful, rotate using rsnapshot hourly
# 2011-09-01
# Brad Taylor
PATH=/usr/local/bin:/usr/bin:/bin
LOGFILE=/var/log/rsnapshot_sync_and_hourly_`date '+%Y-%m'`.log
echo '\r\n' >> $LOGFILE
echo `date '+%F %T'` START $0 >> $LOGFILE
echo 'PID: '$$ >> $LOGFILE
/usr/bin/rsnapshot sync
RESULT=$?
echo 'rsnapshot sync result: '$RESULT >> $LOGFILE
case $RESULT in
0)
echo "rsnapshot ok; continuing with rotation" >> $LOGFILE
/usr/bin/rsnapshot hourly
RESULT=$?
echo 'rsnapshot hourly result: '$RESULT >> $LOGFILE
;;
1)
echo "rsnapshot fatal error; not rotating" >> $LOGFILE
;;
2)
echo "rsnapshot warning; continuing with rotation" >> $LOGFILE
/usr/bin/rsnapshot hourly
RESULT=$?
echo 'rsnapshot hourly result: '$RESULT >> $LOGFILE
;;
*)
echo "rsnapshot unknown result; check logs for more info" >> $LOGFILE
# hope for the best...
/usr/bin/rsnapshot hourly
RESULT=$?
echo 'rsnapshot hourly result: '$RESULT >> $LOGFILE
;;
esac
echo `date '+%F %T END'` >> $LOGFILE
log file sample:
2011-09-03 00:00:01 START /var/backups/rsnapshot_sync_and_hourly.sh
PID: 4980
rsnapshot sync result: 141
rsnapshot unknown result; check logs for more info
rsnapshot hourly result: 141
2011-09-03 00:29:53 END
When I did some googling on exit code 141, it seems that this is actually exit code 13 (141 - 128), which corresponds to SIGPIPE.
(reference: http://unix.derkeiler.com/Newsgroups/comp.unix.admin/2003-05/0495.html )
SIGPIPE being defined as: On POSIX-compliant platforms, SIGPIPE is the signal sent to a process when it attempts to write to a pipe without a process connected to the other end. (reference http://en.wikipedia.org/wiki/SIGPIPE
exit code 141 wouldn't be a problem for me, except I am seeing that the snapshot_root/.sync directory is not getting rotated consistently:
backup@ubuntu01:~/snapshots$ ls -ltha
total 0
drwxrwxr-x 7 backup backup 78 2011-09-03 00:00 .
drwxr-xr-x 3 backup backup 24 2011-09-03 00:00 .sync
drwxr-xr-x 3 backup backup 24 2011-09-02 20:00 hourly.0
drwxr-xr-x 3 backup backup 24 2011-09-02 16:55 hourly.1
drwxr-xr-x 3 backup backup 24 2011-09-01 23:49 hourly.2
drwxrwxr-x 3 backup backup 24 2011-09-01 07:43 hourly.3
drwxr-xr-x 3 root root 22 2011-08-29 00:26 ..
backup@ubuntu01:~/snapshots$ rsnapshot du
require Lchown
Lchown module loaded successfully
/usr/bin/du -csh /var/backups/snapshots/.sync \
/var/backups/snapshots/hourly.0/ /var/backups/snapshots/hourly.1/ \
/var/backups/snapshots/hourly.2/ /var/backups/snapshots/hourly.3/
5.5T /var/backups/snapshots/.sync
2.2G /var/backups/snapshots/hourly.0/
4.0G /var/backups/snapshots/hourly.1/
2.3T /var/backups/snapshots/hourly.2/
3.8G /var/backups/snapshots/hourly.3/
7.8T total
Nothing unhappy seems to be present in /var/log/rsnapshot:
[03/Sep/2011:00:00:01] require Lchown
[03/Sep/2011:00:00:01] Lchown module loaded successfully
[03/Sep/2011:00:00:01] /usr/bin/rsnapshot sync: started
[03/Sep/2011:00:00:01] Setting locale to POSIX "C"
[03/Sep/2011:00:00:01] echo 4983 > /var/run/rsnapshot.pid
[03/Sep/2011:00:00:01] mkdir -m 0755 -p /var/backups/snapshots/.sync/nas02.local/share/
[03/Sep/2011:00:00:01] /usr/bin/rsync -av --fake-super --delete --numeric-ids --relative --delete-excluded --password-file=/var/backups/nas02_rsync_password_file --stats --human-readable --itemize-changes --log-file=/var/log/rsnapshot_rsync --link-dest=/var/backups/snapshots/hourly.0/nas02.local/share/MD0_DATA/ rsync://rsync@nas02.local/backup-rsync-target /var/backups/snapshots/.sync/nas02.local/share/MD0_DATA/
[03/Sep/2011:00:29:53] touch /var/backups/snapshots/.sync/
or /var/log/rsnapshot_rsync:
2011/09/03 00:00:02 [4985] receiving file list
2011/09/03 00:00:02 [4985] created directory /var/backups/snapshots/.sync/nas02.local/share/MD0_DATA
2011/09/03 00:00:03 [4986] >f..t...... aquota.user
2011/09/03 00:00:03 [4986] >f..t...... .locks/connections.tdb
2011/09/03 00:00:09 [4986] cd..t...... .timemachine/
2011/09/03 00:00:09 [4986] >f..t...... .timemachine/.AppleDB/__db.001
2011/09/03 00:00:09 [4986] >f..t...... .timemachine/.AppleDB/__db.002
--- snip ---
2011/09/03 00:29:52 [4986] Number of files: 2781079
2011/09/03 00:29:52 [4986] Number of files transferred: 248
2011/09/03 00:29:52 [4986] Total file size: 6030.20G bytes
2011/09/03 00:29:52 [4986] Total transferred file size: 1.93G bytes
2011/09/03 00:29:52 [4986] Literal data: 307.82M bytes
2011/09/03 00:29:52 [4986] Matched data: 1.62G bytes
2011/09/03 00:29:52 [4986] File list size: 66.12M
2011/09/03 00:29:52 [4986] File list generation time: 0.334 seconds
2011/09/03 00:29:52 [4986] File list transfer time: 0.000 seconds
2011/09/03 00:29:52 [4986] Total bytes sent: 4.32M
2011/09/03 00:29:52 [4986] Total bytes received: 377.49M
2011/09/03 00:29:52 [4986] sent 4.32M bytes received 377.49M bytes 213.12K bytes/sec
2011/09/03 00:29:52 [4986] total size is 6030.20G speedup is 15793.73
The only other odd symptom seems to be two copies of rsync spawned at the same time during the job; I don't have that available now, but I can provide the process list if that is required.
thanks for any ideas... bt
