Anyone know why git ls-remote output might be corrupted?

I have some scripting on my CI/CD servers that invokes git ls-remote and parses the output. The scripting is in Python. Sometimes, but not always, the output of this command is corrupted. I've enhanced the error handling and I see this:

*** INTERNAL: remote branch lookup failed:
Output:
-----
8431d80571dea5cc8e6d0848f27124f66346dcc4        refs/heads/foo1
aaec1feb1167cf3fbd39a36cdd7736679a9f4fae        refs/heads/foo2
6167c73fbaded389ff54d52a01878975f4a6d5e5        refs/heads/foo3
   ...
3a2e8036a6f6605d4dd14c72bd395298bff9d80e        refs/heads/xxx1
3a2e8036a6f6605d4dd14c72bd395298bff9d80e        refs/heads/xxx2
795d2ff669041fc91341cf5bf820aibab79dc92bd741e77a7dcf71d94285a6ae494dc0        refs/heads/yyy1
1496ea0ddab29ae3935754fced4bd5858cff7940        refs/heads/yyy2
1496ea0ddab29ae3935754fced4bd5858cff7940        refs/heads/yyy3
-----

Also a bunch of the heads are missing. It's pretty clear that right in the middle of printing one of the SHAs we suddenly lost a bunch of output, and started printing stuff from later (in the last instance 66 out of 131 heads were missing). Breaking down the output above you can see:

  3a2e8036a6f6605d4dd14c72bd395298bff9d80e        refs/heads/xxx2
  795d2ff669041fc91341cf5bf820aibab79dc92bd741e77a7dcf71d94285a6ae494dc0        refs/heads/yyy1
                               ^

where the "795d2ff669041fc91341cf5bf820a" before the "i" char is a valid start of a SHA for a head (not shown), then the "i", then a fully valid SHA for heads/yyy1 which is 66 heads later.

I've seen this happen with different versions of Git on the client side and on different OS's (Windows and Linux). The only real constant here is the Git server.

Is it feasible that this is an error on the server side? Does the server return formatted output for ls-remote? I would naively have expected it to return a binary representation of the heads, and the formatting be done by the client. But maybe not.

I should point out that subsequent runs in the same client work fine, and when I log into the CI/CD client and run the command by hand I can't reproduce it. It's random. I also can't find any errors printed anywhere on either the server (we are using ssh access only for client connections, managed via gitolite) or the client, except for the above.

Help, this is causing a few spurious failures in my CI/CD system per day!

On Fri, 2023-06-02 at 14:59 -0400, Paul Smith wrote:

I forgot to mention: git ls-remote does not exit with an error code. The exit code is 0 (success).

The reason I get this failure is that as I parse the output I notice that the SHA is invalid (contains a non-hex character "i") and it throws this error.

On Friday, June 2, 2023 3:13 PM, Paul Smith wrote:

Does your CI/CD system use sparse checkout or depth=1 or some other partial clone?

On Fri, 2023-06-02 at 15:34 -0400, rsbecker@nexbridge.com wrote:

Yes, the local copy of the repo is a sparse checkout.

I'm surprised that matters to ls-remote... I would have expected that the "sparseness" of the local repo is irrelevant when listing the state of the remote's heads? Is that the reason for the issue I'm seeing?

On Friday, June 2, 2023 3:53 PM, Paul Smith wrote:

I'm just wondering whether this might be an impact somehow and adding info to help the team diagnose. I have seen other commands have some issues in the past with --depth=n --Randall

On Fri, 2023-06-02 at 16:02 -0400, rsbecker@nexbridge.com wrote:

I see. Well I can try changing my call to avoid the local repo in any way, and run 'git ls-remote --heads user@server:reponame' from a temporary directory outside of any repo, rather than using "origin".

I would be surprised if it makes a difference but the behavior is sure strange enough that I wouldn't be THAT surprised :)

On Fri, Jun 2, 2023 at 1:26 PM <rsbecker@nexbridge.com> wrote:

I think if shallowness or sparseness affected ls-remote output in any way whatsoever, that would itself be a bug. Granted, I don't know much about the protocol side of things, but I'd be very surprised if either of these conditions mattered.

On Fri, Jun 2, 2023 at 12:27 PM Paul Smith <paul@mad-scientist.net> wrote:

Can you trigger this problem with just `git ls-remote --heads origin`, or do you only see it after processing by your python script?

If you can trigger with the former, what does
    GIT_TRACE_PACKET=1 git ls-remote --heads origin
report?

If the latter, can you find a way to minimize your python script or find some equivalent shell commands with the same buggy behavior?

Sounds kind of like https://lore.kernel.org/git/6786526.72e2EbofS7@devpool47/ which also triggered for some other tooling and then was reduced down to some shell commands. Unfortunately, the thread ended without a lot of resolution other than "don't mix stdout and stderr" and "if we slow down the network connection somehow, that'll avoid the problem".

On Fri, Jun 02, 2023 at 06:12:52PM -0700, Elijah Newren wrote:

Thanks for digging up that thread. I had a vague memory of this coming up before, but wasn't sure what to search for to find it. :)

From that thread, one theory that I think remains unexplored: could ls-remote's stdout be opened in non-blocking mode?

The output of ls-remote is written with printf(). We don't bother checking for errors from stdio, since typically a write error would result in us getting EPIPE and being killed. But if stdout were unexpectedly in non-blocking mode, we might get EAGAIN. I'm not sure how libc would handle that.

Now, why the descriptor would be in non-blocking mode, I have no idea. But maybe something funny going on in your python script.

I'd be curious if applying the patch from:

  https://lore.kernel.org/git/YUTo1BTp7BXOw6K9@coredump.intra.peff.net/

reports any problems. As well as whether the suggested "sleep" pipeline there (triggered via your script in this case) shows the problem more reliably.

-Peff

On Sun, Jun 04, 2023 at 02:00:48AM -0400, Jeff King wrote:

It does look like glibc's stdio will throw away buffer contents that get EAGAIN. Doing:

  perl -MFcntl -e '
    fcntl(STDOUT, F_GETFL, $flags);
    $flags |= O_NONBLOCK;
    fcntl(STDOUT, F_SETFL, $flags);
    exec @ARGV;
  ' git ls-remote . | (sleep 1; tee output) | sha256sum

does result in some missing writes and broken input that looks like what's going on in this thread (in this case, it's writing to my terminal, which isn't fast enough to keep up; but you could also pipe to something like "tee output | sha256sum" to see that the output changes with each run). And naturally you'll need a big enough output from ls-remote to fill the pipe buffer.

However, Git _does_ eventually produce a non-zero exit code in this case, because we check ferror() after running any builtin. So it eventually ends with:

  fatal: unknown write failure on standard output

So I dunno. Maybe this is not the same thing. I do think running the problematic case under "strace -o foo.out" may yield more information.

-Peff

On Sun, Jun 04, 2023 at 02:25:57AM -0400, Jeff King wrote:

Sorry for some slight confusion above. I edited my example command to show piping to "sha256sum", but didn't modify the paragraph below it (originally I was not piping anywhere, just sending to the terminal).

Adding the "sleep 1" means that the command will always fail (ls-remote easily writes all of its output and hits EAGAIN before the other side reads anything). But it means that the output is deterministic (the first PIPE_BUF bytes make it through, and nothing else does). Removing the sleep makes the output non-deterministic, but much more interesting (you get missing chunks in the interior of the output).

So perhaps:

  perl ... git ls-remote . | tee output | sha256sum

is the most interesting case, because you'll get one of several possible broken outputs, which you can identify by the changing sha256 output (and then see the actual breakage by peeking at the "output" file).

-Peff

On Fri, 2023-06-02 at 18:12 -0700, Elijah Newren wrote:

As I was riding my bike home last week I had this exact same epiphany. So, I examined my script and discovered that indeed, I was using subprocess.PIPE for stderr, which is the Python equivalent of the shell's 2>&1 operation. So, both stdout and stderr are going to the same place.

I also checked and indeed, the git ls-remote command does print to both stdout and stderr as part of its "standard" behavior:

  $ git ls-remote --heads >/dev/null
  From git@git:myrepo

This is unexpected to me, although of course there's nothing inherently wrong with it but usually you don't expect "regular" output to go to stderr. I suppose the idea is that people can run:

  $ git ls-remote --heads 2>/dev/null

if they want just the output without the header.

Anyway, I modified my scripting to keep stdout and stderr separate and I haven't heard anything about things continuing to fail so I guess that was the problem.

The mode of failure is very very bizarre to me: first why is it just one "bogus" character embedded in the output? Second why are 60 lines just dropped? Third where did the REST of the stderr output go?

And finally, why did this not fail 100% of the time on Linux? I can believe that Windows pipe behavior is not POSIX and maybe Python's emulation of it is imperfect, but surely that is not the case on Linux and we would ALWAYS get the full results of both stdout and stderr on Linux, even if mixed together?!?!

The mysteries never end.

Thanks all; hopefully this helps someone else.

Paul Smith <paul@mad-scientist.net> writes:

The above sounds like a reasonable expectation; then the issue is there are some fflush missing when the command writes to one stream and switches to write to another stream?

Thanks.

On Sat, 2023-06-10 at 03:58 +0900, Junio C Hamano wrote:

It's not immediately clear to me which "above" you refer to as a reasonable expectation (the reason for the stdout vs. stderr different I suppose?)

But I agree that forcing flush would be a good idea (or perhaps forcing line buffering? Changing buffering can be annoying to do portably), for situations in which the output is being sent to a non-TTY, because the default in that situation is fully buffered output.

Maybe it would be sufficient to have any output to stderr run fflush(stdout) before the output, and fflush(stderr) after the output. Presumably output to stderr is relatively rare, and so this wouldn't be very noticeable.