threads / patch / 1904

patchVerbose git-daemon logging

Subject: [PATCH] Verbose git-daemon logging

## tl;dr

6 messages between Sep 21, 2005 and Sep 23, 2005. Diffs are folded; open one to read it.

replies: 5people: 4as markdown or json

Petr Baudis· Sep 21, 2005, 21:39 UTC · lore

This patch makes git-daemon --verbose log some useful things on stderr - in particular connects, disconnects and upload requests, and in such a way to be able to trace a particular session. Some more errors are now also logged (even when --verbose is not passed). It is still not perfect since messages produced by the non-daemon-specific code are obviously not formatted properly.

Signed-off-by: Petr Baudis <pasky@suse.cz>

--- commit 419408cb9545495cd542d18219598c318f91007d tree da6735878367946edae024c76e6f8165f82cfe07 parent ff0b3368b45a07ac080574eb721a607892413b99 author Petr Baudis <pasky@suse.cz> Wed, 21 Sep 2005 23:36:20 +0200 committer Petr Baudis <xpasky@machine.(none)> Wed, 21 Sep 2005 23:36:20 +0200

 daemon.c |   78 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++---
 1 files changed, 74 insertions(+), 4 deletions(-)

Show changes to daemon.c +74 −4

diff --git a/daemon.c b/daemon.c
--- a/daemon.c
+++ b/daemon.c
@@ -6,13 +6,54 @@
 #include <sys/time.h>
 #include <netdb.h>
 #include <netinet/in.h>
+#include <arpa/inet.h>
+
+static int verbose;
+
+static const char daemon_usage[] = "git-daemon [--verbose] [--inetd | --port=n]";
+
+
+static void logreport(const char *err, va_list params)
+{
+	/* We should do a single write so that it is atomic and output
+	 * of several threads does not get intermangled. */
+	char buf[1024];
+	int buflen;
+
+	buflen = snprintf(buf, 1024, "[%d] ", getpid());
+	buflen += vsnprintf(buf + buflen, 1024 - buflen, err, params);
+	buf[buflen++] = '\n';
+	buf[buflen] = '\0';
+
+	fputs(buf, stderr);
+}
+
+void logerror(const char *err, ...)
+{
+	va_list params;
+	va_start(params, err);
+	logreport(err, params);
+	va_end(params);
+}
+
+void lognotice(const char *err, ...)
+{
+	va_list params;
+	if (!verbose)
+		return;
+	va_start(params, err);
+	logreport(err, params);
+	va_end(params);
+}
 
-static const char daemon_usage[] = "git-daemon [--inetd | --port=n]";
 
 static int upload(char *dir, int dirlen)
 {
-	if (chdir(dir) < 0)
+	lognotice("Request for '%s'", dir);
+	if (chdir(dir) < 0) {
+		logerror("Cannot chdir('%s'): %s", dir, strerror(errno));
 		return -1;
+	}
 	chdir(".git");
 
 	/*
@@ -24,8 +65,10 @@ static int upload(char *dir, int dirlen)
 	 */
 	if (access("git-daemon-export-ok", F_OK) ||
 	    access("objects/00", X_OK) ||
-	    access("HEAD", R_OK))
+	    access("HEAD", R_OK)) {
+		logerror("Not a valid gitd-enabled repository: '%s'", dir);
 		return -1;
+	}
 
 	/*
 	 * We'll ignore SIGTERM from now on, we have a
@@ -51,7 +94,7 @@ static int execute(void)
 	if (!strncmp("git-upload-pack /", line, 17))
 		return upload(line + 16, len - 16);
 
-	fprintf(stderr, "got bad connection '%s'\n", line);
+	logerror("Protocol error: '%s'", line);
 	return -1;
 }
 
@@ -181,6 +224,8 @@ static void check_max_connections(void)
 static void handle(int incoming, struct sockaddr *addr, int addrlen)
 {
 	pid_t pid = fork();
+	char addrbuf[256] = "";
+	int port = -1;
 
 	if (pid) {
 		unsigned idx;
@@ -200,6 +245,24 @@ static void handle(int incoming, struct 
 	dup2(incoming, 0);
 	dup2(incoming, 1);
 	close(incoming);
+
+	if (addr->sa_family == AF_INET) {
+		struct sockaddr_in *sin_addr = (void *) addr;
+		inet_ntop(AF_INET, &sin_addr->sin_addr, addrbuf, sizeof(addrbuf));
+		port = sin_addr->sin_port;
+
+	} else if (addr->sa_family == AF_INET6) {
+		struct sockaddr_in6 *sin6_addr = (void *) addr;
+
+		char *buf = addrbuf;
+		*buf++ = '['; *buf = '\0'; /* stpcpy() is cool */
+		inet_ntop(AF_INET6, &sin6_addr->sin6_addr, buf, sizeof(addrbuf) - 1);
+		strcat(buf, "]");
+
+		port = sin6_addr->sin6_port;
+	}
+	lognotice("Connection from %s:%d", addrbuf, port);
+
 	exit(execute());
 }
 
@@ -212,6 +275,9 @@ static void child_handler(int signo)
 			unsigned reaped = children_reaped;
 			dead_child[reaped % MAX_CHILDREN] = pid;
 			children_reaped = reaped + 1;
+			/* XXX: Custom logging, since we don't wanna getpid() */
+			if (verbose)
+				fprintf(stderr, "[%d] Disconnected\n", pid);
 			continue;
 		}
 		break;
@@ -349,6 +415,10 @@ int main(int argc, char **argv)
 			inetd_mode = 1;
 			continue;
 		}
+		if (!strcmp(arg, "--verbose")) {
+			verbose = 1;
+			continue;
+		}
 
 		usage(daemon_usage);
 	}

-- 
				Petr "Pasky" Baudis
Stuff: http://pasky.or.cz/
VI has two modes: the one in which it beeps and the one in which
it doesn't.

Junio C Hamano· Sep 22, 2005, 08:52 UTC · re: Petr Baudis · lore

Re: [PATCH] Verbose git-daemon logging

Overall looks very informative to me. Couple of points, although your patch was not directly addressed to me... ;-).

> +static void logreport(const char *err, va_list params)
> +{
> +	/* We should do a single write so that it is atomic and output
> +	 * of several threads does not get intermangled. */

"threads"?  Nevertheless yes it is nicer to do a single write.

> +	char buf[1024];
> +	int buflen;
> +
> +	buflen = snprintf(buf, 1024, "[%d] ", getpid());

sizeof(buf)?

> +	buflen += vsnprintf(buf + buflen, 1024 - buflen, err, params);

vsnprintf() would return number of characters that would have been written if the buffer were sufficiently long, so buflen can grow outside buf[]. I could ask for a deeeeeeeeeeep directory to git-daemon, have it say "Request for 'diiiiiiiiiiiiii....r'", and have this code

> +	buf[buflen++] = '\n';
> +	buf[buflen] = '\0';

overwrite the stack with these two bytes; overwriting with constant bytes may or may not be exploitable, though.

Also the man page says glibc 2.0.6 returned -1 upon output truncation. Do we care?

Show 7 quoted lines

> @@ -212,6 +275,9 @@ static void child_handler(int signo)
>  			unsigned reaped = children_reaped;
>  			dead_child[reaped % MAX_CHILDREN] = pid;
>  			children_reaped = reaped + 1;
> +			/* XXX: Custom logging, since we don't wanna getpid() */
> +			if (verbose)
> +				fprintf(stderr, "[%d] Disconnected\n", pid);

"we don't wanna getpid()" because the guy reporting is the parent? I would presume knowing parent PID would also useful, so maybe we could say "[1012] child 1014 disconnected\n" for parent 1012 reaping chilid 1014?

Petr Baudis· Sep 22, 2005, 09:25 UTC · re: Junio C Hamano · lore

Re: [PATCH] Verbose git-daemon logging

Dear diary, on Thu, Sep 22, 2005 at 10:52:18AM CEST, I got a letter where Junio C Hamano <junkio@cox.net> told me that...

Show 6 quoted lines

> > +static void logreport(const char *err, va_list params)
> > +{
> > +	/* We should do a single write so that it is atomic and output
> > +	 * of several threads does not get intermangled. */
> 
> "threads"?  Nevertheless yes it is nicer to do a single write.

Ok, perhaps the "threads" name is not so appropriate after all. It looked so cute in the sentence... ;-)

Show 6 quoted lines

> > +	char buf[1024];
> > +	int buflen;
> > +
> > +	buflen = snprintf(buf, 1024, "[%d] ", getpid());
> 
> sizeof(buf)?

Ack.

Show 13 quoted lines

> > +	buflen += vsnprintf(buf + buflen, 1024 - buflen, err, params);
> 
> vsnprintf() would return number of characters that would have
> been written if the buffer were sufficiently long, so buflen can
> grow outside buf[].  I could ask for a deeeeeeeeeeep directory
> to git-daemon, have it say "Request for 'diiiiiiiiiiiiii....r'",
> and have this code
> 
> > +	buf[buflen++] = '\n';
> > +	buf[buflen] = '\0';
> 
> overwrite the stack with these two bytes; overwriting with
> constant bytes may or may not be exploitable, though.

Whoops.

Hm, the vsnprintf() code ended up more complicated that I'd have liked. Well, I hope I got it right now. :-)

> Also the man page says glibc 2.0.6 returned -1 upon output
> truncation.  Do we care?

If we do, there seems to be like 10 other places in the code where we need to fix that.

Show 12 quoted lines

> > @@ -212,6 +275,9 @@ static void child_handler(int signo)
> >  			unsigned reaped = children_reaped;
> >  			dead_child[reaped % MAX_CHILDREN] = pid;
> >  			children_reaped = reaped + 1;
> > +			/* XXX: Custom logging, since we don't wanna getpid() */
> > +			if (verbose)
> > +				fprintf(stderr, "[%d] Disconnected\n", pid);
> 
> "we don't wanna getpid()" because the guy reporting is the
> parent?  I would presume knowing parent PID would also useful,
> so maybe we could say "[1012] child 1014 disconnected\n" for
> parent 1012 reaping chilid 1014?

What would be knowing parent PID be useful for? (It's not really the PID number that's useful anyway (at least mostly), it's just a good unique identifier to distinguish between several simultaneous sessions.)

The way it is now, it is consistent and all messages concerning lifetime of one session have that session ID prepended. Otherwise not only a mechanical parser would be more complicated, but also visual inspection would be more demanding.

Fixed up patch follows.

--

[PATCH] Verbose git-daemon logging

Signed-off-by: Petr Baudis <pasky@suse.cz>

--- commit ebb97336b876ebc56b60fe8381c8d0145c0e47d0 tree e2234a568608743889a36750ae11ea4d00e9a7b4 parent ff0b3368b45a07ac080574eb721a607892413b99 author Petr Baudis <pasky@suse.cz> Thu, 22 Sep 2005 11:24:07 +0200 committer Petr Baudis <xpasky@machine.(none)> Thu, 22 Sep 2005 11:24:07 +0200

 daemon.c |   87 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++---
 1 files changed, 83 insertions(+), 4 deletions(-)

Show changes to daemon.c +83 −4

diff --git a/daemon.c b/daemon.c
--- a/daemon.c
+++ b/daemon.c
@@ -6,13 +6,63 @@
 #include <sys/time.h>
 #include <netdb.h>
 #include <netinet/in.h>
+#include <arpa/inet.h>
+
+static int verbose;
+
+static const char daemon_usage[] = "git-daemon [--verbose] [--inetd | --port=n]";
+
+
+static void logreport(const char *err, va_list params)
+{
+	/* We should do a single write so that it is atomic and output
+	 * of several processes does not get intermangled. */
+	char buf[1024];
+	int buflen;
+	int maxlen, msglen;
+
+	buflen = snprintf(buf, sizeof(buf), "[%d] ", getpid());
+
+	maxlen = sizeof(buf) - buflen - 1;
+	msglen = vsnprintf(buf + buflen, maxlen, err, params);
+	if (msglen > maxlen)
+		msglen = maxlen;
+	else if (msglen < 0)
+		msglen = -1; /* Protect against weird return values. */
+	buflen += msglen;
+
+	buf[buflen++] = '\n';
+	buf[buflen] = '\0';
+
+	fputs(buf, stderr);
+}
+
+void logerror(const char *err, ...)
+{
+	va_list params;
+	va_start(params, err);
+	logreport(err, params);
+	va_end(params);
+}
+
+void lognotice(const char *err, ...)
+{
+	va_list params;
+	if (!verbose)
+		return;
+	va_start(params, err);
+	logreport(err, params);
+	va_end(params);
+}
 
-static const char daemon_usage[] = "git-daemon [--inetd | --port=n]";
 
 static int upload(char *dir, int dirlen)
 {
-	if (chdir(dir) < 0)
+	lognotice("Request for '%s'", dir);
+	if (chdir(dir) < 0) {
+		logerror("Cannot chdir('%s'): %s", dir, strerror(errno));
 		return -1;
+	}
 	chdir(".git");
 
 	/*
@@ -24,8 +74,10 @@ static int upload(char *dir, int dirlen)
 	 */
 	if (access("git-daemon-export-ok", F_OK) ||
 	    access("objects/00", X_OK) ||
-	    access("HEAD", R_OK))
+	    access("HEAD", R_OK)) {
+		logerror("Not a valid gitd-enabled repository: '%s'", dir);
 		return -1;
+	}
 
 	/*
 	 * We'll ignore SIGTERM from now on, we have a
@@ -51,7 +103,7 @@ static int execute(void)
 	if (!strncmp("git-upload-pack /", line, 17))
 		return upload(line + 16, len - 16);
 
-	fprintf(stderr, "got bad connection '%s'\n", line);
+	logerror("Protocol error: '%s'", line);
 	return -1;
 }
 
@@ -181,6 +233,8 @@ static void check_max_connections(void)
 static void handle(int incoming, struct sockaddr *addr, int addrlen)
 {
 	pid_t pid = fork();
+	char addrbuf[256] = "";
+	int port = -1;
 
 	if (pid) {
 		unsigned idx;
@@ -200,6 +254,24 @@ static void handle(int incoming, struct 
 	dup2(incoming, 0);
 	dup2(incoming, 1);
 	close(incoming);
+
+	if (addr->sa_family == AF_INET) {
+		struct sockaddr_in *sin_addr = (void *) addr;
+		inet_ntop(AF_INET, &sin_addr->sin_addr, addrbuf, sizeof(addrbuf));
+		port = sin_addr->sin_port;
+
+	} else if (addr->sa_family == AF_INET6) {
+		struct sockaddr_in6 *sin6_addr = (void *) addr;
+
+		char *buf = addrbuf;
+		*buf++ = '['; *buf = '\0'; /* stpcpy() is cool */
+		inet_ntop(AF_INET6, &sin6_addr->sin6_addr, buf, sizeof(addrbuf) - 1);
+		strcat(buf, "]");
+
+		port = sin6_addr->sin6_port;
+	}
+	lognotice("Connection from %s:%d", addrbuf, port);
+
 	exit(execute());
 }
 
@@ -212,6 +284,9 @@ static void child_handler(int signo)
 			unsigned reaped = children_reaped;
 			dead_child[reaped % MAX_CHILDREN] = pid;
 			children_reaped = reaped + 1;
+			/* XXX: Custom logging, since we don't wanna getpid() */
+			if (verbose)
+				fprintf(stderr, "[%d] Disconnected\n", pid);
 			continue;
 		}
 		break;
@@ -349,6 +424,10 @@ int main(int argc, char **argv)
 			inetd_mode = 1;
 			continue;
 		}
+		if (!strcmp(arg, "--verbose")) {
+			verbose = 1;
+			continue;
+		}
 
 		usage(daemon_usage);
 	}

-- 
				Petr "Pasky" Baudis
Stuff: http://pasky.or.cz/
VI has two modes: the one in which it beeps and the one in which
it doesn't.

Junio C Hamano· Sep 22, 2005, 23:42 UTC · re: Petr Baudis · lore

Re: [PATCH] Verbose git-daemon logging

Petr Baudis <pasky@suse.cz> writes:

> What would be knowing parent PID be useful for? (It's not really the PID
> number that's useful anyway (at least mostly), it's just a good unique
> identifier to distinguish between several simultaneous sessions.)

Maybe running two daemons serving two sets of repos? But anyway what you have look more consistent so let's keep that.

> Fixed up patch follows.

Thanks.

Show 23 quoted lines

> +static void logreport(const char *err, va_list params)
> +{
> +	/* We should do a single write so that it is atomic and output
> +	 * of several processes does not get intermangled. */
> +	char buf[1024];
> +	int buflen;
> +	int maxlen, msglen;
> +
> +	buflen = snprintf(buf, sizeof(buf), "[%d] ", getpid());
> +
> +	maxlen = sizeof(buf) - buflen - 1;
> +	msglen = vsnprintf(buf + buflen, maxlen, err, params);
> +	if (msglen > maxlen)
> +		msglen = maxlen;
> +	else if (msglen < 0)
> +		msglen = -1; /* Protect against weird return values. */
> +	buflen += msglen;
> +
> +	buf[buflen++] = '\n';
> +	buf[buflen] = '\0';
> +
> +	fputs(buf, stderr);
> +}

The tail part still looks odd here.  Maybe something like this?

+static void logreport(const char *err, va_list params) +{ + /* We should do a single write so that it is atomic and output + * of several processes does not get intermangled. */ + char buf[1024]; + int buflen; + int maxlen, msglen; + + /* sizeof(buf) should be big enough for "[pid] \n" */ + buflen = snprintf(buf, sizeof(buf), "[%d] ", getpid()); + + maxlen = sizeof(buf) - buflen - 1; /* -1 for our own LF */ + msglen = vsnprintf(buf + buflen, maxlen, err, params); + + /* maxlen counted our own LF but also counts space given to + * vsnprintf for the terminating NUL. We want to make sure that + * we have space for our own LF and NUL after the "meat" of the + * message, so truncate it at maxlen - 1. + */ + if (msglen > maxlen - 1) + msglen = maxlen - 1; + else if (msglen < 0) + msglen = 0; /* Protect against weird return values. */ + buflen += msglen; + + buf[buflen++] = '\n'; + buf[buflen] = '\0'; + + fputs(buf, stderr); +}

Linus Torvalds· Sep 22, 2005, 23:58 UTC · re: Junio C Hamano · lore

Re: [PATCH] Verbose git-daemon logging

On Thu, 22 Sep 2005, Junio C Hamano wrote:

> 
> The tail part still looks odd here.  Maybe something like this?

And if you actually want it to be more reliable, don't use fputs. That can still split lines, and even if it doesn't, it doesn't help.

> +	buf[buflen++] = '\n';
> +	buf[buflen] = '\0';
> +
> +	fputs(buf, stderr);

Why use "fputs()", when you migth as well do write()?

Also, it would probably be nice if you allow the use of syslog()..

		Linus

Morten Welinder· Sep 23, 2005, 12:08 UTC · re: Petr Baudis · lore

Re: [PATCH] Verbose git-daemon logging

> +       buflen = snprintf(buf, 1024, "[%d] ", getpid());

pid_t is not int.

Please cast it to int, or use %ld and cast it to long int.

Morten