ruby-changes:31432
From: naruse <ko1@a...>
Date: Sat, 2 Nov 2013 07:15:06 +0900 (JST)
Subject: [ruby-changes:31432] naruse:r43511 (trunk): * lib/logger.rb: Inter-process locking for log rotation
naruse 2013-11-02 07:14:42 +0900 (Sat, 02 Nov 2013) New Revision: 43511 http://svn.ruby-lang.org/cgi-bin/viewvc.cgi?view=rev&revision=43511 Log: * lib/logger.rb: Inter-process locking for log rotation Current implementation fails log rotation on multi process env. by sonots <sonots@g...> https://github.com/ruby/ruby/pull/428 fix GH-428 [Bug #9046] Modified files: trunk/ChangeLog trunk/lib/logger.rb trunk/test/logger/test_logger.rb Index: ChangeLog =================================================================== --- ChangeLog (revision 43510) +++ ChangeLog (revision 43511) @@ -1,3 +1,10 @@ https://github.com/ruby/ruby/blob/trunk/ChangeLog#L1 +Sat Nov 2 07:08:43 2013 NARUSE, Yui <naruse@r...> + + * lib/logger.rb: Inter-process locking for log rotation + Current implementation fails log rotation on multi process env. + by sonots <sonots@g...> + https://github.com/ruby/ruby/pull/428 fix GH-428 [Bug #9046] + Fri Nov 1 23:24:31 2013 Nobuyoshi Nakada <nobu@r...> * gc.c (wmap_mark_map): mark live objects only, but delete zombies. Index: lib/logger.rb =================================================================== --- lib/logger.rb (revision 43510) +++ lib/logger.rb (revision 43511) @@ -588,24 +588,32 @@ private https://github.com/ruby/ruby/blob/trunk/lib/logger.rb#L588 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,14 +622,47 @@ private https://github.com/ruby/ruby/blob/trunk/lib/logger.rb#L622 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 Index: test/logger/test_logger.rb =================================================================== --- test/logger/test_logger.rb (revision 43510) +++ test/logger/test_logger.rb (revision 43511) @@ -472,6 +472,111 @@ class TestLogDevice < Test::Unit::TestCa https://github.com/ruby/ruby/blob/trunk/test/logger/test_logger.rb#L472 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 -- ML: ruby-changes@q... Info: http://www.atdot.net/~ko1/quickml/