Merge pull request rails#22968 from rabbitt/bugfix/rails41-logger-threadsafety

4.1 Backport of LoggerSilence#silence Threadsafety patch (see: PR rails#20507)

Author: rafaelfranca

activesupport/lib/active_support/logger.rb

@@ -44,6 +44,20 @@ def self.broadcast(logger) # :nodoc:
     def initialize(*args)
       super
       @formatter = SimpleFormatter.new
+      after_initialize if respond_to? :after_initialize
+    end
+
+    def add(severity, message = nil, progname = nil, &block)
+      return true if @logdev.nil? || (severity || UNKNOWN) < level
+      super
+    end
+
+    Logger::Severity.constants.each do |severity|
+      class_eval(<<-EOT, __FILE__, __LINE__ + 1)
+        def #{severity.downcase}?                # def debug?
+          Logger::#{severity} >= level           #   DEBUG >= level
+        end                                      # end
+      EOT
     end
 
     # Simple formatter which only displays the message.

activesupport/lib/active_support/logger_silence.rb

@@ -1,24 +1,45 @@
 require 'active_support/concern'
+require 'thread_safe'
 
 module LoggerSilence
   extend ActiveSupport::Concern
 
   included do
     cattr_accessor :silencer
+    attr_reader :local_levels
     self.silencer = true
   end
 
+
+  def after_initialize
+    @local_levels = ThreadSafe::Cache.new(:initial_capacity => 2)
+  end
+
+  def local_log_id
+    Thread.current.__id__
+  end
+
+  def level
+    local_levels[local_log_id] || super
+  end
+
   # Silences the logger for the duration of the block.
   def silence(temporary_level = Logger::ERROR)
     if silencer
       begin
-        old_logger_level, self.level = level, temporary_level
+        old_local_level            = local_levels[local_log_id]
+        local_levels[local_log_id] = temporary_level
+
         yield self
       ensure
-        self.level = old_logger_level
+        if old_local_level
+          local_levels[local_log_id] = old_local_level
+        else
+          local_levels.delete(local_log_id)
+        end
       end
     else
       yield self
     end
   end
-end
+end

activesupport/test/logger_test.rb

@@ -3,6 +3,7 @@
 require 'stringio'
 require 'fileutils'
 require 'tempfile'
+require 'active_support/concurrency/latch'
 
 class LoggerTest < ActiveSupport::TestCase
   include MultibyteTestHelpers
@@ -113,21 +114,101 @@ def test_should_know_if_its_loglevel_is_below_a_given_level
   end
 
   def test_buffer_multibyte
+    @logger.level = Logger::INFO
     @logger.info(UNICODE_STRING)
     @logger.info(BYTE_STRING)
     assert @output.string.include?(UNICODE_STRING)
     byte_string = @output.string.dup
     byte_string.force_encoding("ASCII-8BIT")
     assert byte_string.include?(BYTE_STRING)
   end
-  
+
   def test_silencing_everything_but_errors
     @logger.silence do
       @logger.debug "NOT THERE"
       @logger.error "THIS IS HERE"
     end
-    
+
     assert !@output.string.include?("NOT THERE")
     assert @output.string.include?("THIS IS HERE")
   end
+
+  def test_logger_level_per_object_thread_safety
+    logger1 = Logger.new(StringIO.new)
+    logger2 = Logger.new(StringIO.new)
+
+    level = Logger::DEBUG
+    assert_equal level, logger1.level, "Expected level #{level_name(level)}, got #{level_name(logger1.level)}"
+    assert_equal level, logger2.level, "Expected level #{level_name(level)}, got #{level_name(logger2.level)}"
+
+    logger1.level = Logger::ERROR
+    assert_equal level, logger2.level, "Expected level #{level_name(level)}, got #{level_name(logger2.level)}"
+  end
+
+  def test_logger_level_main_thread_safety
+    @logger.level = Logger::INFO
+    assert_level(Logger::INFO)
+
+    latch  = ActiveSupport::Concurrency::Latch.new
+    latch2 = ActiveSupport::Concurrency::Latch.new
+
+    t = Thread.new do
+      latch.await
+      assert_level(Logger::INFO)
+      latch2.release
+    end
+
+    @logger.silence(Logger::ERROR) do
+      assert_level(Logger::ERROR)
+      latch.release
+      latch2.await
+    end
+
+    t.join
+  end
+
+  def test_logger_level_local_thread_safety
+    @logger.level = Logger::INFO
+    assert_level(Logger::INFO)
+
+    thread_1_latch = ActiveSupport::Concurrency::Latch.new
+    thread_2_latch = ActiveSupport::Concurrency::Latch.new
+
+    threads = (1..2).collect do |thread_number|
+      Thread.new do
+        # force thread 2 to wait until thread 1 is already in @logger.silence
+        thread_2_latch.await if thread_number == 2
+
+        @logger.silence(Logger::ERROR) do
+          assert_level(Logger::ERROR)
+          @logger.silence(Logger::DEBUG) do
+            # allow thread 2 to finish but hold thread 1
+            if thread_number == 1
+              thread_2_latch.release
+              thread_1_latch.await
+            end
+            assert_level(Logger::DEBUG)
+          end
+        end
+
+        # allow thread 1 to finish
+        assert_level(Logger::INFO)
+        thread_1_latch.release if thread_number == 2
+      end
+    end
+
+    threads.each(&:join)
+    assert_level(Logger::INFO)
+  end
+
+  private
+    def level_name(level)
+      ::Logger::Severity.constants.find do |severity|
+        Logger.const_get(severity) == level
+      end.to_s
+    end
+
+    def assert_level(level)
+      assert_equal level, @logger.level, "Expected level #{level_name(level)}, got #{level_name(@logger.level)}"
+    end
 end