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

Signed-off-by: Zbigniew Jędrzejewski-Szmek <zbyszek@in.waw.pl>
---
 t/lib-git-daemon.sh |    5 +++--
 1 file changed, 3 insertions(+), 2 deletions(-)

On Sat, Apr 14, 2012 at 10:44:30AM +0200, Zbigniew Jędrzejewski-Szmek wrote:

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

On Sat, Apr 14, 2012 at 02:13:58PM +0200, Clemens Buchacher wrote:

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

On 04/14/2012 02:21 PM, Clemens Buchacher wrote:

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

Zbigniew Jędrzejewski-Szmek  <zbyszek@in.waw.pl> writes:

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)?

On Mon, Apr 16, 2012 at 10:09:08AM -0700, Junio C Hamano wrote:

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

On 04/16/2012 11:22 PM, Clemens Buchacher wrote:

Exactly.

- Zbyszek

Zbigniew Jędrzejewski-Szmek <zbyszek@in.waw.pl> writes:

Thanks both for clarifications..

On Mon, Apr 16, 2012 at 05:43:11PM +0200, Zbigniew Jędrzejewski-Szmek wrote:

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

On Mon, Apr 16, 2012 at 01:42:30PM -0400, Jeff King wrote:

Yes, me too. I can reproduce reliably with dash and the above fixes it reliably.

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.

On Tue, Apr 17, 2012 at 12:44:25AM +0200, Clemens Buchacher wrote:

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

On Thu, Apr 19, 2012 at 08:58:01AM +0200, Johannes Sixt wrote:

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?

On Thu, Apr 26, 2012 at 08:16:37PM +0200, Johannes Sixt wrote:

I won't pretend to understand why this works. I have to study this some more. But if this is 'correct', then it is obviously preferable to the comparatively complicated wrapper.

We should move the cat <&7 >&4 & and exec 7<&- part in front of the output check, otherwise output would be truncated in an error condition. This can be tested by passing an invalid argument to git daemon above, for example.

Clemens

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.

Signed-off-by: Johannes Sixt <j6t@kdbg.org>
---
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(-)

On 04/26/2012 11:00 PM, Johannes Sixt wrote:

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

- Zbyszek

On Thu, Apr 26, 2012 at 11:00:39PM +0200, Johannes Sixt wrote:

Argh. I didn't notice your patch yet when I wrote my previous reply, and ended up rediscovering your analysis and the final form of the solution.

So please disregard my prior email, and consider this:

  Acked-by: Jeff King <peff@peff.net>

-Peff

Johannes Sixt <j6t@kdbg.org> writes:

Very clearly explained and fixed; thanks.

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

On Thu, Apr 26, 2012 at 08:16:37PM +0200, Johannes Sixt wrote:

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