rsync - Dec 2008 - rsync Failure

Hello All:

I'm having an issue with rsync in that it recently (11/29/2008)  
started to crash during a daily cron job backup.  Below is some info  
on how rsync is being used to backup our servers.

Version:
	2.6.9
Execution:
	Called daily via a wrapper script, and up until about 2 weeks ago,  
ran fine.  The wrapper script just loops through a series servers to  
backup.  The first server succeeds but the second fails.    
Interesting, this server that does the backing up, is actually backed  
up by another server, which is not having any issues (leads me to  
believe that this is not an ssh connection issue).

Command Used:

	rsync -vvv -a -e "ssh -i /etc/backup/some_id.rsa" --delete --numeric-
ids --exclude-from=/etc/backup/exclude_list --log-file=/usr/local/bin/ 
rsync2.log --link-dest=../$LASTBACKUPDIR root@$HOSTNAME:/ $NEWBACKUPDIR

I've added the -vvv and --log-file options while trying to debug this  
issue.

Issue:

	rsync runs for while, but then it freezes up.  Sits in this state for  
about 15 minutes until the connection is closed (I'm guessing ssh is  
timing out due to inactivity).

Here are some of the exerts from the log file for various server  
failures:

Server A:

2008/12/01 16:59:27 [7453] send_files mapped //home/dgranzow/om51/ 
cygdrive/d/server_assistant/drivers/r57338/bcmsm.sys of size 110131
2
2008/12/01 16:59:27 [7453] recv_files(home/dgranzow/om51/cygdrive/d/ 
server_assistant/drivers/r57338/bcmsm.sys)
2008/12/01 16:59:27 [7453] calling match_sums //home/dgranzow/om51/ 
cygdrive/d/server_assistant/drivers/r57338/bcmsm.sys
2008/12/01 17:15:35 [7444] rsync: writefd_unbuffered failed to write  
4092 bytes [generator]: Broken pipe (32)
2008/12/01 17:15:35 [7453] rsync: connection unexpectedly closed  
(448450920 bytes received so far) [receiver]
2008/12/01 17:15:35 [7444] rsync error: unexplained error (code 255)  
at io.c(1122) [generator=2.6.9]
2008/12/01 17:15:35 [7444] _exit_cleanup(code=12, file=io.c,  
line=1122): about to call exit(255)
2008/12/01 17:15:35 [7453] rsync: connection unexpectedly closed  
(448450920 bytes received so far) [receiver]


Server B:

2008/12/03 16:08:35 [26912] sender finished //var/log/httpd/ 
ssl_request_log.4
2008/12/03 16:08:35 [26912] send_files(145596,//var/log/httpd/stage- 
rewrite_log)
2008/12/03 16:08:35 [26912] send_files mapped //var/log/httpd/stage- 
rewrite_log of size 38039011
2008/12/03 16:08:35 [26912] recv_files(var/log/httpd/stage-rewrite_log)
2008/12/03 16:08:35 [26912] calling match_sums //var/log/httpd/stage- 
rewrite_log
2008/12/03 16:25:24 [26912] rsync: connection unexpectedly closed  
(218901485 bytes received so far) [receiver]
2008/12/03 16:25:24 [26912] rsync error: error in rsync protocol data  
stream (code 12) at io.c(453) [receiver=2.6.9]
2008/12/03 16:25:24 [26912] _exit_cleanup(code=12, file=io.c,  
line=453): about to call exit(12)
2008/12/03 16:25:24 [26910] rsync: connection unexpectedly closed  
(2929535 bytes received so far) [generator]
2008/12/03 16:25:24 [26910] rsync error: unexplained error (code 255)  
at io.c(453) [generator=2.6.9]
2008/12/03 16:25:24 [26910] _exit_cleanup(code=12, file=io.c,  
line=453): about to call exit(255)


Server C:


2008/12/03 17:02:36 [27198] send_files(113183,//usr/share/terminfo/w/ 
wy60-AT)
2008/12/03 17:02:36 [27198] send_files mapped //usr/share/terminfo/w/ 
wy60-AT of size 1251
2008/12/03 17:02:36 [27198] recv_files(usr/share/terminfo/w/wy60-AT)
2008/12/03 17:02:36 [27198] calling match_sums //usr/share/terminfo/w/ 
wy60-AT
2008/12/03 17:02:36 [27198] sending file_sum
2008/12/03 17:18:29 [27195] rsync: writefd_unbuffered failed to write  
4092 bytes [generator]: Broken pipe (32)
2008/12/03 17:18:29 [27198] rsync: connection unexpectedly closed  
(202855385 bytes received so far) [receiver]
2008/12/03 17:18:29 [27195] rsync error: unexplained error (code 255)  
at io.c(1122) [generator=2.6.9]
2008/12/03 17:18:29 [27198] rsync error: error in rsync protocol data  
stream (code 12) at io.c(453) [receiver=2.6.9]
2008/12/03 17:18:29 [27195] _exit_cleanup(code=12, file=io.c,  
line=1122): about to call exit(255)
2008/12/03 17:18:29 [27198] _exit_cleanup(code=12, file=io.c,  
line=453): about to call exit(12)


I can post more log file printouts if needed.   I did run strace, but  
it didn't appear to be of much use.  I'm not strace expert, so any  
suggestions on how to utilize that better to debug this would also be  
useful.

Any help or suggestions on where to look next to debug this would be  
greatly appreciated.

Thanks.

sg

On Thu, 2008-12-04 at 16:50 -0500, Shawn Geraghty wrote:
> I'm having an issue with rsync in that it recently (11/29/2008)  
> started to crash during a daily cron job backup.  Below is some info  
> on how rsync is being used to backup our servers.
> 
> Version:
> 	2.6.9
Please try the latest stable version of rsync, 3.0.4, if at all
possible.
> Execution:
> 	Called daily via a wrapper script, and up until about 2 weeks ago,  
> ran fine.  The wrapper script just loops through a series servers to  
> backup.  The first server succeeds but the second fails.    
> Interesting, this server that does the backing up, is actually backed  
> up by another server, which is not having any issues (leads me to  
> believe that this is not an ssh connection issue).
I'm not clear on how you reached this conclusion.
> Command Used:
> 
> 	rsync -vvv -a -e "ssh -i /etc/backup/some_id.rsa" --delete
--numeric-
> ids --exclude-from=/etc/backup/exclude_list --log-file=/usr/local/bin/ 
> rsync2.log --link-dest=../$LASTBACKUPDIR root@$HOSTNAME:/ $NEWBACKUPDIR
> 
> I've added the -vvv and --log-file options while trying to debug this  
> issue.
> 
> Issue:
> 
> 	rsync runs for while, but then it freezes up.  Sits in this state for  
> about 15 minutes until the connection is closed (I'm guessing ssh is  
> timing out due to inactivity).
Please send the last 50 lines or so of the strace of each of the three
rsync processes (one on the sending side and the other two on the
receiving side) so we can see how they are hanging.
> Server B:
> 
> 2008/12/03 16:08:35 [26912] sender finished //var/log/httpd/ 
> ssl_request_log.4
> 2008/12/03 16:08:35 [26912] send_files(145596,//var/log/httpd/stage- 
> rewrite_log)
> 2008/12/03 16:08:35 [26912] send_files mapped //var/log/httpd/stage- 
> rewrite_log of size 38039011
> 2008/12/03 16:08:35 [26912] recv_files(var/log/httpd/stage-rewrite_log)
> 2008/12/03 16:08:35 [26912] calling match_sums //var/log/httpd/stage- 
> rewrite_log
> 2008/12/03 16:25:24 [26912] rsync: connection unexpectedly closed  
> (218901485 bytes received so far) [receiver]
> 2008/12/03 16:25:24 [26912] rsync error: error in rsync protocol data  
> stream (code 12) at io.c(453) [receiver=2.6.9]
> 2008/12/03 16:25:24 [26912] _exit_cleanup(code=12, file=io.c,  
> line=453): about to call exit(12)
> 2008/12/03 16:25:24 [26910] rsync: connection unexpectedly closed  
> (2929535 bytes received so far) [generator]
> 2008/12/03 16:25:24 [26910] rsync error: unexplained error (code 255)  
> at io.c(453) [generator=2.6.9]
> 2008/12/03 16:25:24 [26910] _exit_cleanup(code=12, file=io.c,  
> line=453): about to call exit(255)