• Status: Solved
  • Priority: Medium
  • Security: Public
  • Views: 774
  • Last Modified:

Apache 2.2.4 rotatelogs is generating the wrong hour

My sites gets a lot of hits so I rotate my logs hourly (%H).  This was working perfectly for nearly a year until two or three months ago.  Now rotatelogs is generating logs with %H being one hour ahead of SLES 9 Linux OS system time, xntpd is running and OS time is correct.  Module log_config is working and log entries match the correct time.

CustomLog "|/apache/httpd-2.2.4-worker/bin/rotatelogs \
            /apache/httpd-2.2.4-worker/logs/%Y%m%d_%H.appName.nssl_access_log 3600 -300" MYFORMAT

$ date
Thu Jan 31 11:28:40 CST 2008

$ tail 20080131_12.appName.nssl_access_log
[31/Jan/2008:11:28:47 -0600] "GET /images/  ...

# System Time reporting 11:29 but 20080131_%H is evaluating one hour ahead.
$ ls -ltr *appName*
-rw-r--r--  1 root   root        69 2008-01-31 09:55 20080131_10.appName.ssl_error_log
-rw-r--r--  1 root   root      4024 2008-01-31 09:59 20080131_10.appName.nssl_error_log
-rw-r--r--  1 root   root   3332523 2008-01-31 09:59 20080131_10.appName.nssl_access_log
-rw-r--r--  1 root   root   1711130 2008-01-31 09:59 20080131_10.appName.ssl_access_log
-rw-r--r--  1 root   root       483 2008-01-31 10:19 20080131_11.appName.ssl_error_log
-rw-r--r--  1 root   root      3299 2008-01-31 10:59 20080131_11.appName.nssl_error_log
-rw-r--r--  1 root   root   3265565 2008-01-31 10:59 20080131_11.appName.nssl_access_log
-rw-r--r--  1 root   root   1552938 2008-01-31 10:59 20080131_11.appName.ssl_access_log
-rw-r--r--  1 root   root      1035 2008-01-31 11:29 20080131_12.appName.nssl_error_log
-rw-r--r--  1 root   root   1272661 2008-01-31 11:29 20080131_12.appName.ssl_access_log
-rw-r--r--  1 root   root   1621269 2008-01-31 11:29 20080131_12.appName.nssl_access_log

Anybody have any ideas.  I have tested the rotatelogs binary from 2.0.59, 2.061, 2.2.4 and even recompiled from source after Nov Day Light Savings switch.

Thanks - Dave
  • 7
  • 5
1 Solution
What do you get if issue the command:

    date +%H

is it the correct hour, or hour+1?
Do you have the TZ env variable set?

I'm in CST and I use:

D-OKC1:/u/unilocal/apache2> echo $TZ
dmwaffAuthor Commented:
$ date ; date +%H
Sat Feb  2 01:34:04 CST 2008
### Date cmd looks good

TZ environment is not reported as being set....I have considered that.   I did add the following to the startup script and to the .profile
#TZ='America/Chicago'; export TZ
TZ=6ST6CDT ; export TZ

-rw-r--r--  1 apache apache  84 2008-02-02 01:53 20080202_02.appName.ssl_error_log

I have done nearly everything I can think of.  Checking localtime, zdump -v /etc/localtime|grep 200[78], grep -i tz /etc/profile, adding TZ env var in different fashions. NTP is running well.  Every program and test I have performed returns the correct date and hour.

root      6680     1  0 Jan14 ?        00:00:00 /sbin/syslogd -a /var/lib/ntp/dev/log
ntp       7101     1  0 Jan14 ?        00:00:01 /usr/sbin/ntpd -p /var/lib/ntp/var/run/ntp/ntpd.pid -u ntp -i /var/lib/ntp

Obviously rotatelogs binary is A) not evaluating the date properly B) retrieving the date incorrectly from its reference source.

I am currently looking at the man pages for "strace" to attempt to see the syscalls.   I let everyone know if  it leads anywhere.
Free Tool: ZipGrep

ZipGrep is a utility that can list and search zip (.war, .ear, .jar, etc) archives for text patterns, without the need to extract the archive's contents.

One of a set of tools we're offering as a way to say thank you for being a part of the community.

dmwaffAuthor Commented:
#TZ='America/Chicago'; export TZ
TZ=6ST6CDT ; export TZ  <---- fat fingered

#TZ='America/Chicago'; export TZ
TZ=CST6CDT ; export TZ  <--- does not work
dmwaffAuthor Commented:
Found bugzilla report  from apache and hoping it is the issue.  Sounds solid. Its a few year old but what the hey.  I'll give it a try.

You may want to look at the source code to see if that fix is in there.  The bugreport is against 2.0.47 and you tested against level newer than that.

Also, without looking at the code in detail, it seems that the problem that bugreport is reporting is that when DST is in effect, it is not be taken into account.  But I could be mis-interpreting the description.  It could be that it is always assuming that DST in is effect.
dmwaffAuthor Commented:
Notice that old 2.0.47 too.  Been mucking my way through and around the rotatelogs.lo code in 2.059, 2.0.61, and 2.2.4.  Found a -l option and a local option and tried them, but without success.  "local" just produces naming conventions six hours ahead.  I am considering switching my standards for log file naming convention to GMT.

Sadly, I have been unable to weed through the search engine (google, yahoo, etc..) noise of hundreds of hits, regardless of how granular I attempt to make the search query, to find someone experiencing the same issue or a clear fix.

Positive note is the log_config mod is writing the timestamp entries properly in the logs.  So it doesn't take a rocket scientist to quickly figure out he or she needs to go back to the previous log to look for what is of interest.

I'll keep at it, but it is an eye sore for my anal personality and I have accounted for log deletion and pulling with regular-expressions.   I have to tell management it is the price you pay for open source self compiled and maintained software.  I don't have any C programming background, just UNIX Shell, Perl, Python, and a small bit of Java.
What exact level of Apache are you running?  I don't have any C programming background either, but I will more than willing to look at the code.
O.K.  I think I figured it out.  You have the rotatelogs command wrong.

You are CST time, which means you are 6 hours behind GMT.  In your rotatelogs command you have your UTC offset coded as -300, which is 5 hours.

You need to change the -300 to -360 or possibly use the -l option.  
I have re-read and re-read the rotatelogs man page and based on my interpretation you should be able to leave the offset off and use the -l option.

My guess is that it appeared to be working before, because -300 would be correct while you are under DST.
O.K.  After reading it again.  You can't use -l if your timezone offset changes.  So if you have DST in your area, you can NOT use -l.

This means you have two options:  

Leave the offset off of the rotatelogs command and it will use GMT time for the time stamp.

Use the offset on the rotatelogs command, but you will need to change it between -300 and -360 whenever DST changes.
dmwaffAuthor Commented:
Thanks,  I completely forgot I set an offset -360 correct it.  I was so used to looking at that line and using -300.  I was blindly focused on was working and now it was not working.   I'll probably switch to GMT, but I will discuss with the team.  Thanks again.
You know, I can't remember how many times a simple answer was staring me in the face and I never saw it.  :)

The advantage of GMT time is that when you switch between standard and daylight savings time, you have no conflicts with the timestamps on the log names.  The dis-advantage, you have to alter the time in your mind to look at the correct logs.  

The advantage of using local time on the log names, is, no math involved, you want to look at what happen during a specific time period, you go to that log.  The disadvantage is when the time changes, you have to change the offset and you will have some type of conflict with log names and you could end up loosing 1 hour worth of logs.
Question has a verified solution.

Are you are experiencing a similar issue? Get a personalized answer when you ask a related question.

Have a better answer? Share it in a comment.

Join & Write a Comment

Featured Post

Free Tool: Site Down Detector

Helpful to verify reports of your own downtime, or to double check a downed website you are trying to access.

One of a set of tools we are providing to everyone as a way of saying thank you for being a part of the community.

  • 7
  • 5
Tackle projects and never again get stuck behind a technical roadblock.
Join Now