Project

General

Profile

Bug #713

DST bug in Logger

Added by ckhall (Chris Hall) about 11 years ago. Updated over 8 years ago.

Status:
Closed
Priority:
Normal
Assignee:
-
Target version:
-
ruby -v:
[ruby-core:19711]

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

History

#1

Updated by shyouhei (Shyouhei Urabe) almost 11 years ago

  • Status changed from Open to Closed

=begin
refer [ruby-core:19712].
=end

Also available in: Atom PDF