* 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/branches/ruby_1_8@9011 b2dd03c8-39d4-4d8f-98ff-823fe69b080e

3 files changed, 141 insertions, 73 deletions

diff --git a/ChangeLog b/ChangeLog
index df9603936f..7d39cdca13 100644
--- a/ChangeLog
+++ b/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 
diff --git a/lib/logger.rb b/lib/logger.rb
index 1162e31f3c..52e5a45684 100644
--- a/lib/logger.rb
+++ b/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,22 +513,25 @@ private
     # mixed.
     #
     def write(message)
-      if shift_log?
-       	begin
-  	  shift_log
-   	rescue
-  	  raise Logger::ShiftingError.new("Shifting failed. #{$!}")
-   	end
+      @mutex.synchronize do
+        if @shift_age and @dev.respond_to?(:stat)
+          begin
+            check_shift_log
+          rescue
+            raise Logger::ShiftingError.new("Shifting failed. #{$!}")
+          end
+        end
+        @dev.write(message)
       end
-
-      @dev.write(message)
     end
 
     #
     # Close the logging device.
     #
     def close
-      @dev.close
+      @mutex.synchronize do
+        @dev.close
+      end
     end
 
   private
@@ -551,66 +559,57 @@ private
 
     SiD = 24 * 60 * 60
 
-    def shift_log?
-      if !@shift_age or !@dev.respond_to?(:stat)
-     	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))
+    def check_shift_log
+      if @shift_age.is_a?(Integer)
+        # Note: always returns false if '0'.
+        if @filename && (@shift_age > 0) && (@dev.stat.size > @shift_size)
+          shift_log_age
+        end
       else
-	now = Time.now
-	limit_time = case @shift_age
-	  when /^daily$/
-	    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)
+        now = Time.now
+        if @dev.stat.mtime <= previous_period_end(now)
+          shift_log_period(now)
+        end
       end
     end
 
-    def shift_log
-      # 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}"))
-	    File.rename("#{@filename}.#{i}", "#{@filename}.#{i+1}")
-	  end
-	end
-	File.rename("#{@filename}", "#{@filename}.0")
-      else
-	now = Time.now
-	postfix_time = case @shift_age
-	  when /^daily$/
-	    eod(now - 1 * SiD)
-	  when /^weekly$/
-	    eod(now - ((now.wday + 1) * SiD))
-	  when /^monthly$/
-	    eod(now - now.mday * SiD)
-	  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)
+    def shift_log_age
+      (@shift_age-3).downto(0) do |i|
+        if FileTest.exist?("#{@filename}.#{i}")
+          File.rename("#{@filename}.#{i}", "#{@filename}.#{i+1}")
+        end
       end
+      @dev.close
+      File.rename("#{@filename}", "#{@filename}.0")
+      @dev = create_logfile(@filename)
+      return true
+    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$/
+        eod(now - ((now.wday + 1) * SiD))
+      when /^monthly$/
+        eod(now - now.mday * SiD)
+      else
+        now
+      end
+    end
+
     def eod(t)
       Time.mktime(t.year, t.month, t.mday, 23, 59, 59)
     end
diff --git a/test/logger/test_logger.rb b/test/logger/test_logger.rb
index c953a89d9c..3528ff21e2 100644
--- a/test/logger/test_logger.rb
+++ b/test/logger/test_logger.rb
@@ -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"
-    #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@"
+    logger.datetime_format = "%d%b%Y@%H:%M:%S"
     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)
@@ -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