Re: data loss when doing ls-remote and piped to command

Linus Torvalds [off-list ref] writes:

On Thu, Sep 16, 2021 at 5:17 AM Rolf Eike Beer [off-list ref] wrote:

quoted

Am Donnerstag, 16. September 2021, 12:12:48 CEST schrieb Tobias Ulmer:

quoted

quoted

The redirection seems to be an important part of it. I now did:

git ... 2>&1 | sha256sum

I've tried to reproduce this since yesterday, but couldn't until now:

2>&1 made all the difference, took less than a minute.

So if that redirection is what matters, and what causes problems, I
can almost guarantee that the reason is very simple:
...
Anyway. That was a long email just to tell people it's almost
certainly user error, not the kernel.

Yes, 2>&1 will mix messages from the standard error stream at random
places in the output, which explains the checksum quite well.

I am not sure if it explains the initial report where

	ls-remote 2>&1 | less

produced

    > 6f38b5d6cfd43dde3058a10c68baae9cf17af912        refs/tags/v5.0-rc2
    > 1c7fc5cbc33980acd13ae83d0b416db002fe95601e7f97f64b59514d936     refs/tags/v5.7-rc2^{}
    > d0709bb6da2ab6d49b11643e98abdf79b1a2817f        refs/tags/v5.7-rc3

    What we see on the second line is the beginning of peeled
    v5.0-rc2^{} up to the "acd13" (that is, the first 19 bytes of the
    line), followed by the full line for peeled v5.7-rc2^{} (which
    begins with "ae83d").  12407 bytes in between are missing, which
    is even more puzzling as it is not a nice round number.

I can sort of guess that the progress display during transfer, which
comes out on the standard error stream and uses terminal control
sequences like "go back to the end of the line without feeding a new
line", "erase to the end of the line", etc., would be contributing,
but because it is piped to "less", which would make it "visible"
(i.e. you do not get the raw escape but see three capital letters
ESC in reverse), it does not quite explain how the display was
broken.

In any case, I do not think the kernel is involved, or more
generally I do not think any "loss of output bytes" is happening
here.  It's just "| less" that failed to show a range about 12k
bytes long is mystery to me ;-).

Am Donnerstag, 16. September 2021, 22:42:22 CEST schrieb Junio C Hamano:

Linus Torvalds [off-list ref] writes:

quoted

On Thu, Sep 16, 2021 at 5:17 AM Rolf Eike Beer [off-list ref] wrote:

quoted

Am Donnerstag, 16. September 2021, 12:12:48 CEST schrieb Tobias Ulmer:

quoted

quoted

The redirection seems to be an important part of it. I now did:

git ... 2>&1 | sha256sum

I've tried to reproduce this since yesterday, but couldn't until now:

2>&1 made all the difference, took less than a minute.

So if that redirection is what matters, and what causes problems, I
can almost guarantee that the reason is very simple:
...
Anyway. That was a long email just to tell people it's almost
certainly user error, not the kernel.

Yes, 2>&1 will mix messages from the standard error stream at random
places in the output, which explains the checksum quite well.

If there would be any errors. The point is: if I run the command with ">/dev/
null" just to the terminals a hundred times there is never any output on 
stderr at all. If I pipe stderr into a file it's empty after all of this (yes, 
I did append, not overwrite).

That the particular construct in this case is sort of nonsense is granted, I 
just hit it because some tool here used some very similar construct and 
suddenly started failing. "less" isn't the original reproducer, it was just 
something I started testing with to be able to easily visually inspect the 
output.

What you need is a _fast_ git server. kernel.org or github.com seem to be too 
slow for this if you don't sit somewhere in their datacenter. Use something in 
your local network, a Xeon E5 with lot's of RAM and connected with 1GBit/s 
Ethernet in my case.

And the reader must be "somewhat" slow. Using sha256sum works reliably for me. 
Using "wc -l" does not, also md5sum and sha1sum are too fast as it seems.

When I run the whole thing with strace I can't see the effect, which isn't 
really surprising. But there is a difference between the cases where I run 
with redirection "2>&1":

ioctl(2, TCGETS, 0x7ffd6f119b10)        = -1 ENOTTY (Inappropriate ioctl for 
device)

and without:

ioctl(2, TCGETS, {B38400 opost isig icanon echo ...}) = 0

AFAICT this is the only place where fd 2 is used at all during the whole time.

Regards,

Eike
-- 
Rolf Eike Beer, emlix GmbH, http://www.emlix.com
Fon +49 551 30664-0, Fax +49 551 30664-11
Gothaer Platz 3, 37083 Göttingen, Germany
Sitz der Gesellschaft: Göttingen, Amtsgericht Göttingen HR B 3160
Geschäftsführung: Heike Jordan, Dr. Uwe Kracke – Ust-IdNr.: DE 205 198 055

emlix - smart embedded open source

On Fri, Sep 17, 2021 at 08:59:07AM +0200, Rolf Eike Beer wrote:

What you need is a _fast_ git server. kernel.org or github.com seem to be too 
slow for this if you don't sit somewhere in their datacenter. Use something in 
your local network, a Xeon E5 with lot's of RAM and connected with 1GBit/s 
Ethernet in my case.

One thing that puzzled me here: is the bad output between the server and
ls-remote, or between ls-remote and its output pipe?

I'd guess it has to be the latter, since otherwise ls-remote itself
would barf with an error message.

In that case, I'd think "git ls-remote ." would give you the fastest
outcome, because it's talking to upload-pack on the local box. But I'm
also confused how the speed could matter, as ls-remote reads the entire
input into an in-memory array, and then formats it.

We do the write using printf(). Is it possible your libc's stdio may
drop bytes when the pipe is full, rather than blocking? In general, I'd
expect write() to block, so libc doesn't have to care at all. But might
there be something in your environment putting the pipe into
non-blocking mode, and we get EAGAIN or something? If so, I'd expect
stdio to return the error.

Maybe patching Git like this would help:

diff --git a/builtin/ls-remote.c b/builtin/ls-remote.c
index f4fd823af8..5936b2b42c 100644
--- a/builtin/ls-remote.c
+++ b/builtin/ls-remote.c

@@ -146,7 +146,8 @@ int cmd_ls_remote(int argc, const char **argv, const char *prefix)
 		const struct ref_array_item *ref = ref_array.items[i];
 		if (show_symref_target && ref->symref)
 			printf("ref: %s\t%s\n", ref->symref, ref->refname);
-		printf("%s\t%s\n", oid_to_hex(&ref->objectname), ref->refname);
+		if (printf("%s\t%s\n", oid_to_hex(&ref->objectname), ref->refname) < 0)
+			die_errno("printf failed");
 		status = 0; /* we found something */
 	}
 

And the reader must be "somewhat" slow. Using sha256sum works reliably for me. 
Using "wc -l" does not, also md5sum and sha1sum are too fast as it seems.

If a slow pipe is involved, maybe:

  git ls-remote . | (sleep 5; cat) | sha256sum

would help reproduce. Assuming ls-remote's output is bigger than your
system pipe buffer (which is another interesting thing to check), then
it should block for 5 seconds on write() midway through the output,
which you can verify with strace.

-Peff

On Thu, Sep 16, 2021 at 11:59 PM Rolf Eike Beer [off-list ref] wrote:

When I run the whole thing with strace I can't see the effect, which isn't
really surprising. But there is a difference between the cases where I run
with redirection "2>&1":

ioctl(2, TCGETS, 0x7ffd6f119b10)        = -1 ENOTTY (Inappropriate ioctl for device)

Ehh. That format of strace implies that you didn't use "strace -f"
(which would have the PID in it).

Although maybe you edited it out.

I think the error output would come from the other process (ssh, or
whatever process you use to run "git-upload-pack" on the other end).

I still strongly doubt it's about pipes - we've had changes to them,
but if they are broken we'd see a lot more breakage than some very
incidental use by git.

But I can easily see it being timing-dependent. And yes, sadly
'strace' can often end up hiding any timing issues because it
obviously slows down the target quite a bit.

Doing "strace -o tracefile -f" in a loop would be interesting if you
can reproduce it (and then stop when you reproduce it, so that the
final 'tracefile' is the one for the case that reproduced it).

            Linus

On Fri, 2021-09-17 at 08:59 +0200, Rolf Eike Beer wrote:

What you need is a _fast_ git server. kernel.org or github.com seem to be too
slow for this if you don't sit somewhere in their datacenter. Use something in
your local network, a Xeon E5 with lot's of RAM and connected with 1GBit/s
Ethernet in my case.

Even faster: what's coming across that wire should be a constant (is?),
variable is only delivery/consumption jitter.  If there's really really
a pipe problem lurking, you should also be able to trigger by saving
the data once, and just catting it, letting interrupts etc provide
jitter.  Which stdout is left of '|' in a script shouldn't matter one
whit to the interpreter/kernel conversation, they're all the same.

That said, if I had a reproducer I was confident pointed to the kernel,
I'd try to bisect.. boring as hell, but highly effective.

	-Mike