Non-inetd git-daemon hangs in syslog(3)/fclose(3) if --syslog --verbose accessing non-repositories

 I've seen several reports of what seems to be the following
 problem, but no fixes.  I do not understand the root-cause.
 I have found, however, what seems to be a work-around.

 I'm starting v1.5.2.5 (the Kubuntu 7.10 package) git-daemon
 (as a normal-user, *not* super-user) as:

     export GIT_TRACE=/tmp/LOG-git-daemon
     exec  \
        git daemon --detach --syslog --verbose --base-path=/pub/scm

 The repositories being served are simple (non-bare) clones,
 with nothing strange/weird.  The remote machine (CentOS),
 running a self-built un-modified v1.5.5, can access them Ok:

     $ git ls-remote git://SERVER/repo
     ... works ...
     $ 

 However, an invalid path causes both the git-daemon and the
 client to hang (I'm too impatient and do not know if either
 times out):

     $ git ls-remote git://SERVER/repo/garbage
     ... hangs ...

 I can ^C the client, but the server is still hung, and will
 not respond to *any* requests.  I must kill the git-daemon.
 The GIT_TRACE log's contents do not seem to be interesting.
 The last entries in the syslog are:

     git-daemon: [3705] Connection from <REMOTE>
     git-daemon: [3705] Extended attributes (17 bytes) exist <...>
     git-daemon: [3705] Request upload-pack for '/repo/garbage'
     git-daemon: [3705] '/pub/scm/repo/garbage': unable to chdir or not a git archive

 Annoyingly, strace(1)ing git-daemon causes the problem to
 vanish!  Everything then seems to be work as expected.
 But now the syslog contains an additional, 5th, line:

     git-daemon: [3705] Disconnected (with error)

 (The "with error" is present only in the .../garbage case.)

 Attaching to a hung git-daemon with strace shows that it's
 hung in futex(2):

     $ strace -p3705
     Process 3705 attached - interrupt to quit
     futex(0x2b502cbf3980, FUTEX_WAIT, 2, NULL <unfinished ...>
     ... hangs ...

 Attaching to a hung git-daemon with gdb(1) results in the
 following backtrace:

     (gdb) where
     #0  0x00002b502c97d1d8 in ?? () from /lib/libc.so.6
     #1  0x00002b502c913698 in ?? () from /lib/libc.so.6
     #2  0x00002b502c912960 in realloc () from /lib/libc.so.6
     #3  0x00002b502c905eb4 in ?? () from /lib/libc.so.6
     #4  0x00002b502c8fd897 in fclose () from /lib/libc.so.6
     #5  0x00002b502c96d371 in __vsyslog_chk () from /lib/libc.so.6
     #6  0x00002b502c96d8a0 in syslog () from /lib/libc.so.6
     #7  0x0000000000403896 in ?? ()
     #8  <signal handler called>
     #9  0x00002b502c9373ab in fork () from /lib/libc.so.6
     #10 0x0000000000404443 in ?? ()
     #11 0x0000000000404c99 in ?? ()
     #12 0x00002b502c8bab44 in __libc_start_main () from /lib/libc.so.6
     #13 0x0000000000403179 in ?? ()
     #14 0x00007fff7e63eab8 in ?? ()
     #15 0x0000000000000000 in ?? ()
     (gdb) 

 It's fairly clear it's hung doing the syslog(3) of the (missing)
 "Disconnected (with error)" message.  A interesting point is the
 SIGCHLD handler in (git-)daemon.c appears to have been called
 before the parent's fork(2) returned.  I presume there is a race
 here, but admit I do not see it.  This (broadly) makes sense; the
 server is a Very Fast machine.  And strace'ing slows things down.

 The workaround is to omit --verbose and hence never try to syslog
 the "Disconnected ..." message.

cheers!
	-blf-

-- 
“How many surrealists does it take to   | Brian Foster
 change a lightbulb? Three. One calms   | somewhere in south of France
 the warthog, and two fill the bathtub  |   Stop E$$o (ExxonMobil)!
 with brightly-coloured machine tools.” |      http://www.stopesso.com

Hi,

On Thu, 3 Jul 2008, Brian Foster wrote:

 I've seen several reports of what seems to be the following
 problem, but no fixes.

[describes that git-daemon -v syslog()s in a signal handler, which is 
 unsupported]

I reported this bug earlier, and my workaround was to comment out the 
syslog() in the signal handler, but I have no real fix for that, either.

Unfortunately, the wise people on this list did not have an idea either, 
at least they did not share it with me.

Ciao,
Dscho

On Thursday 03 July 2008 Johannes Schindelin wrote:

On Thu, 3 Jul 2008, Brian Foster wrote:

quoted

[... describes that git-daemon -v syslog()s in a signal handler,
 which is unsupported ...]

I reported this bug earlier [ ... ]

 Ah, yes, I've (now) found the (long!) thread,
 about log-rotation (which, as you observe, is
 not the problem).  Sorry for the duplication.

cheers!
	-blf-

-- 
“How many surrealists does it take to   | Brian Foster
 change a lightbulb? Three. One calms   | somewhere in south of France
 the warthog, and two fill the bathtub  |   Stop E$$o (ExxonMobil)!
 with brightly-coloured machine tools.” |      http://www.stopesso.com

Hi,

On Thu, 3 Jul 2008, Brian Foster wrote:

On Thursday 03 July 2008 Johannes Schindelin wrote:

quoted

On Thu, 3 Jul 2008, Brian Foster wrote:

quoted

[... describes that git-daemon -v syslog()s in a signal handler,
 which is unsupported ...]

I reported this bug earlier [ ... ]

 Ah, yes, I've (now) found the (long!) thread, about log-rotation 
 (which, as you observe, is not the problem).

Yeah, sorry, should have mentioned that.

Sorry for the duplication.

No need to be sorry.  It may raise awareness so much that somebody gets a 
clever idea how to cope with it.

Ciao,
Dscho

Signal handlers should never call syslog(), as that can raise signals
of its own.

Instead, call the syslog() from the master process.

Signed-off-by: Johannes Schindelin <redacted>
---

	On Thu, 3 Jul 2008, Johannes Schindelin wrote:

	> It may raise awareness so much that somebody gets a clever idea 
	> how to cope with it.

	Okay, it might not be clever, but I think this is pretty 
	straight-forward.

	However, this part of the code is tricky, as it can (and will) be 
	interrupted by signal handlers, so I would appreciate several 
	careful reviews (but maybe it is not necessary to ask for it, 
	since I am no longer trusted).

 daemon.c |   61 +++++++++++++++++++++++++++++++++++++++++--------------------
 1 files changed, 41 insertions(+), 20 deletions(-)

diff --git a/daemon.c b/daemon.c
index 63cd12c..35fd439 100644
--- a/daemon.c
+++ b/daemon.c

@@ -694,23 +694,47 @@ static void kill_some_children(int signo, unsigned start, unsigned stop)
 	}
 }
 
+static void check_dead_children(void)
+{
+	unsigned spawned, reaped, deleted;
+
+	spawned = children_spawned;
+	reaped = children_reaped;
+	deleted = children_deleted;
+
+	while (deleted < reaped) {
+		pid_t pid = dead_child[deleted % MAX_CHILDREN];
+		const char *dead = pid < 0 ? " (with error)" : "";
+
+		if (pid < 0)
+			pid = -pid;
+
+		/* XXX: Custom logging, since we don't wanna getpid() */
+		if (verbose) {
+			if (log_syslog)
+				syslog(LOG_INFO, "[%d] Disconnected%s",
+						pid, dead);
+			else
+				fprintf(stderr, "[%d] Disconnected%s\n",
+						pid, dead);
+		}
+		remove_child(pid, deleted, spawned);
+		deleted++;
+	}
+	children_deleted = deleted;
+}
+
 static void check_max_connections(void)
 {
 	for (;;) {
 		int active;
-		unsigned spawned, reaped, deleted;
+		unsigned spawned, deleted;
+
+		check_dead_children();
 
 		spawned = children_spawned;
-		reaped = children_reaped;
 		deleted = children_deleted;
 
-		while (deleted < reaped) {
-			pid_t pid = dead_child[deleted % MAX_CHILDREN];
-			remove_child(pid, deleted, spawned);
-			deleted++;
-		}
-		children_deleted = deleted;
-
 		active = spawned - deleted;
 		if (active <= max_connections)
 			break;

@@ -760,18 +784,10 @@ static void child_handler(int signo)
 
 		if (pid > 0) {
 			unsigned reaped = children_reaped;
+			if (!WIFEXITED(status) || WEXITSTATUS(status) > 0)
+				pid = -pid;
 			dead_child[reaped % MAX_CHILDREN] = pid;
 			children_reaped = reaped + 1;
-			/* XXX: Custom logging, since we don't wanna getpid() */
-			if (verbose) {
-				const char *dead = "";
-				if (!WIFEXITED(status) || WEXITSTATUS(status) > 0)
-					dead = " (with error)";
-				if (log_syslog)
-					syslog(LOG_INFO, "[%d] Disconnected%s", pid, dead);
-				else
-					fprintf(stderr, "[%d] Disconnected%s\n", pid, dead);
-			}
 			continue;
 		}
 		break;

@@ -929,7 +945,8 @@ static int service_loop(int socknum, int *socklist)
 	for (;;) {
 		int i;
 
-		if (poll(pfd, socknum, -1) < 0) {
+		i = poll(pfd, socknum, 1);
+		if (i < 0) {
 			if (errno != EINTR) {
 				error("poll failed, resuming: %s",
 				      strerror(errno));

@@ -937,6 +954,10 @@ static int service_loop(int socknum, int *socklist)
 			}
 			continue;
 		}
+		if (i == 0) {
+			check_dead_children();
+			continue;
+		}
 
 		for (i = 0; i < socknum; i++) {
 			if (pfd[i].revents & POLLIN) {

-- 
1.5.6.1.376.g6b0fd