diff options
| -rw-r--r-- | ChangeLog | 7 | ||||
| -rw-r--r-- | lib/logger.rb | 57 | ||||
| -rw-r--r-- | test/logger/test_logger.rb | 105 |
3 files changed, 161 insertions, 8 deletions
@@ -1,3 +1,10 @@ +Sat Nov 2 07:08:43 2013 NARUSE, Yui <naruse@ruby-lang.org> + + * lib/logger.rb: Inter-process locking for log rotation + Current implementation fails log rotation on multi process env. + by sonots <sonots@gmail.com> + https://github.com/ruby/ruby/pull/428 fix GH-428 [Bug #9046] + Fri Nov 1 23:24:31 2013 Nobuyoshi Nakada <nobu@ruby-lang.org> * gc.c (wmap_mark_map): mark live objects only, but delete zombies. diff --git a/lib/logger.rb b/lib/logger.rb index f24b20b1a6..2eb4e642d2 100644 --- a/lib/logger.rb +++ b/lib/logger.rb @@ -588,24 +588,32 @@ private private def open_logfile(filename) - if (FileTest.exist?(filename)) + begin open(filename, (File::WRONLY | File::APPEND)) - else + rescue Errno::ENOENT create_logfile(filename) end end def create_logfile(filename) - logdev = open(filename, (File::WRONLY | File::APPEND | File::CREAT)) - logdev.sync = true - add_log_header(logdev) + begin + logdev = open(filename, (File::WRONLY | File::APPEND | File::CREAT | File::EXCL)) + logdev.flock(File::LOCK_EX) + logdev.sync = true + add_log_header(logdev) + logdev.flock(File::LOCK_UN) + rescue Errno::EEXIST + # file is created by another process + logdev = open_logfile(filename) + logdev.sync = true + end logdev end def add_log_header(file) file.write( "# Logfile created on %s by %s\n" % [Time.now.to_s, Logger::ProgName] - ) + ) if file.size == 0 end SiD = 24 * 60 * 60 @@ -614,17 +622,50 @@ private 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 + lock_shift_log { shift_log_age } end else now = Time.now period_end = previous_period_end(now) if @dev.stat.mtime <= period_end - shift_log_period(period_end) + lock_shift_log { shift_log_period(period_end) } end end end + def lock_shift_log + begin + retry_limit = 8 + retry_sleep = 0.1 + begin + 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 + yield # log shifting + else + # log shifted by another process (i-node before locking and i-node after locking are different) + @dev.close rescue nil + @dev = open_logfile(@filename) + @dev.sync = true + end + end + rescue Errno::ENOENT + # @filename file would not exist right after #rename and before #create_logfile + if retry_limit <= 0 + warn("log rotation inter-process lock failed. #{$!}") + else + sleep retry_sleep + retry_limit -= 1 + retry_sleep *= 2 + retry + end + end + rescue + warn("log rotation inter-process lock failed. #{$!}") + end + end + def shift_log_age (@shift_age-3).downto(0) do |i| if FileTest.exist?("#{@filename}.#{i}") diff --git a/test/logger/test_logger.rb b/test/logger/test_logger.rb index eac2c7a5a6..92f27dfe93 100644 --- a/test/logger/test_logger.rb +++ b/test/logger/test_logger.rb @@ -472,6 +472,111 @@ class TestLogDevice < Test::Unit::TestCase end end end + + def test_shifting_size_in_multiprocess + tmpfile = Tempfile.new([File.basename(__FILE__, '.*'), '_1.log']) + logfile = tmpfile.path + logfile0 = logfile + '.0' + logfile1 = logfile + '.1' + logfile2 = logfile + '.2' + logfile3 = logfile + '.3' + tmpfile.close(true) + 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) + begin + logger = Logger.new(logfile, 4, 10) + r, w = IO.pipe + $stderr = w # To capture #warn output in Logger + pid1 = Process.fork do + 10.times do + logger.info '0' * 15 + end + end + pid2 = Process.fork do + 10.times do + logger.info '0' * 15 + end + end + Process.waitpid pid1 + Process.waitpid pid2 + w.close + stderr = r.read + r.close + assert_no_match(/log shifting failed/, stderr) + assert_no_match(/log writing failed/, stderr) + assert_no_match(/log rotation inter-process lock failed/, stderr) + ensure + $stderr = STDERR # restore + logger.close if logger + 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) + end + end + + def test_shifting_age_in_multiprocess + yyyymmdd = Time.now.strftime("%Y%m%d") + filename1 = @filename + ".#{yyyymmdd}" + filename2 = @filename + ".#{yyyymmdd}.1" + filename3 = @filename + ".#{yyyymmdd}.2" + begin + logger = Logger.new(@filename, 'now') + r, w = IO.pipe + $stderr = w # To capture #warn output in Logger + pid1 = Process.fork do + 10.times do + logger.info '0' * 15 + end + end + pid2 = Process.fork do + 10.times do + logger.info '0' * 15 + end + end + Process.waitpid pid1 + Process.waitpid pid2 + w.close + stderr = r.read + r.close + assert_no_match(/log shifting failed/, stderr) + assert_no_match(/log writing failed/, stderr) + assert_no_match(/log rotation inter-process lock failed/, stderr) + ensure + $stderr = STDERR # restore + logger.close if logger + [filename1, filename2, filename3].each do |filename| + File.unlink(filename) if File.exist?(filename) + end + end + end + + def test_open_logfile_in_multiprocess + tmpfile = Tempfile.new([File.basename(__FILE__, '.*'), '_1.log']) + logfile = tmpfile.path + tmpfile.close(true) + logdev = Logger::LogDevice.new(logfile) + File.unlink(logfile) if File.exist?(logfile) + begin + 20.times do + pid1 = Process.fork do + logdev.send(:open_logfile, logfile) + end + pid2 = Process.fork do + logdev.send(:open_logfile, logfile) + end + Process.waitpid pid1 + Process.waitpid pid2 + assert_not_equal(2, File.readlines(logfile).grep(/# Logfile created on/).size) + File.unlink(logfile) + end + ensure + logdev.close if logdev + File.unlink(logfile) if File.exist?(logfile) + end + end end |