[PATCH] git-daemon: fix for rotating logs

[PATCH] git-daemon: fix for rotating logs

[Johannes Schindelin]

With rotating logs, there is a problem when the syslog is opened only once 
(in the beginning).  So open the log everytime we write something, and 
close it directly after writing.

Signed-off-by: Johannes Schindelin <johannes.schindelin@gmx.de>
---
 daemon.c |   11 +++++++----
 1 files changed, 7 insertions(+), 4 deletions(-)

diff --git a/daemon.c b/daemon.c
index 2b4a6f1..a887c72 100644
--- a/daemon.c
+++ b/daemon.c
@@ -90,7 +90,9 @@ static void logreport(int priority, const char *err, va_list params)
 	msglen = vsnprintf(buf + buflen, maxlen, err, params);
 
 	if (log_syslog) {
+		openlog("git-daemon", 0, LOG_DAEMON);
 		syslog(priority, "%s", buf);
+		closelog();
 		return;
 	}
 
@@ -767,8 +769,11 @@ static void child_handler(int signo)
 				const char *dead = "";
 				if (!WIFEXITED(status) || WEXITSTATUS(status) > 0)
 					dead = " (with error)";
-				if (log_syslog)
+				if (log_syslog) {
+					openlog("git-daemon", 0, LOG_DAEMON);
 					syslog(LOG_INFO, "[%d] Disconnected%s", pid, dead);
+					closelog();
+				}
 				else
 					fprintf(stderr, "[%d] Disconnected%s\n", pid, dead);
 			}
@@ -1149,10 +1154,8 @@ int main(int argc, char **argv)
 		usage(daemon_usage);
 	}
 
-	if (log_syslog) {
-		openlog("git-daemon", 0, LOG_DAEMON);
+	if (log_syslog)
 		set_die_routine(daemon_die);
-	}
 
 	if (inetd_mode && (group_name || user_name))
 		die("--user and --group are incompatible with --inetd");
-- 
1.5.4.4.GIT

Re: [PATCH] git-daemon: fix for rotating logs

[Junio C Hamano]

Johannes Schindelin <Johannes.Schindelin@gmx.de> writes:

> With rotating logs, there is a problem when the syslog is opened only once 
> (in the beginning).  So open the log everytime we write something, and 
> close it directly after writing.

Gaah, this is ugly.

Is this something all the daemons need to deal with?

> diff --git a/daemon.c b/daemon.c
> index 2b4a6f1..a887c72 100644
> --- a/daemon.c
> +++ b/daemon.c
> @@ -90,7 +90,9 @@ static void logreport(int priority, const char *err, va_list params)
>  	msglen = vsnprintf(buf + buflen, maxlen, err, params);
>  
>  	if (log_syslog) {
> +		openlog("git-daemon", 0, LOG_DAEMON);
>  		syslog(priority, "%s", buf);
> +		closelog();
>  		return;
>  	}

Re: [PATCH] git-daemon: fix for rotating logs

[Johannes Schindelin]

Hi,

On Mon, 28 Apr 2008, Junio C Hamano wrote:

> Johannes Schindelin <Johannes.Schindelin@gmx.de> writes:
> 
> > With rotating logs, there is a problem when the syslog is opened only 
> > once (in the beginning).  So open the log everytime we write 
> > something, and close it directly after writing.
> 
> Gaah, this is ugly.
> 
> Is this something all the daemons need to deal with?

I have no idea, but it seems to fix a real issue.

Ciao,
Dscho

Re: [PATCH] git-daemon: fix for rotating logs

[Miklos Vajna]

[-- Attachment #1: Type: text/plain, Size: 597 bytes --]

On Mon, Apr 28, 2008 at 07:08:50PM +0100, Johannes Schindelin <Johannes.Schindelin@gmx.de> wrote:
> > > With rotating logs, there is a problem when the syslog is opened only 
> > > once (in the beginning).  So open the log everytime we write 
> > > something, and close it directly after writing.
> > 
> > Gaah, this is ugly.
> > 
> > Is this something all the daemons need to deal with?
> 
> I have no idea, but it seems to fix a real issue.

logrotate supports sending a signal (typically SIGHUP) to the process
after it rotated the log. Couldn't we just re-open the log on SIGHUP?

[-- Attachment #2: Type: application/pgp-signature, Size: 197 bytes --]

Re: [PATCH] git-daemon: fix for rotating logs

[Mike Hommey]

On Mon, Apr 28, 2008 at 08:21:14PM +0200, Miklos Vajna wrote:
> On Mon, Apr 28, 2008 at 07:08:50PM +0100, Johannes Schindelin <Johannes.Schindelin@gmx.de> wrote:
> > > > With rotating logs, there is a problem when the syslog is opened only 
> > > > once (in the beginning).  So open the log everytime we write 
> > > > something, and close it directly after writing.
> > > 
> > > Gaah, this is ugly.
> > > 
> > > Is this something all the daemons need to deal with?
> > 
> > I have no idea, but it seems to fix a real issue.
> 
> logrotate supports sending a signal (typically SIGHUP) to the process
> after it rotated the log. Couldn't we just re-open the log on SIGHUP?

Isn't the problem that git-daemon loses its connection to the syslog
daemon when logrotate sighups syslog?

Mike

Re: [PATCH] git-daemon: fix for rotating logs

[Johannes Schindelin]

Hi,

On Mon, 28 Apr 2008, Mike Hommey wrote:

> On Mon, Apr 28, 2008 at 08:21:14PM +0200, Miklos Vajna wrote:
> > On Mon, Apr 28, 2008 at 07:08:50PM +0100, Johannes Schindelin <Johannes.Schindelin@gmx.de> wrote:
> > > > > With rotating logs, there is a problem when the syslog is opened 
> > > > > only once (in the beginning).  So open the log everytime we 
> > > > > write something, and close it directly after writing.
> > > > 
> > > > Gaah, this is ugly.
> > > > 
> > > > Is this something all the daemons need to deal with?
> > > 
> > > I have no idea, but it seems to fix a real issue.
> > 
> > logrotate supports sending a signal (typically SIGHUP) to the process 
> > after it rotated the log. Couldn't we just re-open the log on SIGHUP?
> 
> Isn't the problem that git-daemon loses its connection to the syslog 
> daemon when logrotate sighups syslog?

I have no idea, but other programs must have the same problem.  I should 
have shown some diligence and researched that.  Will do so now.

Ciao,
Dscho

Re: [PATCH] git-daemon: fix for rotating logs

[Miklos Vajna]

[-- Attachment #1: Type: text/plain, Size: 558 bytes --]

On Mon, Apr 28, 2008 at 07:37:54PM +0100, Johannes Schindelin <Johannes.Schindelin@gmx.de> wrote:
> > Isn't the problem that git-daemon loses its connection to the syslog 
> > daemon when logrotate sighups syslog?

Right, but logrotate could send SIGHUP to git-daemon as well.

> I have no idea, but other programs must have the same problem.  I should 
> have shown some diligence and researched that.  Will do so now.

I don't say that just one example justifies me, but here is an example:
icald (google://openlog+sighup 2nd result) does this.

[-- Attachment #2: Type: application/pgp-signature, Size: 197 bytes --]

Re: [PATCH] git-daemon: fix for rotating logs

[Johannes Schindelin]

Hi,

On Mon, 28 Apr 2008, Miklos Vajna wrote:

> On Mon, Apr 28, 2008 at 07:37:54PM +0100, Johannes Schindelin <Johannes.Schindelin@gmx.de> wrote:
> > > Isn't the problem that git-daemon loses its connection to the syslog 
> > > daemon when logrotate sighups syslog?
> 
> Right, but logrotate could send SIGHUP to git-daemon as well.

Probably.  But I do not understand how git-daemon just hangs when trying 
to close() something from within syslog().  Maybe my analysis is 
completely wrong, and I should do something completely different.

Ciao,
Dscho

Re: [PATCH] git-daemon: fix for rotating logs

[Stephen R. van den Berg]

Miklos Vajna wrote:
>Johannes Schindelin <Johannes.Schindelin@gmx.de> wrote:
>> > Isn't the problem that git-daemon loses its connection to the syslog 
>> > daemon when logrotate sighups syslog?

No.

>Right, but logrotate could send SIGHUP to git-daemon as well.

It could, but that's the reason one uses the openlog(3) interface to
syslog, to centralise logfilemanagement and *not* having to deal with
the intricacies of logfile rotation and the like.  So it doesn't need
to.  When you need logfile rotation, you're better off with using
openlog(3), and doing that the proper way means *NOT* closing and
reopening that everytime.

>> I have no idea, but other programs must have the same problem.  I should 

They don't.  Your patch fixes the wrong problem.  Please don't fix
something that wasn't broken in the first place.

>> have shown some diligence and researched that.  Will do so now.

>I don't say that just one example justifies me, but here is an example:
>icald (google://openlog+sighup 2nd result) does this.

N.B. I've never had to close and reopen the openlog(3) syslog interface
in any of the daemons I've written.
The example you refer to of icald is where it directly writes to a
logfile, which is *not* what this patch was about, so please do not use
it as justification.
-- 
Sincerely,                                                          srb@cuci.nl
           Stephen R. van den Berg.

Re: [PATCH] git-daemon: fix for rotating logs

[Johannes Schindelin]

Hi,

since you seem to be very new to this list: we really appreciate a 
Reply-to-all here.

On Mon, 28 Apr 2008, Stephen R. van den Berg wrote:

> >> I have no idea, but other programs must have the same problem.  I 
> >> should
> 
> They don't.  Your patch fixes the wrong problem.  Please don't fix 
> something that wasn't broken in the first place.

So do you have any ideas what is happening there?  It seems that after 
logrotate does its thing, syslog() is stuck in the close() call.

Any constructive help is very much appreciated.

Ciao,
Dscho

Re: [PATCH] git-daemon: fix for rotating logs

[Stephen R. van den Berg]

Johannes Schindelin wrote:
>since you seem to be very new to this list: we really appreciate a 
>Reply-to-all here.

I see.  I normally consider that bad form (maybe my age shows ;-);
but if people insist here, no problem.

>On Mon, 28 Apr 2008, Stephen R. van den Berg wrote:

>> >> I have no idea, but other programs must have the same problem.  I 
>> >> should

>So do you have any ideas what is happening there?  It seems that after 
>logrotate does its thing, syslog() is stuck in the close() call.

Erm, just so I understand the problem:
- git-daemon is configured to use syslog(3) to log
- git-daemon uses openlog(3)
- git-daemon logs happily for a while
- rotatelog rotates logfiles in /var/log and communicates with syslogd
  to make sure syslogd starts new logfiles in /var/log
- And then git-daemon hangs on which system/library call?
-- 
Sincerely,                                                          srb@cuci.nl
           Stephen R. van den Berg.

Re: [PATCH] git-daemon: fix for rotating logs

[Johannes Schindelin]

Hi,

On Mon, 28 Apr 2008, Stephen R. van den Berg wrote:

> Johannes Schindelin wrote:
> 
> >On Mon, 28 Apr 2008, Stephen R. van den Berg wrote:
> 
> >> >> I have no idea, but other programs must have the same problem.  I 
> >> >> should
> 
> >So do you have any ideas what is happening there?  It seems that after 
> >logrotate does its thing, syslog() is stuck in the close() call.
> 
> Erm, just so I understand the problem:
> - git-daemon is configured to use syslog(3) to log
> - git-daemon uses openlog(3)
> - git-daemon logs happily for a while
> - rotatelog rotates logfiles in /var/log and communicates with syslogd
>   to make sure syslogd starts new logfiles in /var/log
> - And then git-daemon hangs on which system/library call?

It seems that this happens, yes.

Ciao,
Dscho

Re: [PATCH] git-daemon: fix for rotating logs

[Stephen R. van den Berg]

Johannes Schindelin wrote:
>On Mon, 28 Apr 2008, Stephen R. van den Berg wrote:
>> - git-daemon logs happily for a while
>> - rotatelog rotates logfiles in /var/log and communicates with syslogd
>>   to make sure syslogd starts new logfiles in /var/log
>> - And then git-daemon hangs on which system/library call?

>It seems that this happens, yes.

Could you hang an strace off of git-daemon and check what system call it
hangs on at that point in time?
-- 
Sincerely,                                                          srb@cuci.nl
           Stephen R. van den Berg.

Re: [PATCH] git-daemon: fix for rotating logs

[Johannes Schindelin]

Hi,

On Mon, 28 Apr 2008, Stephen R. van den Berg wrote:

> Johannes Schindelin wrote:
> >On Mon, 28 Apr 2008, Stephen R. van den Berg wrote:
> >> - git-daemon logs happily for a while
> >> - rotatelog rotates logfiles in /var/log and communicates with syslogd
> >>   to make sure syslogd starts new logfiles in /var/log
> >> - And then git-daemon hangs on which system/library call?
> 
> >It seems that this happens, yes.
> 
> Could you hang an strace off of git-daemon and check what system call it
> hangs on at that point in time?

I can do better than that.  I attached to the process, and like I said, it 
hung in close().

Ciao,
Dscho

Re: [PATCH] git-daemon: fix for rotating logs

[Stephen R. van den Berg]

Johannes Schindelin wrote:
>On Mon, 28 Apr 2008, Stephen R. van den Berg wrote:
>> Johannes Schindelin wrote:
>> >On Mon, 28 Apr 2008, Stephen R. van den Berg wrote:
>> >> - rotatelog rotates logfiles in /var/log and communicates with syslogd
>> >>   to make sure syslogd starts new logfiles in /var/log
>> >> - And then git-daemon hangs on which system/library call?

>I can do better than that.  I attached to the process, and like I said, it 
>hung in close().

On which descriptor?  (I.e. what does the descriptor point to?)
-- 
Sincerely,                                                          srb@cuci.nl
           Stephen R. van den Berg.

Re: [PATCH] git-daemon: fix for rotating logs

[Johannes Schindelin]

Hi,

On Mon, 28 Apr 2008, Stephen R. van den Berg wrote:

> Johannes Schindelin wrote:
> >On Mon, 28 Apr 2008, Stephen R. van den Berg wrote:
> >> Johannes Schindelin wrote:
> >> >On Mon, 28 Apr 2008, Stephen R. van den Berg wrote:
> >> >> - rotatelog rotates logfiles in /var/log and communicates with syslogd
> >> >>   to make sure syslogd starts new logfiles in /var/log
> >> >> - And then git-daemon hangs on which system/library call?
> 
> >I can do better than that.  I attached to the process, and like I said, it 
> >hung in close().
> 
> On which descriptor?  (I.e. what does the descriptor point to?)

Sorry, that I don't remember, but I strongly suspect the syslog 
descriptor, since the backtrace showed "syslog()" a few levels up of 
close().

Ciao,
Dscho

Re: [PATCH] git-daemon: fix for rotating logs

[Stephen R. van den Berg]

Johannes Schindelin wrote:
>On Mon, 28 Apr 2008, Stephen R. van den Berg wrote:
>> >I can do better than that.  I attached to the process, and like I said, it 
>> >hung in close().

>> On which descriptor?  (I.e. what does the descriptor point to?)

>Sorry, that I don't remember, but I strongly suspect the syslog 
>descriptor, since the backtrace showed "syslog()" a few levels up of 
>close().

AFAICT, sending SIGHUP to syslogd doesn't cause the /dev/log pipe to be
closed, therefore there shouldn't be any closing of that /dev/log pipe.
So if you can reproduce it, please report which filedescriptor it is
trying to close.
-- 
Sincerely,                                                          srb@cuci.nl
           Stephen R. van den Berg.

Re: [PATCH] git-daemon: fix for rotating logs

[Andreas Ericsson]

Mike Hommey wrote:
> On Mon, Apr 28, 2008 at 08:21:14PM +0200, Miklos Vajna wrote:
>> On Mon, Apr 28, 2008 at 07:08:50PM +0100, Johannes Schindelin <Johannes.Schindelin@gmx.de> wrote:
>>>>> With rotating logs, there is a problem when the syslog is opened only 
>>>>> once (in the beginning).  So open the log everytime we write 
>>>>> something, and close it directly after writing.
>>>> Gaah, this is ugly.
>>>>
>>>> Is this something all the daemons need to deal with?
>>> I have no idea, but it seems to fix a real issue.
>> logrotate supports sending a signal (typically SIGHUP) to the process
>> after it rotated the log. Couldn't we just re-open the log on SIGHUP?
> 
> Isn't the problem that git-daemon loses its connection to the syslog
> daemon when logrotate sighups syslog?
> 

It really shouldn't. The connection to the syslog daemon is just a
unix socket (/dev/log) which is used to send whatever passes for
UDP packets on unix domain sockets. Since the socket isn't re-created
by syslogd (well, a sane syslogd anyways), but rather just open()'ed
for reading, no program should ever need to reconnect.

-- 
Andreas Ericsson                   andreas.ericsson@op5.se
OP5 AB                             www.op5.se
Tel: +46 8-230225                  Fax: +46 8-230231

Re: [PATCH] git-daemon: fix for rotating logs

[Johannes Schindelin]

Hi,

On Tue, 29 Apr 2008, Andreas Ericsson wrote:

> Mike Hommey wrote:
> > On Mon, Apr 28, 2008 at 08:21:14PM +0200, Miklos Vajna wrote:
> > > On Mon, Apr 28, 2008 at 07:08:50PM +0100, Johannes Schindelin
> > > <Johannes.Schindelin@gmx.de> wrote:
> > > > > > With rotating logs, there is a problem when the syslog is opened
> > > > > > only once (in the beginning).  So open the log everytime we write
> > > > > > something, and close it directly after writing.
> > > > > Gaah, this is ugly.
> > > > >
> > > > > Is this something all the daemons need to deal with?
> > > > I have no idea, but it seems to fix a real issue.
> > > logrotate supports sending a signal (typically SIGHUP) to the process
> > > after it rotated the log. Couldn't we just re-open the log on SIGHUP?
> > 
> > Isn't the problem that git-daemon loses its connection to the syslog
> > daemon when logrotate sighups syslog?
> > 
> 
> It really shouldn't. The connection to the syslog daemon is just a
> unix socket (/dev/log) which is used to send whatever passes for
> UDP packets on unix domain sockets. Since the socket isn't re-created
> by syslogd (well, a sane syslogd anyways), but rather just open()'ed
> for reading, no program should ever need to reconnect.

What can I say?  The problem just went away with my workaround.  Is it 
possible that I have to catch SIGHUP, and closelog() && openlog()?  But 
why do other daemons seem to not have that problem at all?

Ciao,
Dscho

Re: [PATCH] git-daemon: fix for rotating logs

[Andreas Ericsson]

Johannes Schindelin wrote:
> Hi,
> 
> On Tue, 29 Apr 2008, Andreas Ericsson wrote:
> 
>> Mike Hommey wrote:
>>> On Mon, Apr 28, 2008 at 08:21:14PM +0200, Miklos Vajna wrote:
>>>> On Mon, Apr 28, 2008 at 07:08:50PM +0100, Johannes Schindelin
>>>> <Johannes.Schindelin@gmx.de> wrote:
>>>>>>> With rotating logs, there is a problem when the syslog is opened
>>>>>>> only once (in the beginning).  So open the log everytime we write
>>>>>>> something, and close it directly after writing.
>>>>>> Gaah, this is ugly.
>>>>>>
>>>>>> Is this something all the daemons need to deal with?
>>>>> I have no idea, but it seems to fix a real issue.
>>>> logrotate supports sending a signal (typically SIGHUP) to the process
>>>> after it rotated the log. Couldn't we just re-open the log on SIGHUP?
>>> Isn't the problem that git-daemon loses its connection to the syslog
>>> daemon when logrotate sighups syslog?
>>>
>> It really shouldn't. The connection to the syslog daemon is just a
>> unix socket (/dev/log) which is used to send whatever passes for
>> UDP packets on unix domain sockets. Since the socket isn't re-created
>> by syslogd (well, a sane syslogd anyways), but rather just open()'ed
>> for reading, no program should ever need to reconnect.
> 
> What can I say?  The problem just went away with my workaround.  Is it 
> possible that I have to catch SIGHUP, and closelog() && openlog()?  But 
> why do other daemons seem to not have that problem at all?
> 

Other daemons don't get SIGHUP'ed when logs are rotated. I think something
else is going on there.

What syslogd are you using? Perhaps it insists on re-creating the socket.
That might cause the behaviour you're seeing, but then you should probably
see it in a ton of other daemons as well.

-- 
Andreas Ericsson                   andreas.ericsson@op5.se
OP5 AB                             www.op5.se
Tel: +46 8-230225                  Fax: +46 8-230231

Re: [PATCH] git-daemon: fix for rotating logs

[Johannes Schindelin]

Hi,

On Tue, 29 Apr 2008, Andreas Ericsson wrote:

> Johannes Schindelin wrote:
> 
> > On Tue, 29 Apr 2008, Andreas Ericsson wrote:
> > 
> > > Mike Hommey wrote:
> > > > On Mon, Apr 28, 2008 at 08:21:14PM +0200, Miklos Vajna wrote:
> > > > > On Mon, Apr 28, 2008 at 07:08:50PM +0100, Johannes Schindelin 
> > > > > <Johannes.Schindelin@gmx.de> wrote:
> > > > > > > > With rotating logs, there is a problem when the syslog is 
> > > > > > > > opened only once (in the beginning).  So open the log 
> > > > > > > > everytime we write something, and close it directly after 
> > > > > > > > writing.
> > > > > > > Gaah, this is ugly.
> > > > > > >
> > > > > > > Is this something all the daemons need to deal with?
> > > > > > I have no idea, but it seems to fix a real issue.
> > > > > logrotate supports sending a signal (typically SIGHUP) to the 
> > > > > process after it rotated the log. Couldn't we just re-open the 
> > > > > log on SIGHUP?
> > > > Isn't the problem that git-daemon loses its connection to the 
> > > > syslog daemon when logrotate sighups syslog?
> > > >
> > > It really shouldn't. The connection to the syslog daemon is just a 
> > > unix socket (/dev/log) which is used to send whatever passes for UDP 
> > > packets on unix domain sockets. Since the socket isn't re-created by 
> > > syslogd (well, a sane syslogd anyways), but rather just open()'ed 
> > > for reading, no program should ever need to reconnect.
> > 
> > What can I say?  The problem just went away with my workaround.  Is it 
> > possible that I have to catch SIGHUP, and closelog() && openlog()?  
> > But why do other daemons seem to not have that problem at all?
> > 
> 
> Other daemons don't get SIGHUP'ed when logs are rotated. I think 
> something else is going on there.
> 
> What syslogd are you using? Perhaps it insists on re-creating the 
> socket. That might cause the behaviour you're seeing, but then you 
> should probably see it in a ton of other daemons as well.

This is sysklogd from Ubuntu, compiled for amd64.  The timestamp on 
/dev/log is older than a month.

Thanks,
Dscho

Re: [PATCH] git-daemon: fix for rotating logs

[Stephen R. van den Berg]

Johannes Schindelin wrote:
>On Tue, 29 Apr 2008, Andreas Ericsson wrote:
>> What syslogd are you using? Perhaps it insists on re-creating the 
>> socket. That might cause the behaviour you're seeing, but then you 
>> should probably see it in a ton of other daemons as well.

Recreating the socket should not cause this to happen either, because
the git-daemon will still hold on to the old inode (even after the file
has been removed).

>This is sysklogd from Ubuntu, compiled for amd64.  The timestamp on 
>/dev/log is older than a month.

I'd still recommend trying to reproduce the problem, then find out which
filedescriptor/file the close is hanging on.
-- 
Sincerely,                                                          srb@cuci.nl
           Stephen R. van den Berg.

Re: [PATCH] git-daemon: fix for rotating logs

[Johannes Schindelin]

Hi,

On Mon, 28 Apr 2008, Johannes Schindelin wrote:

> With rotating logs, there is a problem when the syslog is opened only 
> once (in the beginning).  So open the log everytime we write something, 
> and close it directly after writing.

Actually, the culprit were _not_ rotating logs.  At least not really.  
syslog() is not supposed to be called from a signal handler.  In 
git-daemon, it is, from child_handler(), but only when called with 
--verbose (and --syslog, or --detach).  Bummer.

Sorry for my wrong analysis,
Dscho