You are viewing a plain text version of this content. The canonical link for it is here.
Posted to bugs@httpd.apache.org by bu...@apache.org on 2014/01/10 16:39:03 UTC

[Bug 55985] New: apache does not reopen logs when multiple graceful restarts happen in quick succession

https://issues.apache.org/bugzilla/show_bug.cgi?id=55985

            Bug ID: 55985
           Summary: apache does not reopen logs when multiple graceful
                    restarts happen in quick succession
           Product: Apache httpd-2
           Version: 2.2.26
          Hardware: PC
                OS: Linux
            Status: NEW
          Severity: normal
          Priority: P2
         Component: mod_log_config
          Assignee: bugs@httpd.apache.org
          Reporter: rainer-apache@7val.com

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
}

-- 
You are receiving this mail because:
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org


[Bug 55985] apache does not reopen logs when multiple graceful restarts happen in quick succession

Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=55985

Rainer Canavan <ra...@7val.com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|RESOLVED                    |REOPENED
         Resolution|INVALID                     |---

--- Comment #2 from Rainer Canavan <ra...@7val.com> ---
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?

-- 
You are receiving this mail because:
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org


[Bug 55985] apache does not reopen logs when multiple graceful restarts happen in quick succession

Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=55985

--- Comment #4 from Rainer Canavan <ra...@7val.com> ---
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.

-- 
You are receiving this mail because:
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org


[Bug 55985] apache does not reopen logs when multiple graceful restarts happen in quick succession

Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=55985

Eric Covener <co...@gmail.com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|REOPENED                    |RESOLVED
         Resolution|---                         |INVALID

--- Comment #3 from Eric Covener <co...@gmail.com> ---
> 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.

-- 
You are receiving this mail because:
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org


[Bug 55985] apache does not reopen logs when multiple graceful restarts happen in quick succession

Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=55985

Eric Covener <co...@gmail.com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|NEW                         |RESOLVED
         Resolution|---                         |INVALID

--- Comment #1 from Eric Covener <co...@gmail.com> ---
> 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.

-- 
You are receiving this mail because:
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org


[Bug 55985] apache does not reopen logs when multiple graceful restarts happen in quick succession

Posted by bu...@apache.org.
https://issues.apache.org/bugzilla/show_bug.cgi?id=55985

Rainer Canavan <ra...@7val.com> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|RESOLVED                    |REOPENED
         Resolution|INVALID                     |---

-- 
You are receiving this mail because:
You are the assignee for the bug.

---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org