Re: [PATCH] t5500.43: make the check a bit more robust

[Johannes Schindelin <Johannes.Schindelin@gmx.de>]

Hi Peff,

On Tue, 13 Oct 2020, Jeff King wrote:

> On Tue, Oct 13, 2020 at 02:45:23PM +0000, Johannes Schindelin via GitGitGadget wrote:
>
> > Note: we have code in `demultiplex_sideband()` _specifically_ to stitch
> > back together lines that were delivered in separate sideband packets.
> > However, this stitching fails when a primary packet is delivered in
> > between the two sideband packets: since a primary packet was received,
> > `demultiplex_sideband()` has to return that (and cannot wait for other
> > sideband packets, and therefore has to flush any incomplete line it
> > received).
>
> This sounds like a bug. We should accumulate multiple sideband 2
> packets, even across data packets. And I think we _used_ to do that. The
> original recv_sideband() looked roughly like this:
>
> 	while (!retval) {
> 		 packet_read();
> 		 band = buf[0] & 0xff;
> 		 switch (band) {
> 		 case 3:
> 		   ...stuff data into outbuf...
> 		   retval = SIDEBAND_ERROR_REMOTE;
> 		   break;
> 		 case 2:
> 		   ...print full lines, stuff remainder into outbuf...
> 		   break; /* note, does _not_ set retval */
> 		 case 1:
> 		   write_or_die(out, buf + 1, len);
> 		   break; /* likewise, does not set retval */
> 		 default:
> 		   ...complain about broken sideband...
> 		   retval = SIDEBAND_PROTOCOL_ERROR;
> 		}
> 	}
> 	if (outbuf.len)
> 		...print outbuf...
>
> So we would keep looping until we see EOF, sideband 3, or a protocol
> error. But notably we would not break out of the loop on bands 1 or 2,
> and we do not flush band 2 until we break out of the loop.
>
> But then in fbd76cd450 (sideband: reverse its dependency on pkt-line,
> 2019-01-16), the function became demultiplex_sideband(). The loop went
> away, and we pump only a single packet on each call. When we see
> sideband 2, we do an early return. But on sideband 1, we continue to the
> cleanup: label, which flushes the scratch buffer.
>
> I think we need to return from there without hitting that cleanup label,
> like this:
>
> diff --git a/sideband.c b/sideband.c
> index 0a60662fa6..a5405b9aaa 100644
> --- a/sideband.c
> +++ b/sideband.c
> @@ -190,7 +190,7 @@ int demultiplex_sideband(const char *me, char *buf, int len,
>  		return 0;
>  	case 1:
>  		*sideband_type = SIDEBAND_PRIMARY;
> -		break;
> +		return 1;
>  	default:
>  		strbuf_addf(scratch, "%s%s: protocol error: bad band #%d",
>  			    scratch->len ? "\n" : "", me, band);
>
> Does that make the problem go away for you?

Yes. But it took a substantial amount of time for myself to convince
myself that this oneliner is actually correct.

>
> >     Work around flakiness in t5500.43
> >
> >     It seems that this test became flaky only recently, although I have to
> >     admit that I have no idea why: the involved code does not seem to have
> >     changed recently at all. It should have been fixed by
> >     https://lore.kernel.org/git/20200506220741.71021-1-jonathantanmy@google.com/
> >     , but apparently wasn't completely fixed, despite what I said in that
> >     thread.
>
> I think this is a real bug, and we shouldn't be changing the tests to
> accommodate. Users may actually see the broken lines, and our tests are
> telling us that.
>
> I suspect it's uncommon in practice because it requires the server side
> also splitting the line across two packets. And while the server-side
> upload-pack might get a partial write from a child pack-objects or
> whatever, that should only happen if:
>
>   - the pipe buffer fills up. Which is hard to do since our messages
>     tend to be very small. So perhaps it implies a very tiny pipe
>     buffer, and/or slow scheduling of the receiving side to actually
>     clean it out.
>
>   - the writer is fully buffering its stderr writes instead of sending
>     them a line at a time
>
> The latter seems a more likely candidate for switching from gcc to
> Visual C (which presumably has a different libc / CRT).  I think the
> client should be handling this more robustly, but it may be worth
> digging into the buffering issue if it means progress may not be
> delivered in quite as timely a way as we expect it to be.

FWIW I _think_ the issue at hand is that newer MSVC runtimes deliver
`stderr` byte-by-byte. While that is totally allowed, it is different from
how things seem to be done on Linux/Unix/Darwin.

In my tests, I frequently saw the first two or four characters of that
"Total 3" line be delivered in its own sideband packet, hence the
breakage.

Thank you for keeping me honest. I would much rather have avoided spending
several hours on this investigation, but in the end, it is something that
is better made correct than left incorrect.

Having said that it is neither a very new bug nor does it seem to matter
on Linux/macOS (and not even in Git for Windows because it is built using
mingw-w64-gcc, which uses an older MSVC runtime, which apparently does not
share that issue with newer versions), therefore I plan on sending off v2
only after v2.29.0 was published.

Ciao,
Dscho