#627025 svn client with ssh: data loss in output when both stdout and stderr are redirected to a pipe #627025
- Package:
- libsvn1
- Source:
- subversion
- Description:
- Shared libraries used by Apache Subversion
- Submitter:
- Vincent Lefevre
- Date:
- 2026-08-31 03:55:02 UTC
- Severity:
- important
When stdout and stderr are both redirected to a pipe, some of the
output data can be lost!
I can reproduce this bug with:
------------------------------------------------------------
#!/usr/bin/env perl
use strict;
use SVN::Client;
my $ctx = new SVN::Client;
$ctx->log(\@ARGV, 'HEAD', 1, 0, undef, \&log_receiver);
sub log_receiver
{
print "@_[0..4]\n";
}
------------------------------------------------------------
For instance, with a large local repository:
xvii% ./svn2log wd 2>&1 | cat >| out; ls -l out
-rw-r--r-- 1 vinc17 vinc17 5398648 2011-05-17 04:45:57 out
xvii% ./svn2log wd 2>&1 | cat >| out; ls -l out
-rw-r--r-- 1 vinc17 vinc17 3993720 2011-05-17 04:45:59 out
xvii% ./svn2log wd 2>&1 | cat >| out; ls -l out
-rw-r--r-- 1 vinc17 vinc17 5398648 2011-05-17 04:46:02 out
xvii% ./svn2log wd 2>&1 | cat >| out; ls -l out
-rw-r--r-- 1 vinc17 vinc17 5398648 2011-05-17 04:46:05 out
xvii% ./svn2log wd 2>&1 | cat >| out; ls -l out
-rw-r--r-- 1 vinc17 vinc17 5398648 2011-05-17 04:46:07 out
xvii% ./svn2log wd 2>&1 | cat >| out; ls -l out
-rw-r--r-- 1 vinc17 vinc17 5398648 2011-05-17 04:46:09 out
xvii% ./svn2log wd 2>&1 | cat >| out; ls -l out
-rw-r--r-- 1 vinc17 vinc17 5398648 2011-05-17 04:46:12 out
xvii% ./svn2log wd 2>&1 | cat >| out; ls -l out
-rw-r--r-- 1 vinc17 vinc17 4943992 2011-05-17 04:46:14 out
The shell doesn't matter: same problem with zsh, bash and dash.
The problem is even more visible when using "less".
./svn2log wd 2>&1 | less -M
then type [End]. The number of lines changes each time.
I couldn't reproduce the problem with a remote repository,
perhaps because of some race condition that occurs when one
gets data much faster.
The problem doesn't occur if I don't redirect stderr.
This may be a regression, as I cannot reproduce this problem on a Debian/lenny machine, still with a local repository, but a different one. However the environment is rather different, and since the bug may be due to a race condition, one cannot draw a definitive conclusion.
Thanks for letting us know. My next question (not yet having had time to do any detailed analysis of the issue) would be whether it can be reproduced on squeeze (or even better, pre-5.12 sid/wheezy, but that's probably rather awkward to set up now). Cheers, Dominic.
It seems that the problem doesn't occur when one uses the "file:"
scheme, but it occurs when one uses the "svn+ssh:" scheme. I don't
know whether this is related to the timing ("file:" is probably too
fast) or something else.
So, do not take into account my remark on Debian/lenny, as I was
using the "file:" scheme. I can reproduce the bug on it too.
Here's the script (called bigrep):
------------------------------------------------------------
#!/bin/sh
set -e
rm -rf bigrep-repos bigrep-wc
svnadmin create bigrep-repos
svn co svn+ssh://localhost`pwd`/bigrep-repos bigrep-wc
cd bigrep-wc
for i in `seq 1 10`
do
touch file$i
svn add file$i
seq 1 3000 > log
svn ci -F log
done
svn update
------------------------------------------------------------
Running "./svn2log bigrep-wc 2>&1 | less -M" often gives after
typing the End key:
[...]
2990
2991
2992
29
2986
2987
2988
2989
2990
2991
2992
2993
2994
2995
2996
2997
2998
2999
3000
lines 14957-15015/15015 (END)
Also:
tomate% ./svn2log bigrep-wc 2>&1 | wc
26521 26553 123083
tomate% ./svn2log bigrep-wc 2>&1 | wc
25701 25733 118987
tomate% ./svn2log bigrep-wc 2>&1 | wc
25702 25734 118987
tomate% ./svn2log bigrep-wc 2>&1 | wc
30012 30046 139467
tomate% ./svn2log bigrep-wc 2>&1 | wc
30012 30046 139467
tomate% ./svn2log bigrep-wc 2>&1 | wc
26521 26553 123083
The problem is still reproducible with:
strace -f -o strace.out ./svn2log bigrep-wc 2>&1 | less
The strace output shows interesting things:
[...]
2109 write(5, "06\n2607\n2608\n2609\n2610\n2611\n2612"..., 16384) = 16384
2108 <... read resumed> "06\n2607\n2608\n2609\n2610\n2611\n2612"..., 4096) = 4096
2109 read(3, <unfinished ...>
2108 write(1, "93\n2994\n2995\n2996\n2997\n2998\n2999"..., 4096 <unfinished ...>
2109 <... read resumed> "\306q\22\221X7\317p\201<\265\222\277\270;:O\225\37\272\212P\212*]q\4\337\370\262s\201"..., 8192) = 8192
2108 <... write resumed> ) = -1 EAGAIN (Resource temporarily unavailable)
2109 select(7, [3 4], [3], NULL, NULL <unfinished ...>
2108 write(1, "\n1026\n1027\n1028\n1029\n1030\n1031\n1"..., 4096 <unfinished ...>
2109 <... select resumed> ) = 2 (in [3], out [3])
2108 <... write resumed> ) = -1 EAGAIN (Resource temporarily unavailable)
2109 read(3, <unfinished ...>
2108 write(1, "1845\n1846\n1847\n1848\n1849\n1850\n18"..., 4096 <unfinished ...>
2109 <... read resumed> "\236k\205\214QuEe>\236\312\204@\204\205\264p\t\353y\5Zln\212s\245V\241Nqf"..., 8192) = 8192
2108 <... write resumed> ) = -1 EAGAIN (Resource temporarily unavailable)
2109 write(3, "v\337\365\300\245\225/\343\336D\0177\35\302\350\276\220(4\266x\314\3769\344\270}c\340\365\315\351"..., 48 <unfinished ...>
2108 read(6, <unfinished ...>
2109 <... write resumed> ) = 48
2108 <... read resumed> "6\n537\n538\n539\n540\n541\n542\n543\n54"..., 4096) = 4096
2109 select(7, [3 4], [5], NULL, NULL <unfinished ...>
2108 read(6, <unfinished ...>
2109 <... select resumed> ) = 2 (in [3], out [5])
2108 <... read resumed> "48\n1449\n1450\n1451\n1452\n1453\n1454"..., 4096) = 4096
2109 write(5, "113\n114\n115\n116\n117\n118\n119\n120\n"..., 16384 <unfinished ...>
2108 read(6, <unfinished ...>
2109 <... write resumed> ) = 16384
2108 <... read resumed> "7\n2268\n2269\n2270\n2271\n2272\n2273\n"..., 4096) = 4096
2109 read(3, <unfinished ...>
2108 write(1, "664\n2665\n2666\n2667\n2668\n2669\n267"..., 4096 <unfinished ...>
2109 <... read resumed> "\267F\31I\225l\323\365\351\346\357\226\f\3038r\247e\257:\2\207\27O\366\237\rV\7\347\1F"..., 8192) = 8192
2108 <... write resumed> ) = -1 EAGAIN (Resource temporarily unavailable)
2109 select(7, [3 4], [], NULL, NULL <unfinished ...>
2108 write(1, "\n621\n622\n623\n624\n625\n626\n627\n628"..., 4096 <unfinished ...>
2109 <... select resumed> ) = 1 (in [3])
2108 <... write resumed> ) = -1 EAGAIN (Resource temporarily unavailable)
2109 read(3, <unfinished ...>
2108 write(1, "\n1516\n1517\n1518\n1519\n1520\n1521\n1"..., 4096 <unfinished ...>
2109 <... read resumed> "\4\311\375z{\341\312~H\20\321g\341_u1\253\2376*\177\263P}\242:\177\354X\205\7\340"..., 8192) = 8192
2108 <... write resumed> ) = -1 EAGAIN (Resource temporarily unavailable)
2109 select(7, [3 4], [5], NULL, NULL <unfinished ...>
2108 read(6, <unfinished ...>
2109 <... select resumed> ) = 2 (in [3], out [5])
2108 <... read resumed> "113\n114\n115\n116\n117\n118\n119\n120\n"..., 4096) = 4096
2109 write(5, "3\n714\n715\n716\n717\n718\n719\n720\n72"..., 16384 <unfinished ...>
2108 read(6, <unfinished ...>
2109 <... write resumed> ) = 16384
2108 <... read resumed> "9\n1110\n1111\n1112\n1113\n1114\n1115\n"..., 4096) = 4096
[...]
The write errors from the Perl script could explain the problem.
Not sure whether this is related, but cvs had the same problem: http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=179729 http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=232555
After testing with "strace -f -t", I can see that the problem comes
from that the write's do not block: all the output is sent by the
Perl script before I do anything in less.
If I omit the 2>&1, then the write's from the Perl script block as
expected. They also block with the following Perl script (and 2>&1):
#!/usr/bin/env perl
use strict;
foreach my $i (1..100000)
{
warn if $i == 17;
print "$i\n";
}
I think that the cause of the problem may come from that the
svn client starts a child process (ssh). This would explain
the similarity with the old cvs bug (which occurred only with
ssh and stderr redirected to stdout too).
Right. The ssh process sets its stderr to non blocking mode (in ssh_session2_open()), and afterwards when the kernel pipe buffer fills up, your print() call to the same duplicated file descriptor fails with $! set to EAGAIN. If there is a bug here, it's not in perl. Perl is already doing the only thing it can to save you, but you don't check the return value of the print() call. Possibly subversion should make a new descriptor for the ssh stderr and then shovel data between that and its own stderr. Please reassign to subversion if you like, but consider downgrading the severity.
reassign 627025 libsvn1 severity 627025 important retitle 627025 svn client with ssh: data loss in output when both stdout and stderr are redirected to a pipe thanks I agree. I suppose that the problem would be the same when using the svn client API from C. Checking the return value of the print() call would only be useful to detect the error. But it is not possible to correct the error as corrupt data have been sent to stdout before the return value can be tested. And if I tried to output an error message in such a case, it is also lost in the process. Done. Reassigning to libsvn1 since I'm using the API, and I suppose the problem is there.
forwarded 627025 http://subversion.tigris.org/issues/show_bug.cgi?id=3906
I suppose this is more or less what the trick below does (until Subversion does that itself). GNU Emacs is affected by this bug, and a workaround has been posted in the corresponding bug report here: http://debbugs.gnu.org/cgi/bugreport.cgi?bug=7791 In short, add exec 2> >(exec cat >&2 2>/dev/null) in a ssh wrapper (this works at least with bash and zsh), which can be specified in the SVN_SSH environment variable.
Still reproducible in Debian 7, 8 and sid, with:
for i in `seq 100`
do
env -u SVN_SSH svn log 2>&1 | wc
done
on the bigrep-wc mentioned in
https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=627025#20
(the "env -u SVN_SSH" is used in case there is a workaround in
an ssh wrapper).
Dear Customer, Your item has arrived at January 22, but our courier was not able to deliver the parcel. Please review delivery label in attachment! All the best, Kevin Kerr, USPS Senior Delivery Manager.
Dear Sir or Madam, You have to appear in the Court on the February 20 for your case hearing. Please prepare all the documents relating to the case and bring them on the specified date. Please review all the details in the attachment. All the best, , District Clerk.
This is still reproducible, as I could test with "svn diff"[*] after unsetting SVN_SSH (which contains the workaround). [*] https://github.com/termux/termux-packages/issues/31395 for the context (I had completely forgotten this bug and wasn't using a wrapper script with the workaround there).
Actually, not stderr, but stdout. A command like (without the "2>&1")
strace -f -o str.out sh -c "env -u SVN_SSH svn diff --diff-cmd diff -x -U80 -c191480 | wc"
gives
581297 dup(0) = 4
581297 dup(1) = 5
581297 dup(2) = 6
581297 fcntl(4, F_SETFD, FD_CLOEXEC) = 0
581297 fcntl(5, F_SETFD, FD_CLOEXEC) = 0
581297 fcntl(6, F_SETFD, FD_CLOEXEC) = 0
581297 ioctl(4, TCGETS2, 0x7ffddf553e90) = -1 ENOTTY (Inappropriate ioctl for device)
581297 fcntl(4, F_GETFL) = 0 (flags O_RDONLY)
581297 fcntl(4, F_GETFL) = 0 (flags O_RDONLY)
581297 fcntl(4, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
581297 ioctl(5, TCGETS2, 0x7ffddf553e90) = -1 ENOTTY (Inappropriate ioctl for device)
581297 fcntl(5, F_GETFL) = 0x1 (flags O_WRONLY)
581297 fcntl(5, F_GETFL) = 0x1 (flags O_WRONLY)
581297 fcntl(5, F_SETFL, O_WRONLY|O_NONBLOCK) = 0
Both stdin (fd 0) and stdout (fd 1) are set to nonblocking,
since fd 0 and fd 4 share the file status flags, and ditto
for fd 1 and fd 5.
So I'm wondering why the bug with Subversion doesn't also occur
without the "2>&1".
If I add the "2>&1" as below
strace -f -o str.out sh -c "(env -u SVN_SSH svn diff --diff-cmd diff -x -U80 -c191480) 2>&1 | wc"
I get:
582707 dup(0) = 4
582707 dup(1) = 5
582707 dup(2) = 6
582707 fcntl(4, F_SETFD, FD_CLOEXEC) = 0
582707 fcntl(5, F_SETFD, FD_CLOEXEC) = 0
582707 fcntl(6, F_SETFD, FD_CLOEXEC) = 0
582707 ioctl(4, TCGETS2, 0x7ffe7c961ee0) = -1 ENOTTY (Inappropriate ioctl for device)
582707 fcntl(4, F_GETFL) = 0 (flags O_RDONLY)
582707 fcntl(4, F_GETFL) = 0 (flags O_RDONLY)
582707 fcntl(4, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
582707 ioctl(5, TCGETS2, 0x7ffe7c961ee0) = -1 ENOTTY (Inappropriate ioctl for device)
582707 fcntl(5, F_GETFL) = 0x1 (flags O_WRONLY)
582707 fcntl(5, F_GETFL) = 0x1 (flags O_WRONLY)
582707 fcntl(5, F_SETFL, O_WRONLY|O_NONBLOCK) = 0
582707 ioctl(6, TCGETS2, 0x7ffe7c961ee0) = -1 ENOTTY (Inappropriate ioctl for device)
582707 fcntl(6, F_GETFL) = 0x1 (flags O_WRONLY)
582707 fcntl(6, F_GETFL) = 0x1 (flags O_WRONLY)
582707 fcntl(6, F_SETFL, O_WRONLY|O_NONBLOCK) = 0
Now, every standard fd is set to nonblocking.
I get the same thing without svn, by using:
strace -f -o str.out sh -c "( true | ssh localhost true | cat; ) 2>&1 | wc"
The "true |" part is needed to get the F_SETFL on fd 4.
The "| cat" part is needed to get the F_SETFL on fd 6.
With just "ssh localhost true", only fd 5 is set to nonblocking.
Consider the following Perl script stdout-nonblock, which
• outputs the (non)blocking status of stdout,
• sets stdout to nonblocking (this will be used for the
first test below).
----------------------------------------------------------------
#!/usr/bin/env perl
use strict;
use Fcntl qw(F_GETFL F_SETFL O_NONBLOCK);
my $flags = fcntl(STDOUT, F_GETFL, 0) or die;
print ($flags & O_NONBLOCK ? "Nonblocking\n" : "Blocking\n");
fcntl(STDOUT, F_SETFL, $flags | O_NONBLOCK) or die;
----------------------------------------------------------------
One gets:
$ sh -c "( ./stdout-nonblock; ./stdout-nonblock; ) 2>&1 | cat"
Blocking
Nonblocking
The 2 stdout-nonblock invocations allow one to confirm that if fd 1 is
set to nonblocking, this affects the parent process, i.e. the shell.
Now, let's test ssh:
$ sh -c "( true | ssh localhost true | cat; ./stdout-nonblock; ) 2>&1 | cat"
Blocking
because ssh resets the fd file status flags to their default.
But the following test shows that a background ssh can affect the shell
(just like it affects Subversion).
$ sh -c "( true | ssh localhost sleep 2 | cat & sleep 1; ./stdout-nonblock; ) 2>&1 | cat"
Nonblocking
Ditto with just
$ sh -c "( ssh localhost sleep 2 & sleep 1; ./stdout-nonblock; ) 2>&1 | cat"
Nonblocking
All shells seem to be affected. I'm wondering whether this is also
a bug in the shells or it should be forbidden for programs to change
the file status flags of the standard file descriptors.
That's assuming that ssh doesn't get killed with SIGKILL. Otherwise, one gets "Nonblocking".