{"thread":{"id":"48924","subject":"[PATCH] t9300: wait for background fast-import process to die after killing it","startedAt":"2018-07-19T22:26:55Z","lastAt":"2018-07-20T19:03:47Z","messageCount":3,"participants":["SZEDER Gábor","Eric Rannaud","Elijah Newren"],"isPatch":true,"patchVersion":1,"patchTotal":null},"messages":[{"id":"353096","messageId":"20180719222641.12152-1-szeder.dev@gmail.com","threadId":"48924","inReplyTo":null,"subject":"[PATCH] t9300: wait for background fast-import process to die after killing it","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2018-07-19T22:26:41Z","receivedAt":"2018-07-19T22:26:55Z","isPatch":true,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"The five new tests added to 't9300-fast-import.sh' in 30e215a65c\n(fast-import: checkpoint: dump branches/tags/marks even if\nobject_count==0, 2017-09-28), all with the prefix \"V:\" in their test\ndescription, run 'git fast-import' in the background and then 'kill'\nit as part of a 'test_when_finished' cleanup command.  When this test\nscript is executed with Bash, some or even all of these tests tend to\npollute the test script's stderr, and messages about terminated\nprocesses end up on the terminal:\n\n  $ bash ./t9300-fast-import.sh\n  <... snip ...>\n  ok 179 - V: checkpoint helper does not get stuck with extra output\n  /<...>/test-lib-functions.sh: line 388: 28383 Terminated              git fast-import $options 0<&8 1>&9\n  ok 180 - V: checkpoint updates refs after reset\n  ./t9300-fast-import.sh: line 3210: 28401 Terminated              git fast-import $options 0<&8 1>&9\n  ok 181 - V: checkpoint updates refs and marks after commit\n  ok 182 - V: checkpoint updates refs and marks after commit (no new objects)\n  ./test-lib.sh: line 634: line 3250: 28485 Terminated              git fast-import $options 0<&8 1>&9\n  ok 183 - V: checkpoint updates tags after tag\n  ./t9300-fast-import.sh: line 3264: 28510 Terminated              git fast-import $options 0<&8 1>&9\n\nAfter a background child process terminates, its parent Bash process\nalways outputs a message like those above to stderr, even when in\nnon-interactive mode.\n\nBut how do some of these messages end up on the test script's stderr,\nwhy don't we get them from all five tests, and why do they come from\ndifferent file/line locations?  Well, after sending the TERM signal to\nthe background child process, it takes a little while until that\nprocess receives the signal and terminates, and then it takes another\nwhile until the parent process notices it.  During this time the\nparent Bash process is continuing execution, and by the time it\nnotices that its child terminated it might have already left\n'test_eval_inner_' and its stderr is not redirected to /dev/null\nanymore.  That's why such a message can appear on the test script's\nstderr, while other times, when the child terminates fast and/or the\nparent shell is slow enough, the message ends up in /dev/null, just\nlike any other output of the test does.  Bash always adds the file\nname and line number of the code location it was about to execute when\nit notices the termination of its child process as a prefix to that\nmessage, hence the varying and sometimes totally unrelated location\nprefixes in those messages (e.g. line 388 in 'test-lib-functions.sh'\nis 'test_verify_prereq', and I saw such a message pointing to\n'say_color' as well).\n\nPrevent these messages from appearing on the test script's stderr by\n'wait'-ing on the pid of the background 'git fast-import' process\nafter sending it the TERM signal.  This ensures that the executing\nshell's stderr is still redirected when the shell notices the\ntermination of its child process in the background, and that these\nmessages get a consistent file/line location prefix.\n\nNote that this is not an issue when the test script is run with Bash\nand '-v', because then these messages are supposed to go to the test\nscript's stderr anyway, and indeed all of them do; though the\nsometimes seemingly random file/line prefixes could be confusing\nstill.  Similarly, it's not an issue with Bash and '--verbose-log'\neither, because then all messages go to the log file as they should.\nFinally, it's not an issue with some other shells (I tried dash, ksh,\nksh93 and mksh) even without any of the verbose options, because they\ndon't print messages like these in non-interactive mode in the first\nplace.\n\nSigned-off-by: SZEDER Gábor <szeder.dev@gmail.com>\n---\n t/t9300-fast-import.sh | 5 ++++-\n 1 file changed, 4 insertions(+), 1 deletion(-)\n\ndiff --git a/t/t9300-fast-import.sh b/t/t9300-fast-import.sh\nindex 9e7f96223d..fac33e524c 100755\n--- a/t/t9300-fast-import.sh\n+++ b/t/t9300-fast-import.sh\n@@ -3147,7 +3147,10 @@ background_import_then_checkpoint () {\n \techo $! >V.pid\n \t# We don't mind if fast-import has already died by the time the test\n \t# ends.\n-\ttest_when_finished \"exec 8>&-; exec 9>&-; kill $(cat V.pid) || true\"\n+\ttest_when_finished \"\n+\t\texec 8>&-; exec 9>&-;\n+\t\tkill $(cat V.pid) && wait $(cat V.pid)\n+\t\ttrue\"\n \n \t# Start in the background to ensure we adhere strictly to (blocking)\n \t# pipes writing sequence. We want to assume that the write below could\n-- \n2.18.0.408.g42635c01bc\n\n"},{"id":"353109","messageId":"CAH_=xoYyRhwQJhr_8hf_4dWs9DikZh8vSkQSDXbqOPjZVw5qfg@mail.gmail.com","threadId":"48924","inReplyTo":"20180719222641.12152-1-szeder.dev@gmail.com","subject":"Re: [PATCH] t9300: wait for background fast-import process to die after killing it","fromName":"Eric Rannaud","fromEmail":"e@nanocritical.com","sentAt":"2018-07-20T05:20:32Z","receivedAt":"2018-07-20T05:20:55Z","isPatch":true,"sender":{"key":"e@nanocritical.com","avatar":"https://avatars.githubusercontent.com/u/925816?v=4"},"body":"On Thu, Jul 19, 2018 at 3:26 PM, SZEDER Gábor <szeder.dev@gmail.com> wrote:\n> But how do some of these messages end up on the test script's stderr,\n> why don't we get them from all five tests, and why do they come from\n> different file/line locations?\n\nThanks for the detailed explanation.\n\nSigned-off-by: Eric Rannaud <e@nanocritical.com>\n"},{"id":"353171","messageId":"CABPp-BGko5_N7uX=AgTqjTyF2rSusR81FnSQpSNhXxi64uvY3A@mail.gmail.com","threadId":"48924","inReplyTo":"20180719222641.12152-1-szeder.dev@gmail.com","subject":"Re: [PATCH] t9300: wait for background fast-import process to die after killing it","fromName":"Elijah Newren","fromEmail":"newren@gmail.com","sentAt":"2018-07-20T19:03:44Z","receivedAt":"2018-07-20T19:03:47Z","isPatch":true,"sender":{"key":"newren@gmail.com","avatar":"https://avatars.githubusercontent.com/u/5455730?v=4"},"body":"On Thu, Jul 19, 2018 at 3:26 PM, SZEDER Gábor <szeder.dev@gmail.com> wrote:\n> The five new tests added to 't9300-fast-import.sh' in 30e215a65c\n> (fast-import: checkpoint: dump branches/tags/marks even if\n> object_count==0, 2017-09-28), all with the prefix \"V:\" in their test\n> description, run 'git fast-import' in the background and then 'kill'\n> it as part of a 'test_when_finished' cleanup command.  When this test\n> script is executed with Bash, some or even all of these tests tend to\n> pollute the test script's stderr, and messages about terminated\n> processes end up on the terminal:\n>\n>   $ bash ./t9300-fast-import.sh\n>   <... snip ...>\n>   ok 179 - V: checkpoint helper does not get stuck with extra output\n>   /<...>/test-lib-functions.sh: line 388: 28383 Terminated              git fast-import $options 0<&8 1>&9\n>   ok 180 - V: checkpoint updates refs after reset\n>   ./t9300-fast-import.sh: line 3210: 28401 Terminated              git fast-import $options 0<&8 1>&9\n>   ok 181 - V: checkpoint updates refs and marks after commit\n>   ok 182 - V: checkpoint updates refs and marks after commit (no new objects)\n>   ./test-lib.sh: line 634: line 3250: 28485 Terminated              git fast-import $options 0<&8 1>&9\n>   ok 183 - V: checkpoint updates tags after tag\n>   ./t9300-fast-import.sh: line 3264: 28510 Terminated              git fast-import $options 0<&8 1>&9\n>\n> After a background child process terminates, its parent Bash process\n> always outputs a message like those above to stderr, even when in\n> non-interactive mode.\n>\n> But how do some of these messages end up on the test script's stderr,\n> why don't we get them from all five tests, and why do they come from\n> different file/line locations?  Well, after sending the TERM signal to\n> the background child process, it takes a little while until that\n> process receives the signal and terminates, and then it takes another\n> while until the parent process notices it.  During this time the\n> parent Bash process is continuing execution, and by the time it\n> notices that its child terminated it might have already left\n> 'test_eval_inner_' and its stderr is not redirected to /dev/null\n> anymore.  That's why such a message can appear on the test script's\n> stderr, while other times, when the child terminates fast and/or the\n> parent shell is slow enough, the message ends up in /dev/null, just\n> like any other output of the test does.  Bash always adds the file\n> name and line number of the code location it was about to execute when\n> it notices the termination of its child process as a prefix to that\n> message, hence the varying and sometimes totally unrelated location\n> prefixes in those messages (e.g. line 388 in 'test-lib-functions.sh'\n> is 'test_verify_prereq', and I saw such a message pointing to\n> 'say_color' as well).\n>\n> Prevent these messages from appearing on the test script's stderr by\n> 'wait'-ing on the pid of the background 'git fast-import' process\n> after sending it the TERM signal.  This ensures that the executing\n> shell's stderr is still redirected when the shell notices the\n> termination of its child process in the background, and that these\n> messages get a consistent file/line location prefix.\n>\n> Note that this is not an issue when the test script is run with Bash\n> and '-v', because then these messages are supposed to go to the test\n> script's stderr anyway, and indeed all of them do; though the\n> sometimes seemingly random file/line prefixes could be confusing\n> still.  Similarly, it's not an issue with Bash and '--verbose-log'\n> either, because then all messages go to the log file as they should.\n> Finally, it's not an issue with some other shells (I tried dash, ksh,\n> ksh93 and mksh) even without any of the verbose options, because they\n> don't print messages like these in non-interactive mode in the first\n> place.\n>\n> Signed-off-by: SZEDER Gábor <szeder.dev@gmail.com>\n> ---\n>  t/t9300-fast-import.sh | 5 ++++-\n>  1 file changed, 4 insertions(+), 1 deletion(-)\n>\n> diff --git a/t/t9300-fast-import.sh b/t/t9300-fast-import.sh\n> index 9e7f96223d..fac33e524c 100755\n> --- a/t/t9300-fast-import.sh\n> +++ b/t/t9300-fast-import.sh\n> @@ -3147,7 +3147,10 @@ background_import_then_checkpoint () {\n>         echo $! >V.pid\n>         # We don't mind if fast-import has already died by the time the test\n>         # ends.\n> -       test_when_finished \"exec 8>&-; exec 9>&-; kill $(cat V.pid) || true\"\n> +       test_when_finished \"\n> +               exec 8>&-; exec 9>&-;\n> +               kill $(cat V.pid) && wait $(cat V.pid)\n> +               true\"\n>\n>         # Start in the background to ensure we adhere strictly to (blocking)\n>         # pipes writing sequence. We want to assume that the write below could\n> --\n> 2.18.0.408.g42635c01bc\n\nSweet, thanks for fixing this.  I got these messages nearly 100% of\nthe time on a certain machine when running prove with a high enough\nparallel flag.  I was getting a little annoyed by them, but hadn't dug\nin yet.  Your patch squelches them up in my testing.\n"}]}