Bug 55985 - apache does not reopen logs when multiple graceful restarts happen in quick succession
Summary: apache does not reopen logs when multiple graceful restarts happen in quick s...
Status: REOPENED
Alias: None
Product: Apache httpd-2
Classification: Unclassified
Component: mod_log_config (show other bugs)
Version: 2.2.26
Hardware: PC Linux
: P2 normal (vote)
Target Milestone: ---
Assignee: Apache HTTPD Bugs Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2014-01-10 15:39 UTC by Rainer Canavan
Modified: 2014-01-10 19:29 UTC (History)
0 users



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Rainer Canavan 2014-01-10 15:39:03 UTC
Since we want to use different "postrotate" scripts for different CustomLogs, we configure lgrotate with 3 different sections, one for each "type" of log file. Since none of the sections is guaranteed to run every time, each has its own call to apachectl graceful. Sometimes, this causes multiple calls to apachectl graceful within the same second, which in turn sometimes results in httpd not reopening the access logs. This is usually fixed by manually performing an apachectl graceful at a later time, but httpd may just as well continue to write to the same (deleted) access_log.1 for multiple days. This results in log data that never gets analyzed or can result in the /var partition filling up.

I was able to reproduce this behaviour by running ab, a loop that just does graceful restarts every 5 seconds, and a second loop that uses lsof to find deleted files opened by httpd processes and forces logrotate to run for the single configured transfer log. I only have a single virtualhost configured, and ab is requesting a small static file.

bin/ab -n 999999 -c 4 -t 10000 http://testserver:10106/favicon.ico

for i in {1..1000}; do 
   echo $i; 
   lsof |grep httpd |grep deleted | egrep -v 'ssl_mutex'; 
   echo; 
   logrotate  -f logrotate.conf ; 
   j=0; 
   while lsof |grep httpd |grep deleted | egrep -v 'ssl_mutex'; do 
      echo ====== $j ======; sleep 1; j=$[ $j + 1 ]; 
   done; 
done

while true; do apachectl graceful; sleep 5; done

I've tried httpd 2.2.22, 2.2.24 and 2.2.26 on debian Wheezy (i686), RHEL 6.5 x86_64 and SLES 11 SP2 x86_64, all of which show the described behavior. The deleted access_log.1 is used even by children forked after the previous ones have exceeded their MaxRequestsPerChild.
 
httpd  -t -D DUMP_MODULES
Loaded Modules:
 core_module (static)
 authn_file_module (static)
 authn_default_module (static)
 authz_host_module (static)
 authz_groupfile_module (static)
 authz_user_module (static)
 authz_default_module (static)
 auth_basic_module (static)
 cache_module (static)
 disk_cache_module (static)
 mem_cache_module (static)
 include_module (static)
 filter_module (static)
 deflate_module (static)
 log_config_module (static)
 log_forensic_module (static)
 logio_module (static)
 env_module (static)
 expires_module (static)
 headers_module (static)
 unique_id_module (static)
 setenvif_module (static)
 version_module (static)
 proxy_module (static)
 proxy_connect_module (static)
 proxy_ftp_module (static)
 proxy_http_module (static)
 proxy_scgi_module (static)
 proxy_ajp_module (static)
 proxy_balancer_module (static)
 ssl_module (static)
 mpm_prefork_module (static)
 http_module (static)
 mime_module (static)
 dav_module (static)
 status_module (static)
 autoindex_module (static)
 asis_module (static)
 cgi_module (static)
 dav_fs_module (static)
 dav_lock_module (static)
 vhost_alias_module (static)
 negotiation_module (static)
 dir_module (static)
 actions_module (static)
 userdir_module (static)
 alias_module (static)
 rewrite_module (static)
 so_module (static)
Syntax OK

the logrotate.conf used:

logs/access_log {
        su rainer rainer
	compress
	nodelaycompress
	compresscmd /bin/bzip2
	compressext .bz2
	create 644 rainer rainer
	sharedscripts
	postrotate
		bin/apachectl graceful
	endscript
}
Comment 1 Eric Covener 2014-01-10 16:01:39 UTC
> I've tried httpd 2.2.22, 2.2.24 and 2.2.26 on debian Wheezy (i686), RHEL 6.5
> x86_64 and SLES 11 SP2 x86_64, all of which show the described behavior. The
> deleted access_log.1 is used even by children forked after the previous ones
> have exceeded their MaxRequestsPerChild.

Logs are opened in the parent, not in the children.  New children cannot be expected to reopen logs that have been deleted out from under them, this requires at least a graceful restart.

Based on these comments, tt sounds like in some way you may know that a graceful does not always follow your unlink, so I am marking as invalid.
Comment 2 Rainer Canavan 2014-01-10 16:58:20 UTC
Can you explain why the loop 

while true; do apachectl graceful; sleep 5; done

is required to trigger this behaviour if there's only one apachectl graceful in the logrotate config, or, alternatively the logrotate must have multiple sections with one apachectl graceful in each section to causes the described behaviour?
Comment 3 Eric Covener 2014-01-10 17:29:47 UTC
> Can you explain why the loop 
> 
> while true; do apachectl graceful; sleep 5; done
> 
> is required to trigger this behaviour if there's only one apachectl graceful
> in the logrotate config, or, alternatively the logrotate must have multiple
> sections with one apachectl graceful in each section to causes the described
> behaviour?

I assume there are windows where nearly simulataneous gracefuls happen don't "stack", and that somehow leads to you unlinking without a graceful being processed after. But i don't think there is a remedy in httpd.
Comment 4 Rainer Canavan 2014-01-10 17:46:09 UTC
I think the fact that just running logrotate -f with a single section over and over again does not cause the problem to happen, as opposed to doing the same and running a separate loop with just apachectl graceful and sleep, is a clear indicator that logrotate is not at fault.