threads / discuss / 48217

Timing issue in t5570 "daemon log records all attributes"

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

## tl;dr

4 messages between Apr 3, 2018 and Apr 5, 2018.

replies: 3people: 2as markdown or json

Jan Palus· Apr 3, 2018, 19:33 UTC · lore

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

Jeff King· Apr 3, 2018, 20:32 UTC · re: Jan Palus · lore

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

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

Show 19 quoted lines

> 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

Jan Palus· Apr 4, 2018, 21:57 UTC · re: Jeff King · lore

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

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

Jeff King· Apr 5, 2018, 16:39 UTC · re: Jan Palus · lore

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

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

Show 16 quoted lines

> 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.