{"thread":{"id":"48217","subject":"Timing issue in t5570 \"daemon log records all attributes\"","startedAt":"2018-04-03T19:33:18Z","lastAt":"2018-04-05T16:40:00Z","messageCount":4,"participants":["Jan Palus","Jeff King"],"isPatch":false,"patchVersion":null,"patchTotal":null},"messages":[{"id":"343759","messageId":"1522783990.964448.1325338528.0D49CC15@webmail.messagingengine.com","threadId":"48217","inReplyTo":null,"subject":"Timing issue in t5570 \"daemon log records all attributes\"","fromName":"Jan Palus","fromEmail":"jpalus@fastmail.com","sentAt":"2018-04-03T19:33:10Z","receivedAt":"2018-04-03T19:33:18Z","isPatch":false,"sender":{"key":"jpalus@fastmail.com","avatar":"https://avatars.githubusercontent.com/u/484155?v=4"},"body":"My understanding of test \"daemon log records all attributes\" is that daemon\nprocess is started in background, some git command is executed and daemon's\noutput (saved to daemon.log) is compared against expected value. However\ndaemon.log is not a straight redirect to file -- it is being piped through fifo,\nread by a loop in test-git-daemon.sh, additional processing is performed and\nfinally it makes it to daemon.log. All of this performed concurrently with test\nexecution. My question is how do you exactly avoid timing issues here? grep on\ndaemon.log is performed immediately after git invocation:\n\n        >daemon.log &&\n        GIT_OVERRIDE_VIRTUAL_HOST=localhost \\\n                git -c protocol.version=1 \\\n                        ls-remote \"$GIT_DAEMON_URL/interp.git\" &&\n        grep -i extended.attribute daemon.log | cut -d\" \" -f2- >actual &&\n\nhow can you be sure grep operates on daemon.log that already includes all output\nand not on intermediate state that is just being processed by while loop? Same\nquestion applies to \">daemon.log\" since shell might still be processing output\nof previous test and its content might possibly land in the file after zeroing.\n\nThe reason I'm asking is because /bin/sh in my distribution (mksh) actually\nmanifests the issue -- test fails because at the time of grep output was not\nprocessed yet (fixed by sleep 1 before grep). Also there is an issue with output\nof previous test landing in daemon.log despite \">daemon.log\".\n\n\nRegards\nJan\n"},{"id":"343765","messageId":"20180403203233.GB15157@sigill.intra.peff.net","threadId":"48217","inReplyTo":"1522783990.964448.1325338528.0D49CC15@webmail.messagingengine.com","subject":"Re: Timing issue in t5570 \"daemon log records all attributes\"","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2018-04-03T20:32:33Z","receivedAt":"2018-04-03T20:32:47Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Tue, Apr 03, 2018 at 09:33:10PM +0200, Jan Palus wrote:\n\n> My understanding of test \"daemon log records all attributes\" is that daemon\n> process is started in background, some git command is executed and daemon's\n> output (saved to daemon.log) is compared against expected value. However\n> daemon.log is not a straight redirect to file -- it is being piped through fifo,\n> read by a loop in test-git-daemon.sh, additional processing is performed and\n> finally it makes it to daemon.log. All of this performed concurrently with test\n> execution. My question is how do you exactly avoid timing issues here? grep on\n> daemon.log is performed immediately after git invocation:\n> \n>         >daemon.log &&\n>         GIT_OVERRIDE_VIRTUAL_HOST=localhost \\\n>                 git -c protocol.version=1 \\\n>                         ls-remote \"$GIT_DAEMON_URL/interp.git\" &&\n>         grep -i extended.attribute daemon.log | cut -d\" \" -f2- >actual &&\n> \n> how can you be sure grep operates on daemon.log that already includes all output\n> and not on intermediate state that is just being processed by while loop? Same\n> question applies to \">daemon.log\" since shell might still be processing output\n> of previous test and its content might possibly land in the file after zeroing.\n\nYou're right, this is racy. You can see it much more obviously with:\n\ndiff --git a/t/lib-git-daemon.sh b/t/lib-git-daemon.sh\nindex edbea2d986..3c7fea169b 100644\n--- a/t/lib-git-daemon.sh\n+++ b/t/lib-git-daemon.sh\n@@ -62,6 +62,7 @@ start_git_daemon() {\n \t\t(\n \t\t\twhile read -r line <&7\n \t\t\tdo\n+\t\t\t\tsleep 1\n \t\t\t\tprintf \"%s\\n\" \"$line\"\n \t\t\t\tprintf >&4 \"%s\\n\" \"$line\"\n \t\t\tdone\n\nI'm not sure of the best solution. Even if we removed the shell-loop\npumping the data from the fifo, it's still possible to race if\ngit-daemon hangs up the client socket before flushing its log output\n(since our only real synchronization is waiting for the client to exit).\n\nNor could we even wait for an EOF on the fifo, since we won't get one\nuntil the daemon actually exits.\n\nIf we want to do it without polling, I think the best we could do is\nhave the pumping loop key on some particular line in the output as a\nsynchronization point, and then trigger _another_ fifo that the test\nsnippet listens on. Yuck.\n\nI'm tempted to say we should just scrap this test. It was added\nrelatively recently and only shows the fix for a pretty minor bug.\nIt's probably not worth the contortions to make it race-proof.\n\n-Peff\n"},{"id":"343822","messageId":"20180404215752.6qsipaaskrzwiv4q@kalarepa","threadId":"48217","inReplyTo":"20180403203233.GB15157@sigill.intra.peff.net","subject":"Re: Timing issue in t5570 \"daemon log records all attributes\"","fromName":"Jan Palus","fromEmail":"jpalus@fastmail.com","sentAt":"2018-04-04T21:57:52Z","receivedAt":"2018-04-04T21:58:01Z","isPatch":false,"sender":{"key":"jpalus@fastmail.com","avatar":"https://avatars.githubusercontent.com/u/484155?v=4"},"body":"On 03.04.2018 16:32, Jeff King wrote:\n> I'm tempted to say we should just scrap this test. It was added\n> relatively recently and only shows the fix for a pretty minor bug.\n> It's probably not worth the contortions to make it race-proof.\n\nThanks for your reply Jeff.\n\nIt appears race condition in reading/writing daemon.log is not the only issue of\nt5570. On a different machine I've just randomly got:\n\nt5570-git-daemon.sh[163]: can't create git_daemon_output: Interrupted system call\n\nwhich I believe might also be associated with concurrent processing of piped\ndata connected with a fact that test restarts daemon few times. I can barely\nwrap my head around it but I guess it's somewhat around \"shell still tries to\nread fifo while attempt to create new one is made\".\n\n\nRegards\nJan\n"},{"id":"343869","messageId":"20180405163953.GB25224@sigill.intra.peff.net","threadId":"48217","inReplyTo":"20180404215752.6qsipaaskrzwiv4q@kalarepa","subject":"Re: Timing issue in t5570 \"daemon log records all attributes\"","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2018-04-05T16:39:53Z","receivedAt":"2018-04-05T16:40:00Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Wed, Apr 04, 2018 at 11:57:52PM +0200, Jan Palus wrote:\n\n> On 03.04.2018 16:32, Jeff King wrote:\n> > I'm tempted to say we should just scrap this test. It was added\n> > relatively recently and only shows the fix for a pretty minor bug.\n> > It's probably not worth the contortions to make it race-proof.\n> \n> Thanks for your reply Jeff.\n> \n> It appears race condition in reading/writing daemon.log is not the only issue of\n> t5570. On a different machine I've just randomly got:\n> \n> t5570-git-daemon.sh[163]: can't create git_daemon_output: Interrupted system call\n> \n> which I believe might also be associated with concurrent processing of piped\n> data connected with a fact that test restarts daemon few times. I can barely\n> wrap my head around it but I guess it's somewhat around \"shell still tries to\n> read fifo while attempt to create new one is made\".\n\nThat sounds more like your system doesn't handle EINTR gracefully\n(presumably it's getting SIGCLD during the mknod() call). Normally that\nwould be done by an external program, but is mkfifo perhaps a builtin in\nyour shell?\n\nIf I run t5570 on a loop on a loaded system[1], I can't seem to provoke\nany failures, using dash.\n\n-Peff\n\n[1] The script I use is:\n\n      https://github.com/peff/git/blob/meta/stress\n\n    which runs the test script over and over in parallel. That's usually\n    enough to exhibit practical races, since it creates enough load to\n    show timing effects.\n"}]}