rsync - Apr 2005 - Rsync 2.6.4 Multiplexing Overflows when File Name Too Long (cwRsync)

I installed the newly released version of cwRsync today on a few Windows 
machines and have noticed a new problem that I have not seen mentioned 
anywhere.

When syncing to an NT machine used for backups, my rsync client exited 
at the end of the transfer with the following message to standard error:

multiplexing overflow 1:296 [sender]
rsync error: error in rsync protocol data stream (code 12) at io.c(777)

The server daemon logs the following error regarding a file with a name 
that is too long before this error:

2005/04/01 13:01:43 [365] rsync: mkstemp "(very long file name 
removed).000679" (in backup) failed: File name too long (91)
2005/04/01 13:01:43 [365] (various other files being backed up, all with 
same timestamp)
2005/04/01 13:01:43 [365] rsync: writefd_unbuffered failed to write 12 
bytes: phase "unknown" [generator]: Connection reset by peer (104)
2005/04/01 13:01:43 [365] rsync error: error in rsync protocol data 
stream (code 12) at io.c(1080)

There is no mention of this long file name error in the standard error 
or standard out of the client rsync process.  Incidentally, this is an 
error I have seen for a long time with previous versions of rsync, but 
it was always visible in the standard error from the client.  Although 
the transfer appears to have completed (i.e. everything has syncs up as 
expected), the client then exists without printing the statistics it 
normally does (it is invoked with --stats).  In addition, the client 
actually exits with a status code of 3072, not 12 as indicated by the 
standard error message.  The binary-aware reader may notice that this is 
actually 12 * 256.

Interestingly, when I manually copied the offending long-named file to 
the server and reran the rsync session, the program terminated 
successfully with the normal "some files could not be transferred" 
status I am used to.  This was also multiplied by 256 in the client 
rsync process exit code to become 5888 instead of 23.  I'm sure the exit 
code anomaly is not related to the multiplexing error I am experiencing, 
which is the main problem I am having.

So far this observation has been made on one out of one clients that I 
have tested.  I was able to repeat this error several times on this 
machine before I discovered the message in the server log pointing me to 
the long file name problem.  I am running a test from another client to 
duplicate this problem, but this process will not finish for at least 
another half hour.  I will report back when I know if this happens on 
that system as well.

Otherwise, I am a very happy rsync user of many years.  Thanks for a 
great example of what FOSS can accomplish.

-Ben : )

Benjamin Watkins wrote:
> So far this observation has been made on one out of one clients that I 
> have tested.  I was able to repeat this error several times on this 
> machine before I discovered the message in the server log pointing me 
> to the long file name problem.  I am running a test from another 
> client to duplicate this problem, but this process will not finish for 
> at least another half hour.  I will report back when I know if this 
> happens on that system as well.

I can now confirm that this seems to happen whenever there is a long 
file name error.  This appears to cause a corruption in the protocol stream.

-Ben : )

Benjamin Watkins wrote:
> Benjamin Watkins wrote:
>
>> So far this observation has been made on one out of one clients that 
>> I have tested.  I was able to repeat this error several times on this 
>> machine before I discovered the message in the server log pointing me 
>> to the long file name problem.  I am running a test from another 
>> client to duplicate this problem, but this process will not finish 
>> for at least another half hour.  I will report back when I know if 
>> this happens on that system as well.
>
>
>
> I can now confirm that this seems to happen whenever there is a long 
> file name error.  This appears to cause a corruption in the protocol 
> stream.
>
> -Ben : )
>
Testing with another set of machines further confirms the error with a 
twist.  This time no files are transferred before the program exits 
(still with an exit code of 3072).

The options I use when rsyncing files are:

(First two tests reported, workstations 1 and 2 to server 1)
-av --delete --delete-excluded --stats --ignore-errors --force 
--exclude-from=exclude.txt

(Most recent test, syncing server 1 to offsite server 2)
-av --delete --partial --stats --ignore-errors --force

These options are basically identical with the exception of the use of 
an excluded file in the first example.

Is anyone able to replicate these problems?  I will need to switch back 
to rsync 2.6.3 until this is resolved.  With this version I experienced 
occasional failures on large files, despite the fact that I am not using 
compression.  I did not bother to report this as version 2.6.4 was 
released shortly after I noticed the problem.  I was hoping that one of 
the following bug fixes would have happened to address this issue, 
though neither situation applies to me.  The symptoms are similar, however.
> - If an rsync daemon specified "dont compress = ..." for a file
and
> the client tried to specify --compress, the libz code was not handling 
> a compression level of 0 properly. This could cause a transfer failure 
> if the block-size for a file was large enough (e.g. rsync might have 
> exited with an error for large files).
>
> - Fixed a bug that would sometimes surface when using --compress and 
> sending a file with a block-size larger than 64K (either manually 
> specified, or computed due to the file being really large). Prior 
> versions of rsync would sometimes fail to decompress the data 
> properly, and thus the transferred file would fail its verification. 
I am not specifying compression either way for any of the clients or the 
daemons, so neither of these bugs should have been affecting me.

Hopefully someone else can confirm these problems (2.6.3, 2.6.4, or 
both), or possibly suggest a solution.

-Ben : )

On Fri, Apr 01, 2005 at 03:54:38PM -0500, Benjamin Watkins
wrote:
> multiplexing overflow 1:296 [sender]
This indicates that there is an error message arriving (1) that has a
length of 296 bytes, but this is too long for the "line" buffer in
readfd_unbuffered().  I changed the length of this buffer from 1024
bytes to MAXPATHLEN+1 because it was too short for receiving info/error
messages for really long file names (since a normal system has a
MAXPATHLEN that is closer to 4 KB).  (Hmm, is MAXPATHLEN really supposed
to be that short under Cygwin?  Surprising...)

Anyway, the simple solution is to just make the line buffer larger.
I'll attach a patch.
> In addition, the client actually exits with a status code of 3072, not
> 12 as indicated by the standard error message.
That sounds like a problem with your shell or the Cygwin environment
because rsync exits with the right error code under Linux.

..wayne..
-------------- next part --------------
--- io.c	4 Apr 2005 00:48:39 -0000	1.167
+++ io.c	4 Apr 2005 01:07:10 -0000
@@ -706,7 +706,11 @@ static int readfd_unbuffered(int fd, cha
 	static size_t remaining;
 	static size_t iobuf_in_ndx;
 	int tag, ret = 0;
-	char line[MAXPATHLEN+1];
+#if MAXPATHLEN < 4096
+	char line[4096+1024];
+#else
+	char line[MAXPATHLEN+1024];
+#endif
 
 	if (!iobuf_in || fd != sock_f_in)
 		return read_timeout(fd, buf, len);