[PATCH] t9300: wait for background fast-import process to die after killing it

[PATCH] t9300: wait for background fast-import process to die after killing it

[SZEDER Gábor]

The five new tests added to 't9300-fast-import.sh' in 30e215a65c
(fast-import: checkpoint: dump branches/tags/marks even if
object_count==0, 2017-09-28), all with the prefix "V:" in their test
description, run 'git fast-import' in the background and then 'kill'
it as part of a 'test_when_finished' cleanup command.  When this test
script is executed with Bash, some or even all of these tests tend to
pollute the test script's stderr, and messages about terminated
processes end up on the terminal:

  $ bash ./t9300-fast-import.sh
  <... snip ...>
  ok 179 - V: checkpoint helper does not get stuck with extra output
  /<...>/test-lib-functions.sh: line 388: 28383 Terminated              git fast-import $options 0<&8 1>&9
  ok 180 - V: checkpoint updates refs after reset
  ./t9300-fast-import.sh: line 3210: 28401 Terminated              git fast-import $options 0<&8 1>&9
  ok 181 - V: checkpoint updates refs and marks after commit
  ok 182 - V: checkpoint updates refs and marks after commit (no new objects)
  ./test-lib.sh: line 634: line 3250: 28485 Terminated              git fast-import $options 0<&8 1>&9
  ok 183 - V: checkpoint updates tags after tag
  ./t9300-fast-import.sh: line 3264: 28510 Terminated              git fast-import $options 0<&8 1>&9

After a background child process terminates, its parent Bash process
always outputs a message like those above to stderr, even when in
non-interactive mode.

But how do some of these messages end up on the test script's stderr,
why don't we get them from all five tests, and why do they come from
different file/line locations?  Well, after sending the TERM signal to
the background child process, it takes a little while until that
process receives the signal and terminates, and then it takes another
while until the parent process notices it.  During this time the
parent Bash process is continuing execution, and by the time it
notices that its child terminated it might have already left
'test_eval_inner_' and its stderr is not redirected to /dev/null
anymore.  That's why such a message can appear on the test script's
stderr, while other times, when the child terminates fast and/or the
parent shell is slow enough, the message ends up in /dev/null, just
like any other output of the test does.  Bash always adds the file
name and line number of the code location it was about to execute when
it notices the termination of its child process as a prefix to that
message, hence the varying and sometimes totally unrelated location
prefixes in those messages (e.g. line 388 in 'test-lib-functions.sh'
is 'test_verify_prereq', and I saw such a message pointing to
'say_color' as well).

Prevent these messages from appearing on the test script's stderr by
'wait'-ing on the pid of the background 'git fast-import' process
after sending it the TERM signal.  This ensures that the executing
shell's stderr is still redirected when the shell notices the
termination of its child process in the background, and that these
messages get a consistent file/line location prefix.

Note that this is not an issue when the test script is run with Bash
and '-v', because then these messages are supposed to go to the test
script's stderr anyway, and indeed all of them do; though the
sometimes seemingly random file/line prefixes could be confusing
still.  Similarly, it's not an issue with Bash and '--verbose-log'
either, because then all messages go to the log file as they should.
Finally, it's not an issue with some other shells (I tried dash, ksh,
ksh93 and mksh) even without any of the verbose options, because they
don't print messages like these in non-interactive mode in the first
place.

Signed-off-by: SZEDER Gábor <szeder.dev@gmail.com>
---
 t/t9300-fast-import.sh | 5 ++++-
 1 file changed, 4 insertions(+), 1 deletion(-)

diff --git a/t/t9300-fast-import.sh b/t/t9300-fast-import.sh
index 9e7f96223d..fac33e524c 100755
--- a/t/t9300-fast-import.sh
+++ b/t/t9300-fast-import.sh
@@ -3147,7 +3147,10 @@ background_import_then_checkpoint () {
 	echo $! >V.pid
 	# We don't mind if fast-import has already died by the time the test
 	# ends.
-	test_when_finished "exec 8>&-; exec 9>&-; kill $(cat V.pid) || true"
+	test_when_finished "
+		exec 8>&-; exec 9>&-;
+		kill $(cat V.pid) && wait $(cat V.pid)
+		true"
 
 	# Start in the background to ensure we adhere strictly to (blocking)
 	# pipes writing sequence. We want to assume that the write below could
-- 
2.18.0.408.g42635c01bc

Re: [PATCH] t9300: wait for background fast-import process to die after killing it

[Eric Rannaud]

On Thu, Jul 19, 2018 at 3:26 PM, SZEDER Gábor <szeder.dev@gmail.com> wrote:
> But how do some of these messages end up on the test script's stderr,
> why don't we get them from all five tests, and why do they come from
> different file/line locations?

Thanks for the detailed explanation.

Signed-off-by: Eric Rannaud <e@nanocritical.com>

Re: [PATCH] t9300: wait for background fast-import process to die after killing it

[Elijah Newren]

On Thu, Jul 19, 2018 at 3:26 PM, SZEDER Gábor <szeder.dev@gmail.com> wrote:
> The five new tests added to 't9300-fast-import.sh' in 30e215a65c
> (fast-import: checkpoint: dump branches/tags/marks even if
> object_count==0, 2017-09-28), all with the prefix "V:" in their test
> description, run 'git fast-import' in the background and then 'kill'
> it as part of a 'test_when_finished' cleanup command.  When this test
> script is executed with Bash, some or even all of these tests tend to
> pollute the test script's stderr, and messages about terminated
> processes end up on the terminal:
>
>   $ bash ./t9300-fast-import.sh
>   <... snip ...>
>   ok 179 - V: checkpoint helper does not get stuck with extra output
>   /<...>/test-lib-functions.sh: line 388: 28383 Terminated              git fast-import $options 0<&8 1>&9
>   ok 180 - V: checkpoint updates refs after reset
>   ./t9300-fast-import.sh: line 3210: 28401 Terminated              git fast-import $options 0<&8 1>&9
>   ok 181 - V: checkpoint updates refs and marks after commit
>   ok 182 - V: checkpoint updates refs and marks after commit (no new objects)
>   ./test-lib.sh: line 634: line 3250: 28485 Terminated              git fast-import $options 0<&8 1>&9
>   ok 183 - V: checkpoint updates tags after tag
>   ./t9300-fast-import.sh: line 3264: 28510 Terminated              git fast-import $options 0<&8 1>&9
>
> After a background child process terminates, its parent Bash process
> always outputs a message like those above to stderr, even when in
> non-interactive mode.
>
> But how do some of these messages end up on the test script's stderr,
> why don't we get them from all five tests, and why do they come from
> different file/line locations?  Well, after sending the TERM signal to
> the background child process, it takes a little while until that
> process receives the signal and terminates, and then it takes another
> while until the parent process notices it.  During this time the
> parent Bash process is continuing execution, and by the time it
> notices that its child terminated it might have already left
> 'test_eval_inner_' and its stderr is not redirected to /dev/null
> anymore.  That's why such a message can appear on the test script's
> stderr, while other times, when the child terminates fast and/or the
> parent shell is slow enough, the message ends up in /dev/null, just
> like any other output of the test does.  Bash always adds the file
> name and line number of the code location it was about to execute when
> it notices the termination of its child process as a prefix to that
> message, hence the varying and sometimes totally unrelated location
> prefixes in those messages (e.g. line 388 in 'test-lib-functions.sh'
> is 'test_verify_prereq', and I saw such a message pointing to
> 'say_color' as well).
>
> Prevent these messages from appearing on the test script's stderr by
> 'wait'-ing on the pid of the background 'git fast-import' process
> after sending it the TERM signal.  This ensures that the executing
> shell's stderr is still redirected when the shell notices the
> termination of its child process in the background, and that these
> messages get a consistent file/line location prefix.
>
> Note that this is not an issue when the test script is run with Bash
> and '-v', because then these messages are supposed to go to the test
> script's stderr anyway, and indeed all of them do; though the
> sometimes seemingly random file/line prefixes could be confusing
> still.  Similarly, it's not an issue with Bash and '--verbose-log'
> either, because then all messages go to the log file as they should.
> Finally, it's not an issue with some other shells (I tried dash, ksh,
> ksh93 and mksh) even without any of the verbose options, because they
> don't print messages like these in non-interactive mode in the first
> place.
>
> Signed-off-by: SZEDER Gábor <szeder.dev@gmail.com>
> ---
>  t/t9300-fast-import.sh | 5 ++++-
>  1 file changed, 4 insertions(+), 1 deletion(-)
>
> diff --git a/t/t9300-fast-import.sh b/t/t9300-fast-import.sh
> index 9e7f96223d..fac33e524c 100755
> --- a/t/t9300-fast-import.sh
> +++ b/t/t9300-fast-import.sh
> @@ -3147,7 +3147,10 @@ background_import_then_checkpoint () {
>         echo $! >V.pid
>         # We don't mind if fast-import has already died by the time the test
>         # ends.
> -       test_when_finished "exec 8>&-; exec 9>&-; kill $(cat V.pid) || true"
> +       test_when_finished "
> +               exec 8>&-; exec 9>&-;
> +               kill $(cat V.pid) && wait $(cat V.pid)
> +               true"
>
>         # Start in the background to ensure we adhere strictly to (blocking)
>         # pipes writing sequence. We want to assume that the write below could
> --
> 2.18.0.408.g42635c01bc

Sweet, thanks for fixing this.  I got these messages nearly 100% of
the time on a certain machine when running prove with a high enough
parallel flag.  I was getting a little annoyed by them, but hadn't dug
in yet.  Your patch squelches them up in my testing.