Bug 12774

Summary: child processes not releasing logfiles correctly (not handling signals?)
Product: Apache httpd-2 Reporter: michael <michael>
Component: mpm_workerAssignee: Apache HTTPD Bugs Mailing List <bugs>
Status: CLOSED INVALID    
Severity: major    
Priority: P3    
Version: 2.0.40   
Target Milestone: ---   
Hardware: PC   
OS: Linux   

Description michael 2002-09-18 14:10:42 UTC 
Note: this may be related to http://nagoya.apache.org/bugzilla/show_bug.cgi?
id=12635 (bug #12635)

the following was written on Aug. 27:
        I have an apache 2.0.40 server using the worker MPM that's been running
on a linux 2.2 kernel for about 4 days now, and every day I run
apache -k graceful after rotating the logs (the program is named apache
instead of httpd). It looks like that's not working for killing the child
processes, though. A look at ps shows 271 apache processes running, most
of which have been started sometime today. There are 6, though, that have
not:

root     12526  0.0  0.2  5164 2152 ?        S    Aug24   0:51 lt-apache
web      23633  0.0  1.7 37328 16668 ?       S    Aug25   0:00 lt-apache
web      23635  0.0  1.7 37328 16668 ?       S    Aug25   0:04 lt-apache
web      23681  0.0  1.7 37328 16668 ?       S    Aug25   0:00 lt-apache
web       2754  0.0  1.6 37128 16372 ?       S    Aug25   0:00 lt-apache
web       2755  0.0  1.6 37128 16372 ?       S    Aug25   0:04 lt-apache
web       2797  0.0  1.6 37128 16372 ?       S    Aug25   0:00 lt-apache

        One of them is my root process, one of them is presumably cgid, and
the other five look to be the control processes for the threads I have
running. A look in /proc for these processes shows that the root process
has all my current log files open. The other six, though, have the log
files from the day they were started open (a look in /proc/2797/fd shows
that most of the log files it has open are deleted).

        This doesn't cause any problems with logging, since the threads that
are spawned are using the correct log files. The problem it causes is that
the 500MB that the deleted logfiles take up won't be freed from the
filesystem until I stop and restart apache.

        I've tried apache -k graceful, apache -k restart, and kill -HUP 12526
and none of them have caused the children to close their logfiles.

-- end of original message --

Here's the ps of my apache today. It was last restarted (apache -k stop, 
killall lt-apache, /etc/init.d/apache start) on Sept. 16th


sara:/home/michael# ps auwx | grep apache | grep Sep
root     31708  0.0  0.2  5164 2896 ?        S    Sep16   0:28 lt-apache
web      22401  0.0  1.7 58908 16620 ?       S    Sep16   0:00 lt-apache
web      22402  0.0  1.7 58908 16620 ?       S    Sep16   0:03 lt-apache
web      22540  0.0  1.7 58908 16620 ?       S    Sep16   0:00 lt-apache
web       9222  0.0  1.6 83940 15796 ?       S    Sep16   0:00 lt-apache
web       9223  0.0  1.6 83940 15796 ?       S    Sep16   0:03 lt-apache
web       9243  0.0  1.6 83940 15796 ?       S    Sep16   0:00 lt-apache
web      30047  0.0  1.4 57984 14140 ?       S    Sep17   0:00 lt-apache
web      30048  0.0  1.4 57984 14140 ?       S    Sep17   0:02 lt-apache
web      30068  0.0  1.4 57984 14140 ?       S    Sep17   0:00 lt-apache
web      13156  0.0  1.6 97008 16176 ?       S    Sep17   0:00 lt-apache
web      13157  0.0  1.6 97008 16176 ?       S    Sep17   0:01 lt-apache
web      13165  0.0  1.6 97008 16176 ?       S    Sep17   0:00 lt-apache
web      14975  0.0  1.6 48444 16056 ?       S    Sep17   0:00 lt-apache
web      14976  0.0  1.6 48444 16056 ?       S    Sep17   0:01 lt-apache
web      15007  0.0  1.6 48444 16056 ?       S    Sep17   0:00 lt-apache
sara:/home/michael# ps auwx | grep apache | wc -l
    302
sara:/home/michael#

A look at /proc for the root process shows all the right logfiles open:

sara:/proc/31708# ls -al fd
total 0
dr-x------    2 root     wheel           0 Sep 18 09:59 .
dr-xr-xr-x    3 root     wheel           0 Sep 18 09:59 ..
lr-x------    1 root     wheel          64 Sep 18 09:59 0 -> /dev/null
l-wx------    1 root     wheel          64 Sep 18 09:59 1 -> /dev/null
l-wx------    1 root     wheel          64 Sep 18 09:59 10 -
> /var/log/apache/manage-access_log
l-wx------    1 root     wheel          64 Sep 18 09:59 11 -
> /var/log/apache/author-access_log
l-wx------    1 root     wheel          64 Sep 18 09:59 12 -
> /var/log/apache/qz-access_log
l-wx------    1 root     wheel          64 Sep 18 09:59 13 -
> /var/log/apache/qz-access_log
l-wx------    1 root     wheel          64 Sep 18 09:59 14 -
> /var/log/apache/asstr-access_log
l-wx------    1 root     wheel          64 Sep 18 09:59 15 -
> /var/log/apache/redirect-access_log
l-wx------    1 root     wheel          64 Sep 18 09:59 16 -
> /var/log/apache/assmadmin-access_log
l-wx------    1 root     wheel          64 Sep 18 09:59 17 -
> /var/log/apache/assm-access_log
l-wx------    1 root     wheel          64 Sep 18 09:59 18 -
> /var/log/apache/assm-access_log
l-wx------    1 root     wheel          64 Sep 18 09:59 19 -
> /var/log/apache/mcstories-access_log
lrwx------    1 root     wheel          64 Sep 18 09:59 2 -
> /var/log/apache/error.log
l-wx------    1 root     wheel          64 Sep 18 09:59 20 -
> /var/log/apache/mcstories-access_log
l-wx------    1 root     wheel          64 Sep 18 09:59 21 -
> /var/log/apache/test-access_log
l-wx------    1 root     wheel          64 Sep 18 09:59 22 -
> /var/log/apache/asstr-access_log
l-wx------    1 root     wheel          64 Sep 18 09:59 23 -
> /var/log/apache/asstr-access_log
lr-x------    1 root     wheel          64 Sep 18 09:59 24 -> pipe:[614447598]
l-wx------    1 root     wheel          64 Sep 18 09:59 25 -> pipe:[614447598]
lrwx------    1 root     wheel          64 Sep 18 09:59 26 -
> /var/log/apache/error.log
lrwx------    1 root     wheel          64 Sep 18 09:59 27 -
> /var/log/apache/acctcgi-error_log
lrwx------    1 root     wheel          64 Sep 18 09:59 28 -
> /var/log/apache/search-error_log
lrwx------    1 root     wheel          64 Sep 18 09:59 29 -
> /var/log/apache/author-error_log
lrwx------    1 root     wheel          64 Sep 18 09:59 3 -> socket:[607040926]
lrwx------    1 root     wheel          64 Sep 18 09:59 30 -
> /var/log/apache/iflc-error_log
lrwx------    1 root     wheel          64 Sep 18 09:59 31 -
> /var/log/apache/manage-error_log
lrwx------    1 root     wheel          64 Sep 18 09:59 32 -
> /var/log/apache/asstr-error_log
lrwx------    1 root     wheel          64 Sep 18 09:59 33 -
> /var/log/apache/redirect-error_log
lrwx------    1 root     wheel          64 Sep 18 09:59 34 -
> /var/log/apache/assmadmin-error_log
lrwx------    1 root     wheel          64 Sep 18 09:59 35 -
> /var/log/apache/assm-error_log
lrwx------    1 root     wheel          64 Sep 18 09:59 36 -
> /var/log/apache/mcstories-error_log
lrwx------    1 root     wheel          64 Sep 18 09:59 37 -
> /var/log/apache/test-error_log
lrwx------    1 root     wheel          64 Sep 18 09:59 4 -> socket:[607040927]
l-wx------    1 root     wheel          64 Sep 18 09:59 5 -
> /var/log/apache/acctcgi-access_log
l-wx------    1 root     wheel          64 Sep 18 09:59 6 -
> /var/log/apache/search-access_log
l-wx------    1 root     wheel          64 Sep 18 09:59 7 -
> /var/log/apache/search-access_log
l-wx------    1 root     wheel          64 Sep 18 09:59 8 -
> /var/log/apache/author-access_log
l-wx------    1 root     wheel          64 Sep 18 09:59 9 -
> /var/log/apache/iflc-access_log
sara:/proc/31708# 

A look at one of the child processes (22401) shows the following:

sara:/proc/22401# ls -al fd
total 0
dr-x------    2 root     wheel           0 Sep 18 10:00 .
dr-xr-xr-x    3 web      www-data        0 Sep 18 10:00 ..
lr-x------    1 root     wheel          64 Sep 18 10:00 0 -> /dev/null
l-wx------    1 root     wheel          64 Sep 18 10:00 1 -> /dev/null
l-wx------    1 root     wheel          64 Sep 18 10:00 10 -
> /var/log/apache/manage-access_log.new (deleted)
l-wx------    1 root     wheel          64 Sep 18 10:00 11 -
> /var/log/apache/author-access_log.new (deleted)
l-wx------    1 root     wheel          64 Sep 18 10:00 12 -
> /var/log/apache/qz-access_log.new (deleted)
l-wx------    1 root     wheel          64 Sep 18 10:00 13 -
> /var/log/apache/qz-access_log.new (deleted)
l-wx------    1 root     wheel          64 Sep 18 10:00 14 -
> /var/log/apache/asstr-access_log.new (deleted)
l-wx------    1 root     wheel          64 Sep 18 10:00 15 -
> /var/log/apache/redirect-access_log.new (deleted)
l-wx------    1 root     wheel          64 Sep 18 10:00 16 -
> /var/log/apache/assmadmin-access_log.new (deleted)
l-wx------    1 root     wheel          64 Sep 18 10:00 17 -
> /var/log/apache/assm-access_log.new (deleted)
l-wx------    1 root     wheel          64 Sep 18 10:00 18 -
> /var/log/apache/assm-access_log.new (deleted)
l-wx------    1 root     wheel          64 Sep 18 10:00 19 -
> /var/log/apache/mcstories-access_log.new (deleted)
lrwx------    1 root     wheel          64 Sep 18 10:00 2 -
> /var/log/apache/error.log
l-wx------    1 root     wheel          64 Sep 18 10:00 20 -
> /var/log/apache/mcstories-access_log.new (deleted)
l-wx------    1 root     wheel          64 Sep 18 10:00 21 -
> /var/log/apache/test-access_log.new (deleted)
l-wx------    1 root     wheel          64 Sep 18 10:00 22 -
> /var/log/apache/asstr-access_log.new (deleted)
l-wx------    1 root     wheel          64 Sep 18 10:00 23 -
> /var/log/apache/asstr-access_log.new (deleted)
lr-x------    1 root     wheel          64 Sep 18 10:00 24 -> pipe:[607040934]
l-wx------    1 root     wheel          64 Sep 18 10:00 25 -> pipe:[607040934]
lrwx------    1 root     wheel          64 Sep 18 10:00 26 -
> /var/log/apache/error.log
lrwx------    1 root     wheel          64 Sep 18 10:00 27 -
> /var/log/apache/acctcgi-error_log.new (deleted)
lrwx------    1 root     wheel          64 Sep 18 10:00 28 -
> /var/log/apache/search-error_log.new (deleted)
lrwx------    1 root     wheel          64 Sep 18 10:00 29 -
> /var/log/apache/author-error_log.new (deleted)
lrwx------    1 root     wheel          64 Sep 18 10:00 3 -> socket:[607040926]
lrwx------    1 root     wheel          64 Sep 18 10:00 30 -
> /var/log/apache/iflc-error_log.new (deleted)
lrwx------    1 root     wheel          64 Sep 18 10:00 31 -
> /var/log/apache/manage-error_log.new (deleted)
lrwx------    1 root     wheel          64 Sep 18 10:00 32 -
> /var/log/apache/asstr-error_log.new (deleted)
lrwx------    1 root     wheel          64 Sep 18 10:00 33 -
> /var/log/apache/redirect-error_log.new (deleted)
lrwx------    1 root     wheel          64 Sep 18 10:00 34 -
> /var/log/apache/assmadmin-error_log.new (deleted)
lrwx------    1 root     wheel          64 Sep 18 10:00 35 -
> /var/log/apache/assm-error_log.new (deleted)
lrwx------    1 root     wheel          64 Sep 18 10:00 36 -
> /var/log/apache/mcstories-error_log.new (deleted)
lrwx------    1 root     wheel          64 Sep 18 10:00 37 -
> /var/log/apache/test-error_log.new (deleted)
lr-x------    1 root     wheel          64 Sep 18 10:00 38 -> pipe:[607357926]
l-wx------    1 root     wheel          64 Sep 18 10:00 39 -> pipe:[607357926]
lrwx------    1 root     wheel          64 Sep 18 10:00 4 -> socket:[607040927]
l-wx------    1 root     wheel          64 Sep 18 10:00 5 -
> /var/log/apache/acctcgi-access_log.new (deleted)
l-wx------    1 root     wheel          64 Sep 18 10:00 6 -
> /var/log/apache/search-access_log.new (deleted)
lrwx------    1 root     wheel          64 Sep 18 10:00 63 -> socket:[607361473]
l-wx------    1 root     wheel          64 Sep 18 10:00 7 -
> /var/log/apache/search-access_log.new (deleted)
l-wx------    1 root     wheel          64 Sep 18 10:00 8 -
> /var/log/apache/author-access_log.new (deleted)
l-wx------    1 root     wheel          64 Sep 18 10:00 9 -
> /var/log/apache/iflc-access_log.new (deleted)
sara:/proc/22401# 

The .new files are renames of the original logfiles by the debian savelog 
script.

A look at the partition with our logs on it shows that these files are indeed 
deleted but still open:

sara:/var/log# df .
Filesystem           1k-blocks      Used Available Use% Mounted on
/dev/sda9              1517920   1129948    310864  79% /var/log
sara:/var/log# du -s
593008  .
sara:/var/log# 

I'd be happy to provide any additional information you need.... as it is I get 
a page every 3 days about my hard drive getting full, and have to do a hard 
stop and start of apache to fix it...
Comment 1 Joshua Slive 2002-10-17 02:34:41 UTC 
[This is a mass bug update.]
This bug reports a problem in an older version of Apache 2.
Could you please update to the most recent version and see
if you can reproduce this problem.  If the bug still exists,
please update the bug with the latest version number.  If 
the bug no longer exists, please close the bug report.

Sorry for this impersonal response, but we get many more bug
reports than our volunteers can keep up with.
Thanks for using Apache!
Comment 2 Joshua Slive 2002-11-02 20:18:21 UTC 
[This is a mass bug update.] [Resolve-20021102]
No response from submitter; assuming issue is resolved.
If the problem still exists in the lastest version,
please reopen this report and update appropriately.