Compression error?

Bas van Schaik bas at tuxes.nl
Thu Nov 1 13:17:51 GMT 2007


Hi all,

Sorry, I prefer bottom posting, please scroll down.

> Matt,
>
> Problem seems to have gone away.  Unfortunately (for diagnosis
> problems anyway) the files in question are dynamic and updated nightly.
>
> Will keep an eye out to see if it reoccurs and try to capture.
>
> Regards
>
> /Steve
>
> Matt McCutchen wrote:
>> On 7/19/07, WCSL <rsync at wcsl.net> wrote:
>>> Error received when trying to use rsync -vz on the client
>>>
>>> inflate (token) returned -5
>>> rsync error: error in rsync protocol data stream (code 12) at
>>> token.c(458)
>>> rsync: writefd_unbuffered failed to write 4092 bytes: phase "unknown"
>>> [generator]: Broken pipe (32)
>>> rsync error: error in rsync protocol data stream (code 12) at io.c(909)
>>>
>>> Seems to work fine without compression -z flag omitted.
>>
>> There have been occasional reports of -z getting corrupted in the
>> past, but we've never gotten a reproducible case to investigate and
>> find the underlying problem.  If you run the command repeatedly, does
>> that same error occur every time?  Even better if it still happens
>> with the same files on a different pair of machines.  If so, please
>> send the source and destination files prior to the run to Wayne
>> Davison <wayned at samba.org>, the rsync maintainer, unless they're big
>> and/or private in which case you should discuss other arrangements
>> with him.
>>
>> Matt

I actually have the same problem with transferring large amounts of
files with the "-z" option, but the inflate fails on the same files
every time. Example log snippet (receiving host, which I will call
"server"):
> 2007/11/01 04:59:23 [17567] recv infinity [192.168.0.221] backups
> (infinity)
> tetra-servers/latest/xen_aphrodite/var/lib/mysql/otrs-valintra/article.MYD
> 11272960
> 2007/11/01 04:59:23 [17567] recv infinity [192.168.0.221] backups
> (infinity)
> tetra-servers/latest/xen_aphrodite/var/lib/mysql/otrs-valintra/article.MYI
> 2468864
> 2007/11/01 05:01:09 [17567] inflate (token) returned -5
> 2007/11/01 05:01:09 [17567] rsync error: error in rsync protocol data
> stream (code 12) at token.c(476) [receiver=2.6.9]
> 2007/11/01 05:01:09 [17567] rsync: connection unexpectedly closed
> (45884845 bytes received so far) [generator]
> 2007/11/01 05:01:09 [17567] rsync error: error in rsync protocol data
> stream (code 12) at io.c(453) [generator=2.6.9]

Note that I think that the transfer of
"tetra-servers/latest/xen_aphrodite/var/lib/mysql/otrs-valintra/article.MYI"
did succeed, the inflate error occurs on the next file which isn't
logged. I presumed that this next file is "article_attachment.MYD" which
actually is quite large: about 1.4 gigabytes. This file exists on both
client and server, so it should only be partially transferred. A few
weeks ago I tried to remove the file on the server to force the client
to transfer it entirely, that actually worked and fixed the problem. But
now the problem is back and I felt obliged to report it to the list
since there seem to be more people having the same problem.

Assuming that it was indeed "article_attachment.MYD" which caused the
inflate error, I decided to investigate that file. Client side, this is
the output of "ls -la article_attachment.MYD":
> -rw-rw---- 1 rsync nogroup 1125532216 2007-10-31 22:50
> article_attachment.MYD

And on the server:
> -rw-r----- 1 rsync nogroup 1077162396 2007-11-01 13:14
> article_attachment.MYD

Of course I tried to transfer that file on its own in
verbose-verbose-verbose mode and this is the result:
> $ rsync -atzvvv --compress-level=9 article_attachment.MYD
> --timeout=3600 infinity at dust::tmp/rsync/
> opening tcp connection to dust port 873
> opening connection using --server -vvvlogDtprz --compress-level=9
> --timeout=3600 . tmp/rsync/
>
> Password:
> building file list ...
> [sender] make_file(article_attachment.MYD,*,2)
> done
> send_file_list done
> send_files starting
> send_files(0, article_attachment.MYD)
> send_files mapped article_attachment.MYD of size 1125532216
> calling match_sums article_attachment.MYD
> article_attachment.MYD
> built hash table
> hash search b=32816 len=1125532216
> match at 0 last_match=0 j=0 len=32816 n=0
> (...)
> match at 627409104 last_match=627409104 j=19119 len=32816 n=0
> (...)
> match at 1077119568 last_match=1077119568 j=32823 len=32816 n=0
> rsync: writefd_unbuffered failed to write 16385 bytes [sender]:
> Connection reset by peer (104)
> inflate (token) returned -5
> rsync: connection unexpectedly closed (229801 bytes received so far)
> [sender]
> rsync error: error in rsync protocol data stream (code 12) at
> io.c(453) [sender=2.6.9]
> _exit_cleanup(code=12, file=io.c, line=453): about to call exit(12)
The output was huge, my console got flooded by "match at..." lines, so I
decided only to copy and paste three of them here. The values for 'len'
and 'n' are constant, the value for 'j' increases by one every step and
the other two values gradually increase also with greater steps.
Relevant log snippet of the server side log:
> 2007/11/01 13:15:23 [10684] connect from infinity (192.168.0.221)
> 2007/11/01 13:15:28 [10684] rsync to tmp/rsync/ from infinity at infinity
> (192.168.0.221)
> 2007/11/01 13:15:28 [10684] receiving file list
> 2007/11/01 13:18:23 [10684] inflate (token) returned -5
> 2007/11/01 13:18:23 [10684] rsync error: error in rsync protocol data
> stream (code 12) at token.c(476) [receiver=2.6.9]
> 2007/11/01 13:18:23 [10684] rsync: connection unexpectedly closed (197
> bytes received so far) [generator]
> 2007/11/01 13:18:23 [10684] rsync error: error in rsync protocol data
> stream (code 12) at io.c(453) [generator=2.6.9]

As you can see, the last "match at (...)" line at the client mentions
"1077119568", which actually looks a lot like "1077162396" (the size of
"article_attachment.MYD" on the server). Other files causing similar
problems were also very large (> 1G), also existed both on client and
server and needed a partial transfer.

The execution of a rsync with five "-v" options flooded my console even
more, but didn't provide more details on the actual inflate error. To be
able to reproduce this problem in the future I created copies of both
the client and server "article_attachment.MYD". If needed, I might be
able to supply those two files to a rsync developer, but I will need to
ask permission for that.

This is all the information I have at this moment, please do not
hesitate to ask me for more information when needed. It would be really
nice to finally fix this issue!

Kind regards,

  -- Bas van Schaik


-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 252 bytes
Desc: OpenPGP digital signature
Url : http://lists.samba.org/archive/rsync/attachments/20071101/f1845ee5/signature.bin


More information about the rsync mailing list