* lib/logger.rb (write, shift_log?, shift_log): file shifting race

condition bug fixed.  [ruby-dev:26764]

        * test/logger/test_logger.rb: tests.


git-svn-id: svn+ssh://ci.ruby-lang.org/ruby/trunk@9011 b2dd03c8-39d4-4d8f-98ff-823fe69b080e

ChangeLog

@@ -1,3 +1,10 @@
+Sat Aug 20 22:37:13 2005  NAKAMURA, Hiroshi  <nakahiro@sarion.co.jp>
+
+	* lib/logger.rb (write, shift_log?, shift_log): file shifting race
+	  condition bug fixed.  [ruby-dev:26764]
+
+	* test/logger/test_logger.rb: tests.
+
 Fri Aug 19 18:13:39 2005  Tanaka Akira  <akr@m17n.org>
 
 	* lib/time.rb (Time.apply_offset): fix a problem with last day of

lib/logger.rb

@@ -1,4 +1,7 @@
-#
+# logger.rb - saimple logging utility
+# Copyright (C) 2000-2003, 2005  NAKAMURA, Hiroshi <nakahiro@sarion.co.jp>.
+
+
 # = logger.rb
 #
 # Simple logging utility.
@@ -19,7 +22,6 @@
 #
 # The Logger class provides a simple but sophisticated logging utility that
 # anyone can use because it's included in the Ruby 1.8.x standard library.
-# For more advanced logging, see the "Log4r" package on the RAA.
 #
 # The HOWTOs below give a code-based overview of Logger's usage, but the basic
 # concept is as follows.  You create a Logger object (output to a file or
@@ -76,10 +78,6 @@
 # specifying a program name in conjunction with the message.  The next section
 # shows you how to achieve these things.
 #
-# See http://raa.ruby-lang.org/list.rhtml?name=log4r for Log4r, which contains
-# many advanced features like file-based configuration, a wide range of
-# logging targets, simultaneous logging, and hierarchical logging.
-#
 #
 # == HOWTOs
 #
@@ -174,6 +172,11 @@
 # There is currently no supported way to change the overall format, but you may
 # have some luck hacking the Format constant.
 #
+
+
+require 'monitor'
+
+
 class Logger
   /: (\S+),v (\S+)/ =~ %q$Id$
   ProgName = "#{$1}/#{$2}"
@@ -490,6 +493,8 @@ private
     #
     def initialize(log = nil, opt = {})
       @dev = @filename = @shift_age = @shift_size = nil
+      @mutex = Object.new
+      @mutex.extend(MonitorMixin)
       if log.respond_to?(:write) and log.respond_to?(:close)
 	@dev = log
       else
@@ -508,23 +513,26 @@ private
     # mixed.
     #
     def write(message)
-      if shift_log?
+      @mutex.synchronize do
+        if @shift_age and @dev.respond_to?(:stat)
           begin
-  	  shift_log
+            check_shift_log
           rescue
             raise Logger::ShiftingError.new("Shifting failed. #{$!}")
           end
         end
-
         @dev.write(message)
       end
+    end
 
     #
     # Close the logging device.
     #
     def close
+      @mutex.synchronize do
         @dev.close
       end
+    end
 
   private
 
@@ -551,45 +559,46 @@ private
 
     SiD = 24 * 60 * 60
 
-    def shift_log?
+    def check_shift_log
-      if !@shift_age or !@dev.respond_to?(:stat)
+      if @shift_age.is_a?(Integer)
-     	return false
-      end
-      if (@shift_age.is_a?(Integer))
         # Note: always returns false if '0'.
-	return (@filename && (@shift_age > 0) && (@dev.stat.size > @shift_size))
+        if @filename && (@shift_age > 0) && (@dev.stat.size > @shift_size)
+          shift_log_age
+        end
       else
         now = Time.now
-	limit_time = case @shift_age
+        if @dev.stat.mtime <= previous_period_end(now)
-	  when /^daily$/
+          shift_log_period(now)
-	    eod(now - 1 * SiD)
-	  when /^weekly$/
-	    eod(now - ((now.wday + 1) * SiD))
-	  when /^monthly$/
-	    eod(now - now.mday * SiD)
-	  else
-	    now
         end
-	return (@dev.stat.mtime <= limit_time)
       end
     end
 
-    def shift_log
+    def shift_log_age
-      # At first, close the device if opened.
-      if @dev
-      	@dev.close
-       	@dev = nil
-      end
-      if (@shift_age.is_a?(Integer))
       (@shift_age-3).downto(0) do |i|
-	  if (FileTest.exist?("#{@filename}.#{i}"))
+        if FileTest.exist?("#{@filename}.#{i}")
           File.rename("#{@filename}.#{i}", "#{@filename}.#{i+1}")
         end
       end
+      @dev.close
       File.rename("#{@filename}", "#{@filename}.0")
-      else
+      @dev = create_logfile(@filename)
-	now = Time.now
+      return true
-	postfix_time = case @shift_age
+    end
+
+    def shift_log_period(now)
+      postfix = previous_period_end(now).strftime("%Y%m%d")	# YYYYMMDD
+      age_file = "#{@filename}.#{postfix}"
+      if FileTest.exist?(age_file)
+        raise RuntimeError.new("'#{ age_file }' already exists.")
+      end
+      @dev.close
+      File.rename("#{@filename}", age_file)
+      @dev = create_logfile(@filename)
+      return true
+    end
+
+    def previous_period_end(now)
+      case @shift_age
       when /^daily$/
         eod(now - 1 * SiD)
       when /^weekly$/
@@ -599,16 +608,6 @@ private
       else
         now
       end
-	postfix = postfix_time.strftime("%Y%m%d")	# YYYYMMDD
-	age_file = "#{@filename}.#{postfix}"
-	if (FileTest.exist?(age_file))
-	  raise RuntimeError.new("'#{ age_file }' already exists.")
-	end
-	File.rename("#{@filename}", age_file)
-      end
-
-      @dev = create_logfile(@filename)
-      return true
     end
 
     def eod(t)

test/logger/test_logger.rb

@@ -32,10 +32,10 @@ class TestLogger < Test::Unit::TestCase
   end
 
   def log_add(logger, severity, msg, progname = nil, &block)
-    do_log(logger, :add, severity, msg, progname, &block)
+    log(logger, :add, severity, msg, progname, &block)
   end
 
-  def do_log(logger, msg_id, *arg, &block)
+  def log(logger, msg_id, *arg, &block)
     logdev = Tempfile.new(File.basename(__FILE__) + '.log')
     logger.instance_eval { @logdev = Logger::LogDevice.new(logdev) }
     logger.__send__(msg_id, *arg, &block)
@@ -90,15 +90,9 @@ class TestLogger < Test::Unit::TestCase
     logger = Logger.new(dummy)
     log = log_add(logger, INFO, "foo")
     assert_match(/^\d\d\d\d-\d\d-\d\dT\d\d:\d\d:\d\d.\s*\d+ $/, log.datetime)
-    # [ruby-dev:24828]
+    logger.datetime_format = "%d%b%Y@%H:%M:%S"
-    #logger.datetime_format = "%d%b%Y@%H:%M:%S"
-    #log = log_add(logger, INFO, "foo")
-    #assert_match(/^\d\d\w\w\w\d\d\d\d@\d\d:\d\d:\d\d$/, log.datetime)
-    #
-    # don't run the next test at 23:59, or just run again if failed.
-    logger.datetime_format = "@%d%b%Y@"
     log = log_add(logger, INFO, "foo")
-    assert_equal(Time.now.strftime("@%d%b%Y@"), log.datetime)
+    assert_match(/^\d\d\w\w\w\d\d\d\d@\d\d:\d\d:\d\d$/, log.datetime)
     logger.datetime_format = ""
     log = log_add(logger, INFO, "foo")
     assert_match(/^$/, log.datetime)
@@ -134,44 +128,44 @@ class TestLogger < Test::Unit::TestCase
   def test_level_log
     logger = Logger.new(nil)
     logger.progname = "my_progname"
-    log = do_log(logger, :debug, "custom_progname") { "msg" }
+    log = log(logger, :debug, "custom_progname") { "msg" }
     assert_equal("msg\n", log.msg)
     assert_equal("custom_progname", log.progname)
     assert_equal("DEBUG", log.severity)
     assert_equal("D", log.label)
     #
-    log = do_log(logger, :debug) { "msg_block" }
+    log = log(logger, :debug) { "msg_block" }
     assert_equal("msg_block\n", log.msg)
     assert_equal("my_progname", log.progname)
-    log = do_log(logger, :debug, "msg_inline")
+    log = log(logger, :debug, "msg_inline")
     assert_equal("msg_inline\n", log.msg)
     assert_equal("my_progname", log.progname)
     #
-    log = do_log(logger, :info, "custom_progname") { "msg" }
+    log = log(logger, :info, "custom_progname") { "msg" }
     assert_equal("msg\n", log.msg)
     assert_equal("custom_progname", log.progname)
     assert_equal("INFO", log.severity)
     assert_equal("I", log.label)
     #
-    log = do_log(logger, :warn, "custom_progname") { "msg" }
+    log = log(logger, :warn, "custom_progname") { "msg" }
     assert_equal("msg\n", log.msg)
     assert_equal("custom_progname", log.progname)
     assert_equal("WARN", log.severity)
     assert_equal("W", log.label)
     #
-    log = do_log(logger, :error, "custom_progname") { "msg" }
+    log = log(logger, :error, "custom_progname") { "msg" }
     assert_equal("msg\n", log.msg)
     assert_equal("custom_progname", log.progname)
     assert_equal("ERROR", log.severity)
     assert_equal("E", log.label)
     #
-    log = do_log(logger, :fatal, "custom_progname") { "msg" }
+    log = log(logger, :fatal, "custom_progname") { "msg" }
     assert_equal("msg\n", log.msg)
     assert_equal("custom_progname", log.progname)
     assert_equal("FATAL", log.severity)
     assert_equal("F", log.label)
     #
-    log = do_log(logger, :unknown, "custom_progname") { "msg" }
+    log = log(logger, :unknown, "custom_progname") { "msg" }
     assert_equal("msg\n", log.msg)
     assert_equal("custom_progname", log.progname)
     assert_equal("ANY", log.severity)
@@ -279,4 +273,72 @@ class TestLogDevice < Test::Unit::TestCase
     assert(w.closed?)
     r.close
   end
+
+  def test_shifting_size
+    logfile = File.basename(__FILE__) + '_1.log'
+    logfile0 = logfile + '.0'
+    logfile1 = logfile + '.1'
+    logfile2 = logfile + '.2'
+    logfile3 = logfile + '.3'
+    File.unlink(logfile) if File.exist?(logfile)
+    File.unlink(logfile0) if File.exist?(logfile0)
+    File.unlink(logfile1) if File.exist?(logfile1)
+    File.unlink(logfile2) if File.exist?(logfile2)
+    logger = Logger.new(logfile, 4, 100)
+    logger.error("0" * 15)
+    assert(File.exist?(logfile))
+    assert(!File.exist?(logfile0))
+    logger.error("0" * 15)
+    assert(File.exist?(logfile0))
+    assert(!File.exist?(logfile1))
+    logger.error("0" * 15)
+    assert(File.exist?(logfile1))
+    assert(!File.exist?(logfile2))
+    logger.error("0" * 15)
+    assert(File.exist?(logfile2))
+    assert(!File.exist?(logfile3))
+    logger.error("0" * 15)
+    assert(!File.exist?(logfile3))
+    logger.error("0" * 15)
+    assert(!File.exist?(logfile3))
+    File.unlink(logfile)
+    File.unlink(logfile0)
+    File.unlink(logfile1)
+    File.unlink(logfile2)
+
+    logfile = File.basename(__FILE__) + '_2.log'
+    logfile0 = logfile + '.0'
+    logfile1 = logfile + '.1'
+    logfile2 = logfile + '.2'
+    logfile3 = logfile + '.3'
+    logger = Logger.new(logfile, 4, 150)
+    logger.error("0" * 15)
+    assert(File.exist?(logfile))
+    assert(!File.exist?(logfile0))
+    logger.error("0" * 15)
+    assert(!File.exist?(logfile0))
+    logger.error("0" * 15)
+    assert(File.exist?(logfile0))
+    assert(!File.exist?(logfile1))
+    logger.error("0" * 15)
+    assert(!File.exist?(logfile1))
+    logger.error("0" * 15)
+    assert(File.exist?(logfile1))
+    assert(!File.exist?(logfile2))
+    logger.error("0" * 15)
+    assert(!File.exist?(logfile2))
+    logger.error("0" * 15)
+    assert(File.exist?(logfile2))
+    assert(!File.exist?(logfile3))
+    logger.error("0" * 15)
+    assert(!File.exist?(logfile3))
+    logger.error("0" * 15)
+    assert(!File.exist?(logfile3))
+    logger.error("0" * 15)
+    assert(!File.exist?(logfile3))
+    File.unlink(logfile)
+    File.unlink(logfile0)
+    File.unlink(logfile1)
+    File.unlink(logfile2)
+  end
 end