Bug #9130: logger continues to write in old log file after rotation

• Status: Closed
• Assignee: nobu (Nobuyoshi Nakada)
• Target version: -
• ruby -v: ruby 2.1.0dev (2013-11-18 trunk 43704) [x86_64-linux]
• Backport: 1.9.3: DONTNEED, 2.0.0: DONTNEED

[no6v (Nobuhiro IMAI)]

=begin
Logger continues to write in old log file after rotation as follow:

$ cat l.rb
require "logger"

logdev = "log"
pids = []
2.times do |n|
pids << fork{
logger = Logger.new(logdev, 10, 300)
5.times do
logger.debug("")
sleep(rand * 3)
end
exit
}
end
pids.each do |pid|
Process.waitpid(pid)
end
$ rm -f log*
$ time ruby -v l.rb
ruby 2.1.0dev (2013-11-18 trunk 43704) [x86_64-linux]

real 0m8.498s
user 0m0.044s
sys 0m0.016s
$ ls -ltrn --full-time log*
-rw-r--r-- 1 1000 1000 322 2013-11-20 10:36:40.059247700 +0900 log.1
-rw-r--r-- 1 1000 1000 169 2013-11-20 10:36:41.251247688 +0900 log
-rw-r--r-- 1 1000 1000 220 2013-11-20 10:36:43.851247663 +0900 log.0
$ egrep -Tv '^#' log* | sort -k3
log.1 :D, [2013-11-20T10:36:35.983308 #16870] DEBUG -- :
log.1 :D, [2013-11-20T10:36:35.983409 #16867] DEBUG -- :
log.1 :D, [2013-11-20T10:36:37.194691 #16867] DEBUG -- :
log.1 :D, [2013-11-20T10:36:38.242855 #16870] DEBUG -- :
log.1 :D, [2013-11-20T10:36:40.062467 #16867] DEBUG -- :
log.0 :D, [2013-11-20T10:36:40.347119 #16870] DEBUG -- :
log :D, [2013-11-20T10:36:40.953420 #16867] DEBUG -- :
log :D, [2013-11-20T10:36:41.257187 #16867] DEBUG -- :
log.0 :D, [2013-11-20T10:36:43.145010 #16870] DEBUG -- :
log.0 :D, [2013-11-20T10:36:43.856779 #16870] DEBUG -- :
=end

[no6v (Nobuhiro IMAI)]

=begin
We should also compare inode of @filename and @dev, right?
The following patch works fine for me.

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)
  

=end

[nagachika (Tomoyuki Chikanaga)]

• Status changed from Open to Assigned
• Assignee set to naruse (Yui NARUSE)
• Backport changed from 1.9.3: UNKNOWN, 2.0.0: UNKNOWN to 1.9.3: DONTNEED, 2.0.0: DONTNEED

This issue seems introduced by r43511. So I assign this to naruse san.

[no6v (Nobuhiro IMAI)]

nagachika (Tomoyuki Chikanaga) wrote:

This issue seems introduced by r43511. So I assign this to naruse san.

No. This bug is what logger.rb has been having for a long time.
The above patch fixes the newly implemented method for simplicity.
The actual problem is #9133. Updated patch is also available there.
Please see to it.

$ ruby -v l.rb
ruby 2.0.0p247 (2013-06-27 revision 41674) [x86_64-linux]
$ egrep -Tv '^#' log* | sort -k3
log.1 :D, [2013-12-02T21:19:25.262587 #12207] DEBUG -- :
log.1 :D, [2013-12-02T21:19:25.262713 #12204] DEBUG -- :
log.1 :D, [2013-12-02T21:19:25.577349 #12207] DEBUG -- :
log.1 :D, [2013-12-02T21:19:27.339095 #12204] DEBUG -- :
log.1 :D, [2013-12-02T21:19:27.961317 #12207] DEBUG -- :
log.0 :D, [2013-12-02T21:19:29.225823 #12207] DEBUG -- :
log :D, [2013-12-02T21:19:30.152343 #12204] DEBUG -- :
log.0 :D, [2013-12-02T21:19:31.307252 #12207] DEBUG -- :
log :D, [2013-12-02T21:19:32.378369 #12204] DEBUG -- :
log :D, [2013-12-02T21:19:32.693861 #12204] DEBUG -- :

[nagachika (Tomoyuki Chikanaga)]

Yes, I saw #9133 after I've written the previous comment.
Anyway, this ticket should be opened for trunk. We have to handle these issues separately.

[nagachika (Tomoyuki Chikanaga)]

• Status changed from Assigned to Closed
• Assignee changed from naruse (Yui NARUSE) to nobu (Nobuyoshi Nakada)

fixed by r44203.