On Thu, Jul 19, 2018 at 3:26 PM, SZEDER Gábor <szeder.dev@xxxxxxxxx> 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@xxxxxxxxx>
> ---
> 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.
