Bug #713
closedDST bug in Logger
Description
=begin
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,
=end
Updated by shyouhei (Shyouhei Urabe) about 15 years ago
- Status changed from Open to Closed
=begin
refer [ruby-core:19712].
=end