rsync - Jan 2009 - Rsync error 'unexpected tag 93' when --log-file= parameter is present and run from crontab

L.S.

I hope someone can enlighten me on the following phenomenon.

When I run rsync (3.0.2 or 3.0.4) from a (SH) script as follows:

rsync -vrpth --stats --progress --log-file=/nslu2/rsync.log
--log-file-format="%t %i %n%L" --include-from=/nslu2/rsync-files
/share/hdd/data/public/Ernst/ 192.168.1.69::rsync-nslu2

All is well; it works fine. Log file is created, both client (NSLU2 from
LinkSys) and server (here 192.168.1.69, a small embedded linux box) do not
report any errors. Copy is performed flawlessly.

However, if I include the same line in crontab, when executed the server reports
an unexpected tag 93 and protocol errors in io.c at line 1169, which is the
default handler for communication errors. This *only* happens when the
--log-file=/nslu2/rsync.log line is present. If I change the line in crontab
from the above to:

rsync -vrpth --stats --progress --include-from=/nslu2/rsync-files
/share/hdd/data/public/Ernst/ 192.168.1.69::rsync-nslu2 > /nslu2/rsync.log

(i.e. omit the --log-file= parameter and generate a log by redirection)

all is well again. The moment I add the --log-file= parameter, the error pops up
again.

The weird thing is that a search with Google for 'unexpected tag'
generates a lot of links but no links whatsoever for 'unexpected tag
93', so I must be the first to report this kind of protocol error.

I tried --blocking-io and --no-blocking-io but that didn't help. I
recompiled the server rsync package and tried both 3.0.2 and 3.0.4 to no avail.
At the client side I used both 3.0.4 and 3.0.5. It is hard to tell which side
generates the error though. The error message appears in /var/log/messages at
the server's end. The client's syslog does not report an error, it only
reports that cron has started rsync.

I tried calling rsync (with the --log-file parameter present) from a script
within crontab instead of calling it directly; same result: it only works when I
remove the --log-file= parameter.

I can live with the latter option since it also generates a log file by
redirection of rsync's output but I prefer the --log-file= version since
that allows me to change the log format.

Any clues?

Thanks in advance!

Ernst

BTW; how can an error such as this be 'unexpected'? The tag '93'
must mean something? Why can't the error handler be more specific about what
caused this? At least some information in a client-server environment on which
side generated the protocol error would help enormously!
-------------- next part --------------
HTML attachment scrubbed and removed

I have some general remarks about the problem; I hope Wayne will have
more specific ideas on how to debug it.

On Sun, 2009-01-11 at 13:33 +0100, Ernst J. Oud wrote:
> rsync -vrpth --stats --progress --log-file=/nslu2/rsync.log
> --log-file-format="%t %i %n%L"
> --include-from=/nslu2/rsync-files /share/hdd/data/public/Ernst/
> 192.168.1.69::rsync-nslu2
> However, if I include the same line in crontab, when executed the
> server reports an unexpected tag 93 and protocol errors in io.c at
> line 1169, which is the default handler for communication errors. This
> *only* happens when the --log-file=/nslu2/rsync.log line is present.
>  BTW; how can an error such as this be 'unexpected'? The tag
'93' must
> mean something? Why can't the error handler be more specific about
> what caused this? At least some information in a client-server
> environment on which side generated the protocol error would help
> enormously!
 
The rsync protocol consists of messages of different types, and each
type is identified by a tag number.  The error means that an rsync got a
message with tag number 93, which is not one of the valid tags whose
meaning is defined by the protocol.  This is generally a result of the
protocol somehow getting out of sync. 
> It is hard to tell which side generates the error though. The error
> message appears in /var/log/messages at the server's end. The
client's
> syslog does not report an error, it only reports that cron has started
> rsync.
The error should have a [client] or [server] prefix that tells you which
side detected the error.  That doesn't, however, reveal which side is at
fault for the protocol getting out of sync.
> I can live with the latter option since it also generates a log file
> by redirection of rsync's output but I prefer the --log-file= version
> since that allows me to change the log format.
You should be able to change the stdout format with --out-format.

-- 
Matt