t5570: forward git-daemon messages in a different way

git-daemon is not launched properly in t5570:

$ GIT_TEST_GIT_DAEMON=t ./t5570-git-daemon.sh
ok 1 - setup repository
ok 2 - create git-accessible bare repository
not ok - 3 clone git repository
not ok - 4 fetch changes via git protocol
...

Current setup code to spawn git daemon (start_git_daemon() in lib-git-daemon.sh) redirects daemon output to a pipe, and then redirects input from this pipe to a different fd, which is in turn connected to a terminal:
mkfifo git_daemon_output
git daemon ... >&3 2>git_daemon_output

  {
      ...
      cat >&4

} <git_daemon_output

Unfortunately, it seems that the shell (at least bash 4.1-3 from debian) closes the pipe and cat doesn't really copy any messages. This causes git-daemon to die.

Running 'strace -o log cat' instead of just 'cat' shows that no input is read:
execve("/bin/cat", ...) = 0
...

  read(0, "", 8192)         = 0
  close(0)                  = 0
  close(1)                  = 0
  close(2)                  = 0
  exit_group(0)             = ?

I guess that the shell closes the redirection when exiting the {}-delimited part. It seems easiest to move the cat invocation outside of the {}-delimited part and provide a separate redirection which will not be closed.

While at it, print the address on which git-daemon is started, to make debugging easier.

---
 t/lib-git-daemon.sh |    5 +++--
 1 file changed, 3 insertions(+), 2 deletions(-)

index ef2d01f..8f9c1b6 100644
@@ -22,7 +22,7 @@ start_git_daemon() {
 
 	trap 'code=$?; stop_git_daemon; (exit $code); die' EXIT
 
-	say >&3 "Starting git daemon ..."
+	say >&3 "Starting git daemon on $GIT_DAEMON_URL ..."
 	mkfifo git_daemon_output
 	git daemon --listen=127.0.0.1 --port="$LIB_GIT_DAEMON_PORT" \
 		--reuseaddr --verbose \

@@ -33,7 +33,6 @@ start_git_daemon() {
 	{
 		read line
 		echo >&4 "$line"
-		cat >&4 &
 
 		# Check expected output
 		if test x"$(expr "$line" : "\[[0-9]*\] \(.*\)")" != x"Ready to rumble"

@@ -44,6 +43,8 @@ start_git_daemon() {
 			error "git daemon failed to start"
 		fi
 	} <git_daemon_output
+
+	cat <git_daemon_output >&4 &
 }
 
 stop_git_daemon() {

1.7.10.226.gfe575

And as a consequence, t5570 tests fail for you? I cannot reproduce with bash 4.2.24(2). Which git version are you seeing this with?

What do you expect it to read? If git-daemon exits without error, it does not output anything.

I am not sure about that part myself, but it seems to work for me in all cases.

With your patch, only the first line of output will be read from git-daemon, because the pipe is broken as soon as you close the fifo for the first time. You can check this by passing an invalid argument to git-daemon. Only the first line of the usage string will be printed.

In order to better understand the problem on your side, can you execute this script and tell me what it does for you?

#!/bin/sh

mkfifo fd
yes >fd &
pid=$!
{
read line
echo $line
} <fd
cat <fd &
sleep 1
kill $pid
wait $pid
rm -f fd

If we cannot find a reliable solution using shell script, we should probably write a test-git-daemon wrapper which implements the expected output checking part in C.

Clemens

Oops, this is what I really wanted:

#!/bin/sh

mkfifo fd
yes >fd &
pid=$!
{
read line
echo $line
cat <fd &
} <fd
sleep 1
kill $pid
wait $pid
rm -f fd

Hi,
many thanks for looking into this. I'm sorry I didn't reply sooner, but I was away for the weekend.

Yes. Example test output is:

----(on master 146fe8ce2)------------------------------------------------------------------

$ (cd t && GIT_TEST_GIT_DAEMON=t ./t5570*sh)
ok 1 - setup repository
ok 2 - create git-accessible bare repository
not ok - 3 clone git repository
#
#               git clone "$GIT_DAEMON_URL/repo.git" clone &&
#               test_cmp file clone/file
#
not ok - 4 fetch changes via git protocol
#
#               echo content >>file &&
#               git commit -a -m two &&
#               git push public &&
#               (cd clone && git pull) &&
#               test_cmp file clone/file
#
not ok 5 - remote detects correct HEAD # TODO known breakage
ok 6 - prepare pack objects
ok 7 - fetch notices corrupt pack
ok 8 - fetch notices corrupt idx
not ok - 9 clone non-existent
#       test_remote_error    clone nowhere.git 'access denied or repository not exported'
not ok - 10 push disabled
#       test_remote_error    push  repo.git    'access denied or repository not exported'
not ok - 11 read access denied
#       test_remote_error -x fetch repo.git    'access denied or repository not exported'
not ok - 12 not exported
#       test_remote_error -n fetch repo.git    'access denied or repository not exported'
./t5570-git-daemon.sh: 59: kill: No such process

error: git daemon exited with status: 141
-----------------------------------------------------------------------------------------

OK, I run your test scripts and found the problem (test.sh is the first version, and test2.sh is the second version with 'cat' inside {}). Yikes! I have /bin/sh symlinked to dash, and dash behaves differently:

% bash -x test2.sh | wc -l
+ mkfifo fd
+ pid=10685
+ yes
+ read line
+ echo y
+ sleep 1
+ cat
+ kill 10685
+ wait 10685
test2.sh: line 13: 10685 Terminated yes > fd
+ rm -f fd
45400064

% dash -x test2.sh | wc -l
+ mkfifo fd
+ pid=10738
+ read line
+ yes
+ echo y
+ sleep 1
+ kill 10738
test2.sh: 12: kill: No such process

+ wait 10738
+ rm -f fd
^C

It hangs at the end until killed with ^C. This seem to happen fairly reliably (nineteen times out of twenty or so). This is with dash 0.5.7-3 and 0.5.5.1-7.4 from debian. With bash test2.sh seems to always run successfully.

I also run test.sh for comparison, and dash runs test.sh successfully every once in a while, and test.sh always fails with bash.

So my patch was totally bogus, it was just probably changing the timing.

Now your patches (on top of next):
'git-daemon wrapper to wait until daemon is ready' fixes the problem, thanks!

(I now see that they are both in pu: pu runs fine too.)

Thanks,
Zbyszek

Hmm. t5570 seems to pass reliably on dash for me with:

index ef2d01f..9f52cb6 100644
@@ -33,7 +33,7 @@ start_git_daemon() {
 	{
 		read line
 		echo >&4 "$line"
-		cat >&4 &
+		cat >&4 <git_daemon_output &
 
 		# Check expected output
 		if test x"$(expr "$line" : "\[[0-9]*\] \(.*\)")" != x"Ready to rumble"

But the test above does fail. Is it purely luck of the timing that git-daemon never gets SIGPIPE? I guess the problem is that the {}-section can finish before "cat <git_daemon_output" has actually opened the pipe?

I'd just feel better about the solution if we were sure we understood the exact problem.

-Peff

Which one do you mean? The output check works for me.

No clue. But shouldn't the fork return only after the fd's have been opened successfully? If I change cat to "(echo di; cat; echo do); sleep 1; pgrep yes", then one can see that cat terminates right away, even though yes is still running. It's as if cat never gets to read from the pipe, but from /dev/null instead. A bug in dash?

Yeah. I have to admit that I have a strongly empirical approach to these things and no true understanding of the inner workings.

Sorry, I meant the test you posted with "yes":

mkfifo fd
yes >fd &
pid=$!
{
read line
echo $line
cat <fd &
} <fd
sleep 1
kill $pid
wait $pid
rm -f fd

It sometimes succeeds and sometimes fails for me. So I think we are perhaps just winning a race every time in the actual git-daemon run (because it is not writing nearly as quickly as "yes").

Hmm. Yeah, if you strace the cat, it gets an immediate EOF. And even weirder, I notice this in the strace output:

clone(...)
close(0) = 0
open("/dev/null", O_RDONLY) = 0
...
execve("/bin/cat", ["cat"], [/* 50 vars */]) = 0

What? The shell is literally redirecting the cat process's stdin from /dev/null. I'm totally confused. If you do "cat <foo", it will still close stdin momentarily before reopening it (which means that the "yes" process can get SIGPIPE in that instant).

Looking in the dash source code, this is very deliberate:

  $ sed -n 838,840p jobs.c
   * When job control is turned off, background processes have their standard
   * input redirected to /dev/null (except for the second and later processes
   * in a pipeline).

I can't find anything relevant in POSIX. But I don't really see a way to work around this. The cat _has_ to be a background job. So I think we are stuck with a solution like your custom C wrapper.

As an aside, though, does it really make sense for git-daemon to respect SIGPIPE? Under what circumstance would that actually be useful? So we should perhaps fix that, too. But even if we do so, it's nice for our test script to robustly report the actual stderr.

-Peff

Am 4/19/2012 8:03, schrieb Jeff King:

...

You don't have to be; it's mandated by POSIX:

http://pubs.opengroup.org/onlinepubs/9699919799/utilities/V3_chap02.html#tag_18_09_03_02

-- Hannes

Sorry for the delayed response.

Thanks for the pointer; I looked in POSIX but couldn't find that passage. It does say "In all cases, explicit redirection of standard input shall override this activity". It looks like dash interprets that as "open /dev/null, then open the redirected stdin". Which leaves a race condition. So I think a custom wrapper like the one posted by Clemens is our only portable option.

As an aside, should git-daemon be respecting SIGPIPE at all? It seems pointless at best, as it should be checking all of its writes, and a liability at worst, as something like failing to log to stderr can kill the whole process.

(Ignoring SIGPIPE would downgrade the severity of this problem, but I
think we would still want Clemens' solution. Otherwise the error output in the test could be truncated).

-Peff

Am 26.04.2012 15:01, schrieb Jeff King:

I don't see a race condition. The specs are clear: First redirect stdin to /dev/null, and if there are other redirections, apply them later. But in our code we have only:

	cat >&4 &

i.e., there are no other redirections. It does not matter that the whole block where this command occurs is redirected from git_daemon_output; that redirection was applied before the command was executed, and it was already overridden by the implicit /dev/null redirection.

I don't think so. How about this?

index ef2d01f..7245ab3 100644
@@ -30,10 +30,10 @@ start_git_daemon() {
 		"$@" "$GIT_DAEMON_DOCUMENT_ROOT_PATH" \
 		>&3 2>git_daemon_output &
 	GIT_DAEMON_PID=$!
+	exec 7<git_daemon_output &&
 	{
-		read line
+		read line <&7
 		echo >&4 "$line"
-		cat >&4 &
 
 		# Check expected output
 		if test x"$(expr "$line" : "\[[0-9]*\] \(.*\)")" != x"Ready to rumble"

@@ -43,7 +43,9 @@ start_git_daemon() {
 			trap 'die' EXIT
 			error "git daemon failed to start"
 		fi
-	} <git_daemon_output
+		cat <&7 >&4 &
+		exec 7<&-
+	}
 }
 
 stop_git_daemon() {

i.e., we open the readable end of the pipe in the shell, and dup it from there to 'read' and later to 'cat'. Finally, we can close it, because 'cat' has it still open in the background.

This works with dash, bash, and (half-way through) ksh. (The failure with ksh is an unrelated problem.)

-- Hannes

The shell function that starts git-daemon wants to read the first line of the daemon's stderr to ensure that it started correctly. Subsequent daemon errors should be redirected to fd 4 (which is the terminal in verbose mode or /dev/null in quiet mode). To that end the shell script used 'read' to get the first line of output, and then 'cat &' to forward everything else in a background process.

The problem is, that 'cat >&4 &' does not produce any output because the shell redirects a background process's stdin to /dev/null. To have this command invocation do anything useful, we have to redirect its stdin explicitly (which overrides the /dev/null redirection).

The shell function connects the daemon's stderr to its consumers via a FIFO. We cannot just do this:

read line <git_daemon_output
cat <git_daemon_output >&4 &

because after the first redirection the pipe is closed and the daemon could receive SIGPIPE if it writes at the wrong moment. Therefore, we open the readable end of the FIFO only once on fd 7 in the shell and dup from there to the stdin of the two consumers.

---
Am 26.04.2012 21:55, schrieb Clemens Buchacher:

How about this?

 t/lib-git-daemon.sh |   22 +++++++++++-----------
 1 file changed, 11 insertions(+), 11 deletions(-)

index ef2d01f..87f0ad8 100644
@@ -31,19 +31,19 @@ start_git_daemon() {
 		>&3 2>git_daemon_output &
 	GIT_DAEMON_PID=$!
 	{
-		read line
+		read line <&7
 		echo >&4 "$line"
-		cat >&4 &
+		cat <&7 >&4 &
+	} 7<git_daemon_output &&
 
-		# Check expected output
-		if test x"$(expr "$line" : "\[[0-9]*\] \(.*\)")" != x"Ready to rumble"
-		then
-			kill "$GIT_DAEMON_PID"
-			wait "$GIT_DAEMON_PID"
-			trap 'die' EXIT
-			error "git daemon failed to start"
-		fi
-	} <git_daemon_output
+	# Check expected output
+	if test x"$(expr "$line" : "\[[0-9]*\] \(.*\)")" != x"Ready to rumble"
+	then
+		kill "$GIT_DAEMON_PID"
+		wait "$GIT_DAEMON_PID"
+		trap 'die' EXIT
+		error "git daemon failed to start"
+	fi
 }
 
 stop_git_daemon() {

1.7.10.4.g51807

Beautiful explanation. Thanks!
I can confirm that this fix works for me.

-
Zbyszek

Very clearly explained and fixed; thanks.

Will replace cb/daemon-test-race-fix and queue.

One of the proposed solutions was:

  {
    read line
    cat <fifo &
  } <fifo

which I think can end up with this race:

1. shell opens pipe, reads line

2. shell forks for 'cat' process

3. parent shell sees that cat is to be backgrounded, so it does not wait for cat to finish, ends {} block, and closes pipe

4. forked shell process re-opens stdin from /dev/null

5. nobody has the fifo open, so a writer may get SIGPIPE

6. forked shell process re-opens stdin from the fifo

Yes. But it also fails sometimes with the solution above, in which we explicitly redirect from the fifo. The issue is not that we redirect from /dev/null in the long term, but that there is a moment where we have closed the old stdin and not yet opened the new one.

Yes, I believe this will work reliably. Though there is one subtle thing happening. At first glance, I thought you might have the same race I mentioned above; there's no guarantee that the shell subprocess has actually set up its stdin before your "exec 7<&-" runs. But because the subprocess has inherited descriptor 7, and because it never explicitly closes descriptor 7 (as it does for descriptor 0 while setting up the command's redirections), the pipe is always open. As fd 7 before exec'ing cat, and as both 7 and 0 afterwards.

So I think you could even get rid of your "exec" lines entirely, and just do:

  {
    read line <&7
    cat <&7 &
  } 7<git_daemon_output

That works reliably for me with this test:

  mkfifo fd
  yes >fd &
  pid=$!
  {
    read line
    echo $line
    wc <fd &
  } <fd
  sleep 1
  kill $pid
  wait $pid
  rm -f fd

which fails for me about one-third of the time in the form above, but works if you replace the middle part with:

  {
    read line <&7
    echo $line
    wc <&7 &
  } 7<fd

(This is the same thing the test script is doing, but it exercises the race much better because "yes" is constantly writing output).

Thanks for a clever solution. This is much better than doing something custom in C.

-Peff

Sorry, I think one of the "both" you mean is 7122c9e (git-daemon wrapper to wait until daemon is ready, 2012-04-15), but which one is "the other one" (which I should discard)?

I believe he is referring to 1bcb0ab4 (t5570: use explicit push refspec), which is also necessary to run the tests on pu.

Exactly.

-
Zbyszek

Thanks both for clarifications..