diff mbox series

t5570 shaky for anyone ?

Message ID 9d4e5224-9ff4-f3f8-519d-7b2a6f1ea7cd@web.de (mailing list archive)
State New, archived
Headers show
Series t5570 shaky for anyone ? | expand

Commit Message

Torsten Bögershausen Nov. 25, 2018, 8:52 p.m. UTC 
After running the  "Git 2.20-rc1" testsuite here on a raspi,
the only TC that failed was t5570.
When the "grep" was run on daemon.log, the file was empty (?).
When inspecting it later, it was filled, and grep would have found
the "extended.attribute" it was looking for.

The following fixes it, but I am not sure if this is the ideal
solution.


----------------
A slightly better approach may be to use a "sleep on demand":

+	( grep -i -q extended.attribute daemon.log || sleep 1 ) &&

Comments

Thomas Gummerer Nov. 25, 2018, 10:01 p.m. UTC | #1 
On 11/25, Torsten Bögershausen wrote:
> After running the  "Git 2.20-rc1" testsuite here on a raspi,
> the only TC that failed was t5570.
> When the "grep" was run on daemon.log, the file was empty (?).
> When inspecting it later, it was filled, and grep would have found
> the "extended.attribute" it was looking for.

I believe this has been reported before in
https://public-inbox.org/git/1522783990.964448.1325338528.0D49CC15@webmail.messagingengine.com/,
but it seems like the thread never ended with actually fixing it.
Reading the first reply Peff seemed to be fine with just removing the
test completely, which would be the easiest solution ;)  Adding him to
Cc: here.  

> The following fixes it, but I am not sure if this is the ideal
> solution.
> 
> 
> diff --git a/t/t5570-git-daemon.sh b/t/t5570-git-daemon.sh
> index 7466aad111..e259fee0ed 100755
> --- a/t/t5570-git-daemon.sh
> +++ b/t/t5570-git-daemon.sh
> @@ -192,6 +192,7 @@ test_expect_success 'daemon log records all attributes' '
>  	GIT_OVERRIDE_VIRTUAL_HOST=localhost \
>  		git -c protocol.version=1 \
>  			ls-remote "$GIT_DAEMON_URL/interp.git" &&
> +	sleep 1 &&
>  	grep -i extended.attribute daemon.log | cut -d" " -f2- >actual &&
>  	test_cmp expect actual
>  '
> ----------------
> A slightly better approach may be to use a "sleep on demand":
> 
> +	( grep -i -q extended.attribute daemon.log || sleep 1 ) &&
>
SZEDER Gábor Nov. 25, 2018, 10:22 p.m. UTC | #2 
On Sun, Nov 25, 2018 at 09:52:23PM +0100, Torsten Bögershausen wrote:
> After running the  "Git 2.20-rc1" testsuite here on a raspi,
> the only TC that failed was t5570.
> When the "grep" was run on daemon.log, the file was empty (?).
> When inspecting it later, it was filled, and grep would have found
> the "extended.attribute" it was looking for.

I think I saw the same failure on Travis CI already before 2.19, so
it's not a new issue.  Here's the test's verbose output:

  + cat
  + 
  + GIT_OVERRIDE_VIRTUAL_HOST=localhost git -c protocol.version=1 ls-remote git://127.0.0.1:5570/interp.git
  b6752e52dd867264d12240028003f21e3e1dccab        HEAD
  b6752e52dd867264d12240028003f21e3e1dccab        refs/heads/master
  + cut -d  -f2-
  + grep -i extended.attribute daemon.log
  + test_cmp expect actual
  + diff -u expect actual
  --- expect      2018-06-12 10:06:50.758357927 +0000
  +++ actual      2018-06-12 10:06:50.774365936 +0000
  @@ -1,2 +0,0 @@
  -Extended attribute "host": localhost
  -Extended attribute "protocol": version=1
  [10579] Connection from 127.0.0.1:45836
  [10579] Extended attribute "host": localhost
  [10579] Extended attribute "protocol": version=1
  error: last command exited with $?=1
  [10579] Request upload-pack for '/interp.git'
  [10579] Interpolated dir '/usr/src/git/t/trash
  dir.t5570/repo/localhost/interp.git'
  [10462] [10579] Disconnected
  not ok 21 - daemon log records all attributes

The thing is that 'git daemon's log is not written to 'daemon.log'
directly, but it goes through a fifo, which is read by a shell loop,
which then sends all log messages both to 'daemon.log' and to the test
script's standard error.  So there is certainly a race between log
messages going through the fifo and the loop before reaching
'daemon.log' and 'git ls-remote' exiting and 'grep' opening
'daemon.log'.

> The following fixes it, but I am not sure if this is the ideal
> solution.

Currently this is the only test that looks at 'daemon.log', but if we
ever going to add another one, then that will be prone to the same
issue.

I wonder whether it's really that useful to have the daemon log in the
test script's output...  if the log was sent directly to daemon log,
then the window for this race would be smaller, but still not
completely closed.

Anyway, I added Peff to Cc, since he added that whole fifo-shell-loop
thing.

> diff --git a/t/t5570-git-daemon.sh b/t/t5570-git-daemon.sh
> index 7466aad111..e259fee0ed 100755
> --- a/t/t5570-git-daemon.sh
> +++ b/t/t5570-git-daemon.sh
> @@ -192,6 +192,7 @@ test_expect_success 'daemon log records all attributes' '
>  	GIT_OVERRIDE_VIRTUAL_HOST=localhost \
>  		git -c protocol.version=1 \
>  			ls-remote "$GIT_DAEMON_URL/interp.git" &&
> +	sleep 1 &&
>  	grep -i extended.attribute daemon.log | cut -d" " -f2- >actual &&
>  	test_cmp expect actual
>  '
> ----------------
> A slightly better approach may be to use a "sleep on demand":
> 
> +	( grep -i -q extended.attribute daemon.log || sleep 1 ) &&
>
Jeff King Nov. 26, 2018, 4:42 p.m. UTC | #3 
On Sun, Nov 25, 2018 at 10:01:38PM +0000, Thomas Gummerer wrote:

> On 11/25, Torsten Bögershausen wrote:
> > After running the  "Git 2.20-rc1" testsuite here on a raspi,
> > the only TC that failed was t5570.
> > When the "grep" was run on daemon.log, the file was empty (?).
> > When inspecting it later, it was filled, and grep would have found
> > the "extended.attribute" it was looking for.
> 
> I believe this has been reported before in
> https://public-inbox.org/git/1522783990.964448.1325338528.0D49CC15@webmail.messagingengine.com/,
> but it seems like the thread never ended with actually fixing it.
> Reading the first reply Peff seemed to be fine with just removing the
> test completely, which would be the easiest solution ;)  Adding him to
> Cc: here.

Yes, I don't think there is a way to make this race-proof without
somehow convincing "cat" to flush (and let us know when it has). Which
really implies killing the daemon, and wait()ing on cat to process the
EOF and exit.  And that makes the tests a lot more expensive if we have
to start the daemon for each snippet.

So I'm still fine with just dropping this test.

> > diff --git a/t/t5570-git-daemon.sh b/t/t5570-git-daemon.sh
> > index 7466aad111..e259fee0ed 100755
> > --- a/t/t5570-git-daemon.sh
> > +++ b/t/t5570-git-daemon.sh
> > @@ -192,6 +192,7 @@ test_expect_success 'daemon log records all attributes' '
> >  	GIT_OVERRIDE_VIRTUAL_HOST=localhost \
> >  		git -c protocol.version=1 \
> >  			ls-remote "$GIT_DAEMON_URL/interp.git" &&
> > +	sleep 1 &&
> >  	grep -i extended.attribute daemon.log | cut -d" " -f2- >actual &&
> >  	test_cmp expect actual
> >  '
> > ----------------
> > A slightly better approach may be to use a "sleep on demand":
> > 
> > +	( grep -i -q extended.attribute daemon.log || sleep 1 ) &&

That doesn't really fix it, but just broadens the race window. I dunno.
Maybe that is enough in practice. We could do something like:

  repeat_with_timeout () {
	local i=0
	while test $i -lt 10
	do
		"$@" && return 0
		sleep 1
	done
	# no success even after 10 seconds
	return 1
  }

  repeat_with_timeout grep -i extended.attribute daemon.log

to make the pattern a bit more obvious (and make it easy to extend the
window arbitrarily; surely 10s is enough?).

-Peff
Jeff King Nov. 26, 2018, 4:45 p.m. UTC | #4 
On Sun, Nov 25, 2018 at 11:22:47PM +0100, SZEDER Gábor wrote:

> > The following fixes it, but I am not sure if this is the ideal
> > solution.
> 
> Currently this is the only test that looks at 'daemon.log', but if we
> ever going to add another one, then that will be prone to the same
> issue.
> 
> I wonder whether it's really that useful to have the daemon log in the
> test script's output...  if the log was sent directly to daemon log,
> then the window for this race would be smaller, but still not
> completely closed.
> 
> Anyway, I added Peff to Cc, since he added that whole fifo-shell-loop
> thing.

Yeah, see my comments on the other part of the thread. If we did write
directly to a file, I think that would be enough here because git-daemon
writes this entry before running the sub-process. So by the time
ls-remote finishes, we know that it talked to upload-pack, and we know
that before upload-pack was run, git-daemon wrote the log entry. That
assumes git-daemon doesn't buffer its logs (but if it does, we should
probably fix that).

-Peff
diff mbox series

Patch

diff --git a/t/t5570-git-daemon.sh b/t/t5570-git-daemon.sh
index 7466aad111..e259fee0ed 100755
--- a/t/t5570-git-daemon.sh
+++ b/t/t5570-git-daemon.sh
@@ -192,6 +192,7 @@  test_expect_success 'daemon log records all attributes' '
 	GIT_OVERRIDE_VIRTUAL_HOST=localhost \
 		git -c protocol.version=1 \
 			ls-remote "$GIT_DAEMON_URL/interp.git" &&
+	sleep 1 &&
 	grep -i extended.attribute daemon.log | cut -d" " -f2- >actual &&
 	test_cmp expect actual
 '