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 23e7822eeb4e090eee93256020eaa958faecac7d..a21d81fe1aa994b8b959aa9c1bede74b056eaa14 100644 (file)
--- 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 06410e7f5706c645b27a52131d19e9dd487832d6..14b2536745d8f0c4ceaf8cf16b9684b1a7d81ef7 100644 (file)
--- 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).