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.
From: Thomas Gummerer <hidden> Date: 2018-11-25 22:01:42
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.
From: SZEDER Gábor <hidden> Date: 2018-11-25 22:22:53
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.
From: Jeff King <hidden> Date: 2018-11-26 16:42:56
On Sun, Nov 25, 2018 at 10:01:38PM +0000, Thomas Gummerer wrote:
On 11/25, Torsten Bögershausen wrote:
quoted
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.
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.
@@ -192,6 +192,7 @@ test_expect_success 'daemon log records all attributes' 'GIT_OVERRIDE_VIRTUAL_HOST=localhost\git-cprotocol.version=1\ls-remote"$GIT_DAEMON_URL/interp.git"&&+sleep1&&grep-iextended.attributedaemon.log|cut-d" "-f2->actual&&test_cmpexpectactual'----------------
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
From: Jeff King <hidden> Date: 2018-11-26 16:45:42
On Sun, Nov 25, 2018 at 11:22:47PM +0100, SZEDER Gábor wrote:
quoted
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
From: Thomas Gummerer <hidden> Date: 2018-12-20 16:42:02
On 11/26, Jeff King wrote:
On Sun, Nov 25, 2018 at 10:01:38PM +0000, Thomas Gummerer wrote:
quoted
On 11/25, Torsten Bögershausen wrote:
quoted
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.
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.
Alright since this has come up twice on the mailing list now (and I've
seen this racyness as well), and nobody found the time to write a
patch yet, below is a patch to just remove the test.
@@ -192,6 +192,7 @@ test_expect_success 'daemon log records all attributes' 'GIT_OVERRIDE_VIRTUAL_HOST=localhost\git-cprotocol.version=1\ls-remote"$GIT_DAEMON_URL/interp.git"&&+sleep1&&grep-iextended.attributedaemon.log|cut-d" "-f2->actual&&test_cmpexpectactual'----------------
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?).
I gave this a try, with below patch to lib-git-daemon.sh that you
proposed in the previous thread about this racyness. That shows
another problem though, namely when truncating 'daemon.log' before
running 'git ls-remote' in this test, we're not sure all 'git deamon'
has flushed everything from previous invocations. That may be an even
rarer problem in practice, but still something to keep in mind.
Dscho also mentioned on #git-devel a while ago that he may have a look
at actually making this test race-proof, but I guess he's been busy
with the 2.20 release. I'm also not sure it's worth spending a lot of
time trying to fix this test, but I'd definitely be happy if someone
proposes a different solution.
-Peff
--- >8 ---
Subject: [PATCH] t5570: drop racy test
t5570 being racy has been reported twice separately on the mailing
list [*1*, *2*].
To make the test race proof, we'd either have to introduce another
fifo the test snippet is waiting on, or 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.
As this is a test for a relatively minor fix (according to the author)
in 19136be3f8 ("daemon: fix off-by-one in logging extended
attributes", 2018-01-24), drop it to avoid this racyness. It doesn't
seem worth making the test code much more complex, or slowing down all
tests just to keep this one.
*1*: 1522783990.964448.1325338528.0D49CC15@webmail.messagingengine.com/
*2*: 9d4e5224-9ff4-f3f8-519d-7b2a6f1ea7cd@web.de
Reported-by: Jan Palus <redacted>
Reported-by: Torsten Bögershausen <redacted>
Helped-by: Jeff King [off-list ref]
Signed-off-by: Thomas Gummerer <redacted>
---
t/t5570-git-daemon.sh | 13 -------------
1 file changed, 13 deletions(-)
@@ -183,19 +183,6 @@ test_expect_success 'hostname cannot break out of directory' 'gitls-remote"$GIT_DAEMON_URL/escape.git"'-test_expect_success'daemon log records all attributes''-cat>expect<<-\EOF&&-Extendedattribute"host":localhost-Extendedattribute"protocol":version=1-EOF->daemon.log&&-GIT_OVERRIDE_VIRTUAL_HOST=localhost\-git-cprotocol.version=1\-ls-remote"$GIT_DAEMON_URL/interp.git"&&-grep-iextended.attributedaemon.log|cut-d" "-f2->actual&&-test_cmpexpectactual-'- test_expect_successFAKENC'hostname interpolation works after LF-stripping''{printf"git-upload-pack /interp.git\n\0host=localhost"|packetize
From: Jeff King <hidden> Date: 2018-12-20 17:15:04
On Thu, Dec 20, 2018 at 04:41:50PM +0000, Thomas Gummerer wrote:
quoted
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?).
I gave this a try, with below patch to lib-git-daemon.sh that you
proposed in the previous thread about this racyness. That shows
another problem though, namely when truncating 'daemon.log' before
running 'git ls-remote' in this test, we're not sure all 'git deamon'
has flushed everything from previous invocations. That may be an even
rarer problem in practice, but still something to keep in mind.
Right, that makes sense. Making this race-proof really does require a
separate log stream for each test. I guess we'd need to be able to send
git-daemon a signal to re-open the log (which actually is not as
unreasonable as it may seem; lots of daemons have this for log
rotation).
I think getting rid of the "cat" would also help a lot here.
Unfortunately I think we use it not just for its "tee" effect, but also
to avoid startup races by checking the "Ready to rumble" line. So again,
we'd need some cooperation from git-daemon to tell us out-of-band that
it has completed its startup (e.g., by touching another file).
Dscho also mentioned on #git-devel a while ago that he may have a look
at actually making this test race-proof, but I guess he's been busy
with the 2.20 release. I'm also not sure it's worth spending a lot of
time trying to fix this test, but I'd definitely be happy if someone
proposes a different solution.
Yeah. I'm sure it's fixable with enough effort, but I just think there
are more interesting and important things to work on.
This is the only user of daemon.log, so we could drop those bits from
lib-git-daemon.sh, too. That would also prevent people from adding new
tests, thinking that this was somehow not horribly racy). I.e.,
reverting 314a73d658 (t/lib-git-daemon: record daemon log, 2018-01-25).
-Peff
From: Johannes Schindelin <hidden> Date: 2018-12-21 15:49:08
Hi Thomas & Peff,
On Thu, 20 Dec 2018, Jeff King wrote:
On Thu, Dec 20, 2018 at 04:41:50PM +0000, Thomas Gummerer wrote:
quoted
quoted
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?).
I gave this a try, with below patch to lib-git-daemon.sh that you
proposed in the previous thread about this racyness. That shows
another problem though, namely when truncating 'daemon.log' before
running 'git ls-remote' in this test, we're not sure all 'git deamon'
has flushed everything from previous invocations. That may be an even
rarer problem in practice, but still something to keep in mind.
Right, that makes sense. Making this race-proof really does require a
separate log stream for each test. I guess we'd need to be able to send
git-daemon a signal to re-open the log (which actually is not as
unreasonable as it may seem; lots of daemons have this for log
rotation).
I think getting rid of the "cat" would also help a lot here.
Unfortunately I think we use it not just for its "tee" effect, but also
to avoid startup races by checking the "Ready to rumble" line. So again,
we'd need some cooperation from git-daemon to tell us out-of-band that
it has completed its startup (e.g., by touching another file).
quoted
Dscho also mentioned on #git-devel a while ago that he may have a look
at actually making this test race-proof, but I guess he's been busy
with the 2.20 release.
And GitGitGadget. And working on the Azure Pipelines support. And
mentoring two interns.
This is what I still have in my internal ticket:
Try to work around occasional t5570 failures in Git's test suite
Seems that there is a race condition in
https://github.com/git/git/blob/master/t/lib-git-daemon.sh#L48-L69
that could possibly be solved by writing to the daemon.log
directly, and showing the output only via `tail -f` (and only when
running in verbose mode, as it simply won't make sense otherwise).
However, if the preferred route is to go ahead and just remove that test
altogether, I'm fine with that, too.
The only reason, in my mind, why we still have `git-daemon` is that it
allows for easy standing up your own Git server, e.g. as an ad-hoc way to
collaborate in a small ad-hoc team. If we ever get to the point where we
can stand up a minimal HTTP/HTTPS server with an internal Git command (not
requiring sysadmin privileges), from my point of view `git-daemon` can
even go the way of the Kale Island (but for much better reasons [*1*]).
quoted
I'm also not sure it's worth spending a lot of time trying to fix this
test, but I'd definitely be happy if someone proposes a different
solution.
Yeah. I'm sure it's fixable with enough effort, but I just think there
are more interesting and important things to work on.
This is the only user of daemon.log, so we could drop those bits from
lib-git-daemon.sh, too. That would also prevent people from adding new
tests, thinking that this was somehow not horribly racy). I.e.,
reverting 314a73d658 (t/lib-git-daemon: record daemon log, 2018-01-25).
Indeed, that would be good.
The only reason to keep daemon.log that I can think of is to make
debugging easier, but then, if it should become necessary, it is probably
easier to freopen() stdout or stderr into a file in `git daemon`, anyway.
Ciao,
Dscho
Footnote *1*: Kale Island, along with Rapita, Rehana, Kakatina and Zollies
is prominently featured in a scientific article at
http://iopscience.iop.org/article/10.1088/1748-9326/11/5/054011 that is on
my "important papers I read in 2018" list.
From: Thomas Gummerer <hidden> Date: 2019-01-06 17:53:15
This reverts commit 314a73d658 (t/lib-git-daemon: record daemon log,
2018-01-25), which let tests use the output of git-daemon.
The previous commit removed the last user of deamon.log in the tests,
there's no good way to make checking for output in the log
race-proof. Revert this commit as well, to make sure others are not
tempted to use daemon.log in tests in the future, which would lead to
racy tests.
The original commit had one change that still makes sense, namely
switching read/echo for "read -r" and "printf", which relays the data
more faithfully. Don't revert that piece here, as it is still a
useful change.
Suggested-by: Jeff King <redacted>
Signed-off-by: Thomas Gummerer <redacted>
---
t/lib-git-daemon.sh | 14 +++-----------
1 file changed, 3 insertions(+), 11 deletions(-)
From: Thomas Gummerer <hidden> Date: 2019-01-06 17:59:09
On 12/21, Johannes Schindelin wrote:
Hi Thomas & Peff,
On Thu, 20 Dec 2018, Jeff King wrote:
quoted
On Thu, Dec 20, 2018 at 04:41:50PM +0000, Thomas Gummerer wrote:
quoted
Dscho also mentioned on #git-devel a while ago that he may have a look
at actually making this test race-proof, but I guess he's been busy
with the 2.20 release.
And GitGitGadget. And working on the Azure Pipelines support. And
mentoring two interns.
This is what I still have in my internal ticket:
Try to work around occasional t5570 failures in Git's test suite
Seems that there is a race condition in
https://github.com/git/git/blob/master/t/lib-git-daemon.sh#L48-L69
that could possibly be solved by writing to the daemon.log
directly, and showing the output only via `tail -f` (and only when
running in verbose mode, as it simply won't make sense otherwise).
However, if the preferred route is to go ahead and just remove that test
altogether, I'm fine with that, too.
Right, I was of course completely unaware of that internal ticket. If
you still want to go that way there are certainly no objections from
me. I just want to make sure not more users run into this racyness,
and I guess you also may have more important/interesting things to
work on.
The only reason, in my mind, why we still have `git-daemon` is that it
allows for easy standing up your own Git server, e.g. as an ad-hoc way to
collaborate in a small ad-hoc team. If we ever get to the point where we
can stand up a minimal HTTP/HTTPS server with an internal Git command (not
requiring sysadmin privileges), from my point of view `git-daemon` can
even go the way of the Kale Island (but for much better reasons [*1*]).
quoted
quoted
I'm also not sure it's worth spending a lot of time trying to fix this
test, but I'd definitely be happy if someone proposes a different
solution.
Yeah. I'm sure it's fixable with enough effort, but I just think there
are more interesting and important things to work on.
This is the only user of daemon.log, so we could drop those bits from
lib-git-daemon.sh, too. That would also prevent people from adding new
tests, thinking that this was somehow not horribly racy). I.e.,
reverting 314a73d658 (t/lib-git-daemon: record daemon log, 2018-01-25).
Right that makes sense. I sent that as patch 2/1, but I'm happy to
squash those into one if that's preferred.
Indeed, that would be good.
The only reason to keep daemon.log that I can think of is to make
debugging easier, but then, if it should become necessary, it is probably
easier to freopen() stdout or stderr into a file in `git daemon`, anyway.
We do still print the output when tests are run in verbose mode, which
should be just as good as having the log in a separate file in most
cases I suspect.
Ciao,
Dscho
Footnote *1*: Kale Island, along with Rapita, Rehana, Kakatina and Zollies
is prominently featured in a scientific article at
http://iopscience.iop.org/article/10.1088/1748-9326/11/5/054011 that is on
my "important papers I read in 2018" list.
From: Jeff King <hidden> Date: 2019-01-07 08:25:03
On Sun, Jan 06, 2019 at 05:53:10PM +0000, Thomas Gummerer wrote:
This reverts commit 314a73d658 (t/lib-git-daemon: record daemon log,
2018-01-25), which let tests use the output of git-daemon.
The previous commit removed the last user of deamon.log in the tests,
there's no good way to make checking for output in the log
race-proof. Revert this commit as well, to make sure others are not
tempted to use daemon.log in tests in the future, which would lead to
racy tests.
The original commit had one change that still makes sense, namely
switching read/echo for "read -r" and "printf", which relays the data
more faithfully. Don't revert that piece here, as it is still a
useful change.
Suggested-by: Jeff King <redacted>
Signed-off-by: Thomas Gummerer <redacted>
Yep, this looks good to me. Thanks for being extra careful with the
read/printf bits!
Looks like Junio already queued a99653a9b6 (Revert "t/lib-git-daemon:
record daemon log", 2018-12-28) on the tip of tg/t5570-drop-racy-test,
but that's a pure revert. I think we can replace it with this.
-Peff