{"thread":{"id":"60109","subject":"[PATCH] t4053: avoid writing to unopened pipe","startedAt":"2023-08-13T16:32:39Z","lastAt":"2023-08-14T15:24:47Z","messageCount":2,"participants":["Jeff King","Phillip Wood"],"isPatch":true,"patchVersion":1,"patchTotal":null},"messages":[{"id":"480635","messageId":"20230813162440.GA1688763@coredump.intra.peff.net","threadId":"60109","inReplyTo":null,"subject":"[PATCH] t4053: avoid writing to unopened pipe","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2023-08-13T16:24:40Z","receivedAt":"2023-08-13T16:32:39Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"This fixes an occasional hang I see when running t4053 with\n--verbose-log using dash.\n\nCommit 1e3f26542a (diff --no-index: support reading from named pipes,\n2023-07-05) added a test that \"diff --no-index\" will complain when\ncomparing a named pipe and a directory. The minimum we need to test this\nis to mkfifo the pipe, and then run \"git diff --no-index pipe some_dir\".\nBut the test does one thing more: it spawns a background shell process\nthat opens the pipe for writing, like this:\n\n        {\n                (>pipe) &\n        } &&\n\nThis extra writer _could_ be useful if Git misbehaves and tries to open\nthe pipe for reading. Without the writer, Git would block indefinitely\nand the test would never end. But since we do not have such a bug, Git\ndoes not open the pipe and it is the writing process which will block\nindefinitely, since there are no readers. The test addresses this by\nrunning \"kill $!\" in a test_when_finished block. Since the writer should\nbe blocking forever, this kill command will reliably find it waiting.\n\nHowever, this seems to be somewhat racy, in that the writing process\nsometimes hangs around even after the \"kill\". In a normal run of the\ntest script without options, this doesn't have any effect; the\nmain test script completes anyway. But with --verbose-log, we spawn a\n\"tee\" process that reads the script output, and it won't end until all\ndescriptors pointing to its input pipe are closed. And the background\nprocess that is hanging around still has its stderr, etc, pointed into\nthat pipe.\n\nYou can reproduce the situation like this:\n\n  cd t\n  ./t4053-diff-no-index.sh --verbose-log --stress\n\nLet that run for a few minutes, and then you'll find that some of the\nruns have hung. For example, at 11:53, I ran:\n\n  $ ps xk start o pid,start,command | grep tee | head\n   713459 11:48:06 tee -a /home/peff/compile/git/t/test-results/t4053-diff-no-index.stress-9.out\n   713527 11:48:06 tee -a /home/peff/compile/git/t/test-results/t4053-diff-no-index.stress-15.out\n   719434 11:48:07 tee -a /home/peff/compile/git/t/test-results/t4053-diff-no-index.stress-1.out\n   728117 11:48:08 tee -a /home/peff/compile/git/t/test-results/t4053-diff-no-index.stress-5.out\n   738738 11:48:09 tee -a /home/peff/compile/git/t/test-results/t4053-diff-no-index.stress-31.out\n   739457 11:48:09 tee -a /home/peff/compile/git/t/test-results/t4053-diff-no-index.stress-27.out\n   744432 11:48:10 tee -a /home/peff/compile/git/t/test-results/t4053-diff-no-index.stress-21.out\n   744471 11:48:10 tee -a /home/peff/compile/git/t/test-results/t4053-diff-no-index.stress-29.out\n   761961 11:48:12 tee -a /home/peff/compile/git/t/test-results/t4053-diff-no-index.stress-0.out\n   812299 11:48:19 tee -a /home/peff/compile/git/t/test-results/t4053-diff-no-index.stress-8.out\n\nAll of these have been hung for several minutes. We can investigate one\nand see that it's waiting to get EOF on its input:\n\n  $ strace -p 713459\n  strace: Process 713459 attached\n  read(0,\n  ^C\n\nWho else has that descriptor open?\n\n  $ lsof -a -p 713459 -d 0 +E\n  COMMAND    PID USER   FD   TYPE DEVICE SIZE/OFF    NODE NAME\n  tee     713459 peff    0r  FIFO   0,13      0t0 3943636 pipe 719203,sh,5w 719203,sh,7w 719203,sh,12w 719203,sh,13w\n  sh      719203 peff    5w  FIFO   0,13      0t0 3943636 pipe 713459,tee,0r 719203,sh,7w 719203,sh,12w 719203,sh,13w\n  sh      719203 peff    7w  FIFO   0,13      0t0 3943636 pipe 713459,tee,0r 719203,sh,5w 719203,sh,12w 719203,sh,13w\n  sh      719203 peff   12w  FIFO   0,13      0t0 3943636 pipe 713459,tee,0r 719203,sh,5w 719203,sh,7w 719203,sh,13w\n  sh      719203 peff   13w  FIFO   0,13      0t0 3943636 pipe 713459,tee,0r 719203,sh,5w 719203,sh,7w 719203,sh,12w\n\nIt's a shell, presumably a subshell spawned by the main script. Though\nit may seem odd, having the same descriptor open several times is not\nunreasonable (they're all basically the original stdout/stderr of the\nscript that has been copied). And they should all close when the process\nexits. So what's it doing? Curiously, it will exit as soon as we strace\nit:\n\n  $ strace -s 64 -p 719203\n  strace: Process 719203 attached\n  openat(AT_FDCWD, \"pipe\", O_WRONLY|O_CREAT|O_TRUNC, 0666) = -1 ENOENT (No such file or directory)\n  write(2, \"./t4053-diff-no-index.sh: 7: eval: \", 35) = 35\n  write(2, \"cannot create pipe: Directory nonexistent\", 41) = 41\n  write(2, \"\\n\", 1)                       = 1\n  exit_group(2)                           = ?\n  +++ exited with 2 +++\n\nI think what happens is this:\n\n  - it is blocking in the openat() call for the pipe, as we expect (so\n    this is definitely the backgrounded subshell mentioned above)\n\n  - strace sends signals (probably STOP/CONT); those cause the kernel to\n    stop blocking, but libc will restart the system call automatically\n\n  - by this time, the \"pipe\" fifo is gone, so we'll actually try to\n    create a regular file. But of course the surrounding directory is\n    gone, too! So we get ENOENT, and then exit as normal.\n\nSo the blocking is something we expect to happen. But what we didn't\nexpect is for the process to still exist at all! It should have been\nkilled earlier when the parent process called \"kill\", but it wasn't. And\nwe can't catch the race at this point, because it happened much earlier.\n\nOne can guess, though, that there is some race with the shell setting up\nthe signal handling in the backgrounded subshell, and possibly blocking\nor ignoring signals at the time that the \"kill\" is received.  Curiously,\nthe race does not seem to happen if I use \"bash\" instead of \"dash\", so\npresumably bash's setup here is more atomic.\n\nOne fix might be to try killing the subshell more aggressively, either\nusing SIGKILL, or looping on kill/wait. But that seems complex and\nlikely to introduce new problems/races. Instead, we can observe that the\nwriter is not needed at all. Git will notice the pipe via stat() before\nit is ever opened. So we can simply drop the writer subshell entirely.\n\nIf we ever changed Git to open the path and fstat() it, this would\nresult in the test hanging. But we're not likely to do that. After all,\nwe have to stat() paths to see if they are openable at all (e.g., it\ncould be a directory), so this seems like a low risk. And anybody who\ndoes make such a change will immediately see the issue, as Git would\nhang consistently.\n\nSigned-off-by: Jeff King <peff@peff.net>\n---\n t/t4053-diff-no-index.sh | 4 ----\n 1 file changed, 4 deletions(-)\n\ndiff --git a/t/t4053-diff-no-index.sh b/t/t4053-diff-no-index.sh\nindex 1fb7d33462..6781cc9078 100755\n--- a/t/t4053-diff-no-index.sh\n+++ b/t/t4053-diff-no-index.sh\n@@ -232,10 +232,6 @@ test_expect_success 'diff --no-index refuses to diff stdin and a directory' '\n test_expect_success PIPE 'diff --no-index refuses to diff a named pipe and a directory' '\n \ttest_when_finished \"rm -f pipe\" &&\n \tmkfifo pipe &&\n-\t{\n-\t\t(>pipe) &\n-\t} &&\n-\ttest_when_finished \"kill $!\" &&\n \ttest_must_fail git diff --no-index -- pipe a 2>err &&\n \tgrep \"fatal: cannot compare a named pipe to a directory\" err\n '\n-- \n2.42.0.rc1.378.g7c0c59538f\n"},{"id":"480652","messageId":"bc373bcc-2ff0-4902-aa7f-f34c23951173@gmail.com","threadId":"60109","inReplyTo":"20230813162440.GA1688763@coredump.intra.peff.net","subject":"Re: [PATCH] t4053: avoid writing to unopened pipe","fromName":"Phillip Wood","fromEmail":"phillip.wood123@gmail.com","sentAt":"2023-08-14T15:23:35Z","receivedAt":"2023-08-14T15:24:47Z","isPatch":true,"sender":{"key":"phillip.wood@dunelm.org.uk","avatar":null},"body":"Hi Peff\n\nOn 13/08/2023 17:24, Jeff King wrote:\n> This fixes an occasional hang I see when running t4053 with\n> --verbose-log using dash.\n\nWell done for tracking this down, it is interesting that it only affects \ndash. I think your proposed fix is the simplest solution, thanks for the \ncomprehensive commit message.\n\nBest Wishes\n\nPhillip\n\n> Commit 1e3f26542a (diff --no-index: support reading from named pipes,\n> 2023-07-05) added a test that \"diff --no-index\" will complain when\n> comparing a named pipe and a directory. The minimum we need to test this\n> is to mkfifo the pipe, and then run \"git diff --no-index pipe some_dir\".\n> But the test does one thing more: it spawns a background shell process\n> that opens the pipe for writing, like this:\n> \n>          {\n>                  (>pipe) &\n>          } &&\n> \n> This extra writer _could_ be useful if Git misbehaves and tries to open\n> the pipe for reading. Without the writer, Git would block indefinitely\n> and the test would never end. But since we do not have such a bug, Git\n> does not open the pipe and it is the writing process which will block\n> indefinitely, since there are no readers. The test addresses this by\n> running \"kill $!\" in a test_when_finished block. Since the writer should\n> be blocking forever, this kill command will reliably find it waiting.\n> \n> However, this seems to be somewhat racy, in that the writing process\n> sometimes hangs around even after the \"kill\". In a normal run of the\n> test script without options, this doesn't have any effect; the\n> main test script completes anyway. But with --verbose-log, we spawn a\n> \"tee\" process that reads the script output, and it won't end until all\n> descriptors pointing to its input pipe are closed. And the background\n> process that is hanging around still has its stderr, etc, pointed into\n> that pipe.\n> \n> You can reproduce the situation like this:\n> \n>    cd t\n>    ./t4053-diff-no-index.sh --verbose-log --stress\n> \n> Let that run for a few minutes, and then you'll find that some of the\n> runs have hung. For example, at 11:53, I ran:\n> \n>    $ ps xk start o pid,start,command | grep tee | head\n>     713459 11:48:06 tee -a /home/peff/compile/git/t/test-results/t4053-diff-no-index.stress-9.out\n>     713527 11:48:06 tee -a /home/peff/compile/git/t/test-results/t4053-diff-no-index.stress-15.out\n>     719434 11:48:07 tee -a /home/peff/compile/git/t/test-results/t4053-diff-no-index.stress-1.out\n>     728117 11:48:08 tee -a /home/peff/compile/git/t/test-results/t4053-diff-no-index.stress-5.out\n>     738738 11:48:09 tee -a /home/peff/compile/git/t/test-results/t4053-diff-no-index.stress-31.out\n>     739457 11:48:09 tee -a /home/peff/compile/git/t/test-results/t4053-diff-no-index.stress-27.out\n>     744432 11:48:10 tee -a /home/peff/compile/git/t/test-results/t4053-diff-no-index.stress-21.out\n>     744471 11:48:10 tee -a /home/peff/compile/git/t/test-results/t4053-diff-no-index.stress-29.out\n>     761961 11:48:12 tee -a /home/peff/compile/git/t/test-results/t4053-diff-no-index.stress-0.out\n>     812299 11:48:19 tee -a /home/peff/compile/git/t/test-results/t4053-diff-no-index.stress-8.out\n> \n> All of these have been hung for several minutes. We can investigate one\n> and see that it's waiting to get EOF on its input:\n> \n>    $ strace -p 713459\n>    strace: Process 713459 attached\n>    read(0,\n>    ^C\n> \n> Who else has that descriptor open?\n> \n>    $ lsof -a -p 713459 -d 0 +E\n>    COMMAND    PID USER   FD   TYPE DEVICE SIZE/OFF    NODE NAME\n>    tee     713459 peff    0r  FIFO   0,13      0t0 3943636 pipe 719203,sh,5w 719203,sh,7w 719203,sh,12w 719203,sh,13w\n>    sh      719203 peff    5w  FIFO   0,13      0t0 3943636 pipe 713459,tee,0r 719203,sh,7w 719203,sh,12w 719203,sh,13w\n>    sh      719203 peff    7w  FIFO   0,13      0t0 3943636 pipe 713459,tee,0r 719203,sh,5w 719203,sh,12w 719203,sh,13w\n>    sh      719203 peff   12w  FIFO   0,13      0t0 3943636 pipe 713459,tee,0r 719203,sh,5w 719203,sh,7w 719203,sh,13w\n>    sh      719203 peff   13w  FIFO   0,13      0t0 3943636 pipe 713459,tee,0r 719203,sh,5w 719203,sh,7w 719203,sh,12w\n> \n> It's a shell, presumably a subshell spawned by the main script. Though\n> it may seem odd, having the same descriptor open several times is not\n> unreasonable (they're all basically the original stdout/stderr of the\n> script that has been copied). And they should all close when the process\n> exits. So what's it doing? Curiously, it will exit as soon as we strace\n> it:\n> \n>    $ strace -s 64 -p 719203\n>    strace: Process 719203 attached\n>    openat(AT_FDCWD, \"pipe\", O_WRONLY|O_CREAT|O_TRUNC, 0666) = -1 ENOENT (No such file or directory)\n>    write(2, \"./t4053-diff-no-index.sh: 7: eval: \", 35) = 35\n>    write(2, \"cannot create pipe: Directory nonexistent\", 41) = 41\n>    write(2, \"\\n\", 1)                       = 1\n>    exit_group(2)                           = ?\n>    +++ exited with 2 +++\n> \n> I think what happens is this:\n> \n>    - it is blocking in the openat() call for the pipe, as we expect (so\n>      this is definitely the backgrounded subshell mentioned above)\n> \n>    - strace sends signals (probably STOP/CONT); those cause the kernel to\n>      stop blocking, but libc will restart the system call automatically\n> \n>    - by this time, the \"pipe\" fifo is gone, so we'll actually try to\n>      create a regular file. But of course the surrounding directory is\n>      gone, too! So we get ENOENT, and then exit as normal.\n> \n> So the blocking is something we expect to happen. But what we didn't\n> expect is for the process to still exist at all! It should have been\n> killed earlier when the parent process called \"kill\", but it wasn't. And\n> we can't catch the race at this point, because it happened much earlier.\n> \n> One can guess, though, that there is some race with the shell setting up\n> the signal handling in the backgrounded subshell, and possibly blocking\n> or ignoring signals at the time that the \"kill\" is received.  Curiously,\n> the race does not seem to happen if I use \"bash\" instead of \"dash\", so\n> presumably bash's setup here is more atomic.\n> \n> One fix might be to try killing the subshell more aggressively, either\n> using SIGKILL, or looping on kill/wait. But that seems complex and\n> likely to introduce new problems/races. Instead, we can observe that the\n> writer is not needed at all. Git will notice the pipe via stat() before\n> it is ever opened. So we can simply drop the writer subshell entirely.\n> \n> If we ever changed Git to open the path and fstat() it, this would\n> result in the test hanging. But we're not likely to do that. After all,\n> we have to stat() paths to see if they are openable at all (e.g., it\n> could be a directory), so this seems like a low risk. And anybody who\n> does make such a change will immediately see the issue, as Git would\n> hang consistently.\n> \n> Signed-off-by: Jeff King <peff@peff.net>\n> ---\n>   t/t4053-diff-no-index.sh | 4 ----\n>   1 file changed, 4 deletions(-)\n> \n> diff --git a/t/t4053-diff-no-index.sh b/t/t4053-diff-no-index.sh\n> index 1fb7d33462..6781cc9078 100755\n> --- a/t/t4053-diff-no-index.sh\n> +++ b/t/t4053-diff-no-index.sh\n> @@ -232,10 +232,6 @@ test_expect_success 'diff --no-index refuses to diff stdin and a directory' '\n>   test_expect_success PIPE 'diff --no-index refuses to diff a named pipe and a directory' '\n>   \ttest_when_finished \"rm -f pipe\" &&\n>   \tmkfifo pipe &&\n> -\t{\n> -\t\t(>pipe) &\n> -\t} &&\n> -\ttest_when_finished \"kill $!\" &&\n>   \ttest_must_fail git diff --no-index -- pipe a 2>err &&\n>   \tgrep \"fatal: cannot compare a named pipe to a directory\" err\n>   '\n"}]}