{"thread":{"id":"56769","subject":"Is t7006-pager.sh racy?","startedAt":"2021-10-24T00:04:47Z","lastAt":"2021-12-01T14:05:41Z","messageCount":17,"participants":["Junio C Hamano","SZEDER Gábor","Jeff King","Ævar Arnfjörð Bjarmason"],"isPatch":false,"patchVersion":null,"patchTotal":null},"messages":[{"id":"439470","messageId":"xmqq1r4b8ezp.fsf@gitster.g","threadId":"56769","inReplyTo":null,"subject":"Is t7006-pager.sh racy?","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2021-10-24T00:04:42Z","receivedAt":"2021-10-24T00:04:47Z","isPatch":false,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"It seems under --stress it is fairly easy to break the said test,\nespecially the one near the end\n\n    test_expect_success TTY 'git returns SIGPIPE on propagated signals from pager' '\n            test_when_finished \"rm pager-used trace.normal\" &&\n            test_config core.pager \">pager-used; test-tool sigchain\" &&\n            GIT_TRACE2=\"$(pwd)/trace.normal\" &&\n            export GIT_TRACE2 &&\n            test_when_finished \"unset GIT_TRACE2\" &&\n\n            if test_have_prereq !MINGW\n            then\n                    OUT=$( ((test_terminal git log; echo $? 1>&3) | :) 3>&1 ) &&\n                    test_match_signal 13 \"$OUT\"\n            else\n                    test_terminal git log\n            fi &&\n\n            grep child_exit trace.normal >child-exits &&\n            test_line_count = 1 child-exits &&\n            grep \" code:143 \" child-exits &&\n            test_path_is_file pager-used\n    '\n\nWhen it fails the code in child-exits is actually -1 not 143, a\npropagated pipe.\n\nWhat makes us expect that the \"git log\" invocation should trigger a\nSIGPIPE in the first place?  test-sigchain emitting a few lines and\nexiting without ever reading from its standard input?  Will it\nreliably die soon enough before, or linger around until, we attempt\nto write to the pager?  If it does not die quickly enough, can we\nattempt to write, successfully fill the buffer between us and the\npager, and wait to notice that test-sigchain exiting with non-zero,\nor something?\n"},{"id":"439489","messageId":"20211024170349.GA2101@szeder.dev","threadId":"56769","inReplyTo":"xmqq1r4b8ezp.fsf@gitster.g","subject":"Re: Is t7006-pager.sh racy?","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2021-10-24T17:03:49Z","receivedAt":"2021-10-24T17:03:59Z","isPatch":false,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"On Sat, Oct 23, 2021 at 05:04:42PM -0700, Junio C Hamano wrote:\n> It seems under --stress it is fairly easy to break the said test,\n> especially the one near the end\n\nI couldn't reproduce a failure with --stress, but after a cursory look\ninto those tests I doubt that either that test or any of the\npreceeding SIGPIPE tests added in c24b7f6736 (pager: test for exit\ncode with and without SIGPIPE, 2021-02-02) actually check what they\nare supposed to.\n\n>     test_expect_success TTY 'git returns SIGPIPE on propagated signals from pager' '\n>             test_when_finished \"rm pager-used trace.normal\" &&\n>             test_config core.pager \">pager-used; test-tool sigchain\" &&\n>             GIT_TRACE2=\"$(pwd)/trace.normal\" &&\n>             export GIT_TRACE2 &&\n>             test_when_finished \"unset GIT_TRACE2\" &&\n> \n>             if test_have_prereq !MINGW\n>             then\n>                     OUT=$( ((test_terminal git log; echo $? 1>&3) | :) 3>&1 ) &&\n\nThis way too convoluted contruct doesn't do what we expect it to do,\nsee below.\n\n>                     test_match_signal 13 \"$OUT\"\n>             else\n>                     test_terminal git log\n>             fi &&\n> \n>             grep child_exit trace.normal >child-exits &&\n>             test_line_count = 1 child-exits &&\n>             grep \" code:143 \" child-exits &&\n>             test_path_is_file pager-used\n>     '\n> \n> When it fails the code in child-exits is actually -1 not 143, a\n> propagated pipe.\n> \n> What makes us expect that the \"git log\" invocation should trigger a\n> SIGPIPE in the first place?\n\nA misunderstanding, perhaps, because those 'git log' commands with\ntheir early-exiting pagers rarely trigger SIGPIPE.\n\n>  test-sigchain emitting a few lines and\n> exiting without ever reading from its standard input?\n\nIt's 'test_terminal.perl' emitting whatever it read from 'git log' to\nthe \"| :\" pipe, which doesn't ever read from its standard input.\n\n> Will it\n> reliably die soon enough before, or linger around until, we attempt\n> to write to the pager?  If it does not die quickly enough, can we\n> attempt to write, successfully fill the buffer between us and the\n> pager, and wait to notice that test-sigchain exiting with non-zero,\n> or something?\n\nThe history used in those tests is rather small, 'git log |wc -c'\nshows that it outputs merely 811 bytes, which is not enough to fill\nany kind of buffers.  So I think 'git log' can only get SIGPIPE if it\nis still actively producing output after the pager command has already\nexited.\n\nThe first two tests in the patch below use such an early-exiting pager\nthat is supposed to trigger a SIGPIPE, but without that unnecessarily\nclever construct from the other tests, and demonstrate that 'git log'\nusually exits with success; './t7006-pager.sh --no-chain-lint -r\n1,2,101,109,110 --stress' usually takes a few repetitions to fail.\n\nThe third test below sends 'test_terminal's output to a non-reading\npipe stage, and along with the debug output added to\n'test-terminal.perl' demonstrate that it's 'test_terminal' that\nreliably gets SIGPIPE, or at least './t7006-pager.sh --no-chain-lint\n-r 1,2,101,111 --stress' didn't fail in 1000+ repetitions.\n\nAll this means that when those tests run\n\n    OUT=$( ((test_terminal git log; echo $? 1>&3) | :) 3>&1 ) &&\n    test_match_signal 13 \"$OUT\"\n\nthen though they intend to match a SIGPIPE in 'git log' supposedly\ntriggeres by the early-exiting pager, they mistakelly match the\nunexpected SIGPIPE in 'test_terminal' triggered by \"| :\" instead.\n\n\n  ---  >8  ---\n\ndiff --git a/t/t7006-pager.sh b/t/t7006-pager.sh\nindex 0e7cf75435..e3a2cacbb7 100755\n--- a/t/t7006-pager.sh\n+++ b/t/t7006-pager.sh\n@@ -786,4 +786,35 @@ test_expect_success TTY 'git returns SIGPIPE on propagated signals from pager' '\n \ttest_path_is_file pager-used\n '\n \n+echo \"'git log' output size: $(git log |wc -c)\"\n+\n+test_expect_success TTY 'early pager exit rarely triggers SIGPIPE #1' '\n+\ttest_when_finished \"rm -f pager-used\" &&\n+\ttest_config core.pager \">pager-used; head -n 1; exit 0\" &&\n+\n+\ttest_terminal git log &&\n+\ttest_path_is_file pager-used\n+'\n+\n+test_expect_success TTY 'early pager exit rarely triggers SIGPIPE #2' '\n+\ttest_when_finished \"rm -f pager-used\" &&\n+\ttest_config core.pager \">pager-used; head -n 1; exit 0\" &&\n+\n+\techo 0 >expect.EC &&\n+\t# Needs --no-chain-lint\n+\t( test_terminal git log ; echo $? >EC ) &&\n+\ttest_cmp expect.EC EC &&\n+\ttest_path_is_file pager-used\n+'\n+\n+test_expect_success TTY '\"test_terminal ... | :\" triggers SIGPIPE in test_terminal' '\n+\ttest_when_finished \"rm -f pager-used\" &&\n+\ttest_config core.pager \">pager-used; head -n 1; exit 0\" &&\n+\n+\ttest_terminal git log 2>err | : &&\n+\tgrep \"test-terminal.perl caught SIGPIPE\" err &&\n+\t! grep \"test-terminal.perl: waitpid() for child process\" err &&\n+\ttest_path_is_file pager-used\n+'\n+\n test_done\ndiff --git a/t/test-terminal.perl b/t/test-terminal.perl\nindex 1bcf01a9a4..064623031c 100755\n--- a/t/test-terminal.perl\n+++ b/t/test-terminal.perl\n@@ -22,11 +22,14 @@ sub start_child {\n \treturn $pid;\n }\n \n+$SIG{PIPE} = sub { die \"test-terminal.perl caught SIGPIPE: $!\" };\n+\n # Wait for $pid to finish.\n sub finish_child {\n \t# Simplified from wait_or_whine() in run-command.c.\n \tmy ($pid) = @_;\n \n+\twarn \"test-terminal: waitpid() for child process\";\n \tmy $waiting = waitpid($pid, 0);\n \tif ($waiting < 0) {\n \t\tdie \"waitpid failed: $!\";\n"},{"id":"439569","messageId":"YXbsPrU6nRSboQ7r@coredump.intra.peff.net","threadId":"56769","inReplyTo":"20211024170349.GA2101@szeder.dev","subject":"Re: Is t7006-pager.sh racy?","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2021-10-25T17:41:18Z","receivedAt":"2021-10-25T17:41:24Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Sun, Oct 24, 2021 at 07:03:49PM +0200, SZEDER Gábor wrote:\n\n> On Sat, Oct 23, 2021 at 05:04:42PM -0700, Junio C Hamano wrote:\n> > It seems under --stress it is fairly easy to break the said test,\n> > especially the one near the end\n> \n> I couldn't reproduce a failure with --stress, but after a cursory look\n> into those tests I doubt that either that test or any of the\n> preceeding SIGPIPE tests added in c24b7f6736 (pager: test for exit\n> code with and without SIGPIPE, 2021-02-02) actually check what they\n> are supposed to.\n\nYeah, I am puzzled that they are using test_terminal in the first place\n(as opposed to just \"git -p\"). And you are right that a raw git-log is\nunlikely to be slow enough to get SIGPIPE in most cases.\n\nMy usual test for an intentional SIGPIPE is \"yes\". So something like:\n\n  git -p \\\n    -c core.pager='exit 0' \\\n    -c alias.yes='!yes' \\\n    yes\n\nwill reliably trigger SIGPIPE from yes, which git.c will then translate\ninto an exit code of 141.\n\nIf you really want to see SIGPIPE from a builtin (which arguably is the\nmore interesting case here, though I think it behaves the same with\nrespect to the pager), it's a bit trickier. One way to do it is with a\ncommand that doesn't generate output until after it gets EOF on stdin.\n\nSo something like \"git log --stdin\" works, but you have to contort\nyourself a bit to make it race-free:\n\n-- >8 --\n# The I/O setup here is:\n#\n#         fifo:log-in          stdout\n#   shell -----------> git-log ------> pager\n#     ^                                 /\n#      \\-------------------------------/\n#                 fifo:pager-closed\n#\n# The pager closes its stdin, which will give git-log SIGPIPE. But the\n# tricky part is that after doing so, it signals via fifo to the shell,\n# which then writes to git-log's stdin, triggering it to actually\n# generate output (and get SIGPIPE).\n#\n# You can verify that it's race-free by inserting a \"sleep 3\" at the\n# front of the pager command (before the exec) and seeing that the\n# other processes wait (and we still get SIGPIPE).\n\nmkfifo pager-closed\nmkfifo log-in\ngit config core.pager 'exec 0<&-; echo ready >pager-closed; exit 0'\n(git -p log --stdin <log-in; echo $? >exit-code) &\n\n# we have to open a descriptor rather than just \"echo HEAD >log-in\", because\n# that will give git-log an immediate EOF on its input when echo closes it, and\n# we must wait until the signal from pager-closed. Likewise we cannot wait\n# for that signal before the echo, because the subshell is blocking on opening\n# log-in until somebody is hooked up to the write end of the pipe.\nexec 9>log-in\nread ok <pager-closed\necho HEAD >&9\nexec 9>&-\n\n# now we can wait for the subshell to finish and retrieve any output\n# it produced\nwait\ncat exit-code\n-- >8 --\n\n-Peff\n"},{"id":"439932","messageId":"20211028195527.GA2574@szeder.dev","threadId":"56769","inReplyTo":"YXbsPrU6nRSboQ7r@coredump.intra.peff.net","subject":"Re: Is t7006-pager.sh racy?","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2021-10-28T19:55:27Z","receivedAt":"2021-10-28T19:55:35Z","isPatch":false,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"On Mon, Oct 25, 2021 at 01:41:18PM -0400, Jeff King wrote:\n> On Sun, Oct 24, 2021 at 07:03:49PM +0200, SZEDER Gábor wrote:\n> \n> > On Sat, Oct 23, 2021 at 05:04:42PM -0700, Junio C Hamano wrote:\n> > > It seems under --stress it is fairly easy to break the said test,\n> > > especially the one near the end\n> > \n> > I couldn't reproduce a failure with --stress, but after a cursory look\n> > into those tests I doubt that either that test or any of the\n> > preceeding SIGPIPE tests added in c24b7f6736 (pager: test for exit\n> > code with and without SIGPIPE, 2021-02-02) actually check what they\n> > are supposed to.\n> \n> Yeah, I am puzzled that they are using test_terminal in the first place\n> (as opposed to just \"git -p\"). And you are right that a raw git-log is\n> unlikely to be slow enough to get SIGPIPE in most cases.\n> \n> My usual test for an intentional SIGPIPE is \"yes\". So something like:\n> \n>   git -p \\\n>     -c core.pager='exit 0' \\\n>     -c alias.yes='!yes' \\\n>     yes\n> \n> will reliably trigger SIGPIPE from yes, which git.c will then translate\n> into an exit code of 141.\n\nOh, that's clever.  Alas it's not applicable to our tests, because\n'yes' is not portable; 8648732e29 (t/test-lib.sh: provide a shell\nimplementation of the 'yes' utility, 2009-08-28).\n\n\n> If you really want to see SIGPIPE from a builtin (which arguably is the\n> more interesting case here, though I think it behaves the same with\n> respect to the pager), it's a bit trickier. One way to do it is with a\n> command that doesn't generate output until after it gets EOF on stdin.\n> \n> So something like \"git log --stdin\" works, but you have to contort\n> yourself a bit to make it race-free:\n> \n> -- >8 --\n> # The I/O setup here is:\n> #\n> #         fifo:log-in          stdout\n> #   shell -----------> git-log ------> pager\n> #     ^                                 /\n> #      \\-------------------------------/\n> #                 fifo:pager-closed\n> #\n> # The pager closes its stdin, which will give git-log SIGPIPE. But the\n> # tricky part is that after doing so, it signals via fifo to the shell,\n> # which then writes to git-log's stdin, triggering it to actually\n> # generate output (and get SIGPIPE).\n> #\n> # You can verify that it's race-free by inserting a \"sleep 3\" at the\n> # front of the pager command (before the exec) and seeing that the\n> # other processes wait (and we still get SIGPIPE).\n> \n> mkfifo pager-closed\n> mkfifo log-in\n> git config core.pager 'exec 0<&-; echo ready >pager-closed; exit 0'\n> (git -p log --stdin <log-in; echo $? >exit-code) &\n> \n> # we have to open a descriptor rather than just \"echo HEAD >log-in\", because\n> # that will give git-log an immediate EOF on its input when echo closes it, and\n> # we must wait until the signal from pager-closed. Likewise we cannot wait\n> # for that signal before the echo, because the subshell is blocking on opening\n> # log-in until somebody is hooked up to the write end of the pipe.\n> exec 9>log-in\n> read ok <pager-closed\n> echo HEAD >&9\n> exec 9>&-\n> \n> # now we can wait for the subshell to finish and retrieve any output\n> # it produced\n> wait\n> cat exit-code\n> -- >8 --\n\nUgh.  I think this would work reliably, but...  ugh :)\n\nI wonder whether we could do this as a new pair of 'test-tool'\nhelpers, one to run the pager through the usual pager-invoking\nmachinery and to generate a lot of output, the other to be used as the\nearly-exiting pager, with a pipe between the two to ensure that the\nSIGPIPE does happen.  Well, essentially the same that you outlined\nabove but in C instead of shell, which I somehow find less \"ugh\".\n\n"},{"id":"439955","messageId":"YXsfvU+faPH6m/m/@coredump.intra.peff.net","threadId":"56769","inReplyTo":"20211028195527.GA2574@szeder.dev","subject":"Re: Is t7006-pager.sh racy?","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2021-10-28T22:10:05Z","receivedAt":"2021-10-28T22:10:08Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Thu, Oct 28, 2021 at 09:55:27PM +0200, SZEDER Gábor wrote:\n\n> > \n> > My usual test for an intentional SIGPIPE is \"yes\". So something like:\n> > \n> >   git -p \\\n> >     -c core.pager='exit 0' \\\n> >     -c alias.yes='!yes' \\\n> >     yes\n> > \n> > will reliably trigger SIGPIPE from yes, which git.c will then translate\n> > into an exit code of 141.\n> \n> Oh, that's clever.  Alas it's not applicable to our tests, because\n> 'yes' is not portable; 8648732e29 (t/test-lib.sh: provide a shell\n> implementation of the 'yes' utility, 2009-08-28).\n\nTrue, though it would be easy enough to do:\n\n  git -c alias.yes='!while true; do echo y; done' yes\n\n> > So something like \"git log --stdin\" works, but you have to contort\n> > yourself a bit to make it race-free:\n> [...]\n> Ugh.  I think this would work reliably, but...  ugh :)\n\nYes. :)\n\n> I wonder whether we could do this as a new pair of 'test-tool'\n> helpers, one to run the pager through the usual pager-invoking\n> machinery and to generate a lot of output, the other to be used as the\n> early-exiting pager, with a pipe between the two to ensure that the\n> SIGPIPE does happen.  Well, essentially the same that you outlined\n> above but in C instead of shell, which I somehow find less \"ugh\".\n\nMaybe, though now we may be diverging from how git.c uses the pager. As\ngross as what I wrote is, it is testing the code we want to test, I\nthink. I am not sure that the alias vs builtin thing is worth caring\nabout anyway, though, in which case the alias.yes thing above would be\nfine.\n\n-Peff\n"},{"id":"441889","messageId":"YZqSgu4XjPWnURju@coredump.intra.peff.net","threadId":"56769","inReplyTo":"20211024170349.GA2101@szeder.dev","subject":"Re: Is t7006-pager.sh racy?","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2021-11-21T18:40:02Z","receivedAt":"2021-11-21T18:40:06Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Sun, Oct 24, 2021 at 07:03:49PM +0200, SZEDER Gábor wrote:\n\n> > What makes us expect that the \"git log\" invocation should trigger a\n> > SIGPIPE in the first place?\n> \n> A misunderstanding, perhaps, because those 'git log' commands with\n> their early-exiting pagers rarely trigger SIGPIPE.\n\nI happened to be looking in this area today[1], and I think it turns out\nnot to be \"rarely\", but rather \"never\" for some of the tests.\n\nThe test in question sets the pager to \"does-not-exist\". But in that\ncase we will realize immediately via run-command.c that we could not run\nthe pager, and will not even redirect our stdout to it.\n\nFor example, doing this:\n\n  GIT_PAGER=does-not-exist git -c alias.foo='!yes' -p foo\n\nwill never get SIGPIPE; it will just write infinitely to the original\nstdout, and return success.\n\nWhereas this:\n\n  GIT_PAGER=false git -c alias.foo='!yes' -p foo\n\nwill reliably get SIGPIPE. But even if we used it (with a while loop to\ninstead of \"yes\" address the portability concern), the tests in t7006\nwould still be wrong, because they are sending test-terminal's output to\na closed pipe (so we'd still see SIGPIPE regardless of Git's behavior).\nThey should be sending test_terminal's output to a file or /dev/null.\n\nIt seems like this thread stalled. Ævar, were you planning to fix these\ntests?\n\nIt's not too hard to swap out a \"yes\" as I showed above, but it further\nconfuses the trace2 output, because now we have the child yes (or its\nshell equivalent) exiting as well.\n\nThe non-child \"log --stdin\" example I gave earlier in the thread avoids\nthat, but the fifo hackery is so horrible that I'd just as soon avoid\nit. I guess yet another option is a builtin which produces infinite\noutput. Perhaps:\n\n  oid=$(git rev-parse HEAD)\n  while true; do echo $oid; done |\n  test_terminal git -p cat-file --batch-check\n\nThat's guaranteed to get SIGPIPE eventually if the pager stops reading.\nI seem to recall that test_terminal's handling of stdin is somewhat\nbroken, though, and would probably get in our way[2]. Possibly we could\njust rip it out, as nobody is relying on it (they can't be, because it's\nbroken).\n\n-Peff\n\n[1] https://lore.kernel.org/git/YZqSBlvzz2KgOMnJ@coredump.intra.peff.net/\n\n[2] https://lore.kernel.org/git/20190520125016.GA13474@sigill.intra.peff.net/\n"},{"id":"441890","messageId":"YZrCmPb5AIW8YYQ0@coredump.intra.peff.net","threadId":"56769","inReplyTo":"YZqSgu4XjPWnURju@coredump.intra.peff.net","subject":"Re: Is t7006-pager.sh racy?","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2021-11-21T22:05:12Z","receivedAt":"2021-11-21T22:05:17Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Sun, Nov 21, 2021 at 01:40:02PM -0500, Jeff King wrote:\n\n> It seems like this thread stalled. Ævar, were you planning to fix these\n> tests?\n> \n> It's not too hard to swap out a \"yes\" as I showed above, but it further\n> confuses the trace2 output, because now we have the child yes (or its\n> shell equivalent) exiting as well.\n> [...]\n\nI think it also probably doesn't test what the patch adding these tests\nwas interested in. Specifically, it's trying to check the case of\nreporting the pager exit code while we're in a signal handler. So we\nhave to get the SIGPIPE in the main git process to trigger that. Which\nmeans it has to be a builtin.\n\nSo you really do need a builtin that produces infinite output. Or at the\nvery least, enough that we expect it to fill any possible OS pipe\nbuffer. I guess the latter is actually not that hard. A 1MB\ncommit-message would be plenty (or if you prefer, a big file with \"log\n-p\").\n\n-Peff\n"},{"id":"441891","messageId":"YZrOLy03s5ZWMQ+t@coredump.intra.peff.net","threadId":"56769","inReplyTo":"YZrCmPb5AIW8YYQ0@coredump.intra.peff.net","subject":"[PATCH] t7006: clean up SIGPIPE handling in trace2 tests","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2021-11-21T22:54:39Z","receivedAt":"2021-11-21T22:54:42Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Sun, Nov 21, 2021 at 05:05:12PM -0500, Jeff King wrote:\n\n> On Sun, Nov 21, 2021 at 01:40:02PM -0500, Jeff King wrote:\n> \n> > It seems like this thread stalled. Ævar, were you planning to fix these\n> > tests?\n> > \n> > It's not too hard to swap out a \"yes\" as I showed above, but it further\n> > confuses the trace2 output, because now we have the child yes (or its\n> > shell equivalent) exiting as well.\n> > [...]\n> \n> I think it also probably doesn't test what the patch adding these tests\n> was interested in. Specifically, it's trying to check the case of\n> reporting the pager exit code while we're in a signal handler. So we\n> have to get the SIGPIPE in the main git process to trigger that. Which\n> means it has to be a builtin.\n> \n> So you really do need a builtin that produces infinite output. Or at the\n> very least, enough that we expect it to fill any possible OS pipe\n> buffer. I guess the latter is actually not that hard. A 1MB\n> commit-message would be plenty (or if you prefer, a big file with \"log\n> -p\").\n\nThat's actually pretty easy to do. So I came up with the patch below, in\nthe interests of wrapping up this thread.\n\nI'm not 100% sure this fixes any possible races, as the race Junio\ninitially reported seemed to be in the \"propagated signals from pager\"\ntest, which I don't think has these flaky-SIGPIPE problems. But I think\nit's at least correcting some of the confusion. And we can see if it\nhappens again (I haven't been able to trigger any failures with --stress\nmyself).\n\n-- >8 --\nSubject: [PATCH] t7006: clean up SIGPIPE handling in trace2 tests\n\nComit c24b7f6736 (pager: test for exit code with and without SIGPIPE,\n2021-02-02) introduced some tests that don't reliably generate SIGPIPE\nwhere we expect it (i.e., when our pager doesn't read all of the output\nfrom git-log).\n\nThere are two problems that somewhat cancel each other out.\n\nFirst is that the output of git-log isn't very large (only around 800\nbytes). So even if the pager doesn't read all of our output, it's racy\nwhether or not we'll actually get a SIGPIPE (we won't if we write all of\nthe output into the pipe buffer before the pager exits).\n\nBut we wrap git-log with test_terminal, which is supposed to propagate\nthe exit status of git-log. However, it doesn't always do so;\ntest_terminal will copy to stdout any lines that it got from our fake\npager, and it pipes to an empty command. So most of the time we are\nseeing a SIGPIPE from test_terminal itself (though this is likewise\nracy).\n\nLet's try to make this more robust in two ways:\n\n  1. We'll put a commit with a huge message at the tip of history. Since\n     this is over a megabyte, it should fill the OS pipe buffer\n     completely, causing git-log to keep trying to write even after the\n     pager has exited.\n\n  2. We'll redirect the output of test_terminal to /dev/null. That means\n     it can never get SIGPIPE itself, and will always be giving us the\n     exit code from git-log.\n\nThese two changes reveal that one of the tests was looking for the wrong\nbehavior. If we try to start a pager that does not exist (according to\nexecve()), then the error propagates from start_command() back to the\npager code as an error, and we avoid redirecting git-log's stdout to the\nbroken pager entirely.  Instead, it goes straight to the original stdout\n(test_terminal's pty in this case), and we do not see a SIGPIPE at all.\n\nSo the test \"git attempts to page to nonexisting pager command, gets\nSIGPIPE\" is checking the wrong outcome; it should be looking for a\nsuccessful exit (and was only confused by test_terminal's SIGPIPE).\n\nThere's a related test, \"git discards nonexisting pager without\nSIGPIPE\", which sets the pager to a shell command which will read all\ninput and _then_ run a non-existing command. But that doesn't trigger\nthe same execve() behavior. We really do run the shell there and\nredirect git-log's stdout to it. And the fact that the shell then exits\n127 is not interesting. It is not different at that point than the\nearlier test to check for \"exit 1\". So we can drop that test entirely.\n\nSigned-off-by: Jeff King <peff@peff.net>\n---\n t/t7006-pager.sh | 42 ++++++++++++++----------------------------\n 1 file changed, 14 insertions(+), 28 deletions(-)\n\ndiff --git a/t/t7006-pager.sh b/t/t7006-pager.sh\nindex 0e7cf75435..577e51b47a 100755\n--- a/t/t7006-pager.sh\n+++ b/t/t7006-pager.sh\n@@ -661,6 +661,13 @@ test_expect_success 'setup trace2' '\n \texport GIT_TRACE2_BRIEF\n '\n \n+test_expect_success 'setup large log output' '\n+\tperl -e \"\n+\t\tprint \\\"this is a long commit message\\\" x 50000\n+\t\" >commit-msg &&\n+\tgit commit --allow-empty -F commit-msg\n+'\n+\n test_expect_success TTY 'git returns SIGPIPE on early pager exit' '\n \ttest_when_finished \"rm pager-used trace.normal\" &&\n \ttest_config core.pager \">pager-used; head -n 1; exit 0\" &&\n@@ -670,7 +677,7 @@ test_expect_success TTY 'git returns SIGPIPE on early pager exit' '\n \n \tif test_have_prereq !MINGW\n \tthen\n-\t\tOUT=$( ((test_terminal git log; echo $? 1>&3) | :) 3>&1 ) &&\n+\t\tOUT=$( ((test_terminal git log; echo $? 1>&3) >/dev/null) 3>&1 ) &&\n \t\ttest_match_signal 13 \"$OUT\"\n \telse\n \t\ttest_terminal git log\n@@ -691,7 +698,7 @@ test_expect_success TTY 'git returns SIGPIPE on early pager non-zero exit' '\n \n \tif test_have_prereq !MINGW\n \tthen\n-\t\tOUT=$( ((test_terminal git log; echo $? 1>&3) | :) 3>&1 ) &&\n+\t\tOUT=$( ((test_terminal git log; echo $? 1>&3) >/dev/null) 3>&1 ) &&\n \t\ttest_match_signal 13 \"$OUT\"\n \telse\n \t\ttest_terminal git log\n@@ -712,7 +719,7 @@ test_expect_success TTY 'git discards pager non-zero exit without SIGPIPE' '\n \n \tif test_have_prereq !MINGW\n \tthen\n-\t\tOUT=$( ((test_terminal git log; echo $? 1>&3) | :) 3>&1 ) &&\n+\t\tOUT=$( ((test_terminal git log; echo $? 1>&3) >/dev/null) 3>&1 ) &&\n \t\ttest \"$OUT\" -eq 0\n \telse\n \t\ttest_terminal git log\n@@ -724,28 +731,7 @@ test_expect_success TTY 'git discards pager non-zero exit without SIGPIPE' '\n \ttest_path_is_file pager-used\n '\n \n-test_expect_success TTY 'git discards nonexisting pager without SIGPIPE' '\n-\ttest_when_finished \"rm pager-used trace.normal\" &&\n-\ttest_config core.pager \"wc >pager-used; does-not-exist\" &&\n-\tGIT_TRACE2=\"$(pwd)/trace.normal\" &&\n-\texport GIT_TRACE2 &&\n-\ttest_when_finished \"unset GIT_TRACE2\" &&\n-\n-\tif test_have_prereq !MINGW\n-\tthen\n-\t\tOUT=$( ((test_terminal git log; echo $? 1>&3) | :) 3>&1 ) &&\n-\t\ttest \"$OUT\" -eq 0\n-\telse\n-\t\ttest_terminal git log\n-\tfi &&\n-\n-\tgrep child_exit trace.normal >child-exits &&\n-\ttest_line_count = 1 child-exits &&\n-\tgrep \" code:127 \" child-exits &&\n-\ttest_path_is_file pager-used\n-'\n-\n-test_expect_success TTY 'git attempts to page to nonexisting pager command, gets SIGPIPE' '\n+test_expect_success TTY 'git skips paging nonexisting command' '\n \ttest_when_finished \"rm trace.normal\" &&\n \ttest_config core.pager \"does-not-exist\" &&\n \tGIT_TRACE2=\"$(pwd)/trace.normal\" &&\n@@ -754,8 +740,8 @@ test_expect_success TTY 'git attempts to page to nonexisting pager command, gets\n \n \tif test_have_prereq !MINGW\n \tthen\n-\t\tOUT=$( ((test_terminal git log; echo $? 1>&3) | :) 3>&1 ) &&\n-\t\ttest_match_signal 13 \"$OUT\"\n+\t\tOUT=$( ((test_terminal git log; echo $? 1>&3) >/dev/null) 3>&1 ) &&\n+\t\ttest \"$OUT\" -eq 0\n \telse\n \t\ttest_terminal git log\n \tfi &&\n@@ -774,7 +760,7 @@ test_expect_success TTY 'git returns SIGPIPE on propagated signals from pager' '\n \n \tif test_have_prereq !MINGW\n \tthen\n-\t\tOUT=$( ((test_terminal git log; echo $? 1>&3) | :) 3>&1 ) &&\n+\t\tOUT=$( ((test_terminal git log; echo $? 1>&3) >/dev/null) 3>&1 ) &&\n \t\ttest_match_signal 13 \"$OUT\"\n \telse\n \t\ttest_terminal git log\n-- \n2.34.0.636.g3d595567a1\n\n"},{"id":"441892","messageId":"YZrSALOrdhuunHwp@coredump.intra.peff.net","threadId":"56769","inReplyTo":"YZrOLy03s5ZWMQ+t@coredump.intra.peff.net","subject":"Re: [PATCH] t7006: clean up SIGPIPE handling in trace2 tests","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2021-11-21T23:10:56Z","receivedAt":"2021-11-21T23:11:00Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Sun, Nov 21, 2021 at 05:54:39PM -0500, Jeff King wrote:\n\n> That's actually pretty easy to do. So I came up with the patch below, in\n> the interests of wrapping up this thread.\n> \n> I'm not 100% sure this fixes any possible races, as the race Junio\n> initially reported seemed to be in the \"propagated signals from pager\"\n> test, which I don't think has these flaky-SIGPIPE problems. But I think\n> it's at least correcting some of the confusion. And we can see if it\n> happens again (I haven't been able to trigger any failures with --stress\n> myself).\n> \n> -- >8 --\n> Subject: [PATCH] t7006: clean up SIGPIPE handling in trace2 tests\n\nThis one is optional on top. It's just cleanup, but IMHO makes it easier\nto understand what's going on.\n\n-- >8 --\nSubject: [PATCH] t7006: simplify exit-code checks for sigpipe tests\n\nSome tests in t7006 check for a SIGPIPE result by recording $? and\ncomparing it with test_match_signal. Before the previous commit, the\ncommand was on the left-hand side of a pipe, and so we had to do some\nsubshell trickery to extract it.\n\nBut now that this is no longer the case, we can do things much more\nsimply: just run the command directly, using braces to avoid wrecking\nthe &&-chain, and then record $?. We could almost use test_expect_code\nhere, but it doesn't know about test_match_signal.\n\nLikewise, for tests which expect success (i.e., not SIGPIPE), we can\njust put them in the &&-chain as usual. That even lets us get rid of the\n!MINGW check, since the expectation is the same on both sides.\n\nSigned-off-by: Jeff King <peff@peff.net>\n---\n t/t7006-pager.sh | 22 +++++-----------------\n 1 file changed, 5 insertions(+), 17 deletions(-)\n\ndiff --git a/t/t7006-pager.sh b/t/t7006-pager.sh\nindex 577e51b47a..851961c798 100755\n--- a/t/t7006-pager.sh\n+++ b/t/t7006-pager.sh\n@@ -677,7 +677,7 @@ test_expect_success TTY 'git returns SIGPIPE on early pager exit' '\n \n \tif test_have_prereq !MINGW\n \tthen\n-\t\tOUT=$( ((test_terminal git log; echo $? 1>&3) >/dev/null) 3>&1 ) &&\n+\t\t{ test_terminal git log >/dev/null; OUT=$?; } &&\n \t\ttest_match_signal 13 \"$OUT\"\n \telse\n \t\ttest_terminal git log\n@@ -698,7 +698,7 @@ test_expect_success TTY 'git returns SIGPIPE on early pager non-zero exit' '\n \n \tif test_have_prereq !MINGW\n \tthen\n-\t\tOUT=$( ((test_terminal git log; echo $? 1>&3) >/dev/null) 3>&1 ) &&\n+\t\t{ test_terminal git log >/dev/null; OUT=$?; } &&\n \t\ttest_match_signal 13 \"$OUT\"\n \telse\n \t\ttest_terminal git log\n@@ -717,13 +717,7 @@ test_expect_success TTY 'git discards pager non-zero exit without SIGPIPE' '\n \texport GIT_TRACE2 &&\n \ttest_when_finished \"unset GIT_TRACE2\" &&\n \n-\tif test_have_prereq !MINGW\n-\tthen\n-\t\tOUT=$( ((test_terminal git log; echo $? 1>&3) >/dev/null) 3>&1 ) &&\n-\t\ttest \"$OUT\" -eq 0\n-\telse\n-\t\ttest_terminal git log\n-\tfi &&\n+\ttest_terminal git log &&\n \n \tgrep child_exit trace.normal >child-exits &&\n \ttest_line_count = 1 child-exits &&\n@@ -738,13 +732,7 @@ test_expect_success TTY 'git skips paging nonexisting command' '\n \texport GIT_TRACE2 &&\n \ttest_when_finished \"unset GIT_TRACE2\" &&\n \n-\tif test_have_prereq !MINGW\n-\tthen\n-\t\tOUT=$( ((test_terminal git log; echo $? 1>&3) >/dev/null) 3>&1 ) &&\n-\t\ttest \"$OUT\" -eq 0\n-\telse\n-\t\ttest_terminal git log\n-\tfi &&\n+\ttest_terminal git log &&\n \n \tgrep child_exit trace.normal >child-exits &&\n \ttest_line_count = 1 child-exits &&\n@@ -760,7 +748,7 @@ test_expect_success TTY 'git returns SIGPIPE on propagated signals from pager' '\n \n \tif test_have_prereq !MINGW\n \tthen\n-\t\tOUT=$( ((test_terminal git log; echo $? 1>&3) >/dev/null) 3>&1 ) &&\n+\t\t{ test_terminal git log >/dev/null; OUT=$?; } &&\n \t\ttest_match_signal 13 \"$OUT\"\n \telse\n \t\ttest_terminal git log\n-- \n2.34.0.636.g3d595567a1\n\n"},{"id":"441895","messageId":"xmqqa6hxlysf.fsf@gitster.g","threadId":"56769","inReplyTo":"YZrOLy03s5ZWMQ+t@coredump.intra.peff.net","subject":"Re: [PATCH] t7006: clean up SIGPIPE handling in trace2 tests","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2021-11-22T02:17:04Z","receivedAt":"2021-11-22T02:17:08Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Jeff King <peff@peff.net> writes:\n\n> I'm not 100% sure this fixes any possible races, as the race Junio\n> initially reported seemed to be in the \"propagated signals from pager\"\n> test, which I don't think has these flaky-SIGPIPE problems. But I think\n> it's at least correcting some of the confusion. And we can see if it\n> happens again (I haven't been able to trigger any failures with --stress\n> myself).\n\nApplying this (or this and the follow-up) seems to make t7006, which\nused to be flaky, to consistently fail at test \"git returns SIGPIPE\non propagated signals from pager\" for me ;-)\n"},{"id":"441903","messageId":"YZsh6mnjuKbbIrw8@coredump.intra.peff.net","threadId":"56769","inReplyTo":"xmqqa6hxlysf.fsf@gitster.g","subject":"Re: [PATCH] t7006: clean up SIGPIPE handling in trace2 tests","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2021-11-22T04:51:54Z","receivedAt":"2021-11-22T04:51:56Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Sun, Nov 21, 2021 at 06:17:04PM -0800, Junio C Hamano wrote:\n\n> Jeff King <peff@peff.net> writes:\n> \n> > I'm not 100% sure this fixes any possible races, as the race Junio\n> > initially reported seemed to be in the \"propagated signals from pager\"\n> > test, which I don't think has these flaky-SIGPIPE problems. But I think\n> > it's at least correcting some of the confusion. And we can see if it\n> > happens again (I haven't been able to trigger any failures with --stress\n> > myself).\n> \n> Applying this (or this and the follow-up) seems to make t7006, which\n> used to be flaky, to consistently fail at test \"git returns SIGPIPE\n> on propagated signals from pager\" for me ;-)\n\nWell, I guess it's good that we made things more consistent. :) It is\ncurious that you get failures and I don't, though. I wonder what the\ndifference is.\n\nOne curiosity is that the test does this:\n\n\ttest_config core.pager \">pager-used; test-tool sigchain\"\n\nWhile \"test-tool sigchain\" will die with SIGTERM, it's the shell itself\nwhich will waitpid() on it. And so in the end, what Git will generally\nsee is the same as if the shell had done \"exit 143\".\n\nI wonder if the difference is between our shells. I know from previous\nexperience that bash will sometimes directly exec the final command in a\n\"-c\" command, as an optimization. I don't get any difference running the\ntest with dash or bash, but that makes sense; the pager command is run\ninternally by Git via \"sh -c\".\n\nAha, that's it. If I recompile with SHELL_PATH=/bin/bash, then I see a\nfailure. Likewise, if I change the test like this:\n\ndiff --git a/t/t7006-pager.sh b/t/t7006-pager.sh\nindex 851961c798..a87ef37803 100755\n--- a/t/t7006-pager.sh\n+++ b/t/t7006-pager.sh\n@@ -741,7 +741,7 @@ test_expect_success TTY 'git skips paging nonexisting command' '\n \n test_expect_success TTY 'git returns SIGPIPE on propagated signals from pager' '\n \ttest_when_finished \"rm pager-used trace.normal\" &&\n-\ttest_config core.pager \">pager-used; test-tool sigchain\" &&\n+\ttest_config core.pager \">pager-used; exec test-tool sigchain\" &&\n \tGIT_TRACE2=\"$(pwd)/trace.normal\" &&\n \texport GIT_TRACE2 &&\n \ttest_when_finished \"unset GIT_TRACE2\" &&\n\nthen it fails even with dash. And that is, I think, closer to what the\ntest was actually trying to cover (since checking a shell's \"exit 143\"\nis really no different than \"exit 1\", and we checked that earlier).\n\nSo why is it failing? It looks like trace2 reports this as code \"-1\"\nrather than 143. I think that is because the fix from be8fc53e36 (pager:\nproperly log pager exit code when signalled, 2021-02-02) is incomplete.\nIt sets WEXITSTATUS() if the pager exited, but it doesn't handle signal\ndeath at all. I think it needs:\n\ndiff --git a/run-command.c b/run-command.c\nindex f40df01c77..ef9d1d4236 100644\n--- a/run-command.c\n+++ b/run-command.c\n@@ -555,6 +555,8 @@ static int wait_or_whine(pid_t pid, const char *argv0, int in_signal)\n \tif (in_signal) {\n \t\tif (WIFEXITED(status))\n \t\t\tcode = WEXITSTATUS(status);\n+\t\telse if (WIFSIGNALED(status))\n+\t\t\tcode = 128 + WTERMSIG(status); /* see comment below */\n \t\treturn code;\n \t}\n \n\n-Peff\n"},{"id":"441904","messageId":"YZsih3ar+g1ZTZOc@coredump.intra.peff.net","threadId":"56769","inReplyTo":"YZsh6mnjuKbbIrw8@coredump.intra.peff.net","subject":"Re: [PATCH] t7006: clean up SIGPIPE handling in trace2 tests","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2021-11-22T04:54:31Z","receivedAt":"2021-11-22T04:54:33Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Sun, Nov 21, 2021 at 11:51:54PM -0500, Jeff King wrote:\n\n> So why is it failing? It looks like trace2 reports this as code \"-1\"\n> rather than 143. I think that is because the fix from be8fc53e36 (pager:\n> properly log pager exit code when signalled, 2021-02-02) is incomplete.\n> It sets WEXITSTATUS() if the pager exited, but it doesn't handle signal\n> death at all. I think it needs:\n> \n> diff --git a/run-command.c b/run-command.c\n> index f40df01c77..ef9d1d4236 100644\n> --- a/run-command.c\n> +++ b/run-command.c\n> @@ -555,6 +555,8 @@ static int wait_or_whine(pid_t pid, const char *argv0, int in_signal)\n>  \tif (in_signal) {\n>  \t\tif (WIFEXITED(status))\n>  \t\t\tcode = WEXITSTATUS(status);\n> +\t\telse if (WIFSIGNALED(status))\n> +\t\t\tcode = 128 + WTERMSIG(status); /* see comment below */\n>  \t\treturn code;\n>  \t}\n\nI'm tempted to say that this would be clearer if the in_signal code path\njust followed the main logic, like this:\n\ndiff --git a/run-command.c b/run-command.c\nindex f40df01c77..1f58c17b6c 100644\n--- a/run-command.c\n+++ b/run-command.c\n@@ -552,20 +552,17 @@ static int wait_or_whine(pid_t pid, const char *argv0, int in_signal)\n \n \twhile ((waiting = waitpid(pid, &status, 0)) < 0 && errno == EINTR)\n \t\t;\t/* nothing */\n-\tif (in_signal) {\n-\t\tif (WIFEXITED(status))\n-\t\t\tcode = WEXITSTATUS(status);\n-\t\treturn code;\n-\t}\n \n \tif (waiting < 0) {\n \t\tfailed_errno = errno;\n-\t\terror_errno(\"waitpid for %s failed\", argv0);\n+\t\tif (!in_signal)\n+\t\t\terror_errno(\"waitpid for %s failed\", argv0);\n \t} else if (waiting != pid) {\n-\t\terror(\"waitpid is confused (%s)\", argv0);\n+\t\tif (!in_signal)\n+\t\t\terror(\"waitpid is confused (%s)\", argv0);\n \t} else if (WIFSIGNALED(status)) {\n \t\tcode = WTERMSIG(status);\n-\t\tif (code != SIGINT && code != SIGQUIT && code != SIGPIPE)\n+\t\tif (!in_signal && code != SIGINT && code != SIGQUIT && code != SIGPIPE)\n \t\t\terror(\"%s died of signal %d\", argv0, code);\n \t\t/*\n \t\t * This return value is chosen so that code & 0xff\n@@ -576,10 +573,12 @@ static int wait_or_whine(pid_t pid, const char *argv0, int in_signal)\n \t} else if (WIFEXITED(status)) {\n \t\tcode = WEXITSTATUS(status);\n \t} else {\n-\t\terror(\"waitpid is confused (%s)\", argv0);\n+\t\tif (!in_signal)\n+\t\t\terror(\"waitpid is confused (%s)\", argv0);\n \t}\n \n-\tclear_child_for_cleanup(pid);\n+\tif (!in_signal)\n+\t\tclear_child_for_cleanup(pid);\n \n \terrno = failed_errno;\n \treturn code;\n\nThat's a lot more tedious \"if (!in_signal)\" checks, but:\n\n  - we don't have to duplicate any of the actual application logic\n\n  - we'd now cover the extra cases for waitpid failing or returning the\n    wrong pid (previously if waitpid() failed we'd still look at status,\n    which could contain complete garbage!)\n\n-Peff\n"},{"id":"441905","messageId":"xmqq5yskn3ir.fsf@gitster.g","threadId":"56769","inReplyTo":"YZsih3ar+g1ZTZOc@coredump.intra.peff.net","subject":"Re: [PATCH] t7006: clean up SIGPIPE handling in trace2 tests","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2021-11-22T05:49:32Z","receivedAt":"2021-11-22T05:49:46Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Jeff King <peff@peff.net> writes:\n\n> I'm tempted to say that this would be clearer if the in_signal code path\n> just followed the main logic, like this:\n>\n> diff --git a/run-command.c b/run-command.c\n> index f40df01c77..1f58c17b6c 100644\n> --- a/run-command.c\n> +++ b/run-command.c\n> @@ -552,20 +552,17 @@ static int wait_or_whine(pid_t pid, const char *argv0, int in_signal)\n>  \n>  \twhile ((waiting = waitpid(pid, &status, 0)) < 0 && errno == EINTR)\n>  \t\t;\t/* nothing */\n> -\tif (in_signal) {\n> -\t\tif (WIFEXITED(status))\n> -\t\t\tcode = WEXITSTATUS(status);\n> -\t\treturn code;\n> -\t}\n>  \n>  \tif (waiting < 0) {\n>  \t\tfailed_errno = errno;\n> -\t\terror_errno(\"waitpid for %s failed\", argv0);\n> +\t\tif (!in_signal)\n> +\t\t\terror_errno(\"waitpid for %s failed\", argv0);\n>  \t} else if (waiting != pid) {\n> -\t\terror(\"waitpid is confused (%s)\", argv0);\n> +\t\tif (!in_signal)\n> +\t\t\terror(\"waitpid is confused (%s)\", argv0);\n>  \t} else if (WIFSIGNALED(status)) {\n>  \t\tcode = WTERMSIG(status);\n> -\t\tif (code != SIGINT && code != SIGQUIT && code != SIGPIPE)\n> +\t\tif (!in_signal && code != SIGINT && code != SIGQUIT && code != SIGPIPE)\n>  \t\t\terror(\"%s died of signal %d\", argv0, code);\n>  \t\t/*\n>  \t\t * This return value is chosen so that code & 0xff\n> @@ -576,10 +573,12 @@ static int wait_or_whine(pid_t pid, const char *argv0, int in_signal)\n>  \t} else if (WIFEXITED(status)) {\n>  \t\tcode = WEXITSTATUS(status);\n>  \t} else {\n> -\t\terror(\"waitpid is confused (%s)\", argv0);\n> +\t\tif (!in_signal)\n> +\t\t\terror(\"waitpid is confused (%s)\", argv0);\n>  \t}\n>  \n> -\tclear_child_for_cleanup(pid);\n> +\tif (!in_signal)\n> +\t\tclear_child_for_cleanup(pid);\n>  \n>  \terrno = failed_errno;\n>  \treturn code;\n>\n> That's a lot more tedious \"if (!in_signal)\" checks, but:\n>\n>   - we don't have to duplicate any of the actual application logic\n>\n>   - we'd now cover the extra cases for waitpid failing or returning the\n>     wrong pid (previously if waitpid() failed we'd still look at status,\n>     which could contain complete garbage!)\n\nYeah, the repeated \"if (!in_signal)\" look a bit ugly, but fixing\nthat \"we only deal with ifexited in in_signal case\" to do the right\nthing would make the code even more annoying and harder to maintain.\n"},{"id":"441906","messageId":"xmqq1r38n2sx.fsf@gitster.g","threadId":"56769","inReplyTo":"xmqq5yskn3ir.fsf@gitster.g","subject":"Re: [PATCH] t7006: clean up SIGPIPE handling in trace2 tests","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2021-11-22T06:05:02Z","receivedAt":"2021-11-22T06:05:07Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Junio C Hamano <gitster@pobox.com> writes:\n\n> Jeff King <peff@peff.net> writes:\n> ...\n>> That's a lot more tedious \"if (!in_signal)\" checks, but:\n>>\n>>   - we don't have to duplicate any of the actual application logic\n>>\n>>   - we'd now cover the extra cases for waitpid failing or returning the\n>>     wrong pid (previously if waitpid() failed we'd still look at status,\n>>     which could contain complete garbage!)\n> ...\n> Yeah, the repeated \"if (!in_signal)\" look a bit ugly, but fixing\n> that \"we only deal with ifexited in in_signal case\" to do the right\n> thing would make the code even more annoying and harder to maintain.\n\nEh, what I meant was that it would be annoying and harder to\nmaintain, if done inside the single \"if (in_signal) { ... }\" near\nthe beginning. (IOW, I am completely in agreement with your\nreasoning above).\n\n"},{"id":"442013","messageId":"YZvrVj8w8j2Fb14O@coredump.intra.peff.net","threadId":"56769","inReplyTo":"xmqq5yskn3ir.fsf@gitster.g","subject":"Re: [PATCH] t7006: clean up SIGPIPE handling in trace2 tests","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2021-11-22T19:11:18Z","receivedAt":"2021-11-22T19:11:21Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Sun, Nov 21, 2021 at 09:49:32PM -0800, Junio C Hamano wrote:\n\n> > That's a lot more tedious \"if (!in_signal)\" checks, but:\n> >\n> >   - we don't have to duplicate any of the actual application logic\n> >\n> >   - we'd now cover the extra cases for waitpid failing or returning the\n> >     wrong pid (previously if waitpid() failed we'd still look at status,\n> >     which could contain complete garbage!)\n> \n> Yeah, the repeated \"if (!in_signal)\" look a bit ugly, but fixing\n> that \"we only deal with ifexited in in_signal case\" to do the right\n> thing would make the code even more annoying and harder to maintain.\n\nOK. Let me see if I can clean this up into a full series that actually\nfixes the race you saw, and breaks down the other fixes a bit more.\n\n-Peff\n"},{"id":"442023","messageId":"YZwLbV/9GWZ8LsGf@coredump.intra.peff.net","threadId":"56769","inReplyTo":"YZvrVj8w8j2Fb14O@coredump.intra.peff.net","subject":"[PATCH] run-command: unify signal and regular logic for wait_or_whine()","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2021-11-22T21:28:13Z","receivedAt":"2021-11-22T21:28:29Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Mon, Nov 22, 2021 at 02:11:18PM -0500, Jeff King wrote:\n\n> On Sun, Nov 21, 2021 at 09:49:32PM -0800, Junio C Hamano wrote:\n> \n> > > That's a lot more tedious \"if (!in_signal)\" checks, but:\n> > >\n> > >   - we don't have to duplicate any of the actual application logic\n> > >\n> > >   - we'd now cover the extra cases for waitpid failing or returning the\n> > >     wrong pid (previously if waitpid() failed we'd still look at status,\n> > >     which could contain complete garbage!)\n> > \n> > Yeah, the repeated \"if (!in_signal)\" look a bit ugly, but fixing\n> > that \"we only deal with ifexited in in_signal case\" to do the right\n> > thing would make the code even more annoying and harder to maintain.\n> \n> OK. Let me see if I can clean this up into a full series that actually\n> fixes the race you saw, and breaks down the other fixes a bit more.\n\nHmm. So I had thought to maybe split apart the earlier patches and\ninterweave this one at the right spot. But really there is a mutual\ndependency in the test fixes: fixing the SIGPIPE issue means that this\nwill start to fail (but only sometimes, if /bin/sh is bash!), but fixing\nthe \"exec\" thing means it is only testing something sometimes (because\nof the pipe raciness).\n\nSo I ended up doing this as just a separate preparatory fix, which is in\nthe patch below. I see you picked up the earlier diff as\njk/pager-exit-fix.  This one gives much more explanation, and adjusts\nthe test to actually cover this case. It can be applied directly on top\nof ab/pager-exit-log, replacing what's in jk/pager-exit-fix.\n\nAnd then I'd apply the other two (which are currently in\njk/t7006-sigpipe-tests-fix) directly on top of that. IMHO it should all\njust be a single series that graduates together, but we could do the\nother test fixups separately (they are fixing races, but I think the\nraces err on the side of the tests doing nothing, not failing\nerroneously).\n\n-- >8 --\nSubject: run-command: unify signal and regular logic for wait_or_whine()\n\nSince 507d7804c0 (pager: don't use unsafe functions in signal handlers,\n2015-09-04), we have a separate code path in wait_or_whine() for the\ncase that we're in a signal handler. But that code path misses some of\nthe cases handled by the main logic.\n\nThis was improved in be8fc53e36 (pager: properly log pager exit code\nwhen signalled, 2021-02-02), but that covered only case: actually\nreturning the correct error code. But there are some other cases:\n\n  - if waitpid() returns failure, we wouldn't notice and would look at\n    uninitialized garbage in the status variable; it's not clear if it's\n    possible to trigger this or not\n\n  - if the process exited by signal, then we would still report \"-1\"\n    rather than the correct signal code\n\nThis latter case even had a test added in be8fc53e36, but it doesn't\nwork reliably. It sets the pager command to:\n\n  >pager-used; test-tool sigchain\n\nThe latter command will die by signal, but because there are multiple\ncommands, there will be a shell in between. And it's the shell whose\nwaitpid() call will see the signal death, and it will then exit with\ncode 143, which is what Git will see.\n\nTo make matters even more confusing, some shells (such as bash) will\nrealize that there's nothing for the shell to do after test-tool\nfinishes, and will turn it into an exec. So the test was only checking\nwhat it thought when /bin/sh points to a shell like bash (we're relying\non the shell used internally by Git to spawn sub-commands here, so even\nrunning the test under bash would not be enough).\n\nThis patch adjusts the tests to explicitly call \"exec\" in the pager\ncommand, which produces a consistent outcome regardless of shell. Note\nthat without the code change in this patch it _should_ fail reliably,\nbut doesn't. That test, like its siblings, tries to trigger SIGPIPE in\nthe git-log process writing to the pager, but only do so racily. That\nwill be fixed in a follow-on patch.\n\nFor the code change here, we have two options:\n\n  - we can teach the in_signal code to handle WIFSIGNALED()\n\n  - we can stop returning early when in_signal is set, and instead\n    annotate individual calls that we need to skip in this case\n\nThe former is a simpler patch, but means we're essentially duplicating\nall of the logic. So instead I went with the latter. The result is a\nbigger patch, and we do run the risk of new code being added but\nforgetting to handle in_signal. But in the long run it seems more\nmaintainable.\n\nI've skipped any non-trivial calls for the in_signal case, like calling\nerror(). We'll also skip the call to clear_child_for_cleanup(), as we\nwere before. This is arguably the wrong thing to do, since we wouldn't\nwant to try to clean it up again. But:\n\n  - we can't call it as-is, because it calls free(), which we must avoid\n    in a signal handler (we'd have to pass in_signal so it can skip the\n    free() call)\n\n  - we'll only go through the list of children to clean once, since our\n    cleanup_children_on_signal() handler pops itself after running (and\n    then re-raises, so eventually we'd just exit). So this cleanup only\n    matters if a process is on the cleanup list _and_ it has a separate\n    handler to clean itself up. Which is questionable in the first place\n    (and AFAIK we do not do).\n\n  - double-cleanup isn't actually that bad anyway. waitpid() will just\n    return an error, which we won't even report because of in_signal.\n\nSigned-off-by: Jeff King <peff@peff.net>\n---\n run-command.c    | 19 +++++++++----------\n t/t7006-pager.sh |  2 +-\n 2 files changed, 10 insertions(+), 11 deletions(-)\n\ndiff --git a/run-command.c b/run-command.c\nindex 509841bf27..350593928d 100644\n--- a/run-command.c\n+++ b/run-command.c\n@@ -551,20 +551,17 @@ static int wait_or_whine(pid_t pid, const char *argv0, int in_signal)\n \n \twhile ((waiting = waitpid(pid, &status, 0)) < 0 && errno == EINTR)\n \t\t;\t/* nothing */\n-\tif (in_signal) {\n-\t\tif (WIFEXITED(status))\n-\t\t\tcode = WEXITSTATUS(status);\n-\t\treturn code;\n-\t}\n \n \tif (waiting < 0) {\n \t\tfailed_errno = errno;\n-\t\terror_errno(\"waitpid for %s failed\", argv0);\n+\t\tif (!in_signal)\n+\t\t\terror_errno(\"waitpid for %s failed\", argv0);\n \t} else if (waiting != pid) {\n-\t\terror(\"waitpid is confused (%s)\", argv0);\n+\t\tif (!in_signal)\n+\t\t\terror(\"waitpid is confused (%s)\", argv0);\n \t} else if (WIFSIGNALED(status)) {\n \t\tcode = WTERMSIG(status);\n-\t\tif (code != SIGINT && code != SIGQUIT && code != SIGPIPE)\n+\t\tif (!in_signal && code != SIGINT && code != SIGQUIT && code != SIGPIPE)\n \t\t\terror(\"%s died of signal %d\", argv0, code);\n \t\t/*\n \t\t * This return value is chosen so that code & 0xff\n@@ -575,10 +572,12 @@ static int wait_or_whine(pid_t pid, const char *argv0, int in_signal)\n \t} else if (WIFEXITED(status)) {\n \t\tcode = WEXITSTATUS(status);\n \t} else {\n-\t\terror(\"waitpid is confused (%s)\", argv0);\n+\t\tif (!in_signal)\n+\t\t\terror(\"waitpid is confused (%s)\", argv0);\n \t}\n \n-\tclear_child_for_cleanup(pid);\n+\tif (!in_signal)\n+\t\tclear_child_for_cleanup(pid);\n \n \terrno = failed_errno;\n \treturn code;\ndiff --git a/t/t7006-pager.sh b/t/t7006-pager.sh\nindex 0e7cf75435..032bde278e 100755\n--- a/t/t7006-pager.sh\n+++ b/t/t7006-pager.sh\n@@ -767,7 +767,7 @@ test_expect_success TTY 'git attempts to page to nonexisting pager command, gets\n \n test_expect_success TTY 'git returns SIGPIPE on propagated signals from pager' '\n \ttest_when_finished \"rm pager-used trace.normal\" &&\n-\ttest_config core.pager \">pager-used; test-tool sigchain\" &&\n+\ttest_config core.pager \">pager-used; exec test-tool sigchain\" &&\n \tGIT_TRACE2=\"$(pwd)/trace.normal\" &&\n \texport GIT_TRACE2 &&\n \ttest_when_finished \"unset GIT_TRACE2\" &&\n-- \n2.34.0.639.g83a0ed08a8\n\n"},{"id":"442774","messageId":"211201.86czmgbetu.gmgdl@evledraar.gmail.com","threadId":"56769","inReplyTo":"YZqSgu4XjPWnURju@coredump.intra.peff.net","subject":"Re: Is t7006-pager.sh racy?","fromName":"Ævar Arnfjörð Bjarmason","fromEmail":"avarab@gmail.com","sentAt":"2021-12-01T14:03:23Z","receivedAt":"2021-12-01T14:05:41Z","isPatch":false,"sender":{"key":"avarab@gmail.com","avatar":"https://avatars.githubusercontent.com/u/45301?v=4"},"body":"\nOn Sun, Nov 21 2021, Jeff King wrote:\n\n> On Sun, Oct 24, 2021 at 07:03:49PM +0200, SZEDER Gábor wrote:\n>\n>> > What makes us expect that the \"git log\" invocation should trigger a\n>> > SIGPIPE in the first place?\n>> \n>> A misunderstanding, perhaps, because those 'git log' commands with\n>> their early-exiting pagers rarely trigger SIGPIPE.\n>\n> I happened to be looking in this area today[1], and I think it turns out\n> not to be \"rarely\", but rather \"never\" for some of the tests.\n>\n> The test in question sets the pager to \"does-not-exist\". But in that\n> case we will realize immediately via run-command.c that we could not run\n> the pager, and will not even redirect our stdout to it.\n>\n> For example, doing this:\n>\n>   GIT_PAGER=does-not-exist git -c alias.foo='!yes' -p foo\n>\n> will never get SIGPIPE; it will just write infinitely to the original\n> stdout, and return success.\n>\n> Whereas this:\n>\n>   GIT_PAGER=false git -c alias.foo='!yes' -p foo\n>\n> will reliably get SIGPIPE. But even if we used it (with a while loop to\n> instead of \"yes\" address the portability concern), the tests in t7006\n> would still be wrong, because they are sending test-terminal's output to\n> a closed pipe (so we'd still see SIGPIPE regardless of Git's behavior).\n> They should be sending test_terminal's output to a file or /dev/null.\n>\n> It seems like this thread stalled. Ævar, were you planning to fix these\n> tests?\n\nNot at this point I'm not! :)\n\nAnyway, a belated thanks for tackling this issue & sorry about the\nmess. I see jk/t7006-sigpipe-tests-fix is marked already & those fixes\nLGTM. This fell through the cracks for me among other E-Mail traffic.\n\n> [...]\n"}]}