{"thread":{"id":"49892","subject":"t5570 shaky for anyone ?","startedAt":"2018-11-25T20:52:33Z","lastAt":"2019-01-07T15:45:59Z","messageCount":12,"participants":["Torsten Bögershausen","Thomas Gummerer","SZEDER Gábor","Jeff King","Johannes Schindelin","Junio C Hamano"],"isPatch":false,"patchVersion":null,"patchTotal":null},"messages":[{"id":"364037","messageId":"9d4e5224-9ff4-f3f8-519d-7b2a6f1ea7cd@web.de","threadId":"49892","inReplyTo":null,"subject":"t5570 shaky for anyone ?","fromName":"Torsten Bögershausen","fromEmail":"tboegi@web.de","sentAt":"2018-11-25T20:52:23Z","receivedAt":"2018-11-25T20:52:33Z","isPatch":false,"sender":{"key":"tboegi@web.de","avatar":"https://avatars.githubusercontent.com/u/7138363?v=4"},"body":"After running the  \"Git 2.20-rc1\" testsuite here on a raspi,\nthe only TC that failed was t5570.\nWhen the \"grep\" was run on daemon.log, the file was empty (?).\nWhen inspecting it later, it was filled, and grep would have found\nthe \"extended.attribute\" it was looking for.\n\nThe following fixes it, but I am not sure if this is the ideal\nsolution.\n\n\ndiff --git a/t/t5570-git-daemon.sh b/t/t5570-git-daemon.sh\nindex 7466aad111..e259fee0ed 100755\n--- a/t/t5570-git-daemon.sh\n+++ b/t/t5570-git-daemon.sh\n@@ -192,6 +192,7 @@ test_expect_success 'daemon log records all attributes' '\n \tGIT_OVERRIDE_VIRTUAL_HOST=localhost \\\n \t\tgit -c protocol.version=1 \\\n \t\t\tls-remote \"$GIT_DAEMON_URL/interp.git\" &&\n+\tsleep 1 &&\n \tgrep -i extended.attribute daemon.log | cut -d\" \" -f2- >actual &&\n \ttest_cmp expect actual\n '\n----------------\nA slightly better approach may be to use a \"sleep on demand\":\n\n+\t( grep -i -q extended.attribute daemon.log || sleep 1 ) &&\n\n"},{"id":"364041","messageId":"20181125220138.GK4883@hank.intra.tgummerer.com","threadId":"49892","inReplyTo":"9d4e5224-9ff4-f3f8-519d-7b2a6f1ea7cd@web.de","subject":"Re: t5570 shaky for anyone ?","fromName":"Thomas Gummerer","fromEmail":"t.gummerer@gmail.com","sentAt":"2018-11-25T22:01:38Z","receivedAt":"2018-11-25T22:01:42Z","isPatch":false,"sender":{"key":"t.gummerer@gmail.com","avatar":"https://avatars.githubusercontent.com/u/191004?v=4"},"body":"On 11/25, Torsten Bögershausen wrote:\n> After running the  \"Git 2.20-rc1\" testsuite here on a raspi,\n> the only TC that failed was t5570.\n> When the \"grep\" was run on daemon.log, the file was empty (?).\n> When inspecting it later, it was filled, and grep would have found\n> the \"extended.attribute\" it was looking for.\n\nI believe this has been reported before in\nhttps://public-inbox.org/git/1522783990.964448.1325338528.0D49CC15@webmail.messagingengine.com/,\nbut it seems like the thread never ended with actually fixing it.\nReading the first reply Peff seemed to be fine with just removing the\ntest completely, which would be the easiest solution ;)  Adding him to\nCc: here.  \n\n> The following fixes it, but I am not sure if this is the ideal\n> solution.\n> \n> \n> diff --git a/t/t5570-git-daemon.sh b/t/t5570-git-daemon.sh\n> index 7466aad111..e259fee0ed 100755\n> --- a/t/t5570-git-daemon.sh\n> +++ b/t/t5570-git-daemon.sh\n> @@ -192,6 +192,7 @@ test_expect_success 'daemon log records all attributes' '\n>  \tGIT_OVERRIDE_VIRTUAL_HOST=localhost \\\n>  \t\tgit -c protocol.version=1 \\\n>  \t\t\tls-remote \"$GIT_DAEMON_URL/interp.git\" &&\n> +\tsleep 1 &&\n>  \tgrep -i extended.attribute daemon.log | cut -d\" \" -f2- >actual &&\n>  \ttest_cmp expect actual\n>  '\n> ----------------\n> A slightly better approach may be to use a \"sleep on demand\":\n> \n> +\t( grep -i -q extended.attribute daemon.log || sleep 1 ) &&\n> \n"},{"id":"364043","messageId":"20181125222247.GD30222@szeder.dev","threadId":"49892","inReplyTo":"9d4e5224-9ff4-f3f8-519d-7b2a6f1ea7cd@web.de","subject":"Re: t5570 shaky for anyone ?","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2018-11-25T22:22:47Z","receivedAt":"2018-11-25T22:22:53Z","isPatch":false,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"On Sun, Nov 25, 2018 at 09:52:23PM +0100, Torsten Bögershausen wrote:\n> After running the  \"Git 2.20-rc1\" testsuite here on a raspi,\n> the only TC that failed was t5570.\n> When the \"grep\" was run on daemon.log, the file was empty (?).\n> When inspecting it later, it was filled, and grep would have found\n> the \"extended.attribute\" it was looking for.\n\nI think I saw the same failure on Travis CI already before 2.19, so\nit's not a new issue.  Here's the test's verbose output:\n\n  + cat\n  + \n  + GIT_OVERRIDE_VIRTUAL_HOST=localhost git -c protocol.version=1 ls-remote git://127.0.0.1:5570/interp.git\n  b6752e52dd867264d12240028003f21e3e1dccab        HEAD\n  b6752e52dd867264d12240028003f21e3e1dccab        refs/heads/master\n  + cut -d  -f2-\n  + grep -i extended.attribute daemon.log\n  + test_cmp expect actual\n  + diff -u expect actual\n  --- expect      2018-06-12 10:06:50.758357927 +0000\n  +++ actual      2018-06-12 10:06:50.774365936 +0000\n  @@ -1,2 +0,0 @@\n  -Extended attribute \"host\": localhost\n  -Extended attribute \"protocol\": version=1\n  [10579] Connection from 127.0.0.1:45836\n  [10579] Extended attribute \"host\": localhost\n  [10579] Extended attribute \"protocol\": version=1\n  error: last command exited with $?=1\n  [10579] Request upload-pack for '/interp.git'\n  [10579] Interpolated dir '/usr/src/git/t/trash\n  dir.t5570/repo/localhost/interp.git'\n  [10462] [10579] Disconnected\n  not ok 21 - daemon log records all attributes\n\nThe thing is that 'git daemon's log is not written to 'daemon.log'\ndirectly, but it goes through a fifo, which is read by a shell loop,\nwhich then sends all log messages both to 'daemon.log' and to the test\nscript's standard error.  So there is certainly a race between log\nmessages going through the fifo and the loop before reaching\n'daemon.log' and 'git ls-remote' exiting and 'grep' opening\n'daemon.log'.\n\n> The following fixes it, but I am not sure if this is the ideal\n> solution.\n\nCurrently this is the only test that looks at 'daemon.log', but if we\never going to add another one, then that will be prone to the same\nissue.\n\nI wonder whether it's really that useful to have the daemon log in the\ntest script's output...  if the log was sent directly to daemon log,\nthen the window for this race would be smaller, but still not\ncompletely closed.\n\nAnyway, I added Peff to Cc, since he added that whole fifo-shell-loop\nthing.\n\n> diff --git a/t/t5570-git-daemon.sh b/t/t5570-git-daemon.sh\n> index 7466aad111..e259fee0ed 100755\n> --- a/t/t5570-git-daemon.sh\n> +++ b/t/t5570-git-daemon.sh\n> @@ -192,6 +192,7 @@ test_expect_success 'daemon log records all attributes' '\n>  \tGIT_OVERRIDE_VIRTUAL_HOST=localhost \\\n>  \t\tgit -c protocol.version=1 \\\n>  \t\t\tls-remote \"$GIT_DAEMON_URL/interp.git\" &&\n> +\tsleep 1 &&\n>  \tgrep -i extended.attribute daemon.log | cut -d\" \" -f2- >actual &&\n>  \ttest_cmp expect actual\n>  '\n> ----------------\n> A slightly better approach may be to use a \"sleep on demand\":\n> \n> +\t( grep -i -q extended.attribute daemon.log || sleep 1 ) &&\n> \n"},{"id":"364084","messageId":"20181126164252.GA27711@sigill.intra.peff.net","threadId":"49892","inReplyTo":"20181125220138.GK4883@hank.intra.tgummerer.com","subject":"Re: t5570 shaky for anyone ?","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2018-11-26T16:42:52Z","receivedAt":"2018-11-26T16:42:56Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Sun, Nov 25, 2018 at 10:01:38PM +0000, Thomas Gummerer wrote:\n\n> On 11/25, Torsten Bögershausen wrote:\n> > After running the  \"Git 2.20-rc1\" testsuite here on a raspi,\n> > the only TC that failed was t5570.\n> > When the \"grep\" was run on daemon.log, the file was empty (?).\n> > When inspecting it later, it was filled, and grep would have found\n> > the \"extended.attribute\" it was looking for.\n> \n> I believe this has been reported before in\n> https://public-inbox.org/git/1522783990.964448.1325338528.0D49CC15@webmail.messagingengine.com/,\n> but it seems like the thread never ended with actually fixing it.\n> Reading the first reply Peff seemed to be fine with just removing the\n> test completely, which would be the easiest solution ;)  Adding him to\n> Cc: here.\n\nYes, I don't think there is a way to make this race-proof without\nsomehow convincing \"cat\" to flush (and let us know when it has). Which\nreally implies killing the daemon, and wait()ing on cat to process the\nEOF and exit.  And that makes the tests a lot more expensive if we have\nto start the daemon for each snippet.\n\nSo I'm still fine with just dropping this test.\n\n> > diff --git a/t/t5570-git-daemon.sh b/t/t5570-git-daemon.sh\n> > index 7466aad111..e259fee0ed 100755\n> > --- a/t/t5570-git-daemon.sh\n> > +++ b/t/t5570-git-daemon.sh\n> > @@ -192,6 +192,7 @@ test_expect_success 'daemon log records all attributes' '\n> >  \tGIT_OVERRIDE_VIRTUAL_HOST=localhost \\\n> >  \t\tgit -c protocol.version=1 \\\n> >  \t\t\tls-remote \"$GIT_DAEMON_URL/interp.git\" &&\n> > +\tsleep 1 &&\n> >  \tgrep -i extended.attribute daemon.log | cut -d\" \" -f2- >actual &&\n> >  \ttest_cmp expect actual\n> >  '\n> > ----------------\n> > A slightly better approach may be to use a \"sleep on demand\":\n> > \n> > +\t( grep -i -q extended.attribute daemon.log || sleep 1 ) &&\n\nThat doesn't really fix it, but just broadens the race window. I dunno.\nMaybe that is enough in practice. We could do something like:\n\n  repeat_with_timeout () {\n\tlocal i=0\n\twhile test $i -lt 10\n\tdo\n\t\t\"$@\" && return 0\n\t\tsleep 1\n\tdone\n\t# no success even after 10 seconds\n\treturn 1\n  }\n\n  repeat_with_timeout grep -i extended.attribute daemon.log\n\nto make the pattern a bit more obvious (and make it easy to extend the\nwindow arbitrarily; surely 10s is enough?).\n\n-Peff\n"},{"id":"364085","messageId":"20181126164537.GB27711@sigill.intra.peff.net","threadId":"49892","inReplyTo":"20181125222247.GD30222@szeder.dev","subject":"Re: t5570 shaky for anyone ?","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2018-11-26T16:45:38Z","receivedAt":"2018-11-26T16:45:42Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Sun, Nov 25, 2018 at 11:22:47PM +0100, SZEDER Gábor wrote:\n\n> > The following fixes it, but I am not sure if this is the ideal\n> > solution.\n> \n> Currently this is the only test that looks at 'daemon.log', but if we\n> ever going to add another one, then that will be prone to the same\n> issue.\n> \n> I wonder whether it's really that useful to have the daemon log in the\n> test script's output...  if the log was sent directly to daemon log,\n> then the window for this race would be smaller, but still not\n> completely closed.\n> \n> Anyway, I added Peff to Cc, since he added that whole fifo-shell-loop\n> thing.\n\nYeah, see my comments on the other part of the thread. If we did write\ndirectly to a file, I think that would be enough here because git-daemon\nwrites this entry before running the sub-process. So by the time\nls-remote finishes, we know that it talked to upload-pack, and we know\nthat before upload-pack was run, git-daemon wrote the log entry. That\nassumes git-daemon doesn't buffer its logs (but if it does, we should\nprobably fix that).\n\n-Peff\n"},{"id":"365655","messageId":"20181220164150.GB25639@hank.intra.tgummerer.com","threadId":"49892","inReplyTo":"20181126164252.GA27711@sigill.intra.peff.net","subject":"[PATCH] t5570: drop racy test","fromName":"Thomas Gummerer","fromEmail":"t.gummerer@gmail.com","sentAt":"2018-12-20T16:41:50Z","receivedAt":"2018-12-20T16:42:02Z","isPatch":true,"sender":{"key":"t.gummerer@gmail.com","avatar":"https://avatars.githubusercontent.com/u/191004?v=4"},"body":"On 11/26, Jeff King wrote:\n> On Sun, Nov 25, 2018 at 10:01:38PM +0000, Thomas Gummerer wrote:\n> \n> > On 11/25, Torsten Bögershausen wrote:\n> > > After running the  \"Git 2.20-rc1\" testsuite here on a raspi,\n> > > the only TC that failed was t5570.\n> > > When the \"grep\" was run on daemon.log, the file was empty (?).\n> > > When inspecting it later, it was filled, and grep would have found\n> > > the \"extended.attribute\" it was looking for.\n> > \n> > I believe this has been reported before in\n> > https://public-inbox.org/git/1522783990.964448.1325338528.0D49CC15@webmail.messagingengine.com/,\n> > but it seems like the thread never ended with actually fixing it.\n> > Reading the first reply Peff seemed to be fine with just removing the\n> > test completely, which would be the easiest solution ;)  Adding him to\n> > Cc: here.\n> \n> Yes, I don't think there is a way to make this race-proof without\n> somehow convincing \"cat\" to flush (and let us know when it has). Which\n> really implies killing the daemon, and wait()ing on cat to process the\n> EOF and exit.  And that makes the tests a lot more expensive if we have\n> to start the daemon for each snippet.\n> \n> So I'm still fine with just dropping this test.\n\nAlright since this has come up twice on the mailing list now (and I've\nseen this racyness as well), and nobody found the time to write a\npatch yet, below is a patch to just remove the test.\n\n> > > diff --git a/t/t5570-git-daemon.sh b/t/t5570-git-daemon.sh\n> > > index 7466aad111..e259fee0ed 100755\n> > > --- a/t/t5570-git-daemon.sh\n> > > +++ b/t/t5570-git-daemon.sh\n> > > @@ -192,6 +192,7 @@ test_expect_success 'daemon log records all attributes' '\n> > >  \tGIT_OVERRIDE_VIRTUAL_HOST=localhost \\\n> > >  \t\tgit -c protocol.version=1 \\\n> > >  \t\t\tls-remote \"$GIT_DAEMON_URL/interp.git\" &&\n> > > +\tsleep 1 &&\n> > >  \tgrep -i extended.attribute daemon.log | cut -d\" \" -f2- >actual &&\n> > >  \ttest_cmp expect actual\n> > >  '\n> > > ----------------\n> > > A slightly better approach may be to use a \"sleep on demand\":\n> > > \n> > > +\t( grep -i -q extended.attribute daemon.log || sleep 1 ) &&\n> \n> That doesn't really fix it, but just broadens the race window. I dunno.\n> Maybe that is enough in practice. We could do something like:\n> \n>   repeat_with_timeout () {\n> \tlocal i=0\n> \twhile test $i -lt 10\n> \tdo\n> \t\t\"$@\" && return 0\n> \t\tsleep 1\n> \tdone\n> \t# no success even after 10 seconds\n> \treturn 1\n>   }\n> \n>   repeat_with_timeout grep -i extended.attribute daemon.log\n> \n> to make the pattern a bit more obvious (and make it easy to extend the\n> window arbitrarily; surely 10s is enough?).\n\nI gave this a try, with below patch to lib-git-daemon.sh that you\nproposed in the previous thread about this racyness.  That shows\nanother problem though, namely when truncating 'daemon.log' before\nrunning 'git ls-remote' in this test, we're not sure all 'git deamon'\nhas flushed everything from previous invocations.  That may be an even\nrarer problem in practice, but still something to keep in mind.\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\nDscho also mentioned on #git-devel a while ago that he may have a look\nat actually making this test race-proof, but I guess he's been busy\nwith the 2.20 release.  I'm also not sure it's worth spending a lot of\ntime trying to fix this test, but I'd definitely be happy if someone\nproposes a different solution.\n\n> -Peff\n\n--- >8 ---\nSubject: [PATCH] t5570: drop racy test\n\nt5570 being racy has been reported twice separately on the mailing\nlist [*1*, *2*].\n\nTo make the test race proof, we'd either have to introduce another\nfifo the test snippet is waiting on, or somehow convincing \"cat\" to\nflush (and let us know when it has).  Which really implies killing the\ndaemon, and wait()ing on cat to process the EOF and exit.  And that\nmakes the tests a lot more expensive if we have to start the daemon\nfor each snippet.\n\nAs this is a test for a relatively minor fix (according to the author)\nin 19136be3f8 (\"daemon: fix off-by-one in logging extended\nattributes\", 2018-01-24), drop it to avoid this racyness.  It doesn't\nseem worth making the test code much more complex, or slowing down all\ntests just to keep this one.\n\n*1*: 1522783990.964448.1325338528.0D49CC15@webmail.messagingengine.com/\n*2*: 9d4e5224-9ff4-f3f8-519d-7b2a6f1ea7cd@web.de\n\nReported-by: Jan Palus <jpalus@fastmail.com>\nReported-by: Torsten Bögershausen <tboegi@web.de>\nHelped-by: Jeff King <peff@peff.net>\nSigned-off-by: Thomas Gummerer <t.gummerer@gmail.com>\n---\n t/t5570-git-daemon.sh | 13 -------------\n 1 file changed, 13 deletions(-)\n\ndiff --git a/t/t5570-git-daemon.sh b/t/t5570-git-daemon.sh\nindex 7466aad111..58ee787685 100755\n--- a/t/t5570-git-daemon.sh\n+++ b/t/t5570-git-daemon.sh\n@@ -183,19 +183,6 @@ test_expect_success 'hostname cannot break out of directory' '\n \t\tgit ls-remote \"$GIT_DAEMON_URL/escape.git\"\n '\n \n-test_expect_success 'daemon log records all attributes' '\n-\tcat >expect <<-\\EOF &&\n-\tExtended attribute \"host\": localhost\n-\tExtended attribute \"protocol\": version=1\n-\tEOF\n-\t>daemon.log &&\n-\tGIT_OVERRIDE_VIRTUAL_HOST=localhost \\\n-\t\tgit -c protocol.version=1 \\\n-\t\t\tls-remote \"$GIT_DAEMON_URL/interp.git\" &&\n-\tgrep -i extended.attribute daemon.log | cut -d\" \" -f2- >actual &&\n-\ttest_cmp expect actual\n-'\n-\n test_expect_success FAKENC 'hostname interpolation works after LF-stripping' '\n \t{\n \t\tprintf \"git-upload-pack /interp.git\\n\\0host=localhost\" | packetize\n-- \n2.20.1.415.g653613c723\n\n"},{"id":"365658","messageId":"20181220171438.GA6684@sigill.intra.peff.net","threadId":"49892","inReplyTo":"20181220164150.GB25639@hank.intra.tgummerer.com","subject":"Re: [PATCH] t5570: drop racy test","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2018-12-20T17:14:38Z","receivedAt":"2018-12-20T17:15:04Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Thu, Dec 20, 2018 at 04:41:50PM +0000, Thomas Gummerer wrote:\n\n> > That doesn't really fix it, but just broadens the race window. I dunno.\n> > Maybe that is enough in practice. We could do something like:\n> > \n> >   repeat_with_timeout () {\n> > \tlocal i=0\n> > \twhile test $i -lt 10\n> > \tdo\n> > \t\t\"$@\" && return 0\n> > \t\tsleep 1\n> > \tdone\n> > \t# no success even after 10 seconds\n> > \treturn 1\n> >   }\n> > \n> >   repeat_with_timeout grep -i extended.attribute daemon.log\n> > \n> > to make the pattern a bit more obvious (and make it easy to extend the\n> > window arbitrarily; surely 10s is enough?).\n> \n> I gave this a try, with below patch to lib-git-daemon.sh that you\n> proposed in the previous thread about this racyness.  That shows\n> another problem though, namely when truncating 'daemon.log' before\n> running 'git ls-remote' in this test, we're not sure all 'git deamon'\n> has flushed everything from previous invocations.  That may be an even\n> rarer problem in practice, but still something to keep in mind.\n\nRight, that makes sense. Making this race-proof really does require a\nseparate log stream for each test. I guess we'd need to be able to send\ngit-daemon a signal to re-open the log (which actually is not as\nunreasonable as it may seem; lots of daemons have this for log\nrotation).\n\nI think getting rid of the \"cat\" would also help a lot here.\nUnfortunately I think we use it not just for its \"tee\" effect, but also\nto avoid startup races by checking the \"Ready to rumble\" line. So again,\nwe'd need some cooperation from git-daemon to tell us out-of-band that\nit has completed its startup (e.g., by touching another file).\n\n> Dscho also mentioned on #git-devel a while ago that he may have a look\n> at actually making this test race-proof, but I guess he's been busy\n> with the 2.20 release.  I'm also not sure it's worth spending a lot of\n> time trying to fix this test, but I'd definitely be happy if someone\n> proposes a different solution.\n\nYeah. I'm sure it's fixable with enough effort, but I just think there\nare more interesting and important things to work on.\n\n> --- >8 ---\n> Subject: [PATCH] t5570: drop racy test\n\nSo yeah, I'm still fine with this. But...\n\n> ---\n>  t/t5570-git-daemon.sh | 13 -------------\n>  1 file changed, 13 deletions(-)\n\nThis is the only user of daemon.log, so we could drop those bits from\nlib-git-daemon.sh, too. That would also prevent people from adding new\ntests, thinking that this was somehow not horribly racy). I.e.,\nreverting 314a73d658 (t/lib-git-daemon: record daemon log, 2018-01-25).\n\n-Peff\n"},{"id":"365738","messageId":"nycvar.QRO.7.76.6.1812211638180.41@tvgsbejvaqbjf.bet","threadId":"49892","inReplyTo":"20181220171438.GA6684@sigill.intra.peff.net","subject":"Re: [PATCH] t5570: drop racy test","fromName":"Johannes Schindelin","fromEmail":"johannes.schindelin@gmx.de","sentAt":"2018-12-21T15:48:38Z","receivedAt":"2018-12-21T15:49:08Z","isPatch":true,"sender":{"key":"johannes.schindelin@gmx.de","avatar":"https://avatars.githubusercontent.com/u/127790?v=4"},"body":"Hi Thomas & Peff,\n\nOn Thu, 20 Dec 2018, Jeff King wrote:\n\n> On Thu, Dec 20, 2018 at 04:41:50PM +0000, Thomas Gummerer wrote:\n> \n> > > That doesn't really fix it, but just broadens the race window. I dunno.\n> > > Maybe that is enough in practice. We could do something like:\n> > > \n> > >   repeat_with_timeout () {\n> > > \tlocal i=0\n> > > \twhile test $i -lt 10\n> > > \tdo\n> > > \t\t\"$@\" && return 0\n> > > \t\tsleep 1\n> > > \tdone\n> > > \t# no success even after 10 seconds\n> > > \treturn 1\n> > >   }\n> > > \n> > >   repeat_with_timeout grep -i extended.attribute daemon.log\n> > > \n> > > to make the pattern a bit more obvious (and make it easy to extend the\n> > > window arbitrarily; surely 10s is enough?).\n> > \n> > I gave this a try, with below patch to lib-git-daemon.sh that you\n> > proposed in the previous thread about this racyness.  That shows\n> > another problem though, namely when truncating 'daemon.log' before\n> > running 'git ls-remote' in this test, we're not sure all 'git deamon'\n> > has flushed everything from previous invocations.  That may be an even\n> > rarer problem in practice, but still something to keep in mind.\n> \n> Right, that makes sense. Making this race-proof really does require a\n> separate log stream for each test. I guess we'd need to be able to send\n> git-daemon a signal to re-open the log (which actually is not as\n> unreasonable as it may seem; lots of daemons have this for log\n> rotation).\n> \n> I think getting rid of the \"cat\" would also help a lot here.\n> Unfortunately I think we use it not just for its \"tee\" effect, but also\n> to avoid startup races by checking the \"Ready to rumble\" line. So again,\n> we'd need some cooperation from git-daemon to tell us out-of-band that\n> it has completed its startup (e.g., by touching another file).\n> \n> > Dscho also mentioned on #git-devel a while ago that he may have a look\n> > at actually making this test race-proof, but I guess he's been busy\n> > with the 2.20 release.\n\nAnd GitGitGadget. And working on the Azure Pipelines support. And\nmentoring two interns.\n\nThis is what I still have in my internal ticket:\n\n\tTry to work around occasional t5570 failures in Git's test suite\n\n\tSeems that there is a race condition in\n\thttps://github.com/git/git/blob/master/t/lib-git-daemon.sh#L48-L69\n\tthat could possibly be solved by writing to the daemon.log\n\tdirectly, and showing the output only via `tail -f` (and only when\n\trunning in verbose mode, as it simply won't make sense otherwise).\n\nHowever, if the preferred route is to go ahead and just remove that test\naltogether, I'm fine with that, too.\n\nThe only reason, in my mind, why we still have `git-daemon` is that it\nallows for easy standing up your own Git server, e.g. as an ad-hoc way to\ncollaborate in a small ad-hoc team. If we ever get to the point where we\ncan stand up a minimal HTTP/HTTPS server with an internal Git command (not\nrequiring sysadmin privileges), from my point of view `git-daemon` can\neven go the way of the Kale Island (but for much better reasons [*1*]).\n\n> > I'm also not sure it's worth spending a lot of time trying to fix this\n> > test, but I'd definitely be happy if someone proposes a different\n> > solution.\n> \n> Yeah. I'm sure it's fixable with enough effort, but I just think there\n> are more interesting and important things to work on.\n> \n> > --- >8 ---\n> > Subject: [PATCH] t5570: drop racy test\n> \n> So yeah, I'm still fine with this. But...\n> \n> > ---\n> >  t/t5570-git-daemon.sh | 13 -------------\n> >  1 file changed, 13 deletions(-)\n> \n> This is the only user of daemon.log, so we could drop those bits from\n> lib-git-daemon.sh, too. That would also prevent people from adding new\n> tests, thinking that this was somehow not horribly racy). I.e.,\n> reverting 314a73d658 (t/lib-git-daemon: record daemon log, 2018-01-25).\n\nIndeed, that would be good.\n\nThe only reason to keep daemon.log that I can think of is to make\ndebugging easier, but then, if it should become necessary, it is probably\neasier to freopen() stdout or stderr into a file in `git daemon`, anyway.\n\nCiao,\nDscho\n\nFootnote *1*: Kale Island, along with Rapita, Rehana, Kakatina and Zollies\nis prominently featured in a scientific article at\nhttp://iopscience.iop.org/article/10.1088/1748-9326/11/5/054011 that is on\nmy \"important papers I read in 2018\" list.\n"},{"id":"366217","messageId":"20190106175310.GC25639@hank.intra.tgummerer.com","threadId":"49892","inReplyTo":"20181220164150.GB25639@hank.intra.tgummerer.com","subject":"[PATCH 2/1] Revert \"t/lib-git-daemon: record daemon log\"","fromName":"Thomas Gummerer","fromEmail":"t.gummerer@gmail.com","sentAt":"2019-01-06T17:53:10Z","receivedAt":"2019-01-06T17:53:15Z","isPatch":true,"sender":{"key":"t.gummerer@gmail.com","avatar":"https://avatars.githubusercontent.com/u/191004?v=4"},"body":"This reverts commit 314a73d658 (t/lib-git-daemon: record daemon log,\n2018-01-25), which let tests use the output of git-daemon.\n\nThe previous commit removed the last user of deamon.log in the tests,\nthere's no good way to make checking for output in the log\nrace-proof.  Revert this commit as well, to make sure others are not\ntempted to use daemon.log in tests in the future, which would lead to\nracy tests.\n\nThe original commit had one change that still makes sense, namely\nswitching read/echo for \"read -r\" and \"printf\", which relays the data\nmore faithfully.  Don't revert that piece here, as it is still a\nuseful change.\n\nSuggested-by: Jeff King <peff@peff.net>\nSigned-off-by: Thomas Gummerer <t.gummerer@gmail.com>\n---\n t/lib-git-daemon.sh | 14 +++-----------\n 1 file changed, 3 insertions(+), 11 deletions(-)\n\ndiff --git a/t/lib-git-daemon.sh b/t/lib-git-daemon.sh\nindex f98de95c15..fd41229a8f 100644\n--- a/t/lib-git-daemon.sh\n+++ b/t/lib-git-daemon.sh\n@@ -54,19 +54,11 @@ start_git_daemon() {\n \t\t\"$@\" \"$GIT_DAEMON_DOCUMENT_ROOT_PATH\" \\\n \t\t>&3 2>git_daemon_output &\n \tGIT_DAEMON_PID=$!\n-\t>daemon.log\n \t{\n \t\tread -r line <&7\n-\t\tprintf \"%s\\n\" \"$line\"\n-\t\tprintf >&4 \"%s\\n\" \"$line\"\n-\t\t(\n-\t\t\twhile read -r line <&7\n-\t\t\tdo\n-\t\t\t\tprintf \"%s\\n\" \"$line\"\n-\t\t\t\tprintf >&4 \"%s\\n\" \"$line\"\n-\t\t\tdone\n-\t\t) &\n-\t} 7<git_daemon_output >>\"$TRASH_DIRECTORY/daemon.log\" &&\n+\t\tprintf \"%s\\n\" \"$line\" >&4\n+\t\tcat <&7 >&4 &\n+\t} 7<git_daemon_output &&\n \n \t# Check expected output\n \tif test x\"$(expr \"$line\" : \"\\[[0-9]*\\] \\(.*\\)\")\" != x\"Ready to rumble\"\n-- \n2.20.1.153.gd81d796ee0\n"},{"id":"366218","messageId":"20190106175901.GD25639@hank.intra.tgummerer.com","threadId":"49892","inReplyTo":"nycvar.QRO.7.76.6.1812211638180.41@tvgsbejvaqbjf.bet","subject":"Re: [PATCH] t5570: drop racy test","fromName":"Thomas Gummerer","fromEmail":"t.gummerer@gmail.com","sentAt":"2019-01-06T17:59:01Z","receivedAt":"2019-01-06T17:59:09Z","isPatch":true,"sender":{"key":"t.gummerer@gmail.com","avatar":"https://avatars.githubusercontent.com/u/191004?v=4"},"body":"On 12/21, Johannes Schindelin wrote:\n> Hi Thomas & Peff,\n> \n> On Thu, 20 Dec 2018, Jeff King wrote:\n> \n> > On Thu, Dec 20, 2018 at 04:41:50PM +0000, Thomas Gummerer wrote:\n> > \n> > > Dscho also mentioned on #git-devel a while ago that he may have a look\n> > > at actually making this test race-proof, but I guess he's been busy\n> > > with the 2.20 release.\n> \n> And GitGitGadget. And working on the Azure Pipelines support. And\n> mentoring two interns.\n> \n> This is what I still have in my internal ticket:\n> \n> \tTry to work around occasional t5570 failures in Git's test suite\n> \n> \tSeems that there is a race condition in\n> \thttps://github.com/git/git/blob/master/t/lib-git-daemon.sh#L48-L69\n> \tthat could possibly be solved by writing to the daemon.log\n> \tdirectly, and showing the output only via `tail -f` (and only when\n> \trunning in verbose mode, as it simply won't make sense otherwise).\n> \n> However, if the preferred route is to go ahead and just remove that test\n> altogether, I'm fine with that, too.\n\nRight, I was of course completely unaware of that internal ticket.  If\nyou still want to go that way there are certainly no objections from\nme.  I just want to make sure not more users run into this racyness,\nand I guess you also may have more important/interesting things to\nwork on.\n\n> The only reason, in my mind, why we still have `git-daemon` is that it\n> allows for easy standing up your own Git server, e.g. as an ad-hoc way to\n> collaborate in a small ad-hoc team. If we ever get to the point where we\n> can stand up a minimal HTTP/HTTPS server with an internal Git command (not\n> requiring sysadmin privileges), from my point of view `git-daemon` can\n> even go the way of the Kale Island (but for much better reasons [*1*]).\n> \n> > > I'm also not sure it's worth spending a lot of time trying to fix this\n> > > test, but I'd definitely be happy if someone proposes a different\n> > > solution.\n> > \n> > Yeah. I'm sure it's fixable with enough effort, but I just think there\n> > are more interesting and important things to work on.\n> > \n> > > --- >8 ---\n> > > Subject: [PATCH] t5570: drop racy test\n> > \n> > So yeah, I'm still fine with this. But...\n> > \n> > > ---\n> > >  t/t5570-git-daemon.sh | 13 -------------\n> > >  1 file changed, 13 deletions(-)\n> > \n> > This is the only user of daemon.log, so we could drop those bits from\n> > lib-git-daemon.sh, too. That would also prevent people from adding new\n> > tests, thinking that this was somehow not horribly racy). I.e.,\n> > reverting 314a73d658 (t/lib-git-daemon: record daemon log, 2018-01-25).\n\nRight that makes sense.  I sent that as patch 2/1, but I'm happy to\nsquash those into one if that's preferred.\n\n> Indeed, that would be good.\n> \n> The only reason to keep daemon.log that I can think of is to make\n> debugging easier, but then, if it should become necessary, it is probably\n> easier to freopen() stdout or stderr into a file in `git daemon`, anyway.\n\nWe do still print the output when tests are run in verbose mode, which\nshould be just as good as having the log in a separate file in most\ncases I suspect.\n\n> Ciao,\n> Dscho\n> \n> Footnote *1*: Kale Island, along with Rapita, Rehana, Kakatina and Zollies\n> is prominently featured in a scientific article at\n> http://iopscience.iop.org/article/10.1088/1748-9326/11/5/054011 that is on\n> my \"important papers I read in 2018\" list.\n"},{"id":"366231","messageId":"20190107082041.GA21362@sigill.intra.peff.net","threadId":"49892","inReplyTo":"20190106175310.GC25639@hank.intra.tgummerer.com","subject":"Re: [PATCH 2/1] Revert \"t/lib-git-daemon: record daemon log\"","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2019-01-07T08:20:42Z","receivedAt":"2019-01-07T08:25:03Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Sun, Jan 06, 2019 at 05:53:10PM +0000, Thomas Gummerer wrote:\n\n> This reverts commit 314a73d658 (t/lib-git-daemon: record daemon log,\n> 2018-01-25), which let tests use the output of git-daemon.\n> \n> The previous commit removed the last user of deamon.log in the tests,\n> there's no good way to make checking for output in the log\n> race-proof.  Revert this commit as well, to make sure others are not\n> tempted to use daemon.log in tests in the future, which would lead to\n> racy tests.\n> \n> The original commit had one change that still makes sense, namely\n> switching read/echo for \"read -r\" and \"printf\", which relays the data\n> more faithfully.  Don't revert that piece here, as it is still a\n> useful change.\n> \n> Suggested-by: Jeff King <peff@peff.net>\n> Signed-off-by: Thomas Gummerer <t.gummerer@gmail.com>\n\nYep, this looks good to me. Thanks for being extra careful with the\nread/printf bits!\n\nLooks like Junio already queued a99653a9b6 (Revert \"t/lib-git-daemon:\nrecord daemon log\", 2018-12-28) on the tip of tg/t5570-drop-racy-test,\nbut that's a pure revert. I think we can replace it with this.\n\n-Peff\n"},{"id":"366258","messageId":"xmqq7efgbhe6.fsf@gitster-ct.c.googlers.com","threadId":"49892","inReplyTo":"20190107082041.GA21362@sigill.intra.peff.net","subject":"Re: [PATCH 2/1] Revert \"t/lib-git-daemon: record daemon log\"","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2019-01-07T15:45:53Z","receivedAt":"2019-01-07T15:45:59Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Jeff King <peff@peff.net> writes:\n\n> Yep, this looks good to me. Thanks for being extra careful with the\n> read/printf bits!\n>\n> Looks like Junio already queued a99653a9b6 (Revert \"t/lib-git-daemon:\n> record daemon log\", 2018-12-28) on the tip of tg/t5570-drop-racy-test,\n> but that's a pure revert. I think we can replace it with this.\n\nThanks, both.  Will do.\n"}]}