From: "no6v (Nobuhiro IMAI)" <nov@...>
Date: 2013-11-25T09:23:15+09:00
Subject: [ruby-core:58557] [ruby-trunk - Bug #9133] logger rotates log files	more than expected


Issue #9133 has been updated by no6v (Nobuhiro IMAI).


After that, the @logdev.dev of process A is "log.0", so #9133 happens.
I wrote a test for this issue, also fixes #9133.

diff --git a/lib/logger.rb b/lib/logger.rb
index c70b091..071594d 100644
--- a/lib/logger.rb
+++ b/lib/logger.rb
@@ -645,7 +645,7 @@ private
           File.open(@filename, File::WRONLY | File::APPEND) do |lock|
             lock.flock(File::LOCK_EX) # inter-process locking. will be unlocked at closing file
             ino = lock.stat.ino
-            if ino == File.stat(@filename).ino
+            if ino == File.stat(@filename).ino and ino == @dev.stat.ino
               yield # log shifting
             else
               # log shifted by another process (i-node before locking and i-node after locking are different)
diff --git a/test/logger/test_logger.rb b/test/logger/test_logger.rb
index 04bf779..75da962 100644
--- a/test/logger/test_logger.rb
+++ b/test/logger/test_logger.rb
@@ -2,6 +2,7 @@
 require 'test/unit'
 require 'logger'
 require 'tempfile'
+require 'tmpdir'
 require_relative '../ruby/envutil'
 
 
@@ -542,6 +543,46 @@ class TestLogDevice < Test::Unit::TestCase
     end
   end
 
+  def test_shifting_size_not_rotate_too_much
+    d(@filename).__send__(:add_log_header, @tempfile)
+    header_size = @tempfile.size
+    message = "*" * 99 + "\n"
+    shift_size = header_size + message.size * 3 - 1
+    opt = {shift_age: 1, shift_size: shift_size}
+
+    Dir.mktmpdir do |tmpdir|
+      begin
+        log = File.join(tmpdir, "log")
+        logdev1 = d(log, opt)
+        logdev2 = d(log, opt)
+
+        ino = File.stat(log).ino
+        assert_equal(ino, logdev1.dev.stat.ino)
+        assert_equal(ino, logdev2.dev.stat.ino)
+
+        3.times{logdev1.write(message)}
+        assert_equal(ino, logdev1.dev.stat.ino)
+        assert_equal(ino, logdev2.dev.stat.ino)
+
+        logdev1.write(message)
+        assert_equal(File.stat(log).ino, logdev1.dev.stat.ino)
+        assert_equal(ino, logdev2.dev.stat.ino)
+
+        logdev2.write(message)
+        ino = File.stat(log).ino
+        assert_equal(ino, logdev1.dev.stat.ino)
+        assert_equal(ino, logdev2.dev.stat.ino)
+
+        logdev1.write(message)
+        assert_equal(ino, logdev1.dev.stat.ino)
+        assert_equal(ino, logdev2.dev.stat.ino)
+      ensure
+        logdev1.close if logdev1
+        logdev2.close if logdev2
+      end
+    end
+  end
+
   private
 
   def run_children(n, args, src)

----------------------------------------
Bug #9133: logger rotates log files more than expected
https://bugs.ruby-lang.org/issues/9133#change-43135

Author: no6v (Nobuhiro IMAI)
Status: Open
Priority: Normal
Assignee: 
Category: lib
Target version: 
ruby -v: ruby 2.1.0dev (2013-11-18 trunk 43704) [x86_64-linux]
Backport: 1.9.3: UNKNOWN, 2.0.0: UNKNOWN


=begin
(This may be a same problem as #9130, but this also happens with 2.0.0 and 1.9.3.)

Logger rotates log files more than expected as follow:

 SH> rm -f log*
 A>> logger = Logger.new("log", 1, 200)
 B>> logger = Logger.new("log", 1, 200)
 SH> ls -r | xargs head -v
 ==> log <==
 # Logfile created on 2013-11-21 11:02:25 +0900 by logger.rb/31641
 A>> 3.times{logger.fatal("FATAL")}
 SH> ls -r | xargs head -v
 ==> log <==
 # Logfile created on 2013-11-21 11:02:25 +0900 by logger.rb/31641
 F, [2013-11-21T11:02:46.935514 #3164] FATAL -- : FATAL
 F, [2013-11-21T11:02:46.935700 #3164] FATAL -- : FATAL
 F, [2013-11-21T11:02:46.935767 #3164] FATAL -- : FATAL
 A>> logger.debug("DEBUG") # <- trigger for rotation
 SH> ls -r | xargs head -v
 ==> log.0 <==
 # Logfile created on 2013-11-21 11:02:25 +0900 by logger.rb/31641
 F, [2013-11-21T11:02:46.935514 #3164] FATAL -- : FATAL
 F, [2013-11-21T11:02:46.935700 #3164] FATAL -- : FATAL
 F, [2013-11-21T11:02:46.935767 #3164] FATAL -- : FATAL
 
 ==> log <==
 # Logfile created on 2013-11-21 11:03:00 +0900 by logger.rb/31641
 D, [2013-11-21T11:03:00.301294 #3164] DEBUG -- : DEBUG
 B>> logger.debug("DEBUG") # <- also trigger for rotation (unintended)
 SH> ls -r | xargs head -v
 ==> log.0 <==
 # Logfile created on 2013-11-21 11:03:00 +0900 by logger.rb/31641
 D, [2013-11-21T11:03:00.301294 #3164] DEBUG -- : DEBUG
 
 ==> log <==
 # Logfile created on 2013-11-21 11:03:11 +0900 by logger.rb/31641
 D, [2013-11-21T11:03:11.315164 #3169] DEBUG -- : DEBUG

In this case, two DEBUG lines displace the three FATAL lines even
though enough space is still left on "log" at that time.

Logger decides to rotate log files by checking @logdev.dev.stat.size.
In case of @logdev.dev already rotated by another process, so logger
actually checks the size of "log.0".

Trunk can be fixed by a patch in #9130 (#note-1).
=end



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