{"thread":{"id":"54407","subject":"[PATCH] t5500.43: make the check a bit more robust","startedAt":"2020-10-13T14:45:28Z","lastAt":"2020-10-28T23:00:10Z","messageCount":33,"participants":["Johannes Schindelin via GitGitGadget","Junio C Hamano","Jeff King","Johannes Schindelin"],"isPatch":true,"patchVersion":1,"patchTotal":null},"messages":[{"id":"407449","messageId":"pull.753.git.1602600323973.gitgitgadget@gmail.com","threadId":"54407","inReplyTo":null,"subject":"[PATCH] t5500.43: make the check a bit more robust","fromName":"Johannes Schindelin via GitGitGadget","fromEmail":"gitgitgadget@gmail.com","sentAt":"2020-10-13T14:45:23Z","receivedAt":"2020-10-13T14:45:28Z","isPatch":true,"sender":{"key":"johannes.schindelin@gmx.de","avatar":"https://avatars.githubusercontent.com/u/127790?v=4"},"body":"From: Johannes Schindelin \n\nIn 2b695ecd74d (t5500: count objects through stderr, not trace,\n2020-05-06) we tried to ensure that the \"Total 3\" message could be\ngrepped in Git's output, even if it sometimes got chopped up into\nmultiple lines in the trace machinery.\n\nHowever, the first instance where this mattered now goes through the\nsideband machinery, where it is _still_ possible for messages to get\nchopped up.\n\nNote: we have code in `demultiplex_sideband()` _specifically_ to stitch\nback together lines that were delivered in separate sideband packets.\nHowever, this stitching fails when a primary packet is delivered in\nbetween the two sideband packets: since a primary packet was received,\n`demultiplex_sideband()` has to return that (and cannot wait for other\nsideband packets, and therefore has to flush any incomplete line it\nreceived).\n\nThis seems only to happen occasionally in the `vs-test` part of our CI\nbuilds, i.e. with binaries built using Visual C, but not when building\nwith GCC or clang; The symptom is that t5500.43 fails to find a line\nmatching `remote: Total 3` in the `log` file, which ends in something\nalong these lines:\n\n\tremote: Tota\n\tremote: l 3 (delta 0), reused 0 (delta 0), pack-reused 0\n\nTo work around that, use some `sed` magic to re-stitch together those\nsplit lines, after the fact.\n\nThe other test case touched by 2b695ecd74d (t5500: count objects through\nstderr, not trace, 2020-05-06) is not affected by this issue because the\nsideband machinery is not involved there.\n\nSigned-off-by: Johannes Schindelin \n---\n Work around flakiness in t5500.43\n \n It seems that this test became flaky only recently, although I have to\n admit that I have no idea why: the involved code does not seem to have\n changed recently at all. It should have been fixed by \n https://lore.kernel.org/git/20200506220741.71021-1-jonathantanmy@google.com/\n , but apparently wasn't completely fixed, despite what I said in that\n thread.\n\nPublished-As: https://github.com/gitgitgadget/git/releases/tag/pr-753%2Fdscho%2Funflake-t5500.43-v1\nFetch-It-Via: git fetch https://github.com/gitgitgadget/git pr-753/dscho/unflake-t5500.43-v1\nPull-Request: https://github.com/gitgitgadget/git/pull/753\n\n t/t5500-fetch-pack.sh | 15 ++++++++++++++-\n 1 file changed, 14 insertions(+), 1 deletion(-)\n\ndiff --git a/t/t5500-fetch-pack.sh b/t/t5500-fetch-pack.sh\nindex 3557374312..5e556313af 100755\n--- a/t/t5500-fetch-pack.sh\n+++ b/t/t5500-fetch-pack.sh\n@@ -400,7 +400,20 @@ test_expect_success 'in_vain not triggered before first ACK' '\n \ttest_commit -C myserver bar &&\n \n \tgit -C myclient fetch --progress origin 2>log &&\n-\ttest_i18ngrep \"remote: Total 3 \" log\n+\tif ! test_i18ngrep \"remote: Total 3 \" log\n+\tthen\n+\t\t# It is possible that the \"Total 3\" line is delivered in\n+\t\t# multiple sideband packets, and that a primary packet is\n+\t\t# delivered in between. When that happens, the line will be\n+\t\t# presented on multiple \"remote:\" lines.\n+\t\tsed \"/^remote: T/{\n+\t\t\t:a\n+\t\t\tN\n+\t\t\ts/\\nremote: //\n+\t\t\tba\n+\t\t}\" log >log.unsplit &&\n+\t\ttest_i18ngrep \"remote: Total 3 \" log.unsplit\n+\tfi\n '\n \n test_expect_success 'in_vain resetted upon ACK' '\n\nbase-commit: d4a392452e292ff924e79ec8458611c0f679d6d4\n-- \ngitgitgadget\n"},{"id":"407464","messageId":"xmqqy2kaj9m3.fsf@gitster.c.googlers.com","threadId":"54407","inReplyTo":"pull.753.git.1602600323973.gitgitgadget@gmail.com","subject":"Re: [PATCH] t5500.43: make the check a bit more robust","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2020-10-13T17:53:24Z","receivedAt":"2020-10-13T17:53:34Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"\"Johannes Schindelin via GitGitGadget\" \nwrites:\n\n> Note: we have code in `demultiplex_sideband()` _specifically_ to stitch\n> back together lines that were delivered in separate sideband packets.\n> However, this stitching fails when a primary packet is delivered in\n> between the two sideband packets: since a primary packet was received,\n> `demultiplex_sideband()` has to return that (and cannot wait for other\n> sideband packets, and therefore has to flush any incomplete line it\n> received).\n\nOuch. Good find.\n\n> \tgit -C myclient fetch --progress origin 2>log &&\n> -\ttest_i18ngrep \"remote: Total 3 \" log\n> +\tif ! test_i18ngrep \"remote: Total 3 \" log\n> +\tthen\n> +\t\t# It is possible that the \"Total 3\" line is delivered in\n> +\t\t# multiple sideband packets, and that a primary packet is\n> +\t\t# delivered in between. When that happens, the line will be\n> +\t\t# presented on multiple \"remote:\" lines.\n> +\t\tsed \"/^remote: T/{\n> +\t\t\t:a\n> +\t\t\tN\n> +\t\t\ts/\\nremote: //\n> +\t\t\tba\n\nOK, so if we see multiple and adjacent \"remote:\" lines, we strip the\nleading \"remote: \" prefix from the second and subsequent lines and\nconcatenate them into one giant line? Sounds good.\n\nWill queue. Thanks.\n\n> +\t\t}\" log >log.unsplit &&\n> +\t\ttest_i18ngrep \"remote: Total 3 \" log.unsplit\n> +\tfi\n> '\n> \n> test_expect_success 'in_vain resetted upon ACK' '\n>\n> base-commit: d4a392452e292ff924e79ec8458611c0f679d6d4\n"},{"id":"407468","messageId":"20201013185515.GA2994107@coredump.intra.peff.net","threadId":"54407","inReplyTo":"pull.753.git.1602600323973.gitgitgadget@gmail.com","subject":"Re: [PATCH] t5500.43: make the check a bit more robust","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2020-10-13T18:55:15Z","receivedAt":"2020-10-13T18:55:18Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Tue, Oct 13, 2020 at 02:45:23PM +0000, Johannes Schindelin via GitGitGadget wrote:\n\n> Note: we have code in `demultiplex_sideband()` _specifically_ to stitch\n> back together lines that were delivered in separate sideband packets.\n> However, this stitching fails when a primary packet is delivered in\n> between the two sideband packets: since a primary packet was received,\n> `demultiplex_sideband()` has to return that (and cannot wait for other\n> sideband packets, and therefore has to flush any incomplete line it\n> received).\n\nThis sounds like a bug. We should accumulate multiple sideband 2\npackets, even across data packets. And I think we _used_ to do that. The\noriginal recv_sideband() looked roughly like this:\n\n\twhile (!retval) {\n\t\t packet_read();\n\t\t band = buf[0] & 0xff;\n\t\t switch (band) {\n\t\t case 3:\n\t\t ...stuff data into outbuf...\n\t\t retval = SIDEBAND_ERROR_REMOTE;\n\t\t break;\n\t\t case 2:\n\t\t ...print full lines, stuff remainder into outbuf...\n\t\t break; /* note, does _not_ set retval */\n\t\t case 1:\n\t\t write_or_die(out, buf + 1, len);\n\t\t break; /* likewise, does not set retval */\n\t\t default:\n\t\t ...complain about broken sideband...\n\t\t retval = SIDEBAND_PROTOCOL_ERROR;\n\t\t}\n\t}\n\tif (outbuf.len)\n\t\t...print outbuf...\n\nSo we would keep looping until we see EOF, sideband 3, or a protocol\nerror. But notably we would not break out of the loop on bands 1 or 2,\nand we do not flush band 2 until we break out of the loop.\n\nBut then in fbd76cd450 (sideband: reverse its dependency on pkt-line,\n2019-01-16), the function became demultiplex_sideband(). The loop went\naway, and we pump only a single packet on each call. When we see\nsideband 2, we do an early return. But on sideband 1, we continue to the\ncleanup: label, which flushes the scratch buffer.\n\nI think we need to return from there without hitting that cleanup label,\nlike this:\n\ndiff --git a/sideband.c b/sideband.c\nindex 0a60662fa6..a5405b9aaa 100644\n--- a/sideband.c\n+++ b/sideband.c\n@@ -190,7 +190,7 @@ int demultiplex_sideband(const char *me, char *buf, int len,\n \t\treturn 0;\n \tcase 1:\n \t\t*sideband_type = SIDEBAND_PRIMARY;\n-\t\tbreak;\n+\t\treturn 1;\n \tdefault:\n \t\tstrbuf_addf(scratch, \"%s%s: protocol error: bad band #%d\",\n \t\t\t scratch->len ? \"\\n\" : \"\", me, band);\n\nDoes that make the problem go away for you?\n\n> Work around flakiness in t5500.43\n> \n> It seems that this test became flaky only recently, although I have to\n> admit that I have no idea why: the involved code does not seem to have\n> changed recently at all. It should have been fixed by \n> https://lore.kernel.org/git/20200506220741.71021-1-jonathantanmy@google.com/\n> , but apparently wasn't completely fixed, despite what I said in that\n> thread.\n\nI think this is a real bug, and we shouldn't be changing the tests to\naccommodate. Users may actually see the broken lines, and our tests are\ntelling us that.\n\nI suspect it's uncommon in practice because it requires the server side\nalso splitting the line across two packets. And while the server-side\nupload-pack might get a partial write from a child pack-objects or\nwhatever, that should only happen if:\n\n - the pipe buffer fills up. Which is hard to do since our messages\n tend to be very small. So perhaps it implies a very tiny pipe\n buffer, and/or slow scheduling of the receiving side to actually\n clean it out.\n\n - the writer is fully buffering its stderr writes instead of sending\n them a line at a time\n\nThe latter seems a more likely candidate for switching from gcc to\nVisual C (which presumably has a different libc / CRT). I think the\nclient should be handling this more robustly, but it may be worth\ndigging into the buffering issue if it means progress may not be\ndelivered in quite as timely a way as we expect it to be.\n\n-Peff\n"},{"id":"407471","messageId":"xmqqtuuyj677.fsf@gitster.c.googlers.com","threadId":"54407","inReplyTo":"20201013185515.GA2994107@coredump.intra.peff.net","subject":"Re: [PATCH] t5500.43: make the check a bit more robust","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2020-10-13T19:07:08Z","receivedAt":"2020-10-13T19:07:16Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Jeff King writes:\n\n>> Work around flakiness in t5500.43\n>> \n>> It seems that this test became flaky only recently, although I have to\n>> admit that I have no idea why: the involved code does not seem to have\n>> changed recently at all. It should have been fixed by \n>> https://lore.kernel.org/git/20200506220741.71021-1-jonathantanmy@google.com/\n>> , but apparently wasn't completely fixed, despite what I said in that\n>> thread.\n>\n> I think this is a real bug, and we shouldn't be changing the tests to\n> accommodate. Users may actually see the broken lines, and our tests are\n> telling us that.\n\nTrue; I reacted too hastily. Will not queue the workaround ;-)\n\n"},{"id":"407472","messageId":"20201013190913.GB2994107@coredump.intra.peff.net","threadId":"54407","inReplyTo":"20201013185515.GA2994107@coredump.intra.peff.net","subject":"Re: [PATCH] t5500.43: make the check a bit more robust","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2020-10-13T19:09:13Z","receivedAt":"2020-10-13T19:09:16Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Tue, Oct 13, 2020 at 02:55:15PM -0400, Jeff King wrote:\n\n> But then in fbd76cd450 (sideband: reverse its dependency on pkt-line,\n> 2019-01-16), the function became demultiplex_sideband(). The loop went\n> away, and we pump only a single packet on each call. When we see\n> sideband 2, we do an early return. But on sideband 1, we continue to the\n> cleanup: label, which flushes the scratch buffer.\n> \n> I think we need to return from there without hitting that cleanup label,\n> like this:\n\nBy the way, the reason this works is that the \"scratch\" buffer persists\nbeyond individual calls to demultiplex_sideband(). So we can get away\nwith letting it persist between the two.\n\nHowever unlike the original recv_sideband(), which broke out of the loop\non error and then flushed scratch, our post-fbd76cd450 does not do the\nsame. It now looks like:\n\nint recv_sideband(const char *me, int in_stream, int out)\n{\n char buf[LARGE_PACKET_MAX + 1];\n int len;\n struct strbuf scratch = STRBUF_INIT;\n enum sideband_type sideband_type;\n\n while (1) {\n len = packet_read(in_stream, NULL, NULL, buf, LARGE_PACKET_MAX,\n 0);\n if (!demultiplex_sideband(me, buf, len, 0, &scratch,\n &sideband_type))\n continue;\n switch (sideband_type) {\n case SIDEBAND_PRIMARY:\n write_or_die(out, buf + 1, len - 1);\n break;\n default: /* errors: message already written */\n return sideband_type;\n }\n }\n}\n\nI wondered if we could ever have a case where we broke out of the loop\nwith data left over in \"scratch\" (or its buffer left allocated). I think\nthe answer is no. We only break out of the loop if\ndemultiplex_sideband() returned non-zero _and_ its not the primary\nsideband. So both before and after my suggested fix, we'd have hit the\ncleanup label in demultiplex_sideband(), which flushes and frees the\nbuffer.\n\nI do have to say that the original loop before that commit was a lot\neasier to follow, though.\n\nAnother weirdness I noticed is that it doesn't distinguish a flush\npacket (expected) from a zero-byte packet (an error). But neither did\nthe original. I would have guessed the zero-byte packet was meant to\ntrigger this second conditional:\n\n if (len == 0) {\n *sideband_type = SIDEBAND_FLUSH;\n goto cleanup;\n }\n if (len < 1) {\n strbuf_addf(scratch,\n \"%s%s: protocol error: no band designator\",\n scratch->len ? \"\\n\" : \"\", me);\n *sideband_type = SIDEBAND_PROTOCOL_ERROR;\n goto cleanup;\n }\n\nbut we'd hit the first conditional before then. We would still trigger\nthe second if we saw EOF while reading the packet (because we set the\nlength to -1 then), but then it's arguably the wrong error to be\nshowing.\n\nSo I think this could be improved a bit by using\npacket_read_with_status() in the recv_sideband() caller.\n\n-Peff\n"},{"id":"407841","messageId":"nycvar.QRO.7.76.6.2010170429200.56@tvgsbejvaqbjf.bet","threadId":"54407","inReplyTo":"20201013185515.GA2994107@coredump.intra.peff.net","subject":"Re: [PATCH] t5500.43: make the check a bit more robust","fromName":"Johannes Schindelin","fromEmail":"johannes.schindelin@gmx.de","sentAt":"2020-10-17T02:34:27Z","receivedAt":"2020-10-18T09:45:00Z","isPatch":true,"sender":{"key":"johannes.schindelin@gmx.de","avatar":"https://avatars.githubusercontent.com/u/127790?v=4"},"body":"Hi Peff,\n\nOn Tue, 13 Oct 2020, Jeff King wrote:\n\n> On Tue, Oct 13, 2020 at 02:45:23PM +0000, Johannes Schindelin via GitGitGadget wrote:\n>\n> > Note: we have code in `demultiplex_sideband()` _specifically_ to stitch\n> > back together lines that were delivered in separate sideband packets.\n> > However, this stitching fails when a primary packet is delivered in\n> > between the two sideband packets: since a primary packet was received,\n> > `demultiplex_sideband()` has to return that (and cannot wait for other\n> > sideband packets, and therefore has to flush any incomplete line it\n> > received).\n>\n> This sounds like a bug. We should accumulate multiple sideband 2\n> packets, even across data packets. And I think we _used_ to do that. The\n> original recv_sideband() looked roughly like this:\n>\n> \twhile (!retval) {\n> \t\t packet_read();\n> \t\t band = buf[0] & 0xff;\n> \t\t switch (band) {\n> \t\t case 3:\n> \t\t ...stuff data into outbuf...\n> \t\t retval = SIDEBAND_ERROR_REMOTE;\n> \t\t break;\n> \t\t case 2:\n> \t\t ...print full lines, stuff remainder into outbuf...\n> \t\t break; /* note, does _not_ set retval */\n> \t\t case 1:\n> \t\t write_or_die(out, buf + 1, len);\n> \t\t break; /* likewise, does not set retval */\n> \t\t default:\n> \t\t ...complain about broken sideband...\n> \t\t retval = SIDEBAND_PROTOCOL_ERROR;\n> \t\t}\n> \t}\n> \tif (outbuf.len)\n> \t\t...print outbuf...\n>\n> So we would keep looping until we see EOF, sideband 3, or a protocol\n> error. But notably we would not break out of the loop on bands 1 or 2,\n> and we do not flush band 2 until we break out of the loop.\n>\n> But then in fbd76cd450 (sideband: reverse its dependency on pkt-line,\n> 2019-01-16), the function became demultiplex_sideband(). The loop went\n> away, and we pump only a single packet on each call. When we see\n> sideband 2, we do an early return. But on sideband 1, we continue to the\n> cleanup: label, which flushes the scratch buffer.\n>\n> I think we need to return from there without hitting that cleanup label,\n> like this:\n>\n> diff --git a/sideband.c b/sideband.c\n> index 0a60662fa6..a5405b9aaa 100644\n> --- a/sideband.c\n> +++ b/sideband.c\n> @@ -190,7 +190,7 @@ int demultiplex_sideband(const char *me, char *buf, int len,\n> \t\treturn 0;\n> \tcase 1:\n> \t\t*sideband_type = SIDEBAND_PRIMARY;\n> -\t\tbreak;\n> +\t\treturn 1;\n> \tdefault:\n> \t\tstrbuf_addf(scratch, \"%s%s: protocol error: bad band #%d\",\n> \t\t\t scratch->len ? \"\\n\" : \"\", me, band);\n>\n> Does that make the problem go away for you?\n\nYes. But it took a substantial amount of time for myself to convince\nmyself that this oneliner is actually correct.\n\n>\n> > Work around flakiness in t5500.43\n> >\n> > It seems that this test became flaky only recently, although I have to\n> > admit that I have no idea why: the involved code does not seem to have\n> > changed recently at all. It should have been fixed by\n> > https://lore.kernel.org/git/20200506220741.71021-1-jonathantanmy@google.com/\n> > , but apparently wasn't completely fixed, despite what I said in that\n> > thread.\n>\n> I think this is a real bug, and we shouldn't be changing the tests to\n> accommodate. Users may actually see the broken lines, and our tests are\n> telling us that.\n>\n> I suspect it's uncommon in practice because it requires the server side\n> also splitting the line across two packets. And while the server-side\n> upload-pack might get a partial write from a child pack-objects or\n> whatever, that should only happen if:\n>\n> - the pipe buffer fills up. Which is hard to do since our messages\n> tend to be very small. So perhaps it implies a very tiny pipe\n> buffer, and/or slow scheduling of the receiving side to actually\n> clean it out.\n>\n> - the writer is fully buffering its stderr writes instead of sending\n> them a line at a time\n>\n> The latter seems a more likely candidate for switching from gcc to\n> Visual C (which presumably has a different libc / CRT). I think the\n> client should be handling this more robustly, but it may be worth\n> digging into the buffering issue if it means progress may not be\n> delivered in quite as timely a way as we expect it to be.\n\nFWIW I _think_ the issue at hand is that newer MSVC runtimes deliver\n`stderr` byte-by-byte. While that is totally allowed, it is different from\nhow things seem to be done on Linux/Unix/Darwin.\n\nIn my tests, I frequently saw the first two or four characters of that\n\"Total 3\" line be delivered in its own sideband packet, hence the\nbreakage.\n\nThank you for keeping me honest. I would much rather have avoided spending\nseveral hours on this investigation, but in the end, it is something that\nis better made correct than left incorrect.\n\nHaving said that it is neither a very new bug nor does it seem to matter\non Linux/macOS (and not even in Git for Windows because it is built using\nmingw-w64-gcc, which uses an older MSVC runtime, which apparently does not\nshare that issue with newer versions), therefore I plan on sending off v2\nonly after v2.29.0 was published.\n\nCiao,\nDscho\n"},{"id":"407842","messageId":"nycvar.QRO.7.76.6.2010170434340.56@tvgsbejvaqbjf.bet","threadId":"54407","inReplyTo":"20201013190913.GB2994107@coredump.intra.peff.net","subject":"Re: [PATCH] t5500.43: make the check a bit more robust","fromName":"Johannes Schindelin","fromEmail":"johannes.schindelin@gmx.de","sentAt":"2020-10-17T03:31:18Z","receivedAt":"2020-10-18T10:42:22Z","isPatch":true,"sender":{"key":"johannes.schindelin@gmx.de","avatar":"https://avatars.githubusercontent.com/u/127790?v=4"},"body":"Hi Peff,\n\nOn Tue, 13 Oct 2020, Jeff King wrote:\n\n> On Tue, Oct 13, 2020 at 02:55:15PM -0400, Jeff King wrote:\n>\n> > But then in fbd76cd450 (sideband: reverse its dependency on pkt-line,\n> > 2019-01-16), the function became demultiplex_sideband(). The loop went\n> > away, and we pump only a single packet on each call. When we see\n> > sideband 2, we do an early return. But on sideband 1, we continue to the\n> > cleanup: label, which flushes the scratch buffer.\n> >\n> > I think we need to return from there without hitting that cleanup label,\n> > like this:\n>\n> By the way, the reason this works is that the \"scratch\" buffer persists\n> beyond individual calls to demultiplex_sideband(). So we can get away\n> with letting it persist between the two.\n\nThe thing that threw me was that I somehow expected `recv_sideband()` to\nreturn primary data as it is read, much like `read()` operates. And yes,\nI also found the split version of the code (`recv_sideband()` contains the\n`while` loop and lives in `pkt-line.c` while `demultiplex_sideband()`\ncontains the `scratch` handling and the `switch` between packet types and\nit lives in `sideband.c`) was much harder to read than the original\nversion.\n\n> However unlike the original recv_sideband(), which broke out of the loop\n> on error and then flushed scratch, our post-fbd76cd450 does not do the\n> same. It now looks like:\n>\n> int recv_sideband(const char *me, int in_stream, int out)\n> {\n> char buf[LARGE_PACKET_MAX + 1];\n> int len;\n> struct strbuf scratch = STRBUF_INIT;\n> enum sideband_type sideband_type;\n>\n> while (1) {\n> len = packet_read(in_stream, NULL, NULL, buf, LARGE_PACKET_MAX,\n> 0);\n> if (!demultiplex_sideband(me, buf, len, 0, &scratch,\n> &sideband_type))\n> continue;\n> switch (sideband_type) {\n> case SIDEBAND_PRIMARY:\n> write_or_die(out, buf + 1, len - 1);\n> break;\n> default: /* errors: message already written */\n> return sideband_type;\n> }\n> }\n> }\n>\n> I wondered if we could ever have a case where we broke out of the loop\n> with data left over in \"scratch\" (or its buffer left allocated). I think\n> the answer is no. We only break out of the loop if\n> demultiplex_sideband() returned non-zero _and_ its not the primary\n> sideband. So both before and after my suggested fix, we'd have hit the\n> cleanup label in demultiplex_sideband(), which flushes and frees the\n> buffer.\n\nRight.\n\nIt took me quite a while to convince myself of that, too.\n\nAnd since I am really worried that the complexity of the code makes it\neasy to introduce a regression, I spent quite a bit of time to figure out\nhow to implement a good regression test for exactly this issue.\n\nEven so, the regression test will not necessarily catch problems where the\n`while` loop is abandoned without processing any unfinished sideband\nmessage. I introduced a `BUG()` for that case, but it is quite a bit\nunsatisfying that I could not come up with a better way to ensure that\nthis does not happen.\n\n> I do have to say that the original loop before that commit was a lot\n> easier to follow, though.\n>\n> Another weirdness I noticed is that it doesn't distinguish a flush\n> packet (expected) from a zero-byte packet (an error). But neither did\n> the original. I would have guessed the zero-byte packet was meant to\n> trigger this second conditional:\n>\n> if (len == 0) {\n> *sideband_type = SIDEBAND_FLUSH;\n> goto cleanup;\n> }\n> if (len < 1) {\n> strbuf_addf(scratch,\n> \"%s%s: protocol error: no band designator\",\n> scratch->len ? \"\\n\" : \"\", me);\n> *sideband_type = SIDEBAND_PROTOCOL_ERROR;\n> goto cleanup;\n> }\n>\n> but we'd hit the first conditional before then. We would still trigger\n> the second if we saw EOF while reading the packet (because we set the\n> length to -1 then), but then it's arguably the wrong error to be\n> showing.\n>\n> So I think this could be improved a bit by using\n> packet_read_with_status() in the recv_sideband() caller.\n\nPossibly. But is it really a bug to send a zero-byte packet? It is\ninefficient, sure. But I could see how it could potentially simplify code,\nor serve e.g. as some sort of a \"keep-alive\" mechanism or whatever.\n\nIn other words, I am not sure that we should treat this as an error, but\nyes, we should probably not treat it as a flush (even if it is likely that\nour current sideband users simply won't ever send empty primary packets).\n\nCiao,\nDscho\n"},{"id":"407906","messageId":"e4ba96358b7c5d2b4148c5529a3c253dc0d1f358.1603136143.git.gitgitgadget@gmail.com","threadId":"54407","inReplyTo":"pull.753.v2.git.1603136142.gitgitgadget@gmail.com","subject":"[PATCH v2 1/3] sideband: avoid reporting incomplete sideband messages","fromName":"Johannes Schindelin via GitGitGadget","fromEmail":"gitgitgadget@gmail.com","sentAt":"2020-10-19T19:35:40Z","receivedAt":"2020-10-19T19:35:48Z","isPatch":true,"sender":{"key":"johannes.schindelin@gmx.de","avatar":"https://avatars.githubusercontent.com/u/127790?v=4"},"body":"From: Johannes Schindelin \n\nIn 2b695ecd74d (t5500: count objects through stderr, not trace,\n2020-05-06) we tried to ensure that the \"Total 3\" message could be\ngrepped in Git's output, even if it sometimes got chopped up into\nmultiple lines in the trace machinery.\n\nHowever, the first instance where this mattered now goes through the\nsideband machinery, where it is _still_ possible for messages to get\nchopped up: it *is* possible for the standard error stream to be sent\nbyte-for-byte and hence it can be easily interrupted. Meaning: it is\npossible for the single line that we're looking for to be chopped up\ninto multiple sideband packets, with a primary packet being delivered\nbetween them.\n\nThis seems to happen occasionally in the `vs-test` part of our CI\nbuilds, i.e. with binaries built using Visual C, but not when building\nwith GCC or clang; The symptom is that t5500.43 fails to find a line\nmatching `remote: Total 3` in the `log` file, which ends in something\nalong these lines:\n\n\tremote: Tota\n\tremote: l 3 (delta 0), reused 0 (delta 0), pack-reused 0\n\nThis should not happen, though: we have code in `demultiplex_sideband()`\n_specifically_ to stitch back together lines that were delivered in\nseparate sideband packets.\n\nHowever, this stitching was broken in a subtle way in fbd76cd450\n(sideband: reverse its dependency on pkt-line, 2019-01-16): before that\nchange, incomplete sideband lines would not be flushed upon receiving a\nprimary packet, but after that patch, they would be.\n\nThe subtleness of this bug comes from the fact that it is easy to get\nconfused by the ambiguous meaning of the `break` keyword: after writing\nthe primary packet contents, the `break;` in the original version of\n`recv_sideband()` does _not_ break out of the `while` loop, but instead\nonly ends the `switch` case:\n\n\twhile (!retval) {\n\t\t[...]\n\t\tswitch (band) {\n\t\t\t[...]\n\t\tcase 1:\n/* Write the contents of the primary packet */\n\t\t\twrite_or_die(out, buf + 1, len);\n/* Here, we do *not* break out of the loop, `retval` is unchanged */\n\t\t\tbreak;\n\t\t[...]\n\t}\n\n\tif (outbuf.len) {\n/* Write any remaining sideband messages lacking a trailing LF */\n\t\tstrbuf_addch(&outbuf, '\\n');\n\t\txwrite(2, outbuf.buf, outbuf.len);\n\t}\n\nIn contrast, after fbd76cd450 (sideband: reverse its dependency on\npkt-line, 2019-01-16), the body of the `while` loop was extracted into\n`demultiplex_sideband()`, crucially _including_ the logic to write\nincomplete sideband messages:\n\n\tswitch (band) {\n\t[...]\n\tcase 1:\n\t\t*sideband_type = SIDEBAND_PRIMARY;\n/* This does not break out of the loop: the loop is in the caller */\n\t\tbreak;\n\t[...]\n\t}\n\ncleanup:\n\t[...]\n/* This logic is now no longer _outside_ the loop but _inside_ */\n\tif (scratch->len) {\n\t\tstrbuf_addch(scratch, '\\n');\n\t\txwrite(2, scratch->buf, scratch->len);\n\t}\n\nThe correct way to fix this is to return from `demultiplex_sideband()`\nearly. The caller will then write out the contents of the primary packet\nand continue looping. The `scratch` buffer for incomplete sideband\nmessages is owned by that caller, and will continue to accumulate the\nremainder(s) of those messages. The loop will only end once\n`demultiplex_sideband()` returned non-zero _and_ did not indicate a\nprimary packet, which is the case only when we hit the `cleanup:` path,\nin which we take care of flushing any unfinished sideband messages and\nrelease the `scratch` buffer.\n\nTo ensure that this does not get broken again, we introduce a pair of\nsubcommands of the `pkt-line` test helper that specifically chop up the\nsideband message and squeeze a primary packet into the middle.\n\nFinal note: The other test case touched by 2b695ecd74d (t5500: count\nobjects through stderr, not trace, 2020-05-06) is not affected by this\nissue because the sideband machinery is not involved there.\n\nSigned-off-by: Johannes Schindelin \n---\n sideband.c | 2 +-\n t/helper/test-pkt-line.c | 23 +++++++++++++++++++++++\n t/t0070-fundamental.sh | 6 ++++++\n 3 files changed, 30 insertions(+), 1 deletion(-)\n\ndiff --git a/sideband.c b/sideband.c\nindex 0a60662fa6..a5405b9aaa 100644\n--- a/sideband.c\n+++ b/sideband.c\n@@ -190,7 +190,7 @@ int demultiplex_sideband(const char *me, char *buf, int len,\n \t\treturn 0;\n \tcase 1:\n \t\t*sideband_type = SIDEBAND_PRIMARY;\n-\t\tbreak;\n+\t\treturn 1;\n \tdefault:\n \t\tstrbuf_addf(scratch, \"%s%s: protocol error: bad band #%d\",\n \t\t\t scratch->len ? \"\\n\" : \"\", me, band);\ndiff --git a/t/helper/test-pkt-line.c b/t/helper/test-pkt-line.c\nindex 69152958e5..0bf20642be 100644\n--- a/t/helper/test-pkt-line.c\n+++ b/t/helper/test-pkt-line.c\n@@ -84,6 +84,25 @@ static void unpack_sideband(void)\n \t}\n }\n \n+static int send_split_sideband(void)\n+{\n+\tconst char *part1 = \"Hello,\";\n+\tconst char *primary = \"\\001primary: regular output\\n\";\n+\tconst char *part2 = \" world!\\n\";\n+\n+\tsend_sideband(1, 2, part1, strlen(part1), LARGE_PACKET_MAX);\n+\tpacket_write(1, primary, strlen(primary));\n+\tsend_sideband(1, 2, part2, strlen(part2), LARGE_PACKET_MAX);\n+\tpacket_response_end(1);\n+\n+\treturn 0;\n+}\n+\n+static int receive_sideband(void)\n+{\n+\treturn recv_sideband(\"sideband: \", 0, 1);\n+}\n+\n int cmd__pkt_line(int argc, const char **argv)\n {\n \tif (argc < 2)\n@@ -95,6 +114,10 @@ int cmd__pkt_line(int argc, const char **argv)\n \t\tunpack();\n \telse if (!strcmp(argv[1], \"unpack-sideband\"))\n \t\tunpack_sideband();\n+\telse if (!strcmp(argv[1], \"send-split-sideband\"))\n+\t\tsend_split_sideband();\n+\telse if (!strcmp(argv[1], \"receive-sideband\"))\n+\t\treceive_sideband();\n \telse\n \t\tdie(\"invalid argument '%s'\", argv[1]);\n \ndiff --git a/t/t0070-fundamental.sh b/t/t0070-fundamental.sh\nindex 7b111a56fd..357201640a 100755\n--- a/t/t0070-fundamental.sh\n+++ b/t/t0070-fundamental.sh\n@@ -34,4 +34,10 @@ test_expect_success 'check for a bug in the regex routines' '\n \ttest-tool regex --bug\n '\n \n+test_expect_success 'incomplete sideband messages are reassembled' '\n+\ttest-tool pkt-line send-split-sideband >split-sideband &&\n+\ttest-tool pkt-line receive-sideband err &&\n+\tgrep \"Hello, world\" err\n+'\n+\n test_done\n-- \ngitgitgadget\n\n"},{"id":"407905","messageId":"9ffcc5b78e358d0ed4da2c52ba87174dc94e544c.1603136143.git.gitgitgadget@gmail.com","threadId":"54407","inReplyTo":"pull.753.v2.git.1603136142.gitgitgadget@gmail.com","subject":"[PATCH v2 2/3] sideband: report unhandled incomplete sideband messages as bugs","fromName":"Johannes Schindelin via GitGitGadget","fromEmail":"gitgitgadget@gmail.com","sentAt":"2020-10-19T19:35:41Z","receivedAt":"2020-10-19T19:35:49Z","isPatch":true,"sender":{"key":"johannes.schindelin@gmx.de","avatar":"https://avatars.githubusercontent.com/u/127790?v=4"},"body":"From: Johannes Schindelin \n\nIt was pretty tricky to verify that incomplete sideband messages are\nhandled correctly by the `recv_sideband()`/`demultiplex_sideband()`\ncode: they have to be flushed out at the end of the loop in\n`recv_sideband()`, but the actual flushing is done by the\n`demultiplex_sideband()` function (which therefore has to know somehow\nthat the loop will be done after it returns).\n\nTo catch future bugs where incomplete sideband messages might not be\nshown by mistake, let's catch that condition and report a bug.\n\nSigned-off-by: Johannes Schindelin \n---\n pkt-line.c | 3 +++\n 1 file changed, 3 insertions(+)\n\ndiff --git a/pkt-line.c b/pkt-line.c\nindex 844c253ccd..657a702927 100644\n--- a/pkt-line.c\n+++ b/pkt-line.c\n@@ -471,6 +471,9 @@ int recv_sideband(const char *me, int in_stream, int out)\n \t\t\twrite_or_die(out, buf + 1, len - 1);\n \t\t\tbreak;\n \t\tdefault: /* errors: message already written */\n+\t\t\tif (scratch.len > 0)\n+\t\t\t\tBUG(\"unhandled incomplete sideband: '%s'\",\n+\t\t\t\t scratch.buf);\n \t\t\treturn sideband_type;\n \t\t}\n \t}\n-- \ngitgitgadget\n\n"},{"id":"407907","messageId":"pull.753.v2.git.1603136142.gitgitgadget@gmail.com","threadId":"54407","inReplyTo":"pull.753.git.1602600323973.gitgitgadget@gmail.com","subject":"[PATCH v2 0/3] Work around flakiness in t5500.43","fromName":"Johannes Schindelin via GitGitGadget","fromEmail":"gitgitgadget@gmail.com","sentAt":"2020-10-19T19:35:39Z","receivedAt":"2020-10-19T19:35:49Z","isPatch":true,"sender":{"key":"johannes.schindelin@gmx.de","avatar":"https://avatars.githubusercontent.com/u/127790?v=4"},"body":"It seems that this test became flaky only recently, although I have to admit\nthat I have no idea why: the involved code does not seem to have changed\nrecently at all. It should have been fixed by \nhttps://lore.kernel.org/git/20200506220741.71021-1-jonathantanmy@google.com/\n, but apparently wasn't completely fixed, despite what I said in that\nthread.\n\nChanges since v1:\n\n * Instead of papering over the underlying cause, the patch was completely\n changed to actually fix the bug and add a proper regression test for it\n (originally, I wanted to act according to the common notion that good\n programmers are lazy, oh my, see how well that worked out for me).\n * We now specifically watch out for future bugs where incomplete sideband\n messages would be dropped inadvertently rather than being reported at EOF\n or at encountering a flush/error packet.\n * Before sending 0-length data to demultiplex_sideband(), we now make sure\n that it is not marked as a data packet; Otherwise we now complain loudly\n about a bug.\n\nJohannes Schindelin (3):\n sideband: avoid reporting incomplete sideband messages\n sideband: report unhandled incomplete sideband messages as bugs\n sideband: add defense against packets missing a band designator\n\n pkt-line.c | 11 +++++++++--\n sideband.c | 2 +-\n t/helper/test-pkt-line.c | 23 +++++++++++++++++++++++\n t/t0070-fundamental.sh | 6 ++++++\n 4 files changed, 39 insertions(+), 3 deletions(-)\n\n\nbase-commit: d4a392452e292ff924e79ec8458611c0f679d6d4\nPublished-As: https://github.com/gitgitgadget/git/releases/tag/pr-753%2Fdscho%2Funflake-t5500.43-v2\nFetch-It-Via: git fetch https://github.com/gitgitgadget/git pr-753/dscho/unflake-t5500.43-v2\nPull-Request: https://github.com/gitgitgadget/git/pull/753\n\nRange-diff vs v1:\n\n 1: d977644184 < -: ---------- t5500.43: make the check a bit more robust\n -: ---------- > 1: e4ba96358b sideband: avoid reporting incomplete sideband messages\n -: ---------- > 2: 9ffcc5b78e sideband: report unhandled incomplete sideband messages as bugs\n -: ---------- > 3: c61e560451 sideband: add defense against packets missing a band designator\n\n-- \ngitgitgadget\n"},{"id":"407908","messageId":"c61e560451c4d7f101a23acec69117ddac563330.1603136143.git.gitgitgadget@gmail.com","threadId":"54407","inReplyTo":"pull.753.v2.git.1603136142.gitgitgadget@gmail.com","subject":"[PATCH v2 3/3] sideband: add defense against packets missing a band designator","fromName":"Johannes Schindelin via GitGitGadget","fromEmail":"gitgitgadget@gmail.com","sentAt":"2020-10-19T19:35:42Z","receivedAt":"2020-10-19T19:35:51Z","isPatch":true,"sender":{"key":"johannes.schindelin@gmx.de","avatar":"https://avatars.githubusercontent.com/u/127790?v=4"},"body":"From: Johannes Schindelin \n\nWhile there is currently no instance of code producing this type of\npacket, if the `demultiplex_sideband()` would receive a packet whose\npayload is not only empty but even misses the band designator, it would\nmistake it for a flush packet.\n\nLet's defend against such a bug in the future.\n\nNote: `demultiplex_sideband()` will treat empty flush, delim, eof and\nresponse-end packets all alike: it will treat them as flush packets.\nSince empty packets by definition are missing a band designator, this is\nthe best that function can do. Therefore, it would make little sense to\npass the `status` on to `demultiplex_sideband()`. Besides, fbd76cd450\n(sideband: reverse its dependency on pkt-line, 2019-01-16) went out of\nits way to _stop_ the code inside `demultiplex_sideband()` from relying\non anything in `pkt-line.h`; that includes the data type `enum\npacket_read_status` that we would need if we were to pass `status` as a\nparameter to that function.\n\nBased on a suggestion by Jeff King.\n\nSigned-off-by: Johannes Schindelin \n---\n pkt-line.c | 8 ++++++--\n 1 file changed, 6 insertions(+), 2 deletions(-)\n\ndiff --git a/pkt-line.c b/pkt-line.c\nindex 657a702927..f72048f623 100644\n--- a/pkt-line.c\n+++ b/pkt-line.c\n@@ -461,8 +461,10 @@ int recv_sideband(const char *me, int in_stream, int out)\n \tenum sideband_type sideband_type;\n \n \twhile (1) {\n-\t\tlen = packet_read(in_stream, NULL, NULL, buf, LARGE_PACKET_MAX,\n-\t\t\t\t 0);\n+\t\tint status = packet_read_with_status(in_stream, NULL, NULL, buf,\n+\t\t\t\t\t\t LARGE_PACKET_MAX, &len, 0);\n+\t\tif (!len && status == PACKET_READ_NORMAL)\n+\t\t\tBUG(\"missing band designator\");\n \t\tif (!demultiplex_sideband(me, buf, len, 0, &scratch,\n \t\t\t\t\t &sideband_type))\n \t\t\tcontinue;\n@@ -520,6 +522,8 @@ enum packet_read_status packet_reader_read(struct packet_reader *reader)\n \t\t\t\t\t\t\t reader->options);\n \t\tif (!reader->use_sideband)\n \t\t\tbreak;\n+\t\tif (!reader->pktlen && reader->status == PACKET_READ_NORMAL)\n+\t\t\tBUG(\"missing band designator\");\n \t\tif (demultiplex_sideband(reader->me, reader->buffer,\n \t\t\t\t\t reader->pktlen, 1, &scratch,\n \t\t\t\t\t &sideband_type))\n-- \ngitgitgadget\n"},{"id":"408012","messageId":"xmqqwnzkab85.fsf@gitster.c.googlers.com","threadId":"54407","inReplyTo":"e4ba96358b7c5d2b4148c5529a3c253dc0d1f358.1603136143.git.gitgitgadget@gmail.com","subject":"Re: [PATCH v2 1/3] sideband: avoid reporting incomplete sideband messages","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2020-10-20T20:33:46Z","receivedAt":"2020-10-20T20:33:51Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"\"Johannes Schindelin via GitGitGadget\" \nwrites:\n\n> From: Johannes Schindelin \n>\n> In 2b695ecd74d (t5500: count objects through stderr, not trace,\n> 2020-05-06) we tried to ensure that the \"Total 3\" message could be\n> grepped in Git's output, even if it sometimes got chopped up into\n> multiple lines in the trace machinery.\n> ...\n> The correct way to fix this is to return from `demultiplex_sideband()`\n> early. The caller will then write out the contents of the primary packet\n> and continue looping. The `scratch` buffer for incomplete sideband\n> messages is owned by that caller, and will continue to accumulate the\n> remainder(s) of those messages. The loop will only end once\n> `demultiplex_sideband()` returned non-zero _and_ did not indicate a\n> primary packet, which is the case only when we hit the `cleanup:` path,\n> in which we take care of flushing any unfinished sideband messages and\n> release the `scratch` buffer.\n>\n> To ensure that this does not get broken again, we introduce a pair of\n> subcommands of the `pkt-line` test helper that specifically chop up the\n> sideband message and squeeze a primary packet into the middle.\n>\n> Final note: The other test case touched by 2b695ecd74d (t5500: count\n> objects through stderr, not trace, 2020-05-06) is not affected by this\n> issue because the sideband machinery is not involved there.\n>\n> Signed-off-by: Johannes Schindelin \n> ---\n\nNicely explained. Do we want to also give credit to Peff for the\nsingle-liner fix here, perhaps with a suggested/helped-by trailer?\n\n> sideband.c | 2 +-\n> t/helper/test-pkt-line.c | 23 +++++++++++++++++++++++\n> t/t0070-fundamental.sh | 6 ++++++\n> 3 files changed, 30 insertions(+), 1 deletion(-)\n>\n> diff --git a/sideband.c b/sideband.c\n> index 0a60662fa6..a5405b9aaa 100644\n> --- a/sideband.c\n> +++ b/sideband.c\n> @@ -190,7 +190,7 @@ int demultiplex_sideband(const char *me, char *buf, int len,\n> \t\treturn 0;\n> \tcase 1:\n> \t\t*sideband_type = SIDEBAND_PRIMARY;\n> -\t\tbreak;\n> +\t\treturn 1;\n> \tdefault:\n> \t\tstrbuf_addf(scratch, \"%s%s: protocol error: bad band #%d\",\n> \t\t\t scratch->len ? \"\\n\" : \"\", me, band);\n\n> diff --git a/t/helper/test-pkt-line.c b/t/helper/test-pkt-line.c\n> index 69152958e5..0bf20642be 100644\n> --- a/t/helper/test-pkt-line.c\n> +++ b/t/helper/test-pkt-line.c\n> @@ -84,6 +84,25 @@ static void unpack_sideband(void)\n> \t}\n> }\n> \n> +static int send_split_sideband(void)\n> +{\n> +\tconst char *part1 = \"Hello,\";\n> +\tconst char *primary = \"\\001primary: regular output\\n\";\n> +\tconst char *part2 = \" world!\\n\";\n> +\n> +\tsend_sideband(1, 2, part1, strlen(part1), LARGE_PACKET_MAX);\n> +\tpacket_write(1, primary, strlen(primary));\n> +\tsend_sideband(1, 2, part2, strlen(part2), LARGE_PACKET_MAX);\n> +\tpacket_response_end(1);\n> +\n> +\treturn 0;\n> +}\n\nOK.\n\n> +static int receive_sideband(void)\n> +{\n> +\treturn recv_sideband(\"sideband: \", 0, 1);\n> +}\n> +\n> int cmd__pkt_line(int argc, const char **argv)\n> {\n> \tif (argc < 2)\n> @@ -95,6 +114,10 @@ int cmd__pkt_line(int argc, const char **argv)\n> \t\tunpack();\n> \telse if (!strcmp(argv[1], \"unpack-sideband\"))\n> \t\tunpack_sideband();\n> +\telse if (!strcmp(argv[1], \"send-split-sideband\"))\n> +\t\tsend_split_sideband();\n> +\telse if (!strcmp(argv[1], \"receive-sideband\"))\n> +\t\treceive_sideband();\n> \telse\n> \t\tdie(\"invalid argument '%s'\", argv[1]);\n> \n> diff --git a/t/t0070-fundamental.sh b/t/t0070-fundamental.sh\n> index 7b111a56fd..357201640a 100755\n> --- a/t/t0070-fundamental.sh\n> +++ b/t/t0070-fundamental.sh\n> @@ -34,4 +34,10 @@ test_expect_success 'check for a bug in the regex routines' '\n> \ttest-tool regex --bug\n> '\n> \n> +test_expect_success 'incomplete sideband messages are reassembled' '\n> +\ttest-tool pkt-line send-split-sideband >split-sideband &&\n> +\ttest-tool pkt-line receive-sideband err &&\n> +\tgrep \"Hello, world\" err\n> +'\n> +\n> test_done\n"},{"id":"408013","messageId":"xmqqsga8ab2u.fsf@gitster.c.googlers.com","threadId":"54407","inReplyTo":"c61e560451c4d7f101a23acec69117ddac563330.1603136143.git.gitgitgadget@gmail.com","subject":"Re: [PATCH v2 3/3] sideband: add defense against packets missing a band designator","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2020-10-20T20:36:57Z","receivedAt":"2020-10-20T20:37:06Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"\"Johannes Schindelin via GitGitGadget\" \nwrites:\n\n> From: Johannes Schindelin \n>\n> While there is currently no instance of code producing this type of\n> packet, if the `demultiplex_sideband()` would receive a packet whose\n> payload is not only empty but even misses the band designator, it would\n> mistake it for a flush packet.\n\nQuite sensible. Will queue all three. Thanks.\n"},{"id":"408014","messageId":"nycvar.QRO.7.76.6.2010202246240.56@tvgsbejvaqbjf.bet","threadId":"54407","inReplyTo":"xmqqwnzkab85.fsf@gitster.c.googlers.com","subject":"Re: [PATCH v2 1/3] sideband: avoid reporting incomplete sideband messages","fromName":"Johannes Schindelin","fromEmail":"johannes.schindelin@gmx.de","sentAt":"2020-10-20T20:48:09Z","receivedAt":"2020-10-20T20:48:27Z","isPatch":true,"sender":{"key":"johannes.schindelin@gmx.de","avatar":"https://avatars.githubusercontent.com/u/127790?v=4"},"body":"Hi Junio,\n\nOn Tue, 20 Oct 2020, Junio C Hamano wrote:\n\n> \"Johannes Schindelin via GitGitGadget\" \n> writes:\n>\n> > From: Johannes Schindelin \n> >\n> > In 2b695ecd74d (t5500: count objects through stderr, not trace,\n> > 2020-05-06) we tried to ensure that the \"Total 3\" message could be\n> > grepped in Git's output, even if it sometimes got chopped up into\n> > multiple lines in the trace machinery.\n> > ...\n> > The correct way to fix this is to return from `demultiplex_sideband()`\n> > early. The caller will then write out the contents of the primary packet\n> > and continue looping. The `scratch` buffer for incomplete sideband\n> > messages is owned by that caller, and will continue to accumulate the\n> > remainder(s) of those messages. The loop will only end once\n> > `demultiplex_sideband()` returned non-zero _and_ did not indicate a\n> > primary packet, which is the case only when we hit the `cleanup:` path,\n> > in which we take care of flushing any unfinished sideband messages and\n> > release the `scratch` buffer.\n> >\n> > To ensure that this does not get broken again, we introduce a pair of\n> > subcommands of the `pkt-line` test helper that specifically chop up the\n> > sideband message and squeeze a primary packet into the middle.\n> >\n> > Final note: The other test case touched by 2b695ecd74d (t5500: count\n> > objects through stderr, not trace, 2020-05-06) is not affected by this\n> > issue because the sideband machinery is not involved there.\n> >\n> > Signed-off-by: Johannes Schindelin \n> > ---\n>\n> Nicely explained. Do we want to also give credit to Peff for the\n> single-liner fix here, perhaps with a suggested/helped-by trailer?\n\nSure.\n\nI had not added that because I had actually come up with the fix\nindependently in my analysis before I read Peff's reply thoroughly.\n\nBut credit where credit is due: without Peff's reply, I would not have\nworked on the full fix and stayed with the work-around.\n\nCiao,\nDscho\n"},{"id":"408017","messageId":"xmqqft68a8gn.fsf@gitster.c.googlers.com","threadId":"54407","inReplyTo":"nycvar.QRO.7.76.6.2010202246240.56@tvgsbejvaqbjf.bet","subject":"Re: [PATCH v2 1/3] sideband: avoid reporting incomplete sideband messages","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2020-10-20T21:33:28Z","receivedAt":"2020-10-20T21:33:36Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Johannes Schindelin writes:\n\n>> Nicely explained. Do we want to also give credit to Peff for the\n>> single-liner fix here, perhaps with a suggested/helped-by trailer?\n>\n> Sure.\n>\n> I had not added that because I had actually come up with the fix\n> independently in my analysis before I read Peff's reply thoroughly.\n\nAh, of course, e-mails cross all the time so these things happen.\nThanks, both.\n"},{"id":"408214","messageId":"20201023083424.GD4012156@coredump.intra.peff.net","threadId":"54407","inReplyTo":"c61e560451c4d7f101a23acec69117ddac563330.1603136143.git.gitgitgadget@gmail.com","subject":"Re: [PATCH v2 3/3] sideband: add defense against packets missing a band designator","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2020-10-23T08:34:24Z","receivedAt":"2020-10-23T08:34:27Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Mon, Oct 19, 2020 at 07:35:42PM +0000, Johannes Schindelin via GitGitGadget wrote:\n\n> From: Johannes Schindelin \n> \n> While there is currently no instance of code producing this type of\n> packet, if the `demultiplex_sideband()` would receive a packet whose\n> payload is not only empty but even misses the band designator, it would\n> mistake it for a flush packet.\n> \n> Let's defend against such a bug in the future.\n\nThat seems reasonable, but I'm not sure if these ought to be BUG()s.\nIsn't it an indication that the other side sent us bogus input? That\nlikely is a bug on the other end, but I think it should be a die(), just\nas we would produce for any other malformed protocol input.\n\n-Peff\n"},{"id":"408215","messageId":"20201023084827.GE4012156@coredump.intra.peff.net","threadId":"54407","inReplyTo":"c61e560451c4d7f101a23acec69117ddac563330.1603136143.git.gitgitgadget@gmail.com","subject":"Re: [PATCH v2 3/3] sideband: add defense against packets missing a band designator","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2020-10-23T08:48:27Z","receivedAt":"2020-10-23T08:48:30Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Mon, Oct 19, 2020 at 07:35:42PM +0000, Johannes Schindelin via GitGitGadget wrote:\n\n> diff --git a/pkt-line.c b/pkt-line.c\n> index 657a702927..f72048f623 100644\n> --- a/pkt-line.c\n> +++ b/pkt-line.c\n> @@ -461,8 +461,10 @@ int recv_sideband(const char *me, int in_stream, int out)\n> \tenum sideband_type sideband_type;\n> \n> \twhile (1) {\n> -\t\tlen = packet_read(in_stream, NULL, NULL, buf, LARGE_PACKET_MAX,\n> -\t\t\t\t 0);\n> +\t\tint status = packet_read_with_status(in_stream, NULL, NULL, buf,\n> +\t\t\t\t\t\t LARGE_PACKET_MAX, &len, 0);\n> +\t\tif (!len && status == PACKET_READ_NORMAL)\n> +\t\t\tBUG(\"missing band designator\");\n> \t\tif (!demultiplex_sideband(me, buf, len, 0, &scratch,\n> \t\t\t\t\t &sideband_type))\n\nI also wonder if this status-check should be pushed down into\ndemultiplex_sideband() by passing \"status\", for two reasons:\n\n 1. So we don't have to repeat it (though it isn't that big)\n\n 2. The other half of this weirdness is that if we get an early EOF,\n we'll hit the \"missing sideband designator\" die() message. But\n that's not really what happened; we probably got a network hangup.\n And we could distinguish that case by checking for status ==\n PACKET_READ_EOF and provide a better message.\n\nSomething like this (completely untested):\n\ndiff --git a/sideband.c b/sideband.c\nindex 0a60662fa6..6ad15ed581 100644\n--- a/sideband.c\n+++ b/sideband.c\n@@ -115,6 +115,7 @@ static void maybe_colorize_sideband(struct strbuf *dest, const char *src, int n)\n #define DUMB_SUFFIX \" \"\n \n int demultiplex_sideband(const char *me, char *buf, int len,\n+\t\t\t enum packet_read_status status,\n \t\t\t int die_on_error,\n \t\t\t struct strbuf *scratch,\n \t\t\t enum sideband_type *sideband_type)\n@@ -130,17 +131,29 @@ int demultiplex_sideband(const char *me, char *buf, int len,\n \t\t\tsuffix = DUMB_SUFFIX;\n \t}\n \n-\tif (len == 0) {\n-\t\t*sideband_type = SIDEBAND_FLUSH;\n-\t\tgoto cleanup;\n-\t}\n-\tif (len < 1) {\n+\tif (status == PACKET_READ_EOF) {\n \t\tstrbuf_addf(scratch,\n-\t\t\t \"%s%s: protocol error: no band designator\",\n+\t\t\t \"%s%s: protocol error: eof while reading packet\",\n \t\t\t scratch->len ? \"\\n\" : \"\", me);\n \t\t*sideband_type = SIDEBAND_PROTOCOL_ERROR;\n \t\tgoto cleanup;\n \t}\n+\n+\tif (len < 0)\n+\t\tBUG(\"negative length on non-eof packet read\");\n+\n+\tif (len == 0) {\n+\t\tif (status == PACKET_READ_NORMAL) {\n+\t\t\tstrbuf_addf(scratch,\n+\t\t\t\t \"%s%s protocol error: no band designator\",\n+\t\t\t\t scratch->len ? \"\\n\" : \"\", me);\n+\t\t\t*sideband_type = SIDEBAND_PROTOCOL_ERROR;\n+\t\t} else {\n+\t\t\t*sideband_type = SIDEBAND_FLUSH;\n+\t\t}\n+\t\tgoto cleanup;\n+\t}\n+\n \tband = buf[0] & 0xff;\n \tbuf[len] = '\\0';\n \tlen--;\n"},{"id":"408216","messageId":"20201023085021.GF4012156@coredump.intra.peff.net","threadId":"54407","inReplyTo":"pull.753.v2.git.1603136142.gitgitgadget@gmail.com","subject":"Re: [PATCH v2 0/3] Work around flakiness in t5500.43","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2020-10-23T08:50:21Z","receivedAt":"2020-10-23T08:50:24Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Mon, Oct 19, 2020 at 07:35:39PM +0000, Johannes Schindelin via GitGitGadget wrote:\n\n> Changes since v1:\n> \n> * Instead of papering over the underlying cause, the patch was completely\n> changed to actually fix the bug and add a proper regression test for it\n> (originally, I wanted to act according to the common notion that good\n> programmers are lazy, oh my, see how well that worked out for me).\n\nThanks for fixing this. Your explanation looks thorough and the code\nlooks correct. Definitely patches 1 and 2 look good to me. I left a few\ncomments on patch 3.\n\n-Peff\n"},{"id":"408223","messageId":"nycvar.QRO.7.76.6.2010230732250.56@tvgsbejvaqbjf.bet","threadId":"54407","inReplyTo":"20201023084827.GE4012156@coredump.intra.peff.net","subject":"Re: [PATCH v2 3/3] sideband: add defense against packets missing a band designator","fromName":"Johannes Schindelin","fromEmail":"johannes.schindelin@gmx.de","sentAt":"2020-10-23T05:36:25Z","receivedAt":"2020-10-23T12:47:45Z","isPatch":true,"sender":{"key":"johannes.schindelin@gmx.de","avatar":"https://avatars.githubusercontent.com/u/127790?v=4"},"body":"Hi Peff,\n\nOn Fri, 23 Oct 2020, Jeff King wrote:\n\n> On Mon, Oct 19, 2020 at 07:35:42PM +0000, Johannes Schindelin via GitGitGadget wrote:\n>\n> > diff --git a/pkt-line.c b/pkt-line.c\n> > index 657a702927..f72048f623 100644\n> > --- a/pkt-line.c\n> > +++ b/pkt-line.c\n> > @@ -461,8 +461,10 @@ int recv_sideband(const char *me, int in_stream, int out)\n> > \tenum sideband_type sideband_type;\n> >\n> > \twhile (1) {\n> > -\t\tlen = packet_read(in_stream, NULL, NULL, buf, LARGE_PACKET_MAX,\n> > -\t\t\t\t 0);\n> > +\t\tint status = packet_read_with_status(in_stream, NULL, NULL, buf,\n> > +\t\t\t\t\t\t LARGE_PACKET_MAX, &len, 0);\n> > +\t\tif (!len && status == PACKET_READ_NORMAL)\n> > +\t\t\tBUG(\"missing band designator\");\n> > \t\tif (!demultiplex_sideband(me, buf, len, 0, &scratch,\n> > \t\t\t\t\t &sideband_type))\n>\n> I also wonder if this status-check should be pushed down into\n> demultiplex_sideband() by passing \"status\",\n\nI tried that, but as mentioned in the commit message, fbd76cd450\n(sideband: reverse its dependency on pkt-line, 2019-01-16) went out of its\nway to _stop_ the code inside `demultiplex_sideband()` from relying on\nanything in `pkt-line.h`. And that `PACKET_READ_NORMAL` and\n`PACKET_READ_EOF` _is_ from `pkt-line.h`.\n\nCiao,\nDscho\n\n> for two reasons:\n>\n> 1. So we don't have to repeat it (though it isn't that big)\n>\n> 2. The other half of this weirdness is that if we get an early EOF,\n> we'll hit the \"missing sideband designator\" die() message. But\n> that's not really what happened; we probably got a network hangup.\n> And we could distinguish that case by checking for status ==\n> PACKET_READ_EOF and provide a better message.\n>\n> Something like this (completely untested):\n>\n> diff --git a/sideband.c b/sideband.c\n> index 0a60662fa6..6ad15ed581 100644\n> --- a/sideband.c\n> +++ b/sideband.c\n> @@ -115,6 +115,7 @@ static void maybe_colorize_sideband(struct strbuf *dest, const char *src, int n)\n> #define DUMB_SUFFIX \" \"\n>\n> int demultiplex_sideband(const char *me, char *buf, int len,\n> +\t\t\t enum packet_read_status status,\n> \t\t\t int die_on_error,\n> \t\t\t struct strbuf *scratch,\n> \t\t\t enum sideband_type *sideband_type)\n> @@ -130,17 +131,29 @@ int demultiplex_sideband(const char *me, char *buf, int len,\n> \t\t\tsuffix = DUMB_SUFFIX;\n> \t}\n>\n> -\tif (len == 0) {\n> -\t\t*sideband_type = SIDEBAND_FLUSH;\n> -\t\tgoto cleanup;\n> -\t}\n> -\tif (len < 1) {\n> +\tif (status == PACKET_READ_EOF) {\n> \t\tstrbuf_addf(scratch,\n> -\t\t\t \"%s%s: protocol error: no band designator\",\n> +\t\t\t \"%s%s: protocol error: eof while reading packet\",\n> \t\t\t scratch->len ? \"\\n\" : \"\", me);\n> \t\t*sideband_type = SIDEBAND_PROTOCOL_ERROR;\n> \t\tgoto cleanup;\n> \t}\n> +\n> +\tif (len < 0)\n> +\t\tBUG(\"negative length on non-eof packet read\");\n> +\n> +\tif (len == 0) {\n> +\t\tif (status == PACKET_READ_NORMAL) {\n> +\t\t\tstrbuf_addf(scratch,\n> +\t\t\t\t \"%s%s protocol error: no band designator\",\n> +\t\t\t\t scratch->len ? \"\\n\" : \"\", me);\n> +\t\t\t*sideband_type = SIDEBAND_PROTOCOL_ERROR;\n> +\t\t} else {\n> +\t\t\t*sideband_type = SIDEBAND_FLUSH;\n> +\t\t}\n> +\t\tgoto cleanup;\n> +\t}\n> +\n> \tband = buf[0] & 0xff;\n> \tbuf[len] = '\\0';\n> \tlen--;\n>\n"},{"id":"408238","messageId":"xmqqv9f1huic.fsf@gitster.c.googlers.com","threadId":"54407","inReplyTo":"20201023083424.GD4012156@coredump.intra.peff.net","subject":"Re: [PATCH v2 3/3] sideband: add defense against packets missing a band designator","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2020-10-23T14:44:27Z","receivedAt":"2020-10-23T14:44:32Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Jeff King writes:\n\n> On Mon, Oct 19, 2020 at 07:35:42PM +0000, Johannes Schindelin via GitGitGadget wrote:\n>\n>> From: Johannes Schindelin \n>> \n>> While there is currently no instance of code producing this type of\n>> packet, if the `demultiplex_sideband()` would receive a packet whose\n>> payload is not only empty but even misses the band designator, it would\n>> mistake it for a flush packet.\n>> \n>> Let's defend against such a bug in the future.\n>\n> That seems reasonable, but I'm not sure if these ought to be BUG()s.\n> Isn't it an indication that the other side sent us bogus input? That\n> likely is a bug on the other end, but I think it should be a die(), just\n> as we would produce for any other malformed protocol input.\n\nThanks for spotting. I also think this was a good change, but at\nthis point in the code we found a problem in the data the other side\ncreated (i.e. we diagnosed a bug on the other side), which is a\nusual input error, so it should not be a BUG(). \n\nWould this be something we can warn and ignore if the connection is\nstill active, I wonder, though.\n"},{"id":"408400","messageId":"nycvar.QRO.7.76.6.2010261702410.56@tvgsbejvaqbjf.bet","threadId":"54407","inReplyTo":"20201023085021.GF4012156@coredump.intra.peff.net","subject":"Re: [PATCH v2 0/3] Work around flakiness in t5500.43","fromName":"Johannes Schindelin","fromEmail":"johannes.schindelin@gmx.de","sentAt":"2020-10-26T16:04:10Z","receivedAt":"2020-10-26T16:04:40Z","isPatch":true,"sender":{"key":"johannes.schindelin@gmx.de","avatar":"https://avatars.githubusercontent.com/u/127790?v=4"},"body":"Hi,\n\nOn Fri, 23 Oct 2020, Jeff King wrote:\n\n> On Mon, Oct 19, 2020 at 07:35:39PM +0000, Johannes Schindelin via GitGitGadget wrote:\n>\n> > Changes since v1:\n> >\n> > * Instead of papering over the underlying cause, the patch was completely\n> > changed to actually fix the bug and add a proper regression test for it\n> > (originally, I wanted to act according to the common notion that good\n> > programmers are lazy, oh my, see how well that worked out for me).\n>\n> Thanks for fixing this. Your explanation looks thorough and the code\n> looks correct. Definitely patches 1 and 2 look good to me. I left a few\n> comments on patch 3.\n\nThank you.\n\nAfter thinking about this for several days, I will drop patch 3/3 because\nit is unclear to me how to implement what you suggested without reverting\nthe intention of Jonathan's patch that made `pkt-line` depend on\n`sideband` instead of the other way round.\n\nCiao,\nDscho\n"},{"id":"408401","messageId":"pull.753.v3.git.1603728555.gitgitgadget@gmail.com","threadId":"54407","inReplyTo":"pull.753.v2.git.1603136142.gitgitgadget@gmail.com","subject":"[PATCH v3 0/2] Work around flakiness in t5500.43","fromName":"Johannes Schindelin via GitGitGadget","fromEmail":"gitgitgadget@gmail.com","sentAt":"2020-10-26T16:09:13Z","receivedAt":"2020-10-26T16:09:21Z","isPatch":true,"sender":{"key":"johannes.schindelin@gmx.de","avatar":"https://avatars.githubusercontent.com/u/127790?v=4"},"body":"It seems that this test became flaky only recently, although I have to admit\nthat I have no idea why: the involved code does not seem to have changed\nrecently at all. It should have been fixed by \nhttps://lore.kernel.org/git/20200506220741.71021-1-jonathantanmy@google.com/\n, but apparently wasn't completely fixed, despite what I said in that\nthread.\n\nChanges since v2:\n\n * Dropped patch 3/3 because it was only intended to be defensive\n programming, but turned out to be too hard without layering violations.\n\nChanges since v1:\n\n * Instead of papering over the underlying cause, the patch was completely\n changed to actually fix the bug and add a proper regression test for it\n (originally, I wanted to act according to the common notion that good\n programmers are lazy, oh my, see how well that worked out for me).\n * We now specifically watch out for future bugs where incomplete sideband\n messages would be dropped inadvertently rather than being reported at EOF\n or at encountering a flush/error packet.\n * Before sending 0-length data to demultiplex_sideband(), we now make sure\n that it is not marked as a data packet; Otherwise we now complain loudly\n about a bug.\n\nJohannes Schindelin (2):\n sideband: avoid reporting incomplete sideband messages\n sideband: report unhandled incomplete sideband messages as bugs\n\n pkt-line.c | 3 +++\n sideband.c | 2 +-\n t/helper/test-pkt-line.c | 23 +++++++++++++++++++++++\n t/t0070-fundamental.sh | 6 ++++++\n 4 files changed, 33 insertions(+), 1 deletion(-)\n\n\nbase-commit: d4a392452e292ff924e79ec8458611c0f679d6d4\nPublished-As: https://github.com/gitgitgadget/git/releases/tag/pr-753%2Fdscho%2Funflake-t5500.43-v3\nFetch-It-Via: git fetch https://github.com/gitgitgadget/git pr-753/dscho/unflake-t5500.43-v3\nPull-Request: https://github.com/gitgitgadget/git/pull/753\n\nRange-diff vs v2:\n\n 1: e4ba96358b = 1: e4ba96358b sideband: avoid reporting incomplete sideband messages\n 2: 9ffcc5b78e = 2: 9ffcc5b78e sideband: report unhandled incomplete sideband messages as bugs\n 3: c61e560451 < -: ---------- sideband: add defense against packets missing a band designator\n\n-- \ngitgitgadget\n"},{"id":"408402","messageId":"e4ba96358b7c5d2b4148c5529a3c253dc0d1f358.1603728555.git.gitgitgadget@gmail.com","threadId":"54407","inReplyTo":"pull.753.v3.git.1603728555.gitgitgadget@gmail.com","subject":"[PATCH v3 1/2] sideband: avoid reporting incomplete sideband messages","fromName":"Johannes Schindelin via GitGitGadget","fromEmail":"gitgitgadget@gmail.com","sentAt":"2020-10-26T16:09:14Z","receivedAt":"2020-10-26T16:09:22Z","isPatch":true,"sender":{"key":"johannes.schindelin@gmx.de","avatar":"https://avatars.githubusercontent.com/u/127790?v=4"},"body":"From: Johannes Schindelin \n\nIn 2b695ecd74d (t5500: count objects through stderr, not trace,\n2020-05-06) we tried to ensure that the \"Total 3\" message could be\ngrepped in Git's output, even if it sometimes got chopped up into\nmultiple lines in the trace machinery.\n\nHowever, the first instance where this mattered now goes through the\nsideband machinery, where it is _still_ possible for messages to get\nchopped up: it *is* possible for the standard error stream to be sent\nbyte-for-byte and hence it can be easily interrupted. Meaning: it is\npossible for the single line that we're looking for to be chopped up\ninto multiple sideband packets, with a primary packet being delivered\nbetween them.\n\nThis seems to happen occasionally in the `vs-test` part of our CI\nbuilds, i.e. with binaries built using Visual C, but not when building\nwith GCC or clang; The symptom is that t5500.43 fails to find a line\nmatching `remote: Total 3` in the `log` file, which ends in something\nalong these lines:\n\n\tremote: Tota\n\tremote: l 3 (delta 0), reused 0 (delta 0), pack-reused 0\n\nThis should not happen, though: we have code in `demultiplex_sideband()`\n_specifically_ to stitch back together lines that were delivered in\nseparate sideband packets.\n\nHowever, this stitching was broken in a subtle way in fbd76cd450\n(sideband: reverse its dependency on pkt-line, 2019-01-16): before that\nchange, incomplete sideband lines would not be flushed upon receiving a\nprimary packet, but after that patch, they would be.\n\nThe subtleness of this bug comes from the fact that it is easy to get\nconfused by the ambiguous meaning of the `break` keyword: after writing\nthe primary packet contents, the `break;` in the original version of\n`recv_sideband()` does _not_ break out of the `while` loop, but instead\nonly ends the `switch` case:\n\n\twhile (!retval) {\n\t\t[...]\n\t\tswitch (band) {\n\t\t\t[...]\n\t\tcase 1:\n/* Write the contents of the primary packet */\n\t\t\twrite_or_die(out, buf + 1, len);\n/* Here, we do *not* break out of the loop, `retval` is unchanged */\n\t\t\tbreak;\n\t\t[...]\n\t}\n\n\tif (outbuf.len) {\n/* Write any remaining sideband messages lacking a trailing LF */\n\t\tstrbuf_addch(&outbuf, '\\n');\n\t\txwrite(2, outbuf.buf, outbuf.len);\n\t}\n\nIn contrast, after fbd76cd450 (sideband: reverse its dependency on\npkt-line, 2019-01-16), the body of the `while` loop was extracted into\n`demultiplex_sideband()`, crucially _including_ the logic to write\nincomplete sideband messages:\n\n\tswitch (band) {\n\t[...]\n\tcase 1:\n\t\t*sideband_type = SIDEBAND_PRIMARY;\n/* This does not break out of the loop: the loop is in the caller */\n\t\tbreak;\n\t[...]\n\t}\n\ncleanup:\n\t[...]\n/* This logic is now no longer _outside_ the loop but _inside_ */\n\tif (scratch->len) {\n\t\tstrbuf_addch(scratch, '\\n');\n\t\txwrite(2, scratch->buf, scratch->len);\n\t}\n\nThe correct way to fix this is to return from `demultiplex_sideband()`\nearly. The caller will then write out the contents of the primary packet\nand continue looping. The `scratch` buffer for incomplete sideband\nmessages is owned by that caller, and will continue to accumulate the\nremainder(s) of those messages. The loop will only end once\n`demultiplex_sideband()` returned non-zero _and_ did not indicate a\nprimary packet, which is the case only when we hit the `cleanup:` path,\nin which we take care of flushing any unfinished sideband messages and\nrelease the `scratch` buffer.\n\nTo ensure that this does not get broken again, we introduce a pair of\nsubcommands of the `pkt-line` test helper that specifically chop up the\nsideband message and squeeze a primary packet into the middle.\n\nFinal note: The other test case touched by 2b695ecd74d (t5500: count\nobjects through stderr, not trace, 2020-05-06) is not affected by this\nissue because the sideband machinery is not involved there.\n\nSigned-off-by: Johannes Schindelin \n---\n sideband.c | 2 +-\n t/helper/test-pkt-line.c | 23 +++++++++++++++++++++++\n t/t0070-fundamental.sh | 6 ++++++\n 3 files changed, 30 insertions(+), 1 deletion(-)\n\ndiff --git a/sideband.c b/sideband.c\nindex 0a60662fa6..a5405b9aaa 100644\n--- a/sideband.c\n+++ b/sideband.c\n@@ -190,7 +190,7 @@ int demultiplex_sideband(const char *me, char *buf, int len,\n \t\treturn 0;\n \tcase 1:\n \t\t*sideband_type = SIDEBAND_PRIMARY;\n-\t\tbreak;\n+\t\treturn 1;\n \tdefault:\n \t\tstrbuf_addf(scratch, \"%s%s: protocol error: bad band #%d\",\n \t\t\t scratch->len ? \"\\n\" : \"\", me, band);\ndiff --git a/t/helper/test-pkt-line.c b/t/helper/test-pkt-line.c\nindex 69152958e5..0bf20642be 100644\n--- a/t/helper/test-pkt-line.c\n+++ b/t/helper/test-pkt-line.c\n@@ -84,6 +84,25 @@ static void unpack_sideband(void)\n \t}\n }\n \n+static int send_split_sideband(void)\n+{\n+\tconst char *part1 = \"Hello,\";\n+\tconst char *primary = \"\\001primary: regular output\\n\";\n+\tconst char *part2 = \" world!\\n\";\n+\n+\tsend_sideband(1, 2, part1, strlen(part1), LARGE_PACKET_MAX);\n+\tpacket_write(1, primary, strlen(primary));\n+\tsend_sideband(1, 2, part2, strlen(part2), LARGE_PACKET_MAX);\n+\tpacket_response_end(1);\n+\n+\treturn 0;\n+}\n+\n+static int receive_sideband(void)\n+{\n+\treturn recv_sideband(\"sideband: \", 0, 1);\n+}\n+\n int cmd__pkt_line(int argc, const char **argv)\n {\n \tif (argc < 2)\n@@ -95,6 +114,10 @@ int cmd__pkt_line(int argc, const char **argv)\n \t\tunpack();\n \telse if (!strcmp(argv[1], \"unpack-sideband\"))\n \t\tunpack_sideband();\n+\telse if (!strcmp(argv[1], \"send-split-sideband\"))\n+\t\tsend_split_sideband();\n+\telse if (!strcmp(argv[1], \"receive-sideband\"))\n+\t\treceive_sideband();\n \telse\n \t\tdie(\"invalid argument '%s'\", argv[1]);\n \ndiff --git a/t/t0070-fundamental.sh b/t/t0070-fundamental.sh\nindex 7b111a56fd..357201640a 100755\n--- a/t/t0070-fundamental.sh\n+++ b/t/t0070-fundamental.sh\n@@ -34,4 +34,10 @@ test_expect_success 'check for a bug in the regex routines' '\n \ttest-tool regex --bug\n '\n \n+test_expect_success 'incomplete sideband messages are reassembled' '\n+\ttest-tool pkt-line send-split-sideband >split-sideband &&\n+\ttest-tool pkt-line receive-sideband err &&\n+\tgrep \"Hello, world\" err\n+'\n+\n test_done\n-- \ngitgitgadget\n\n"},{"id":"408403","messageId":"9ffcc5b78e358d0ed4da2c52ba87174dc94e544c.1603728555.git.gitgitgadget@gmail.com","threadId":"54407","inReplyTo":"pull.753.v3.git.1603728555.gitgitgadget@gmail.com","subject":"[PATCH v3 2/2] sideband: report unhandled incomplete sideband messages as bugs","fromName":"Johannes Schindelin via GitGitGadget","fromEmail":"gitgitgadget@gmail.com","sentAt":"2020-10-26T16:09:15Z","receivedAt":"2020-10-26T16:09:26Z","isPatch":true,"sender":{"key":"johannes.schindelin@gmx.de","avatar":"https://avatars.githubusercontent.com/u/127790?v=4"},"body":"From: Johannes Schindelin \n\nIt was pretty tricky to verify that incomplete sideband messages are\nhandled correctly by the `recv_sideband()`/`demultiplex_sideband()`\ncode: they have to be flushed out at the end of the loop in\n`recv_sideband()`, but the actual flushing is done by the\n`demultiplex_sideband()` function (which therefore has to know somehow\nthat the loop will be done after it returns).\n\nTo catch future bugs where incomplete sideband messages might not be\nshown by mistake, let's catch that condition and report a bug.\n\nSigned-off-by: Johannes Schindelin \n---\n pkt-line.c | 3 +++\n 1 file changed, 3 insertions(+)\n\ndiff --git a/pkt-line.c b/pkt-line.c\nindex 844c253ccd..657a702927 100644\n--- a/pkt-line.c\n+++ b/pkt-line.c\n@@ -471,6 +471,9 @@ int recv_sideband(const char *me, int in_stream, int out)\n \t\t\twrite_or_die(out, buf + 1, len - 1);\n \t\t\tbreak;\n \t\tdefault: /* errors: message already written */\n+\t\t\tif (scratch.len > 0)\n+\t\t\t\tBUG(\"unhandled incomplete sideband: '%s'\",\n+\t\t\t\t scratch.buf);\n \t\t\treturn sideband_type;\n \t\t}\n \t}\n-- \ngitgitgadget\n"},{"id":"408435","messageId":"xmqqh7qget10.fsf@gitster.c.googlers.com","threadId":"54407","inReplyTo":"pull.753.v3.git.1603728555.gitgitgadget@gmail.com","subject":"Re: [PATCH v3 0/2] Work around flakiness in t5500.43","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2020-10-26T18:33:47Z","receivedAt":"2020-10-26T18:33:52Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"\"Johannes Schindelin via GitGitGadget\" \nwrites:\n\n> It seems that this test became flaky only recently, although I have to admit\n> that I have no idea why: the involved code does not seem to have changed\n> recently at all. It should have been fixed by \n> https://lore.kernel.org/git/20200506220741.71021-1-jonathantanmy@google.com/\n> , but apparently wasn't completely fixed, despite what I said in that\n> thread.\n>\n> Changes since v2:\n>\n> * Dropped patch 3/3 because it was only intended to be defensive\n> programming, but turned out to be too hard without layering violations.\n\nThanks, the remaining two look identical, so let me preserve the\ntimestamps by just dropping the tip one from what is queued, instead\nof queuing these two patches.\n\n"},{"id":"408485","messageId":"20201027065250.GB3005508@coredump.intra.peff.net","threadId":"54407","inReplyTo":"pull.753.v3.git.1603728555.gitgitgadget@gmail.com","subject":"[PATCH] sideband: diagnose more incoming packet anomalies","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2020-10-27T06:52:50Z","receivedAt":"2020-10-27T06:52:54Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Mon, Oct 26, 2020 at 04:09:13PM +0000, Johannes Schindelin via GitGitGadget wrote:\n\n> Changes since v2:\n> \n> * Dropped patch 3/3 because it was only intended to be defensive\n> programming, but turned out to be too hard without layering violations.\n\nIt is a bit tricky, but here's a working replacement.\n\n-- >8 --\nSubject: [PATCH] sideband: diagnose more sideband anomalies\n\nIn demultiplex_sideband(), there are two oddities when we check an\nincoming packet:\n\n - if it has zero length, then we assume it's a flush packet. This\n means we fail to notice the difference between a real flush and a\n true zero-length packet that's missing its sideband designator. It's\n not a huge problem in practice because we'd never send a zero-length\n data packet (even our keepalives are otherwise-empty sideband-1\n packets).\n\n But it would be nice to detect and report the error, since it's\n likely to cause other confusion (we think the other side flushed,\n but they do not).\n\n - we try to detect packets missing their designator by checking for\n \"if (len < 1)\". But this will never trigger for \"len == 0\"; we've\n already detected that and left the function before then.\n\n It _could_ detect a negative \"len\" parameter. But in that case, the\n error message is wrong. The issue is not \"no sideband\" but rather\n \"eof while reading the packet\". However, this can't actually be\n triggered in practice, because neither of the two callers uses\n pkt_read's GENTLE_ON_EOF flag. Which means they'd die with \"the\n remote end hung up unexpectedly\" before we even get here.\n\n So this truly is dead code.\n\nWe can improve these cases by passing in a pkt-line status to the\ndemultiplexer, and by having recv_sideband() use GENTLE_ON_EOF. This\ngives us two improvements:\n\n - we can now reliably detect flush packets, and will report a normal\n packet missing its sideband designator as an error\n\n - we'll report an eof with a more detailed \"protocol error: eof while\n reading sideband packet\", rather than the generic \"the remote end\n hung up unexpectedly\"\n\n - when we see an eof, we'll flush the sideband scratch buffer, which\n may provide some hints from the remote about why they hung up\n (though note we already flush on newlines, so it's likely that most\n such messages already made it through)\n\nIn some sense this patch goes against fbd76cd450 (sideband: reverse its\ndependency on pkt-line, 2019-01-16), which caused the sideband code not\nto depend on the pkt-line code. But that commit was really just trying\nto deal with the circular header dependency. The two modules are\nconceptually interlinked, and it was just trying to keep things\ncompiling. And indeed, there's a sticking point in this patch: because\npkt-line.h includes sideband.h, we can't add the reverse include we need\nfor the sideband code to have an \"enum packet_read_status\" parameter.\nNor can we forward declare it, because you can't forward declare an enum\nin C. However, C does guarantee that enums fit in an int, so we can just\nuse that type.\n\nOne alternative would be for the callers to check themselves that they\ngot something sane from the pkt-line code. But besides duplicating\nlogic, this gets quite tricky. Any error condition requires flushing the\nsideband #2 scratch buffer, which only demultiplex_sideband() knows how\nto do.\n\nSigned-off-by: Jeff King \n---\n pkt-line.c | 14 ++++++++------\n sideband.c | 29 ++++++++++++++++++++++-------\n sideband.h | 6 +++++-\n t/t0070-fundamental.sh | 12 ++++++++++++\n 4 files changed, 47 insertions(+), 14 deletions(-)\n\ndiff --git a/pkt-line.c b/pkt-line.c\nindex 657a702927..d633005ef7 100644\n--- a/pkt-line.c\n+++ b/pkt-line.c\n@@ -461,9 +461,11 @@ int recv_sideband(const char *me, int in_stream, int out)\n \tenum sideband_type sideband_type;\n \n \twhile (1) {\n-\t\tlen = packet_read(in_stream, NULL, NULL, buf, LARGE_PACKET_MAX,\n-\t\t\t\t 0);\n-\t\tif (!demultiplex_sideband(me, buf, len, 0, &scratch,\n+\t\tint status = packet_read_with_status(in_stream, NULL, NULL,\n+\t\t\t\t\t\t buf, LARGE_PACKET_MAX,\n+\t\t\t\t\t\t &len,\n+\t\t\t\t\t\t PACKET_READ_GENTLE_ON_EOF);\n+\t\tif (!demultiplex_sideband(me, status, buf, len, 0, &scratch,\n \t\t\t\t\t &sideband_type))\n \t\t\tcontinue;\n \t\tswitch (sideband_type) {\n@@ -520,9 +522,9 @@ enum packet_read_status packet_reader_read(struct packet_reader *reader)\n \t\t\t\t\t\t\t reader->options);\n \t\tif (!reader->use_sideband)\n \t\t\tbreak;\n-\t\tif (demultiplex_sideband(reader->me, reader->buffer,\n-\t\t\t\t\t reader->pktlen, 1, &scratch,\n-\t\t\t\t\t &sideband_type))\n+\t\tif (demultiplex_sideband(reader->me, reader->status,\n+\t\t\t\t\t reader->buffer, reader->pktlen, 1,\n+\t\t\t\t\t &scratch, &sideband_type))\n \t\t\tbreak;\n \t}\n \ndiff --git a/sideband.c b/sideband.c\nindex a5405b9aaa..a0d3fb9652 100644\n--- a/sideband.c\n+++ b/sideband.c\n@@ -3,6 +3,7 @@\n #include \"config.h\"\n #include \"sideband.h\"\n #include \"help.h\"\n+#include \"pkt-line.h\"\n \n struct keyword_entry {\n \t/*\n@@ -114,7 +115,8 @@ static void maybe_colorize_sideband(struct strbuf *dest, const char *src, int n)\n #define ANSI_SUFFIX \"\\033[K\"\n #define DUMB_SUFFIX \" \"\n \n-int demultiplex_sideband(const char *me, char *buf, int len,\n+int demultiplex_sideband(const char *me, int status,\n+\t\t\t char *buf, int len,\n \t\t\t int die_on_error,\n \t\t\t struct strbuf *scratch,\n \t\t\t enum sideband_type *sideband_type)\n@@ -130,17 +132,30 @@ int demultiplex_sideband(const char *me, char *buf, int len,\n \t\t\tsuffix = DUMB_SUFFIX;\n \t}\n \n-\tif (len == 0) {\n-\t\t*sideband_type = SIDEBAND_FLUSH;\n-\t\tgoto cleanup;\n-\t}\n-\tif (len < 1) {\n+\tif (status == PACKET_READ_EOF) {\n \t\tstrbuf_addf(scratch,\n-\t\t\t \"%s%s: protocol error: no band designator\",\n+\t\t\t \"%s%s: protocol error: eof while reading sideband packet\",\n \t\t\t scratch->len ? \"\\n\" : \"\", me);\n \t\t*sideband_type = SIDEBAND_PROTOCOL_ERROR;\n \t\tgoto cleanup;\n \t}\n+\n+\tif (len < 0)\n+\t\tBUG(\"negative length on non-eof packet read\");\n+\n+\tif (len == 0) {\n+\t\tif (status == PACKET_READ_NORMAL) {\n+\t\t\tstrbuf_addf(scratch,\n+\t\t\t\t \"%s%s: protocol error: missing sideband designator\",\n+\t\t\t\t scratch->len ? \"\\n\" : \"\", me);\n+\t\t\t*sideband_type = SIDEBAND_PROTOCOL_ERROR;\n+\t\t} else {\n+\t\t\t/* covers flush, delim, etc */\n+\t\t\t*sideband_type = SIDEBAND_FLUSH;\n+\t\t}\n+\t\tgoto cleanup;\n+\t}\n+\n \tband = buf[0] & 0xff;\n \tbuf[len] = '\\0';\n \tlen--;\ndiff --git a/sideband.h b/sideband.h\nindex 227740a58e..5a25331be5 100644\n--- a/sideband.h\n+++ b/sideband.h\n@@ -18,8 +18,12 @@ enum sideband_type {\n *\n * scratch must be a struct strbuf allocated by the caller. It is used to store\n * progress messages split across multiple packets.\n+ *\n+ * The \"status\" parameter is a pkt-line response as returned by\n+ * packet_read_with_status() (e.g., PACKET_READ_NORMAL).\n */\n-int demultiplex_sideband(const char *me, char *buf, int len,\n+int demultiplex_sideband(const char *me, int status,\n+\t\t\t char *buf, int len,\n \t\t\t int die_on_error,\n \t\t\t struct strbuf *scratch,\n \t\t\t enum sideband_type *sideband_type);\ndiff --git a/t/t0070-fundamental.sh b/t/t0070-fundamental.sh\nindex 357201640a..936030a5ef 100755\n--- a/t/t0070-fundamental.sh\n+++ b/t/t0070-fundamental.sh\n@@ -40,4 +40,16 @@ test_expect_success 'incomplete sideband messages are reassembled' '\n \tgrep \"Hello, world\" err\n '\n \n+test_expect_success 'eof on sideband message is reported' '\n+\tprintf 1234 >input &&\n+\ttest-tool pkt-line receive-sideband err &&\n+\ttest_i18ngrep \"eof while reading\" err\n+'\n+\n+test_expect_success 'missing sideband designator is reported' '\n+\tprintf 0004 >input &&\n+\ttest-tool pkt-line receive-sideband err &&\n+\ttest_i18ngrep \"missing sideband\" err\n+'\n+\n test_done\n-- \n2.29.1.634.g9e41dc1bf2\n\n"},{"id":"408486","messageId":"20201027071222.GC3005508@coredump.intra.peff.net","threadId":"54407","inReplyTo":"20201027065250.GB3005508@coredump.intra.peff.net","subject":"Re: [PATCH] sideband: diagnose more incoming packet anomalies","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2020-10-27T07:12:22Z","receivedAt":"2020-10-27T07:12:25Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Tue, Oct 27, 2020 at 02:52:50AM -0400, Jeff King wrote:\n\n> - we'll report an eof with a more detailed \"protocol error: eof while\n> reading sideband packet\", rather than the generic \"the remote end\n> hung up unexpectedly\"\n\nI wasn't sure if \"eof\" was too jargon-y. This is probably a message\nnormal users are likely to see if the network drops out on them.\n\nSo I'm open to rewording suggestions. Or even dropping the eof bits\nentirely. They do give us better flushing behavior:\n\n> - when we see an eof, we'll flush the sideband scratch buffer, which\n> may provide some hints from the remote about why they hung up\n> (though note we already flush on newlines, so it's likely that most\n> such messages already made it through)\n\nBut I suspect that's uncommon in practice.\n\n> t/t0070-fundamental.sh | 12 ++++++++++++\n\nI added this to t0070 since that's where your earlier test went. It does\nfeel like this isn't quite as \"fundamental\" as some of the other things\nin that file, though.\n\n> +test_expect_success 'missing sideband designator is reported' '\n> +\tprintf 0004 >input &&\n> +\ttest-tool pkt-line receive-sideband err &&\n> +\ttest_i18ngrep \"missing sideband\" err\n> +'\n\nI found it much more straight-forward to just printf the sample input,\nrather than writing C code to create it, as your test did. It keeps the\ninput and expectation together, and makes them easier to extend or\nchange.\n\nI wonder if it's worth doing this:\n\n t/helper/test-pkt-line.c | 16 ----------------\n t/t0070-fundamental.sh | 7 ++++++-\n t/test-lib-functions.sh | 12 +++++++++++-\n 3 files changed, 17 insertions(+), 18 deletions(-)\n\ndiff --git a/t/helper/test-pkt-line.c b/t/helper/test-pkt-line.c\nindex 5e638f0b97..0615833bec 100644\n--- a/t/helper/test-pkt-line.c\n+++ b/t/helper/test-pkt-line.c\n@@ -84,20 +84,6 @@ static void unpack_sideband(void)\n \t}\n }\n \n-static int send_split_sideband(void)\n-{\n-\tconst char *part1 = \"Hello,\";\n-\tconst char *primary = \"\\001primary: regular output\\n\";\n-\tconst char *part2 = \" world!\\n\";\n-\n-\tsend_sideband(1, 2, part1, strlen(part1), LARGE_PACKET_MAX);\n-\tpacket_write(1, primary, strlen(primary));\n-\tsend_sideband(1, 2, part2, strlen(part2), LARGE_PACKET_MAX);\n-\tpacket_response_end(1);\n-\n-\treturn 0;\n-}\n-\n static int receive_sideband(void)\n {\n \treturn recv_sideband(\"sideband\", 0, 1);\n@@ -114,8 +100,6 @@ int cmd__pkt_line(int argc, const char **argv)\n \t\tunpack();\n \telse if (!strcmp(argv[1], \"unpack-sideband\"))\n \t\tunpack_sideband();\n-\telse if (!strcmp(argv[1], \"send-split-sideband\"))\n-\t\tsend_split_sideband();\n \telse if (!strcmp(argv[1], \"receive-sideband\"))\n \t\treceive_sideband();\n \telse\ndiff --git a/t/t0070-fundamental.sh b/t/t0070-fundamental.sh\nindex 936030a5ef..f9fda8d610 100755\n--- a/t/t0070-fundamental.sh\n+++ b/t/t0070-fundamental.sh\n@@ -35,7 +35,12 @@ test_expect_success 'check for a bug in the regex routines' '\n '\n \n test_expect_success 'incomplete sideband messages are reassembled' '\n-\ttest-tool pkt-line send-split-sideband >split-sideband &&\n+\t{\n+\t\tpacketize -2 \"Hello,\" &&\n+\t\tpacketize -1 \"primary: regular output\" &&\n+\t\tpacketize -2 \" world!\" &&\n+\t\tprintf 0000\n+\t} >split-sideband &&\n \ttest-tool pkt-line receive-sideband err &&\n \tgrep \"Hello, world\" err\n '\ndiff --git a/t/test-lib-functions.sh b/t/test-lib-functions.sh\nindex 8d59b90348..c90ea61747 100644\n--- a/t/test-lib-functions.sh\n+++ b/t/test-lib-functions.sh\n@@ -1427,10 +1427,20 @@ nongit () {\n # given on stdin, and that empty input becomes an empty packet, not a flush\n # packet (for that you can just print 0000 yourself).\n packetize() {\n+\tband=\n+\tbandlen=0\n+\tcase \"$1\" in\n+\t-[123])\n+\t\tband=\"\\\\${1#-}\"\n+\t\tbandlen=1\n+\t\tshift\n+\t\t;;\n+\tesac\n+\n \tif test $# -gt 0\n \tthen\n \t\tpacket=\"$*\"\n-\t\tprintf '%04x%s' \"$((4 + ${#packet}))\" \"$packet\"\n+\t\tprintf \"%04x$band%s\" \"$((4 + $bandlen + ${#packet}))\" \"$packet\"\n \telse\n \t\tperl -e '\n \t\t\tmy $packet = do { local $/; };\n\nTeaching packetize() about bands isn't strictly necessary (we could\nprintf the band designators ourselves and pipe it into packetize(); that\nwould also add the missing newlines, though those do not matter for this\ntest).\n\n-Peff\n"},{"id":"408487","messageId":"20201027071309.GD3005508@coredump.intra.peff.net","threadId":"54407","inReplyTo":"20201027065250.GB3005508@coredump.intra.peff.net","subject":"Re: [PATCH] sideband: diagnose more incoming packet anomalies","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2020-10-27T07:13:09Z","receivedAt":"2020-10-27T07:13:11Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Tue, Oct 27, 2020 at 02:52:50AM -0400, Jeff King wrote:\n\n> On Mon, Oct 26, 2020 at 04:09:13PM +0000, Johannes Schindelin via GitGitGadget wrote:\n> \n> > Changes since v2:\n> > \n> > * Dropped patch 3/3 because it was only intended to be defensive\n> > programming, but turned out to be too hard without layering violations.\n> \n> It is a bit tricky, but here's a working replacement.\n\nAnd one other small cleanup, worth doing with or without my patch.\n\n-- >8 --\nSubject: [PATCH] test-pkt-line: drop colon from sideband identity\n\nWe pass \"sideband: \" as our identity for errors to recv_sideband(). But\nit already adds the trailing colon and space. This doesn't invalidate\nany tests, but it looks funny when you examine the test output.\n\nSigned-off-by: Jeff King \n---\n t/helper/test-pkt-line.c | 2 +-\n 1 file changed, 1 insertion(+), 1 deletion(-)\n\ndiff --git a/t/helper/test-pkt-line.c b/t/helper/test-pkt-line.c\nindex 0bf20642be..5e638f0b97 100644\n--- a/t/helper/test-pkt-line.c\n+++ b/t/helper/test-pkt-line.c\n@@ -100,7 +100,7 @@ static int send_split_sideband(void)\n \n static int receive_sideband(void)\n {\n-\treturn recv_sideband(\"sideband: \", 0, 1);\n+\treturn recv_sideband(\"sideband\", 0, 1);\n }\n \n int cmd__pkt_line(int argc, const char **argv)\n-- \n2.29.1.634.g9e41dc1bf2\n\n"},{"id":"408520","messageId":"xmqqblgncxap.fsf@gitster.c.googlers.com","threadId":"54407","inReplyTo":"20201027071222.GC3005508@coredump.intra.peff.net","subject":"Re: [PATCH] sideband: diagnose more incoming packet anomalies","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2020-10-27T18:56:46Z","receivedAt":"2020-10-27T18:56:55Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Jeff King writes:\n\n> On Tue, Oct 27, 2020 at 02:52:50AM -0400, Jeff King wrote:\n>\n>> - we'll report an eof with a more detailed \"protocol error: eof while\n>> reading sideband packet\", rather than the generic \"the remote end\n>> hung up unexpectedly\"\n>\n> I wasn't sure if \"eof\" was too jargon-y. This is probably a message\n> normal users are likely to see if the network drops out on them.\n\nWe were expecting to see something, and instead of seeing that\nspecific thing we were waiting, we saw the end-of-file?\n\nThat sounds like \"the other side hung up unexpectedly\" to me. Does\nit bother you for being \"too generic\" because it does not say what\nwe were expecting to see? \"unexpected disconnect while waiting for\na sideband packet\"?\n"},{"id":"408521","messageId":"xmqq7drbcwx8.fsf@gitster.c.googlers.com","threadId":"54407","inReplyTo":"20201027071309.GD3005508@coredump.intra.peff.net","subject":"Re: [PATCH] sideband: diagnose more incoming packet anomalies","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2020-10-27T19:04:51Z","receivedAt":"2020-10-27T19:05:00Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Jeff King writes:\n\n> And one other small cleanup, worth doing with or without my patch.\n>\n> -- >8 --\n> Subject: [PATCH] test-pkt-line: drop colon from sideband identity\n>\n> We pass \"sideband: \" as our identity for errors to recv_sideband(). But\n> it already adds the trailing colon and space. This doesn't invalidate\n> any tests, but it looks funny when you examine the test output.\n>\n> Signed-off-by: Jeff King \n> ---\n\nMakes sense and it is a no-brainer to understand why it is the right\nthing to do. I'll queue it directly on top of two patches from\nDscho.\n\nThanks.\n\n> t/helper/test-pkt-line.c | 2 +-\n> 1 file changed, 1 insertion(+), 1 deletion(-)\n>\n> diff --git a/t/helper/test-pkt-line.c b/t/helper/test-pkt-line.c\n> index 0bf20642be..5e638f0b97 100644\n> --- a/t/helper/test-pkt-line.c\n> +++ b/t/helper/test-pkt-line.c\n> @@ -100,7 +100,7 @@ static int send_split_sideband(void)\n> \n> static int receive_sideband(void)\n> {\n> -\treturn recv_sideband(\"sideband: \", 0, 1);\n> +\treturn recv_sideband(\"sideband\", 0, 1);\n> }\n> \n> int cmd__pkt_line(int argc, const char **argv)\n"},{"id":"408530","messageId":"20201027204205.GA643357@coredump.intra.peff.net","threadId":"54407","inReplyTo":"xmqqblgncxap.fsf@gitster.c.googlers.com","subject":"Re: [PATCH] sideband: diagnose more incoming packet anomalies","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2020-10-27T20:42:05Z","receivedAt":"2020-10-27T20:42:08Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Tue, Oct 27, 2020 at 11:56:46AM -0700, Junio C Hamano wrote:\n\n> Jeff King writes:\n> \n> > On Tue, Oct 27, 2020 at 02:52:50AM -0400, Jeff King wrote:\n> >\n> >> - we'll report an eof with a more detailed \"protocol error: eof while\n> >> reading sideband packet\", rather than the generic \"the remote end\n> >> hung up unexpectedly\"\n> >\n> > I wasn't sure if \"eof\" was too jargon-y. This is probably a message\n> > normal users are likely to see if the network drops out on them.\n> \n> We were expecting to see something, and instead of seeing that\n> specific thing we were waiting, we saw the end-of-file?\n> \n> That sounds like \"the other side hung up unexpectedly\" to me. Does\n> it bother you for being \"too generic\" because it does not say what\n> we were expecting to see? \"unexpected disconnect while waiting for\n> a sideband packet\"?\n\nYes, saying what we were expecting is what seems like an improvement to\nme. I tried coming up with something that said \"hung up\" but the wording\nended up awkward. Your \"unexpected disconnect while waiting for a\nsideband packet\" is exactly what I was trying for. :)\n\nDoes this patch seem otherwise worth doing?\n\nAn alternate patch would be to keep the behavior the same and just\nclarify the code a bit. Something like:\n\n-- >8 --\nSubject: [PATCH] demultiplex_sideband(): clarify corner cases\n\nThe size checks in demultiplex_sideband() are a bit subtle and\nconfusing:\n\n - we consider a zero-length packet (\"0004\") to be a flush packet, even\n though it's not really one. This is perhaps wrong, but it should\n never happen in our protocol, and we err on the side of history and\n leniency. We'll leave a comment indicating that we expect this case.\n\n - likewise we consider any flush-like packet (e.g., \"0001\" delim) to\n be a flush. I didn't confirm whether this is necessary for normal\n protocol usage. It may be for the everything-over-sideband mode\n introduced by 0bbc0bc574 ({fetch,upload}-pack: sideband v2 fetch\n response, 2019-01-16). Likewise let's leave a comment.\n\n - we check for \"len < 1\" to see if there's no sideband designator.\n That's confusing, because we already covered the \"len == 0\" case.\n What is interesting is the \"len < 0\" case. But that's not a missing\n sideband designator, but rather an error or EOF from the pkt-line\n code. This should never happen, though, because our callers instruct\n pkt-line to die() on EOF anyway. So let's make it more obvious\n that we're looking for a negative value here, and consider it a\n BUG() in the caller to pass us garbage.\n\nSigned-off-by: Jeff King \n---\n sideband.c | 15 ++++++++-------\n 1 file changed, 8 insertions(+), 7 deletions(-)\n\ndiff --git a/sideband.c b/sideband.c\nindex 0a60662fa6..6ba1925614 100644\n--- a/sideband.c\n+++ b/sideband.c\n@@ -130,17 +130,18 @@ int demultiplex_sideband(const char *me, char *buf, int len,\n \t\t\tsuffix = DUMB_SUFFIX;\n \t}\n \n+\tif (len < 0)\n+\t\tBUG(\"error/eof packet passed to demultiplex_sideband\");\n+\n \tif (len == 0) {\n+\t\t/*\n+\t\t * we treat all flush-like packets (flush, delim, etc) and even\n+\t\t * empty data packets as a flush\n+\t\t */\n \t\t*sideband_type = SIDEBAND_FLUSH;\n \t\tgoto cleanup;\n \t}\n-\tif (len < 1) {\n-\t\tstrbuf_addf(scratch,\n-\t\t\t \"%s%s: protocol error: no band designator\",\n-\t\t\t scratch->len ? \"\\n\" : \"\", me);\n-\t\t*sideband_type = SIDEBAND_PROTOCOL_ERROR;\n-\t\tgoto cleanup;\n-\t}\n+\n \tband = buf[0] & 0xff;\n \tbuf[len] = '\\0';\n \tlen--;\n-- \n2.29.1.641.gb6287e56d2\n\n"},{"id":"408533","messageId":"xmqqzh479wor.fsf@gitster.c.googlers.com","threadId":"54407","inReplyTo":"20201027204205.GA643357@coredump.intra.peff.net","subject":"Re: [PATCH] sideband: diagnose more incoming packet anomalies","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2020-10-27T21:38:12Z","receivedAt":"2020-10-27T21:38:20Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Jeff King writes:\n\n> Does this patch seem otherwise worth doing?\n\nYeah.\n\nFWIW, I do not find the \"dependency\" thing disturbing. sideband is\nan extension of the pkt-line mechansim, so it is natural that it\ndepends on pkt-line. I'd also be happy if enums, structures and\ncalls defined in both headers are made available by just including\none of them (e.g. retire sideband.h, perhaps).\n\n> An alternate patch would be to keep the behavior the same and just\n> clarify the code a bit. Something like:\n\nThis also looks OK to me from readability's point of view, but it\ndoes not as much help the end user who is puzzled as the real thing,\nI am afraid.\n\nThanks.\n\n> -- >8 --\n> Subject: [PATCH] demultiplex_sideband(): clarify corner cases\n>\n> The size checks in demultiplex_sideband() are a bit subtle and\n> confusing:\n>\n> - we consider a zero-length packet (\"0004\") to be a flush packet, even\n> though it's not really one. This is perhaps wrong, but it should\n> never happen in our protocol, and we err on the side of history and\n> leniency. We'll leave a comment indicating that we expect this case.\n>\n> - likewise we consider any flush-like packet (e.g., \"0001\" delim) to\n> be a flush. I didn't confirm whether this is necessary for normal\n> protocol usage. It may be for the everything-over-sideband mode\n> introduced by 0bbc0bc574 ({fetch,upload}-pack: sideband v2 fetch\n> response, 2019-01-16). Likewise let's leave a comment.\n>\n> - we check for \"len < 1\" to see if there's no sideband designator.\n> That's confusing, because we already covered the \"len == 0\" case.\n> What is interesting is the \"len < 0\" case. But that's not a missing\n> sideband designator, but rather an error or EOF from the pkt-line\n> code. This should never happen, though, because our callers instruct\n> pkt-line to die() on EOF anyway. So let's make it more obvious\n> that we're looking for a negative value here, and consider it a\n> BUG() in the caller to pass us garbage.\n>\n> Signed-off-by: Jeff King \n> ---\n> sideband.c | 15 ++++++++-------\n> 1 file changed, 8 insertions(+), 7 deletions(-)\n>\n> diff --git a/sideband.c b/sideband.c\n> index 0a60662fa6..6ba1925614 100644\n> --- a/sideband.c\n> +++ b/sideband.c\n> @@ -130,17 +130,18 @@ int demultiplex_sideband(const char *me, char *buf, int len,\n> \t\t\tsuffix = DUMB_SUFFIX;\n> \t}\n> \n> +\tif (len < 0)\n> +\t\tBUG(\"error/eof packet passed to demultiplex_sideband\");\n> +\n> \tif (len == 0) {\n> +\t\t/*\n> +\t\t * we treat all flush-like packets (flush, delim, etc) and even\n> +\t\t * empty data packets as a flush\n> +\t\t */\n> \t\t*sideband_type = SIDEBAND_FLUSH;\n> \t\tgoto cleanup;\n> \t}\n> -\tif (len < 1) {\n> -\t\tstrbuf_addf(scratch,\n> -\t\t\t \"%s%s: protocol error: no band designator\",\n> -\t\t\t scratch->len ? \"\\n\" : \"\", me);\n> -\t\t*sideband_type = SIDEBAND_PROTOCOL_ERROR;\n> -\t\tgoto cleanup;\n> -\t}\n> +\n> \tband = buf[0] & 0xff;\n> \tbuf[len] = '\\0';\n> \tlen--;\n"},{"id":"408577","messageId":"20201028093324.GA175617@coredump.intra.peff.net","threadId":"54407","inReplyTo":"xmqqzh479wor.fsf@gitster.c.googlers.com","subject":"Re: [PATCH] sideband: diagnose more incoming packet anomalies","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2020-10-28T09:33:24Z","receivedAt":"2020-10-28T23:00:10Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Tue, Oct 27, 2020 at 02:38:12PM -0700, Junio C Hamano wrote:\n\n> Jeff King writes:\n> \n> > Does this patch seem otherwise worth doing?\n> \n> Yeah.\n\nOK, here it is, then with that one error message reworded. I dropped\n\"protocol error\" from that one message, as well. One, because it was\ngetting quite long. And two, it's probably _not_ a protocol error, but\nrather a network drop. So just describing what we see on the client\nside is the best strategy.\n\n> FWIW, I do not find the \"dependency\" thing disturbing. sideband is\n> an extension of the pkt-line mechansim, so it is natural that it\n> depends on pkt-line. I'd also be happy if enums, structures and\n> calls defined in both headers are made available by just including\n> one of them (e.g. retire sideband.h, perhaps).\n\nI agree with that. Given how easy it was to work around with an int, I'm\nnot inclined to spend time going further at this point, but it's\nsomething to keep in mind.\n\n> > An alternate patch would be to keep the behavior the same and just\n> > clarify the code a bit. Something like:\n> \n> This also looks OK to me from readability's point of view, but it\n> does not as much help the end user who is puzzled as the real thing,\n> I am afraid.\n\nI suspect these cases are rare enough that nobody minds either way. But\nI do think the behavior-changing patch is making us more likely to do\nthe right thing. The downside is the risk of some unintended regression,\nbut I feel pretty good about it.\n\n-- >8 --\nSubject: [PATCH] sideband: diagnose more sideband anomalies\n\nIn demultiplex_sideband(), there are two oddities when we check an\nincoming packet:\n\n - if it has zero length, then we assume it's a flush packet. This\n means we fail to notice the difference between a real flush and a\n true zero-length packet that's missing its sideband designator. It's\n not a huge problem in practice because we'd never send a zero-length\n data packet (even our keepalives are otherwise-empty sideband-1\n packets).\n\n But it would be nice to detect and report the error, since it's\n likely to cause other confusion (we think the other side flushed,\n but they do not).\n\n - we try to detect packets missing their designator by checking for\n \"if (len < 1)\". But this will never trigger for \"len == 0\"; we've\n already detected that and left the function before then.\n\n It _could_ detect a negative \"len\" parameter. But in that case, the\n error message is wrong. The issue is not \"no sideband\" but rather\n \"eof while reading the packet\". However, this can't actually be\n triggered in practice, because neither of the two callers uses\n pkt_read's GENTLE_ON_EOF flag. Which means they'd die with \"the\n remote end hung up unexpectedly\" before we even get here.\n\n So this truly is dead code.\n\nWe can improve these cases by passing in a pkt-line status to the\ndemultiplexer, and by having recv_sideband() use GENTLE_ON_EOF. This\ngives us two improvements:\n\n - we can now reliably detect flush packets, and will report a normal\n packet missing its sideband designator as an error\n\n - we'll report an eof with a more detailed \"protocol error: eof while\n reading sideband packet\", rather than the generic \"the remote end\n hung up unexpectedly\"\n\n - when we see an eof, we'll flush the sideband scratch buffer, which\n may provide some hints from the remote about why they hung up\n (though note we already flush on newlines, so it's likely that most\n such messages already made it through)\n\nIn some sense this patch goes against fbd76cd450 (sideband: reverse its\ndependency on pkt-line, 2019-01-16), which caused the sideband code not\nto depend on the pkt-line code. But that commit was really just trying\nto deal with the circular header dependency. The two modules are\nconceptually interlinked, and it was just trying to keep things\ncompiling. And indeed, there's a sticking point in this patch: because\npkt-line.h includes sideband.h, we can't add the reverse include we need\nfor the sideband code to have an \"enum packet_read_status\" parameter.\nNor can we forward declare it, because you can't forward declare an enum\nin C. However, C does guarantee that enums fit in an int, so we can just\nuse that type.\n\nOne alternative would be for the callers to check themselves that they\ngot something sane from the pkt-line code. But besides duplicating\nlogic, this gets quite tricky. Any error condition requires flushing the\nsideband #2 scratch buffer, which only demultiplex_sideband() knows how\nto do.\n\nSigned-off-by: Jeff King \n---\n pkt-line.c | 14 ++++++++------\n sideband.c | 29 ++++++++++++++++++++++-------\n sideband.h | 6 +++++-\n t/t0070-fundamental.sh | 12 ++++++++++++\n 4 files changed, 47 insertions(+), 14 deletions(-)\n\ndiff --git a/pkt-line.c b/pkt-line.c\nindex 657a702927..d633005ef7 100644\n--- a/pkt-line.c\n+++ b/pkt-line.c\n@@ -461,9 +461,11 @@ int recv_sideband(const char *me, int in_stream, int out)\n \tenum sideband_type sideband_type;\n \n \twhile (1) {\n-\t\tlen = packet_read(in_stream, NULL, NULL, buf, LARGE_PACKET_MAX,\n-\t\t\t\t 0);\n-\t\tif (!demultiplex_sideband(me, buf, len, 0, &scratch,\n+\t\tint status = packet_read_with_status(in_stream, NULL, NULL,\n+\t\t\t\t\t\t buf, LARGE_PACKET_MAX,\n+\t\t\t\t\t\t &len,\n+\t\t\t\t\t\t PACKET_READ_GENTLE_ON_EOF);\n+\t\tif (!demultiplex_sideband(me, status, buf, len, 0, &scratch,\n \t\t\t\t\t &sideband_type))\n \t\t\tcontinue;\n \t\tswitch (sideband_type) {\n@@ -520,9 +522,9 @@ enum packet_read_status packet_reader_read(struct packet_reader *reader)\n \t\t\t\t\t\t\t reader->options);\n \t\tif (!reader->use_sideband)\n \t\t\tbreak;\n-\t\tif (demultiplex_sideband(reader->me, reader->buffer,\n-\t\t\t\t\t reader->pktlen, 1, &scratch,\n-\t\t\t\t\t &sideband_type))\n+\t\tif (demultiplex_sideband(reader->me, reader->status,\n+\t\t\t\t\t reader->buffer, reader->pktlen, 1,\n+\t\t\t\t\t &scratch, &sideband_type))\n \t\t\tbreak;\n \t}\n \ndiff --git a/sideband.c b/sideband.c\nindex a5405b9aaa..6f9e026732 100644\n--- a/sideband.c\n+++ b/sideband.c\n@@ -3,6 +3,7 @@\n #include \"config.h\"\n #include \"sideband.h\"\n #include \"help.h\"\n+#include \"pkt-line.h\"\n \n struct keyword_entry {\n \t/*\n@@ -114,7 +115,8 @@ static void maybe_colorize_sideband(struct strbuf *dest, const char *src, int n)\n #define ANSI_SUFFIX \"\\033[K\"\n #define DUMB_SUFFIX \" \"\n \n-int demultiplex_sideband(const char *me, char *buf, int len,\n+int demultiplex_sideband(const char *me, int status,\n+\t\t\t char *buf, int len,\n \t\t\t int die_on_error,\n \t\t\t struct strbuf *scratch,\n \t\t\t enum sideband_type *sideband_type)\n@@ -130,17 +132,30 @@ int demultiplex_sideband(const char *me, char *buf, int len,\n \t\t\tsuffix = DUMB_SUFFIX;\n \t}\n \n-\tif (len == 0) {\n-\t\t*sideband_type = SIDEBAND_FLUSH;\n-\t\tgoto cleanup;\n-\t}\n-\tif (len < 1) {\n+\tif (status == PACKET_READ_EOF) {\n \t\tstrbuf_addf(scratch,\n-\t\t\t \"%s%s: protocol error: no band designator\",\n+\t\t\t \"%s%s: unexpected disconnect while reading sideband packet\",\n \t\t\t scratch->len ? \"\\n\" : \"\", me);\n \t\t*sideband_type = SIDEBAND_PROTOCOL_ERROR;\n \t\tgoto cleanup;\n \t}\n+\n+\tif (len < 0)\n+\t\tBUG(\"negative length on non-eof packet read\");\n+\n+\tif (len == 0) {\n+\t\tif (status == PACKET_READ_NORMAL) {\n+\t\t\tstrbuf_addf(scratch,\n+\t\t\t\t \"%s%s: protocol error: missing sideband designator\",\n+\t\t\t\t scratch->len ? \"\\n\" : \"\", me);\n+\t\t\t*sideband_type = SIDEBAND_PROTOCOL_ERROR;\n+\t\t} else {\n+\t\t\t/* covers flush, delim, etc */\n+\t\t\t*sideband_type = SIDEBAND_FLUSH;\n+\t\t}\n+\t\tgoto cleanup;\n+\t}\n+\n \tband = buf[0] & 0xff;\n \tbuf[len] = '\\0';\n \tlen--;\ndiff --git a/sideband.h b/sideband.h\nindex 227740a58e..5a25331be5 100644\n--- a/sideband.h\n+++ b/sideband.h\n@@ -18,8 +18,12 @@ enum sideband_type {\n *\n * scratch must be a struct strbuf allocated by the caller. It is used to store\n * progress messages split across multiple packets.\n+ *\n+ * The \"status\" parameter is a pkt-line response as returned by\n+ * packet_read_with_status() (e.g., PACKET_READ_NORMAL).\n */\n-int demultiplex_sideband(const char *me, char *buf, int len,\n+int demultiplex_sideband(const char *me, int status,\n+\t\t\t char *buf, int len,\n \t\t\t int die_on_error,\n \t\t\t struct strbuf *scratch,\n \t\t\t enum sideband_type *sideband_type);\ndiff --git a/t/t0070-fundamental.sh b/t/t0070-fundamental.sh\nindex 357201640a..8d59905ef0 100755\n--- a/t/t0070-fundamental.sh\n+++ b/t/t0070-fundamental.sh\n@@ -40,4 +40,16 @@ test_expect_success 'incomplete sideband messages are reassembled' '\n \tgrep \"Hello, world\" err\n '\n \n+test_expect_success 'eof on sideband message is reported' '\n+\tprintf 1234 >input &&\n+\ttest-tool pkt-line receive-sideband err &&\n+\ttest_i18ngrep \"unexpected disconnect\" err\n+'\n+\n+test_expect_success 'missing sideband designator is reported' '\n+\tprintf 0004 >input &&\n+\ttest-tool pkt-line receive-sideband err &&\n+\ttest_i18ngrep \"missing sideband\" err\n+'\n+\n test_done\n-- \n2.29.1.641.gb6287e56d2\n\n"}]}