[Bug 5478] rsync: writefd_unbuffered failed to write 4092 bytes [sender]: Broken pipe (32)
samba-bugs at samba.org
samba-bugs at samba.org
Fri Sep 23 09:55:28 MDT 2011
https://bugzilla.samba.org/show_bug.cgi?id=5478
--- Comment #15 from Eric Shubert <ejs at shubes.net> 2011-09-23 15:55:27 UTC ---
(In reply to comment #14)
> It's a bit unclear what pid corresponds to what function, especially with both
> sides having 2 pids in the trace output. What is the command-line used?
strace -tt -f -o /tmp/rsync-$$.out rsync \
--verbose \
--exclude "stor/hosts" \
--exclude "var/run" \
--exclude "var/spool" \
--rsh="ssh -p $backoff_port" \
--rsync-path="sudo /usr/local/bin/rsync-debug" \
--recursive \
--links \
--perms \
--times \
--owner \
--group \
--numeric-ids \
--xattrs \
--delete \
--compress \
--human-readable \
--stats \
--exclude='udat/backup*/*' \
--exclude='udat/migrate/*' \
/mnt/stor \
$userid@$backoff_url:$destdir 2>&1
As you can see, it's pushing from the local host via ssh to the remote host.
> So, looking at your trace, it looks like the sender is waiting to write more
> data (its select lists the write and error FDs). The receiving side's 2 pids
> are waiting to read more data. So, something in between has either failed to
> deliver the data, or blocked, or something (it would appear). Are there other
> processes in between the 2 sides (e.g. ssh) that could have blocked? Or
> perhaps a failed pipe (or unix domain socket)?
Here is another run, with processes. Both sides are rsync-3.0.8-1.el5.rfx.
First the sending side processes:
root 4921 4914 5 07:38 tty1 00:00:13 strace -tt -f -o
/tmp/rsync-4914.out rsync --verbose --exclude stor/hosts --exclude var/run
--exclude var/spool --rsh=ssh -p 17113 --rsync-path=sudo
/usr/local/bin/rsync-debug --recursive --links --perms --times --owner --group
--numeric-ids --xattrs --delete --compress --human-readable --stats
--exclude=udat/backup*/* --exclude=udat/migrate/* /mnt/stor
r3i at backoff.shubes.net:/home/r3i/backup/tacs-udat
root 4923 4921 7 07:38 tty1 00:00:17 rsync --verbose --exclude
stor/hosts --exclude var/run --exclude var/spool --rsh=ssh -p 17113
--rsync-path=sudo /usr/local/bin/rsync-debug --recursive --links --perms
--times --owner --group --numeric-ids --xattrs --delete --compress
--human-readable --stats --exclude=udat/backup*/* --exclude=udat/migrate/*
/mnt/stor r3i at backoff.shubes.net:/home/r3i/backup/tacs-udat
root 4924 4923 0 07:38 tty1 00:00:01 ssh -p 17113 -l r3i
backoff.shubes.net sudo /usr/local/bin/rsync-debug --server -vlogtpXrze.isf
--delete --numeric-ids . /home/r3i/backup/tacs-udat
The sending side strace:
4923 07:47:21.380396 select(5, NULL, [4], [4], {60, 0}) = 1 (out [4], left
{60, 0})
4923 07:47:21.380537 write(4,
"4\25\t\20\342Q\353\177A\0039rC\272\301\372\335\364\17?\313g\241\215\313\370%\222s\367F|"...,
4092) = 4092
4923 07:47:21.380683 select(5, NULL, [4], [4], {60, 0}) = 1 (out [4], left
{60, 0})
4923 07:47:21.380806 write(4, "\374\17\0\7", 4) = 4
4923 07:47:21.380914 select(5, NULL, [4], [4], {60, 0}) = 1 (out [4], left
{60, 0})
4923 07:47:21.381034 write(4,
"\351\4n\317\346;f\321Pn>~[\333\337\200\214#\33\233\365\3\5\322P\1\221\364\255\230<\16"...,
4092) = 4092
4923 07:47:21.382583 select(5, NULL, [4], [4], {60, 0}) = 1 (out [4], left
{60, 0})
4923 07:47:21.382777 write(4, "\374\17\0\7", 4) = 4
4923 07:47:21.382897 select(5, NULL, [4], [4], {60, 0} <unfinished ...>
4924 07:47:21.499524 <... select resumed> ) = 1 (out [3])
4924 07:47:21.499685 write(3,
"D\3143?I\322+\362S\231\311Xe\302\264\1\235|R\231Wyw\214\302\211\206\365^\337;\24"...,
131552) = 66240
4924 07:47:21.500711 select(7, [3], [3], NULL, NULL) = 1 (out [3])
4924 07:47:22.518796 write(3,
"\350l\250\255\361YB\241`__\302oM\333\346\247\223\tdcM\203O\217aA\260\t\377gm"...,
98128) = 54720
4924 07:47:22.519874 select(7, [3], [3], NULL, NULL <unfinished ...>
4923 07:48:21.377865 <... select resumed> ) = 0 (Timeout)
4923 07:48:21.377989 select(5, NULL, [4], [4], {60, 0}) = 0 (Timeout)
4923 07:49:21.379500 select(5, NULL, [4], [4], {60, 0}) = 0 (Timeout)
4923 07:50:21.378390 select(5, NULL, [4], [4], {60, 0}) = 0 (Timeout)
The receiving side processes:
root 16837 16836 0 07:39 ? 00:00:00 /bin/sh
/usr/local/bin/rsync-debug --server -vlogtpXrze.i --delete --numeric-ids .
/home/r3i/backup/tacs-udat
root 16848 16837 18 07:39 ? 00:01:03 strace -tt -f -o
/tmp/rsync-16837.out rsync --server -vlogtpXrze.i --delete --numeric-ids .
/home/r3i/backup/tacs-udat
root 16849 16848 15 07:39 ? 00:00:51 rsync --server -vlogtpXrze.i
--delete --numeric-ids . /home/r3i/backup/tacs-udat
root 16850 16849 1 07:39 ? 00:00:04 rsync --server -vlogtpXrze.i
--delete --numeric-ids . /home/r3i/backup/tacs-udat
The receiving side strace:
16850 07:47:22.332291 select(1, [0], [], NULL, {60, 0}) = 1 (in [0], left {60,
0})
16850 07:47:22.332556 read(0, "\374\17\0\7", 4) = 4
16850 07:47:22.332808 select(1, [0], [], NULL, {60, 0}) = 1 (in [0], left {60,
0})
16850 07:47:22.333036 read(0,
"&\f]c\254\306\20\326mK\0\r\365\36k\236IQ\365l\23\337Ne\322p\361\207\237\320'\257"...,
4092) = 4092
16850 07:47:22.333328 select(1, [0], [], NULL, {60, 0}) = 1 (in [0], left {60,
0})
16850 07:47:22.333664 read(0, "\374\17\0\7", 4) = 4
16850 07:47:22.333867 select(1, [0], [], NULL, {60, 0}) = 1 (in [0], left {60,
0})
16850 07:47:22.334091 read(0,
"\212N@\347\31\261\\\4\271g\216\nQ;\331C\34)\365\321\205\363CW\306\313;\322\0226\242\342"...,
4092) = 4092
16850 07:47:22.335051 select(1, [0], [], NULL, {60, 0} <unfinished ...>
16849 07:48:11.629178 <... select resumed> ) = 0 (Timeout)
16849 07:48:11.629374 select(4, [3], [], NULL, {60, 0} <unfinished ...>
16850 07:48:22.335875 <... select resumed> ) = 0 (Timeout)
16850 07:48:22.336060 select(1, [0], [], NULL, {60, 0} <unfinished ...>
Thanks for looking at this. Please let me know what I can do next to help nail
this down.
--
Configure bugmail: https://bugzilla.samba.org/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the QA contact for the bug.
More information about the rsync
mailing list