Bug 23109 - Log pipe programs aren't killed on stop/reload/restart
Summary: Log pipe programs aren't killed on stop/reload/restart
Status: CLOSED DUPLICATE of bug 24805
Alias: None
Product: Apache httpd-2
Classification: Unclassified
Component: Core (show other bugs)
Version: 2.0.47
Hardware: PC other
: P3 major with 1 vote (vote)
Target Milestone: ---
Assignee: Apache HTTPD Bugs Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2003-09-11 16:26 UTC by Peter Bieringer
Modified: 2004-11-16 19:05 UTC (History)
2 users (show)



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Peter Bieringer 2003-09-11 16:26:19 UTC
Hi,

my apache2 config uses per virtual server log pipe "cronolog". On start, per log
 definition one cronolog is started.

init-+-
     |-httpd-+-26*[cronolog]
     |       `-10*[httpd]

On stop/reload/restart, such processes aren't killed, resulting in
hanging-around old cronolog processes.

init-+-
     |-13*[cronolog]

Note, 26 cronolog processes started, after stop, 13 are still haning around. All
 of them are CustomLog processes, none of them are ErrorLog processes

Typical ps -axw

 3276 ?  S  0:00 /usr/sbin/cronolog /path/to/logs/www.server.de-log.%Y%m

Config:

ErrorLog  "|/usr/sbin/cronolog /path/to/logs/www.server.de-error.%Y%m"
CustomLog "|/usr/sbin/cronolog /path/to/logs/www.server.de-log.%Y%m" combined

LogFormat "%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\" %I %O"
combined

Note: I use mod_logio here, too.

Apache log on stop:

piped log program '/usr/sbin/cronolog /path/to/logs/www.server.de-log.%Y%m'
failed unexpectedly
[Thu Sep 11 18:05:04 2003] [notice] caught SIGTERM, shutting down
[Thu Sep 11 18:05:52 2003] [notice] suEXEC mechanism enabled (wrapper:
/usr/sbin/suexec)
[Thu Sep 11 18:05:55 2003] [notice] Apache/2 configured -- resuming normal
operations

I've tried already the patch from attachement given in 
http://nagoya.apache.org/bugzilla/show_bug.cgi?id=21648
but it doesn't help.

Currently I have on config changes to stop Apache2, kill still living cronolog
processes (normal kill helps) and start Apache2 again.

BTW: config is rebuilded from a Apache1 system, here also cronolog is heavily
used, but never seen such problems.

Pls. help me, e.g. leading to some debug capabilities. It's no problem for me to
test some patches, because system is current still in semi-productive state.

Thanky you very much,
 Peter
Comment 1 David Rees 2003-09-23 22:16:28 UTC
FWIW, I notice the same behavior after upgrading to Apache 2.0.47.  Apache
1.3.27 did not exhibit this behavior.
Comment 2 Jeff Trawick 2003-10-23 18:34:25 UTC
Can you do an strace on one of your piped log processes across an "apachectl stop"?

Here's what I get with rotatelogs and HEAD of stable branch, which isn't too
different than 2.0.47:

$ strace -p 28824
read(0, 0xbffefea8, 65536)              = ? ERESTARTSYS (To be restarted)
--- SIGTERM (Terminated) ---

Also, what MPM are you using?
Comment 3 Peter Bieringer 2003-10-23 18:53:55 UTC
Same here:

# strace  -p 22264
read(0,
0xbffeef00, 65536)              = ? ERESTARTSYS (To be restarted)
--- SIGTERM (Terminated) @ 0 (0) ---

Currently I use MPM=prefork, but can easily switch to "worker" by startup config
option. System is RHL 9 with all updates, Apache2 is built on a RHL 9 devel
staging system.
Comment 4 Jeff Trawick 2003-10-23 19:28:26 UTC
I guess I was expecting to see something different in your strace.  Isn't
"apachectl stop" one of the situations where your piped log programs aren't
dying properly?  Maybe the problem doesn't occur consistently?

The goal is to find out if Apache isn't sending SIGTERM to the piped logger
processes, or if it is doing so but they aren't exiting when it happens.
Comment 5 Peter Bieringer 2003-10-23 19:43:05 UTC
Hmm, it's reproducable.

Tested again: resulting in 24 log lines...

piped log program '/usr/sbin/cronolog /path/to/server/www.server.de-log.%Y%m'
failed unexpectedly
....

I have 12 virtual server configured, each has one error and one custom log piped
via cronolog.

Unfortunally, after playing around many more cronolog processes:

# ps -ax|grep cronolog |wc -l
    140

After stopping Apache, still a bunch are in the process table:
# ps -ax |grep cronolog |wc -l
     92

Have now killed them by a loop.

What do you expect?



Comment 6 Jeff Trawick 2003-10-23 22:55:53 UTC
>What do you expect?

When you ran strace on one of the log programs, I expected it to *not* exit,
since *not* exiting is the bad symptom you normally experience.

If it were me, I'd attach strace to a handful of log programs and stop Apache
and see what happens to that handful of log programs -- Do they all get SIGTERM?
 Do they all exit once they get SIGTERM?

If tracing the log process always results in the log process exiting at the
right time, then I don't know what doc can be gathered.
Comment 7 David Rees 2003-10-28 23:26:04 UTC
I did some additional research into this issue.  It turns out I can pretty
easily reproduce this issue by starting, waiting a few seconds and then stopping
Apache2 on a RH 7.3 Linux server here.  

What's interesting is that the cronolog processes are not the same processes
that were originally started by Apache2.  So it appears that Apache2 sees that
the log processes die, but for some reason starts it back up right before
completely shutting down.
Comment 8 Sander Holthaus 2003-11-06 01:37:51 UTC
Bug is also present on 2.0.48 and FreeBSD 4.x ...
Comment 9 Sander Holthaus 2003-11-06 10:42:21 UTC
By the way, this bug seems to have replaced this bug 
http://nagoya.apache.org/bugzilla/show_bug.cgi?id=12033. 
Comment 10 Jeff Trawick 2003-12-13 22:02:42 UTC
Traces showed that the piped loggers really exited (at least some).
Meanwhile, we have a known problem (PR 24805) where piped loggers can
be restarted at termination.  This problem, where it looks like the
loggers aren't really killed, is assumed to be the same as the known
problem where they are killed but then unfortunately we start more copies.

PR 24805 has more info, so I'll keep that one open.


*** This bug has been marked as a duplicate of 24805 ***