From: Chris Hall <redmine@...>
Date: 2008-11-06T13:40:55+09:00
Subject: [ruby-core:19711] [Bug #713] DST bug in Logger

Bug #713: DST bug in Logger
http://redmine.ruby-lang.org/issues/show/713

Author: Chris Hall
Status: Open, Priority: Normal

on 2008-11-02 22:59:59 -0400, Logger raised an exception in a few of our apps.

/usr/lib/ruby/1.8/logger.rb:501:in `write': Shifting failed. '/opt/task_manager/logs/task_manager.log.20081102' already
exists. (Logger::ShiftingError)

I tracked this down to a DST issue.

Logger is set to rotate 'daily'.  So as it did, Logger checked the mtime of the log file and determined that it was
time to rotate.  It created the rotated log fine and created the new log file fine.  Upon the next write however, it appears that the next shift check caused Logger to think it needed to rotate again, and thus caused the exception above.

I built a simple test based on the code from in logger.rb to verify the behavior.

# last time log was written to
>> fmtime = Time.mktime(2008,11,02,22,59,59)
=> Sun Nov 02 22:59:59 -0500 2008

# now
>> now = Time.mktime(2008,11,2,23,0,0)
=> Sun Nov 02 23:00:00 -0500 2008

# shift_log_period
>> t = now - 86400 # previous_period_end(now)
=> Sun Nov 02 00:00:00 -0400 2008
>> ppe = Time.mktime(t.year,t.month,t.day,23,59,59)
=> Sun Nov 02 23:59:59 -0500 2008

# check if log should be rotated
>> fmtime2 <= ppe2
=> true

log gets rotated to .20081102

next rotation check:

>> fmtime2 = Time.mktime(2008,11,02,23,0,0)
=> Sun Nov 02 23:00:01 -0500 2008

>> now2 = Time.mktime(2008,11,2,23,0,1)
=> Sun Nov 02 23:00:01 -0500 2008

# shift_log_period again
>> t2 = now2 - 86400 # previous_period_end(now)
=> Sun Nov 02 00:00:01 -0400 2008
>> ppe2 = Time.mktime(t2.year,t2.month,t2.day,23,59,59)
=> Sun Nov 02 23:59:59 -0500 2008

# check if log should be rotated
>> fmtime2 <= ppe2
=> true

so we see that Logger tries to rotate again, but this time the rotated log already exists, and so it raises the exception.

This issue only appears to show up on period based rotations, specifically if the rotation falls on the day that the clock is turned back,


----------------------------------------
http://redmine.ruby-lang.org