Re: Is t7006-pager.sh racy?

From: SZEDER Gábor <szeder.dev@gmail.com>
Date: Oct 24, 2021, 17:03 UTC
Message-ID: <20211024170349.GA2101@szeder.dev>
In-Reply-To: <xmqq1r4b8ezp.fsf@gitster.g>

On Sat, Oct 23, 2021 at 05:04:42PM -0700, Junio C Hamano wrote:

> It seems under --stress it is fairly easy to break the said test,
> especially the one near the end

I couldn't reproduce a failure with --stress, but after a cursory look into those tests I doubt that either that test or any of the preceeding SIGPIPE tests added in c24b7f6736 (pager: test for exit code with and without SIGPIPE, 2021-02-02) actually check what they are supposed to.

Show 10 quoted lines

>     test_expect_success TTY 'git returns SIGPIPE on propagated signals from pager' '
>             test_when_finished "rm pager-used trace.normal" &&
>             test_config core.pager ">pager-used; test-tool sigchain" &&
>             GIT_TRACE2="$(pwd)/trace.normal" &&
>             export GIT_TRACE2 &&
>             test_when_finished "unset GIT_TRACE2" &&
> 
>             if test_have_prereq !MINGW
>             then
>                     OUT=$( ((test_terminal git log; echo $? 1>&3) | :) 3>&1 ) &&

This way too convoluted contruct doesn't do what we expect it to do, see below.

Show 16 quoted lines

>                     test_match_signal 13 "$OUT"
>             else
>                     test_terminal git log
>             fi &&
> 
>             grep child_exit trace.normal >child-exits &&
>             test_line_count = 1 child-exits &&
>             grep " code:143 " child-exits &&
>             test_path_is_file pager-used
>     '
> 
> When it fails the code in child-exits is actually -1 not 143, a
> propagated pipe.
> 
> What makes us expect that the "git log" invocation should trigger a
> SIGPIPE in the first place?

A misunderstanding, perhaps, because those 'git log' commands with their early-exiting pagers rarely trigger SIGPIPE.

>  test-sigchain emitting a few lines and
> exiting without ever reading from its standard input?

It's 'test_terminal.perl' emitting whatever it read from 'git log' to the "| :" pipe, which doesn't ever read from its standard input.

Show 6 quoted lines

> Will it
> reliably die soon enough before, or linger around until, we attempt
> to write to the pager?  If it does not die quickly enough, can we
> attempt to write, successfully fill the buffer between us and the
> pager, and wait to notice that test-sigchain exiting with non-zero,
> or something?

The history used in those tests is rather small, 'git log |wc -c' shows that it outputs merely 811 bytes, which is not enough to fill any kind of buffers. So I think 'git log' can only get SIGPIPE if it is still actively producing output after the pager command has already exited.

The first two tests in the patch below use such an early-exiting pager that is supposed to trigger a SIGPIPE, but without that unnecessarily clever construct from the other tests, and demonstrate that 'git log' usually exits with success; './t7006-pager.sh --no-chain-lint -r 1,2,101,109,110 --stress' usually takes a few repetitions to fail.

The third test below sends 'test_terminal's output to a non-reading pipe stage, and along with the debug output added to 'test-terminal.perl' demonstrate that it's 'test_terminal' that reliably gets SIGPIPE, or at least './t7006-pager.sh --no-chain-lint -r 1,2,101,111 --stress' didn't fail in 1000+ repetitions.

All this means that when those tests run

    OUT=$( ((test_terminal git log; echo $? 1>&3) | :) 3>&1 ) &&
    test_match_signal 13 "$OUT"

then though they intend to match a SIGPIPE in 'git log' supposedly triggeres by the early-exiting pager, they mistakelly match the unexpected SIGPIPE in 'test_terminal' triggered by "| :" instead.

  ---  >8  ---

diff --git a/t/t7006-pager.sh b/t/t7006-pager.sh
index 0e7cf75435..e3a2cacbb7 100755
--- a/t/t7006-pager.sh
+++ b/t/t7006-pager.sh
@@ -786,4 +786,35 @@ test_expect_success TTY 'git returns SIGPIPE on propagated signals from pager' '
 	test_path_is_file pager-used
 '
 
+echo "'git log' output size: $(git log |wc -c)"
+
+test_expect_success TTY 'early pager exit rarely triggers SIGPIPE #1' '
+	test_when_finished "rm -f pager-used" &&
+	test_config core.pager ">pager-used; head -n 1; exit 0" &&
+
+	test_terminal git log &&
+	test_path_is_file pager-used
+'
+
+test_expect_success TTY 'early pager exit rarely triggers SIGPIPE #2' '
+	test_when_finished "rm -f pager-used" &&
+	test_config core.pager ">pager-used; head -n 1; exit 0" &&
+
+	echo 0 >expect.EC &&
+	# Needs --no-chain-lint
+	( test_terminal git log ; echo $? >EC ) &&
+	test_cmp expect.EC EC &&
+	test_path_is_file pager-used
+'
+
+test_expect_success TTY '"test_terminal ... | :" triggers SIGPIPE in test_terminal' '
+	test_when_finished "rm -f pager-used" &&
+	test_config core.pager ">pager-used; head -n 1; exit 0" &&
+
+	test_terminal git log 2>err | : &&
+	grep "test-terminal.perl caught SIGPIPE" err &&
+	! grep "test-terminal.perl: waitpid() for child process" err &&
+	test_path_is_file pager-used
+'
+
 test_done
diff --git a/t/test-terminal.perl b/t/test-terminal.perl
index 1bcf01a9a4..064623031c 100755
--- a/t/test-terminal.perl
+++ b/t/test-terminal.perl
@@ -22,11 +22,14 @@ sub start_child {
 	return $pid;
 }
 
+$SIG{PIPE} = sub { die "test-terminal.perl caught SIGPIPE: $!" };
+
 # Wait for $pid to finish.
 sub finish_child {
 	# Simplified from wait_or_whine() in run-command.c.
 	my ($pid) = @_;
 
+	warn "test-terminal: waitpid() for child process";
 	my $waiting = waitpid($pid, 0);
 	if ($waiting < 0) {
 		die "waitpid failed: $!";