Timing issue in t5570 "daemon log records all attributes"

Timing issue in t5570 "daemon log records all attributes"

[Jan Palus]

My understanding of test "daemon log records all attributes" is that daemon
process is started in background, some git command is executed and daemon's
output (saved to daemon.log) is compared against expected value. However
daemon.log is not a straight redirect to file -- it is being piped through fifo,
read by a loop in test-git-daemon.sh, additional processing is performed and
finally it makes it to daemon.log. All of this performed concurrently with test
execution. My question is how do you exactly avoid timing issues here? grep on
daemon.log is performed immediately after git invocation:

        >daemon.log &&
        GIT_OVERRIDE_VIRTUAL_HOST=localhost \
                git -c protocol.version=1 \
                        ls-remote "$GIT_DAEMON_URL/interp.git" &&
        grep -i extended.attribute daemon.log | cut -d" " -f2- >actual &&

how can you be sure grep operates on daemon.log that already includes all output
and not on intermediate state that is just being processed by while loop? Same
question applies to ">daemon.log" since shell might still be processing output
of previous test and its content might possibly land in the file after zeroing.

The reason I'm asking is because /bin/sh in my distribution (mksh) actually
manifests the issue -- test fails because at the time of grep output was not
processed yet (fixed by sleep 1 before grep). Also there is an issue with output
of previous test landing in daemon.log despite ">daemon.log".


Regards
Jan

Re: Timing issue in t5570 "daemon log records all attributes"

[Jeff King]

On Tue, Apr 03, 2018 at 09:33:10PM +0200, Jan Palus wrote:

> My understanding of test "daemon log records all attributes" is that daemon
> process is started in background, some git command is executed and daemon's
> output (saved to daemon.log) is compared against expected value. However
> daemon.log is not a straight redirect to file -- it is being piped through fifo,
> read by a loop in test-git-daemon.sh, additional processing is performed and
> finally it makes it to daemon.log. All of this performed concurrently with test
> execution. My question is how do you exactly avoid timing issues here? grep on
> daemon.log is performed immediately after git invocation:
> 
>         >daemon.log &&
>         GIT_OVERRIDE_VIRTUAL_HOST=localhost \
>                 git -c protocol.version=1 \
>                         ls-remote "$GIT_DAEMON_URL/interp.git" &&
>         grep -i extended.attribute daemon.log | cut -d" " -f2- >actual &&
> 
> how can you be sure grep operates on daemon.log that already includes all output
> and not on intermediate state that is just being processed by while loop? Same
> question applies to ">daemon.log" since shell might still be processing output
> of previous test and its content might possibly land in the file after zeroing.

You're right, this is racy. You can see it much more obviously with:

diff --git a/t/lib-git-daemon.sh b/t/lib-git-daemon.sh
index edbea2d986..3c7fea169b 100644
--- a/t/lib-git-daemon.sh
+++ b/t/lib-git-daemon.sh
@@ -62,6 +62,7 @@ start_git_daemon() {
 		(
 			while read -r line <&7
 			do
+				sleep 1
 				printf "%s\n" "$line"
 				printf >&4 "%s\n" "$line"
 			done

I'm not sure of the best solution. Even if we removed the shell-loop
pumping the data from the fifo, it's still possible to race if
git-daemon hangs up the client socket before flushing its log output
(since our only real synchronization is waiting for the client to exit).

Nor could we even wait for an EOF on the fifo, since we won't get one
until the daemon actually exits.

If we want to do it without polling, I think the best we could do is
have the pumping loop key on some particular line in the output as a
synchronization point, and then trigger _another_ fifo that the test
snippet listens on. Yuck.

I'm tempted to say we should just scrap this test. It was added
relatively recently and only shows the fix for a pretty minor bug.
It's probably not worth the contortions to make it race-proof.

-Peff

Re: Timing issue in t5570 "daemon log records all attributes"

[Jan Palus]

On 03.04.2018 16:32, Jeff King wrote:
> I'm tempted to say we should just scrap this test. It was added
> relatively recently and only shows the fix for a pretty minor bug.
> It's probably not worth the contortions to make it race-proof.

Thanks for your reply Jeff.

It appears race condition in reading/writing daemon.log is not the only issue of
t5570. On a different machine I've just randomly got:

t5570-git-daemon.sh[163]: can't create git_daemon_output: Interrupted system call

which I believe might also be associated with concurrent processing of piped
data connected with a fact that test restarts daemon few times. I can barely
wrap my head around it but I guess it's somewhat around "shell still tries to
read fifo while attempt to create new one is made".


Regards
Jan

Re: Timing issue in t5570 "daemon log records all attributes"

[Jeff King]

On Wed, Apr 04, 2018 at 11:57:52PM +0200, Jan Palus wrote:

> On 03.04.2018 16:32, Jeff King wrote:
> > I'm tempted to say we should just scrap this test. It was added
> > relatively recently and only shows the fix for a pretty minor bug.
> > It's probably not worth the contortions to make it race-proof.
> 
> Thanks for your reply Jeff.
> 
> It appears race condition in reading/writing daemon.log is not the only issue of
> t5570. On a different machine I've just randomly got:
> 
> t5570-git-daemon.sh[163]: can't create git_daemon_output: Interrupted system call
> 
> which I believe might also be associated with concurrent processing of piped
> data connected with a fact that test restarts daemon few times. I can barely
> wrap my head around it but I guess it's somewhat around "shell still tries to
> read fifo while attempt to create new one is made".

That sounds more like your system doesn't handle EINTR gracefully
(presumably it's getting SIGCLD during the mknod() call). Normally that
would be done by an external program, but is mkfifo perhaps a builtin in
your shell?

If I run t5570 on a loop on a loaded system[1], I can't seem to provoke
any failures, using dash.

-Peff

[1] The script I use is:

      https://github.com/peff/git/blob/meta/stress

    which runs the test script over and over in parallel. That's usually
    enough to exhibit practical races, since it creates enough load to
    show timing effects.