Bug 429807 - Apache fails to re-open logfiles after SIGHUP from logrotate
Apache fails to re-open logfiles after SIGHUP from logrotate
Status: CLOSED NOTABUG
Product: Red Hat Enterprise Linux 5
Classification: Red Hat
Component: httpd (Show other bugs)
5.1
x86_64 Linux
low Severity medium
: rc
: ---
Assigned To: Joe Orton
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2008-01-23 01:38 EST by Jon Jensen
Modified: 2008-01-28 10:13 EST (History)
0 users

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2008-01-28 06:15:25 EST
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:


Attachments (Terms of Use)

  None (edit)
Description Jon Jensen 2008-01-23 01:38:58 EST
Description of problem:

About 1 in 2 or 1 in 3 times, every 4:00 am Sunday morning, Apache starts 
sending its logs into nowhereland, because if fails to re-open the files after 
logrotate sends a HUP signal. This results in lost logs till Monday, Tuesday, 
or even later, when it happens to work again.

Version-Release number of selected component (if applicable):

RHEL 5.0 and 5.1 on x86_64. Seen with current httpd-2.2.3-11.el5 and all 
earlier RHEL 5 versions.

How reproducible:

It's been happening for months. Can't make it happen intentionally, but 
happens Sunday mornings quite often. We can't see what Sunday has to do with 
it -- no relevant cron jobs, etc. -- but that's what's happening.

Additional info:

We're running SELinux with the default targeted policy in enforcing mode. 
SELinux booleans that may be relevant:

httpd_builtin_scripting --> on
httpd_can_network_connect --> off
httpd_can_network_connect_db --> off
httpd_can_network_relay --> off
httpd_disable_trans --> on
httpd_enable_cgi --> on
httpd_enable_ftp_server --> off
httpd_enable_homedirs --> on
httpd_rotatelogs_disable_trans --> off
httpd_ssi_exec --> off
httpd_suexec_disable_trans --> off
httpd_tty_comm --> on
httpd_unified --> on

What ships in /etc/logrotate.d/httpd is unchanged, but we have added an 
additional stanza, so the whole file looks like this:

/var/log/httpd/*log {
    missingok
    notifempty
    sharedscripts
    postrotate
        /sbin/service httpd reload > /dev/null 2>/dev/null || true
    endscript
}

/var/log/httpd/sites/*/*log {
    daily
    rotate 120
    missingok
    notifempty
    sharedscripts
    postrotate
        /sbin/service httpd reload > /dev/null 2>/dev/null || true
    endscript
}

Thanks for any help.
Comment 1 Joe Orton 2008-01-23 04:15:39 EST
Sunday at 4am is special in the above configuration because on that day, the
parent will get SIGHUP-ed *twice* by logrotate in a very short period of time -
once for each section specified above.  (The "sharedscripts" does not apply
across the two sections.)

Can you clarify what you mean by "fails to re-open the files"?  Are the
access_log/error_log files simply not created; or are they created, but stay
empty? Is the httpd logging configuration otherwise as default?
Comment 2 Jon Jensen 2008-01-23 04:27:04 EST
Oh, of course; I was forgetting that the default is weekly, so that plus the 
daily config above = Sunday specialness. Thanks for pointing that out.

IIRC, access_log/error_log are created but remain empty. My guess is that the 
files are being created by logrotate, though, and Apache doesn't touch them at 
all.

The logging setup is pretty standard. In each virtual host:

ErrorLog logs/sites/$domain/error_log
CustomLog logs/sites/$domain/access_log combined

With $domain varying, of course. And an additional log for SSL:

CustomLog 
logs/sites/$domain/ssl_request_log "%t %h %{SSL_PROTOCOL}x %{SSL_CIPHER}x 
\"%r\" %b"

Perhaps a simple kludge such as a "sleep 10" command in the custom logrotate 
stanza's script would help?
Comment 3 Joe Orton 2008-01-23 06:13:05 EST
There's a period of time during the restart process in which httpd has opened
the log files but is ignoring SIGHUP.  I can see that this results in a race
condition with the double-logrotate; in the above config, when the weekly
logrotate comes along, it may rename the files but fail to restart the server.

This would leave the server logging to the old log files (those renamed during
rotation) until the subsequent daily logrotate run; with no default
access_log/error_log files in existence (logrotate does not create them, AFAIK).

Putting a "sleep 10" or similar before the reload in *both* the stanzas would be
necessary to avoid that race.

I can't see how it would be possible for the server to end up in a state where
the new empty access_log/error_log are created but not being logged to, however.
Comment 4 Joe Orton 2008-01-28 06:15:25 EST
I'm going to mark this as NOTABUG on the assumption that the race being hit is
as described in comment 3 (which is essentially by design); the "sleep" hack
should be able to work around the particular logrotate configurations.  

Another workaround would be to disable the logrotate configuration for httpd
completely, create a separate logrotate config (outside the default directory),
which does *not* run the httpd reload internally, and cron a daily job which
does simply:

  logrotate /etc/special-httpd-logrotate.conf
  service httpd reload

 
Comment 5 Jon Jensen 2008-01-28 10:13:56 EST
Ok, thanks for your help, Joe. It really seems like something Apache should be
able to handle, but I imagine it'd be complicated. In any case, I've
consolidated stanzas and expect that to solve my immediate problem. I appreciate
your input.

Note You need to log in before you can comment on or make changes to this bug.