From: Wayne Davison <wayned@samba.org>
Date: Wed, 21 Dec 2011 16:30:07 +0000 (-0800)
Subject: Improve the handling of verbose/debug messages
X-Git-Tag: v3.1.0pre1~57
X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=1a2704512a6f6c9bf267042ff8beb50a24e1d057;p=thirdparty%2Frsync.git

Improve the handling of verbose/debug messages

The sender no longer allows a filelist to be sent in the middle of
parsing an incoming message, so that the directory sending doesn't block
all further input reading.  The generator no longer allows recursive
reading of info/error messages when it is waiting for the message buffer
to flush.  This avoids a stack overflow when lots of messages are coming
from the receiver and the sender is not reading things quickly enough.
The I/O code now avoids sending debug messages that could mess up the
I/O buffer it was in the middle of tweaking.  This fixes an infinite
loop in reduce_iobuf_size() with high levels of debug enabled.  Several
I/O-related messages were changed to output only when --msgs2stderr is
enabled.
---

diff --git a/io.c b/io.c
index 23e7822e..a21d81fe 100644
--- a/io.c
+++ b/io.c
@@ -480,7 +480,8 @@ static void forward_filesfrom_data(void)
 void reduce_iobuf_size(xbuf *out, size_t new_size)
 {
 	if (new_size < out->size) {
-		if (DEBUG_GTE(IO, 4)) {
+		/* Avoid weird buffer interactions by only outputting this to stderr. */
+		if (msgs2stderr && DEBUG_GTE(IO, 4)) {
 			const char *name = out == &iobuf.out ? "iobuf.out"
 					 : out == &iobuf.msg ? "iobuf.msg"
 					 : NULL;
@@ -497,7 +498,8 @@ void restore_iobuf_size(xbuf *out)
 {
 	if (IOBUF_WAS_REDUCED(out->size)) {
 		size_t new_size = IOBUF_RESTORE_SIZE(out->size);
-		if (DEBUG_GTE(IO, 4)) {
+		/* Avoid weird buffer interactions by only outputting this to stderr. */
+		if (msgs2stderr && DEBUG_GTE(IO, 4)) {
 			const char *name = out == &iobuf.out ? "iobuf.out"
 					 : out == &iobuf.msg ? "iobuf.msg"
 					 : NULL;
@@ -574,7 +576,7 @@ static char *perform_io(size_t needed, int flags)
 			exit_cleanup(RERR_PROTOCOL);
 		}
 
-		if (DEBUG_GTE(IO, 3)) {
+		if (msgs2stderr && DEBUG_GTE(IO, 3)) {
 			rprintf(FINFO, "[%s] perform_io(%ld, %sinput)\n",
 				who_am_i(), (long)needed, flags & PIO_CONSUME_INPUT ? "consume&" : "");
 		}
@@ -588,7 +590,7 @@ static char *perform_io(size_t needed, int flags)
 			exit_cleanup(RERR_PROTOCOL);
 		}
 
-		if (DEBUG_GTE(IO, 3)) {
+		if (msgs2stderr && DEBUG_GTE(IO, 3)) {
 			rprintf(FINFO, "[%s] perform_io(%ld, outroom) needs to flush %ld\n",
 				who_am_i(), (long)needed,
 				iobuf.out.len + needed > iobuf.out.size
@@ -604,7 +606,7 @@ static char *perform_io(size_t needed, int flags)
 			exit_cleanup(RERR_PROTOCOL);
 		}
 
-		if (DEBUG_GTE(IO, 3)) {
+		if (msgs2stderr && DEBUG_GTE(IO, 3)) {
 			rprintf(FINFO, "[%s] perform_io(%ld, msgroom) needs to flush %ld\n",
 				who_am_i(), (long)needed,
 				iobuf.msg.len + needed > iobuf.msg.size
@@ -613,7 +615,7 @@ static char *perform_io(size_t needed, int flags)
 		break;
 
 	case 0:
-		if (DEBUG_GTE(IO, 3))
+		if (msgs2stderr && DEBUG_GTE(IO, 3))
 			rprintf(FINFO, "[%s] perform_io(%ld, %d)\n", who_am_i(), (long)needed, flags);
 		break;
 
@@ -671,7 +673,7 @@ static char *perform_io(size_t needed, int flags)
 					SIVAL(iobuf.out.buf + iobuf.raw_data_header_pos, 0,
 					      ((MPLEX_BASE + (int)MSG_DATA)<<24) + iobuf.out.len - 4);
 
-					if (DEBUG_GTE(IO, 1)) {
+					if (msgs2stderr && DEBUG_GTE(IO, 1)) {
 						rprintf(FINFO, "[%s] send_msg(%d, %ld)\n",
 							who_am_i(), (int)MSG_DATA, (long)iobuf.out.len - 4);
 					}
@@ -732,7 +734,7 @@ static char *perform_io(size_t needed, int flags)
 		}
 
 		if (extra_flist_sending_enabled) {
-			if (file_total - file_old_total < MAX_FILECNT_LOOKAHEAD)
+			if (file_total - file_old_total < MAX_FILECNT_LOOKAHEAD && IN_MULTIPLEXED_AND_READY)
 				tv.tv_sec = 0;
 			else {
 				extra_flist_sending_enabled = False;
@@ -1562,8 +1564,11 @@ static void read_a_msg(void)
 			exit_cleanup(RERR_STREAMIO);
 		}
 		raw_read_buf(data, msg_bytes);
-		iobuf.in_multiplexed = 1;
+		/* We don't set in_multiplexed value back to 1 before writing this message
+		 * because the write might loop back and read yet another message, over and
+		 * over again, while waiting for room to put the message in the msg buffer. */
 		rwrite((enum logcode)tag, data, msg_bytes, !am_generator);
+		iobuf.in_multiplexed = 1;
 		if (first_message) {
 			if (list_only && !am_sender && tag == 1 && msg_bytes < sizeof data) {
 				data[msg_bytes] = '\0';
diff --git a/rsync.yo b/rsync.yo
index 06410e7f..14b25367 100644
--- a/rsync.yo
+++ b/rsync.yo
@@ -535,8 +535,7 @@ reject your attempts at fine-grained control (if one or more flags needed
 to be send to the server and the server was too old to understand them).
 
 dit(bf(--debug=FLAGS))
-This option lets you have fine-grained control over the
-debug
+This option lets you have fine-grained control over the debug
 output you want to see.  An individual flag name may be followed by a level
 number, with 0 meaning to silence that output, 1 being the default output
 level, and higher numbers increasing the output of that flag (for those
@@ -548,6 +547,9 @@ are added for each increase in the verbose level.  Some examples:
 verb(    rsync -avvv --debug=none src/ dest/
     rsync -avA --del --debug=del2,acl src/ dest/ )
 
+Note that some debug messages will only be output when bf(--msgs2stderr) is
+specified, especially those pertaining to I/O and buffer debugging.
+
 This option was added to 3.1.0, so an older rsync on the server side might
 reject your attempts at fine-grained control (if one or more flags needed
 to be send to the server and the server was too old to understand them).