Bug #9130

logger continues to write in old log file after rotation

Added by Nobuhiro IMAI 5 months ago. Updated 4 months ago.

[ruby-core:58442]
Status:Closed
Priority:Normal
Assignee:Nobuyoshi Nakada
Category:lib
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

Description

=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


Related issues

Related to ruby-trunk - Bug #9046: [PATCH] Inter-process locking for log rotation is required Closed 10/23/2013
Duplicated by ruby-trunk - Bug #9133: logger rotates log files more than expected Closed 11/21/2013

History

#1 Updated by Nobuhiro IMAI 5 months ago

=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

#2 Updated by Tomoyuki Chikanaga 5 months ago

  • Status changed from Open to Assigned
  • Assignee set to 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.

#3 Updated by Nobuhiro IMAI 5 months ago

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 -- :

#4 Updated by Tomoyuki Chikanaga 5 months ago

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.

#5 Updated by Tomoyuki Chikanaga 4 months ago

  • Status changed from Assigned to Closed
  • Assignee changed from Yui NARUSE to Nobuyoshi Nakada

fixed by r44203.

Also available in: Atom PDF