rsync - Jan 2011 - Protocol stream error on extended attribute, silent failure to copy all attributes

I'm using rsync 3.0.7 on Mac OS X 10.6, compiled according to Mike
Bombich's instructions at http://www.bombich.com/rsync.html. Rsync
repeatedly exits with a protocol data stream error when trying to copy
some com.apple.FinderInfo extended attributes. While testing this issue,
I found that rsync is not actually copying all extended attributes even
when there is no error message. I'm using a folder of fonts as an
example, but I have experienced the protocol error when copying other
data. This seems like a huge bug, and in my experience those often turn
out to be operator error. Apologies if I waste anyone's time.

In this example, I'm using rsync to make a copy from scratch of the
source data: rsync307 -aX --delete Licensed\ Fonts /Volumes/Storage/

I repeatedly get this error:

[sender] internal abbrev error on Licensed Fonts/Postscript/bradley
(com.apple.FinderInfo, len=32)!
rsync error: error in rsync protocol data stream (code 12) at
xattrs.c(636) [sender=3.0.7]

If you repeat the command a few times, sometimes the error is:

rsync: writefd_unbuffered failed to write 4 bytes to socket [sender]:
Broken pipe (32)
rsync: connection unexpectedly closed (16827 bytes received so far)
[sender]
rsync error: error in rsync protocol data stream (code 12) at io.c(601)
[sender=3.0.7]

In all my testing, I have only seen the error occur with a
com.apple.FinderInfo attribute, and only for a directory.

Running rsync with sudo makes no difference.

The system has no problem reading the extended attribute from the source
folder, or using the xattr command to write it to the target folder:

matt$ xattr -l Licensed\ Fonts/Postscript/bradley/
com.apple.FinderInfo:
00000000  03 99 01 5D 04 7C 02 2F 07 A0 5A 50 00 01 02 07
|...].|./..ZP....|
00000010  FF F8 FF F0 C3 40 00 00 00 00 00 00 00 01 6C 28
|..... at ........l(|
00000020
matt$ xattr -l /Volumes/Storage/Licensed\ Fonts/Postscript/bradley/
matt$ xattr -wx com.apple.FinderInfo "`xattr -px com.apple.FinderInfo
Licensed\ Fonts/Postscript/bradley/`" /Volumes/Storage/Licensed\
Fonts/Postscript/bradley/
matt$ xattr -l /Volumes/Storage/Licensed\ Fonts/Postscript/bradley/
com.apple.FinderInfo:
00000000  03 99 01 5D 04 7C 02 2F 07 A0 5A 50 00 01 02 07
|...].|./..ZP....|
00000010  FF F8 FF F0 C3 40 00 00 00 00 00 00 00 01 6C 28
|..... at ........l(|
00000020

After manually setting the extended attribute, the rsync command
completes without error messages. The process is repeatable, always
choking on the bradley folder.

After rsync completed without error messages, I compared the sizes of
source and copy:

matt$ du -k -d1 /Installers/Licensed\ Fonts/
245196    /Installers/Licensed Fonts//Adobe Font Folio - OpenType
Edition
51800    /Installers/Licensed Fonts//OpenType
256756    /Installers/Licensed Fonts//Postscript
43308    /Installers/Licensed Fonts//TrueType
598692    /Installers/Licensed Fonts/
matt$ du -k -d1 /Volumes/Storage/Licensed\ Fonts/
245196    /Volumes/Storage/Licensed Fonts//Adobe Font Folio - OpenType
Edition
51800    /Volumes/Storage/Licensed Fonts//OpenType
246540    /Volumes/Storage/Licensed Fonts//Postscript
38528    /Volumes/Storage/Licensed Fonts//TrueType
583696    /Volumes/Storage/Licensed Fonts/

My understanding is that the sizes should match. The number of items in
each is the same:

matt$ du -a /Installers/Licensed\ Fonts/ | wc -l
   11916
matt$ du -a /Volumes/Storage/Licensed\ Fonts/ | wc -l
   11916

I saved the output of 'du -a' for source and copy, then ran a diff.
There are hundreds of differences, and it appears that many extended
attributes were not copied. Here's a typical example:

matt$ ls -lh Licensed\ Fonts/TrueType/CCZoinks/CCZoinks.t1 
-rwx------@ 1 matt  matt     0B Jul 16  1999 Licensed
Fonts/TrueType/CCZoinks/CCZoinks.t1
matt$ ls -lh Licensed\
Fonts/TrueType/CCZoinks/CCZoinks.t1/..namedfork/rsrc
-rwx------  1 matt  matt   9.5K Jul 16  1999 Licensed
Fonts/TrueType/CCZoinks/CCZoinks.t1/..namedfork/rsrc

matt$ ls -lh /Volumes/Storage/Licensed\
Fonts/TrueType/CCZoinks/CCZoinks.t1 
-rwx------@ 1 matt  matt     0B Jul 16  1999 /Volumes/Storage/Licensed
Fonts/TrueType/CCZoinks/CCZoinks.t1
matt$ ls -lh /Volumes/Storage/Licensed\
Fonts/TrueType/CCZoinks/CCZoinks.t1/..namedfork/rsrc
-rwx------  1 matt  matt     1B Jul 16  1999 /Volumes/Storage/Licensed
Fonts/TrueType/CCZoinks/CCZoinks.t1/..namedfork/rsrc

The file is actually a PostScript Type 1 font, where all the content is
in the resource fork. Rsync created a com.apple.ResourceFork attribute
on the new file, but the attribute is empty.

After this discovery, I ran my original rsync command again, then
checked sizes:

matt$ du -kd1 /Volumes/Storage/Licensed\ Fonts/
245196    /Volumes/Storage/Licensed Fonts//Adobe Font Folio - OpenType
Edition
51800    /Volumes/Storage/Licensed Fonts//OpenType
254488    /Volumes/Storage/Licensed Fonts//Postscript
42216    /Volumes/Storage/Licensed Fonts//TrueType
595332    /Volumes/Storage/Licensed Fonts/

More data was copied, but it's still missing things. Overall, it took 6
runs of the same rsync command to produce a copy that's the same size as
the original.

Is this a bug?

Matt

> I'm using rsync 3.0.7 on Mac OS X 10.6, compiled according to Mike
> Bombich's instructions at http://www.bombich.com/rsync.html. Rsync
> repeatedly exits with a protocol data stream error when trying to copy
> some com.apple.FinderInfo extended attributes. While testing this issue,
> I found that rsync is not actually copying all extended attributes even
> when there is no error message. I'm using a folder of fonts as an
> example, but I have experienced the protocol error when copying other
> data. This seems like a huge bug, and in my experience those often turn
> out to be operator error. Apologies if I waste anyone's time.
> 
> In this example, I'm using rsync to make a copy from scratch of the
> source data: rsync307 -aX --delete Licensed\ Fonts /Volumes/Storage/
> 
> I repeatedly get this error:
> 
> [sender] internal abbrev error on Licensed Fonts/Postscript/bradley
> (com.apple.FinderInfo, len=32)!
> rsync error: error in rsync protocol data stream (code 12) at
> xattrs.c(636) [sender=3.0.7]
> 
> If you repeat the command a few times, sometimes the error is:
> 
> rsync: writefd_unbuffered failed to write 4 bytes to socket [sender]:
> Broken pipe (32)
> rsync: connection unexpectedly closed (16827 bytes received so far)
> [sender]
> rsync error: error in rsync protocol data stream (code 12) at io.c(601)
> [sender=3.0.7]
> 
> In all my testing, I have only seen the error occur with a
> com.apple.FinderInfo attribute, and only for a directory.
> 
> Running rsync with sudo makes no difference.
> 
> The system has no problem reading the extended attribute from the source
> folder, or using the xattr command to write it to the target folder:
> 
> matt$ xattr -l Licensed\ Fonts/Postscript/bradley/
> com.apple.FinderInfo:
> 00000000  03 99 01 5D 04 7C 02 2F 07 A0 5A 50 00 01 02 07
> |...].|./..ZP....|
> 00000010  FF F8 FF F0 C3 40 00 00 00 00 00 00 00 01 6C 28
> |..... at ........l(|
> 00000020
> matt$ xattr -l /Volumes/Storage/Licensed\ Fonts/Postscript/bradley/
> matt$ xattr -wx com.apple.FinderInfo "`xattr -px com.apple.FinderInfo
> Licensed\ Fonts/Postscript/bradley/`" /Volumes/Storage/Licensed\
> Fonts/Postscript/bradley/
> matt$ xattr -l /Volumes/Storage/Licensed\ Fonts/Postscript/bradley/
> com.apple.FinderInfo:
> 00000000  03 99 01 5D 04 7C 02 2F 07 A0 5A 50 00 01 02 07
> |...].|./..ZP....|
> 00000010  FF F8 FF F0 C3 40 00 00 00 00 00 00 00 01 6C 28
> |..... at ........l(|
> 00000020
> 
> After manually setting the extended attribute, the rsync command
> completes without error messages. The process is repeatable, always
> choking on the bradley folder.
> 
> After rsync completed without error messages, I compared the sizes of
> source and copy:
> 
> matt$ du -k -d1 /Installers/Licensed\ Fonts/
> 245196    /Installers/Licensed Fonts//Adobe Font Folio - OpenType
> Edition
> 51800    /Installers/Licensed Fonts//OpenType
> 256756    /Installers/Licensed Fonts//Postscript
> 43308    /Installers/Licensed Fonts//TrueType
> 598692    /Installers/Licensed Fonts/
> matt$ du -k -d1 /Volumes/Storage/Licensed\ Fonts/
> 245196    /Volumes/Storage/Licensed Fonts//Adobe Font Folio - OpenType
> Edition
> 51800    /Volumes/Storage/Licensed Fonts//OpenType
> 246540    /Volumes/Storage/Licensed Fonts//Postscript
> 38528    /Volumes/Storage/Licensed Fonts//TrueType
> 583696    /Volumes/Storage/Licensed Fonts/
> 
> My understanding is that the sizes should match. The number of items in
> each is the same:
> 
> matt$ du -a /Installers/Licensed\ Fonts/ | wc -l
>   11916
> matt$ du -a /Volumes/Storage/Licensed\ Fonts/ | wc -l
>   11916
> 
> I saved the output of 'du -a' for source and copy, then ran a diff.
> There are hundreds of differences, and it appears that many extended
> attributes were not copied. Here's a typical example:
> 
> matt$ ls -lh Licensed\ Fonts/TrueType/CCZoinks/CCZoinks.t1 
> -rwx------@ 1 matt  matt     0B Jul 16  1999 Licensed
> Fonts/TrueType/CCZoinks/CCZoinks.t1
> matt$ ls -lh Licensed\
> Fonts/TrueType/CCZoinks/CCZoinks.t1/..namedfork/rsrc
> -rwx------  1 matt  matt   9.5K Jul 16  1999 Licensed
> Fonts/TrueType/CCZoinks/CCZoinks.t1/..namedfork/rsrc
> 
> matt$ ls -lh /Volumes/Storage/Licensed\
> Fonts/TrueType/CCZoinks/CCZoinks.t1 
> -rwx------@ 1 matt  matt     0B Jul 16  1999 /Volumes/Storage/Licensed
> Fonts/TrueType/CCZoinks/CCZoinks.t1
> matt$ ls -lh /Volumes/Storage/Licensed\
> Fonts/TrueType/CCZoinks/CCZoinks.t1/..namedfork/rsrc
> -rwx------  1 matt  matt     1B Jul 16  1999 /Volumes/Storage/Licensed
> Fonts/TrueType/CCZoinks/CCZoinks.t1/..namedfork/rsrc
> 
> The file is actually a PostScript Type 1 font, where all the content is
> in the resource fork. Rsync created a com.apple.ResourceFork attribute
> on the new file, but the attribute is empty.
> 
> After this discovery, I ran my original rsync command again, then
> checked sizes:
> 
> matt$ du -kd1 /Volumes/Storage/Licensed\ Fonts/
> 245196    /Volumes/Storage/Licensed Fonts//Adobe Font Folio - OpenType
> Edition
> 51800    /Volumes/Storage/Licensed Fonts//OpenType
> 254488    /Volumes/Storage/Licensed Fonts//Postscript
> 42216    /Volumes/Storage/Licensed Fonts//TrueType
> 595332    /Volumes/Storage/Licensed Fonts/
> 
> More data was copied, but it's still missing things. Overall, it took 6
> runs of the same rsync command to produce a copy that's the same size
as
> the original.
> 
> Is this a bug?


Recently, a user posted the following rsync error to the LBackup mailing list : 
> "rsync: writefd_unbuffered failed to write 4 bytes to socket [sender]:
Broken pipe (32)
> rsync: connection unexpectedly closed (3225054 bytes received so far)
[sender]
> rsync error: error in rsync protocol data stream (code 12) at io.c(601)
[sender=3.0.7]"
> 
> Can anyone tell me what it means, why it would occur and most importantly
how to fix it.
In their case the destination volume disk was running out of space. However, for
some reason rsync was not reporting this error as I would expect.

A link to this thread on the LBackup mailing is available below :
 http://tinyurl.com/lbackup-discussion-diskfull

I am in the process of attempting to reproduce this error when the disk is full.
During testing I have cared out to date, I have not been able to reproduce rsync
results error output when the disk is full. In stead I receive something like
that which is quoted below.
> rsync: mkstemp 
>
"/Volumes/backup_volume/backups/Section.inprogress/to_backup/file_for_which_there_is_not_enough_space.n3pq0e"
>  failed: No space left on device (28)
> rsync_v3.0.7(33235) malloc: *** error for object 0xa: pointer being freed
was
> not allocated
> *** set a breakpoint in malloc_error_break to debug
> rsync: connection unexpectedly closed (22413 bytes received so far)
[sender]
> rsync error: error in rsync protocol data stream (code 12) at io.c(601) 
> [sender=3.0.7]
The reason I have replied is because you have the same error reported at the end
:
> rsync error: error in rsync protocol data stream (code 12) at io.c(601)
> [sender=3.0.7]

In addition you are both running on Mac OS X.

If I manage to reproduce this fault then I will report back to this list. In the
mean time, perhaps someone with a deeper understanding of these error codes will
be able to shed additional light on this error message.


------------------------------------
 This email is protected by LBackup
 http://www.lbackup.org

> From: Henri Shustak <henri.shustak at gmail.com>
> Date: Thu, 3 Feb 2011 00:48:02 +1300
> To: rsync <rsync at lists.samba.org>
> Subject: Re: Protocol stream error on extended attribute, silent failure to
> copy all attributes
>
> [snip]
> 
> Recently, a user posted the following rsync error to the LBackup mailing
list
> : 
> 
>> "rsync: writefd_unbuffered failed to write 4 bytes to socket
[sender]: Broken
>> pipe (32)
>> rsync: connection unexpectedly closed (3225054 bytes received so far)
>> [sender]
>> rsync error: error in rsync protocol data stream (code 12) at io.c(601)
>> [sender=3.0.7]"
>> 
>> Can anyone tell me what it means, why it would occur and most
importantly how
>> to fix it.
>
> In their case the destination volume disk was running out of space.
However,
> for some reason rsync was not reporting this error as I would expect.
> 
> A link to this thread on the LBackup mailing is available below :
>  http://tinyurl.com/lbackup-discussion-diskfull
> 
> I am in the process of attempting to reproduce this error when the disk is
> full. During testing I have cared out to date, I have not been able to
> reproduce rsync results error output when the disk is full. In stead I
receive
> something like that which is quoted below.
Hi Henri,

In the setup I used to produce my example, I have almost 200 GB of available
space on the destination volume (the source has almost 600). I was only
copying a few hundred MB.

On my production servers where I originally encountered this problem, the
free space on each volume is over 1 TB.

Most of the time, I get the protocol stream error. The writed_unbuffered one
only occurs once out of maybe 5 or 6 runs.

Thanks for your reply,

Matt