Bug 105019 - Apache logging dates as GMT (+0000) instead of local timezone about a third of the time.
Summary: Apache logging dates as GMT (+0000) instead of local timezone about a third o...
Alias: None
Product: Red Hat Linux
Classification: Retired
Component: httpd   
(Show other bugs)
Version: 9
Hardware: i386
OS: Linux
Target Milestone: ---
Assignee: Joe Orton
QA Contact: David Lawrence
Depends On:
TreeView+ depends on / blocked
Reported: 2003-09-24 18:18 UTC by Harold Campbell
Modified: 2007-04-18 16:57 UTC (History)
1 user (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Last Closed: 2005-02-03 12:05:29 UTC
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---

Attachments (Terms of Use)

Description Harold Campbell 2003-09-24 18:18:05 UTC
From Bugzilla Helper:
User-Agent: Mozilla/5.0 (X11; U; Linux i686) Gecko/20030610 Galeon/1.3.7

Description of problem:
Apache is logging hits with GMT time (+0000) instead of local time (-0500 for
me) on about 1/3rd of the entries. This makes logfile analyzers very inaccurate.

Here is a good line followed by a bad line:

as1-216-68-14-42.fuse.net - - [22/Sep/2003:00:06:28 -0500] "GET
/gallery/herds/sp/mesasmall.jpg HTTP/1.1" 304 0
"http://ponylagoon.muerte.net/molds/adios.shtml" "Mozilla/4.0 (compatible; MSIE
6.0; Windows NT 5.1; FunWebProducts)"
dialup- - - [22/Sep/2003:00:06:44 +0000]
"GET /molds/trakehner.shtml HTTP/1.1" 200 3985
"http://ponylagoon.muerte.net/breyernumber1000.shtml" "Mozilla/4.0 (compatible;
MSIE 6.0; MSNIA; Windows 98; MSNIA)"

Version-Release number of selected component (if applicable):
started with httpd-2.0.40-21.3

How reproducible:

Steps to Reproduce:
1. hit a site for a day or so
2. look at log file


Additional info:

Comment 1 Harold Campbell 2003-09-24 18:27:40 UTC
Sorry, that log snippit was from a sorted log. Here is an example from the
original log:

dialup- - - [21/Sep/2003:19:06:18 -0500]
"GET /breyernumber1000.shtml HTTP/1.1" 200 21865
"http://ponylagoon.muerte.net/breyernumber.shtml" "Mozilla/4.0 (compatible; MSIE
6.0; MSNIA; Windows 98; MSNIA)"
dialup- - - [22/Sep/2003:00:06:44 +0000]
"GET /molds/trakehner.shtml HTTP/1.1" 200 3985
"http://ponylagoon.muerte.net/breyernumber1000.shtml" "Mozilla/4.0 (compatible;
MSIE 6.0; MSNIA; Windows 98; MSNIA)"

Notice the jump from September 21 to September 22. A few lines further on we go
the other direction:

dialup- - - [22/Sep/2003:00:09:00 +0000]
"GET /breyernumber10000.shtml HTTP/1.1" 200 28603
"http://ponylagoon.muerte.net/breyernumber.shtml" "Mozilla/4.0 (compatible; MSIE
6.0; MSNIA; Windows 98; MSNIA)"
dialup- - - [21/Sep/2003:19:09:22 -0500]
"GET /breyernumber999999.shtml HTTP/1.1" 200 20282
"http://ponylagoon.muerte.net/breyernumber.shtml" "Mozilla/4.0 (compatible; MSIE
6.0; MSNIA; Windows 98; MSNIA)"

Comment 2 Joe Orton 2003-11-03 17:06:13 UTC
Does this happen consistently, all the time? Or does it only start
happening after the server has been running a while?

It would be useful if you could adjust the LogFormat ("combined" by
default) and add:


at the very end, to log the child process ID at the end of each line.  
This should reveal whether only certain processes are forgetting their
timezone setting, for instance.

When you find a log entry with a bad timezone, you can then do:

cp /proc/<pid>/environ /tmp/saved-environ

to capture the environment of that child process, and attach that here.

Comment 3 Harold Campbell 2003-11-03 20:29:22 UTC
It happens pretty quickly. I started getting them within 10 minutes of
restarting with your log change. It is not the case that a child will
always be one way or the other. I have an example of one PID going
from fine to bad, though not yet the other way. Here is the
environment for one which has gone bad. I don't see any reference to
timezone, but I don't see any in my login environment either.

LESSOPEN=|/usr/bin/lesspipe.sh %s

In addition I do not have an /etc/localtime or
/usr/share/zoneinfo/localtime file. My hardware clock is set to GMT.

hairball/usr/share/zoneinfo$ date
Mon Nov  3 14:28:46 CST 2003
hairball/usr/share/zoneinfo$ date -u
Mon Nov  3 20:28:48 UTC 2003

Comment 4 Joe Orton 2003-11-03 21:10:01 UTC
Then I'm confused, if you don't have TZ set or an /etc/localtime, how
is your timezone configured?  There is some other way?

Comment 5 Harold Campbell 2003-11-03 21:14:53 UTC
You work at RedHat. Shouldn't you know this better than me? :)

hairball/etc/sysconfig$ cat clock

This stuff gets used in /etc/rc.d/rc.sysinit.

Comment 6 Joe Orton 2003-11-03 21:24:27 UTC
I know of two ways of configuring a timezone in a Linux system:
/etc/localtime and $TZ.  If you're not using either, then I need to
learn about a new way!  Or else your timezone is not really configured
properly, and that's the source of the problems.

rc.sysinit does not configure a timezone, it doesn't use $ZONE.

What is the output of 

$ strace date

Comment 7 Joe Orton 2003-11-03 21:31:19 UTC
...and the output of "env", both from a fresh root login.

Comment 8 Harold Campbell 2003-11-04 09:36:06 UTC
Sorry, I looked at too many things before I did that last comment and
forgot what exactly I saw. There _is_ an /etc/localtime. It's just not
a symplink to something in /usr/share/zoneinfo, it's a regular file
(which is in the proper format).

hairball~$ file /etc/localtime
/etc/localtime: timezone data

Comment 9 Joe Orton 2003-11-04 14:15:31 UTC
OK, good.  What modules are being used on the server? 

The next thing to do is to look at where particular children forget
the timezone by tracking the pids, and seeing if this is triggered by
a request for a particular file, for instance.

Comment 10 Harold Campbell 2003-11-04 20:15:03 UTC
The module configuration is as installed by the rpm.

Comment 11 Joe Orton 2003-11-07 11:19:21 UTC
I meant: are you using php, perl, ??? scripts, along with the shtml? 
To investigate this further I'd need a larger segment of log file
which shows the good->bad transitions for a few processes to see
whether a particular request is triggering it.

Comment 12 Harold Campbell 2003-11-07 11:31:41 UTC
Both php and perl are in use. Perl is used only rarely and the last
restart I mentioned showed the problem before any perl scripts could
have been called.

I'll work on getting you transition logs, but since I have several
virtual servers, all logging to different files, this will take a bit
of time...

I take it there is nothing obvious added to httpd-2.0.40-21.3 which
could cause this problem?

Comment 13 Joe Orton 2003-11-11 13:26:22 UTC
No.  One more question: is your /etc/localtime world-readable?

ls -l /etc/localtime

Comment 14 Harold Campbell 2003-11-11 13:41:06 UTC
hairball~$ ls -l /etc/localtime
-rw-rw-r--    1 root     root         1279 Nov  7 05:19 /etc/localtime

Comment 15 Martin Pool 2003-12-05 03:53:39 UTC
Remember that the TZ variable is global to the process.  If a mod_perl
or PHP script sets that variable, it will I think  affect logs written
out by Apache in the future.

Also, you might check for SetEnv lines in the apache config.

Personally I think keeping logs in GMT is a good idea...

Comment 16 Joe Orton 2005-02-03 12:05:29 UTC
Thanks for the report.  This is a mass bug update; since this release
of Red Hat Linux is no longer supported, please either:

a) try and reproduce the bug with a supported version of Red Hat
Enterprise Linux or Fedora Core, and re-open this bug as appropriate
after changing the Product field, or,

b) if relevant, try and reproduce this bug using the current version
of the upstream package, and report the bug upstream.

c) report the bug to the Fedora Legacy project who may wish to
continue maintenance of this package.

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