Inter-process locking for log rotation

lib/logger.rb

@@ -614,17 +614,51 @@ def check_shift_log
       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
+          lock = File.open(@filename, File::WRONLY | File::APPEND)
+          begin
+            # inter-process locking
+            lock.flock(File::LOCK_EX)
+            ino = lock.stat.ino
+            if ino == File.stat(@filename).ino
+              yield # log shifting
+            else
+              @dev.close rescue nil
+              @dev = File.open(@filename, File::WRONLY | File::APPEND)
+              @dev.sync = true
+            end
+          ensure
+            lock.flock(File::LOCK_UN)
+            lock.close
+          end
+        rescue Errno::ENOENT => e
+          # @filename file would not exist right after #rename and before #create_logfile
+          raise e if retry_limit <= 0
+          sleep retry_sleep
+          retry_limit -= 1
+          retry_sleep *= 2
+          retry
+        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}")

test/logger/test_logger.rb

@@ -472,6 +472,86 @@ def test_shifting_age
       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
 end