Tests for Rails logger thread safety

log_silencer_test.rb

# Activate the gem you are reporting the issue against.
gem 'activesupport', '4.2.1'

require 'active_support/logger'
require 'minitest/autorun'

# Ensure backward compatibility with Minitest 4
Minitest::Test = MiniTest::Unit::TestCase unless defined?(Minitest::Test)

class BugTest < Minitest::Test

  def test_logger_silence_thread_safety
    logger = ActiveSupport::Logger.new(STDOUT)
    logger.level = ::Logger::INFO

    # Create a new thread that will log using the silencer
    test_thread = Thread.new do
      logger.silence do
        assert logger.level == ::Logger::ERROR
        sleep(3)
      end
    end

    # Make sure our other thread runs if we are on MRI
    sleep(1)

    logger_level_during_silence = logger.level
    test_thread.join
    assert logger.level == ::Logger::INFO
    assert logger_level_during_silence == ::Logger::INFO, "Expected #{logger.level}, got #{logger_level_during_silence}"
  end

  def test_concurrent_silencers
    logger = ActiveSupport::Logger.new(STDOUT)
    logger.level = ::Logger::INFO

    thread1 = Thread.new do
      logger.silence do
        sleep(4)
      end
    end

    # Make sure our thread 1 starts if on MRI
    sleep(1)

    thread2 = Thread.new do
      # Since thread 1 already set the level to ERROR, #silence saves that as the current log level
      logger.silence do
        sleep(6)
        # By this point, thread 1 will have set the value back to INFO, this is the same issue as the test above
        assert logger.level == ::Logger::INFO, "Expected #{::Logger::INFO}, got #{logger.level}"
      end
    end

    # Make sure our thread 2 starts if on MRI
    sleep(1)

    thread1.join
    thread2.join

    # By this point, thread 2 will have set the level back to ERROR because that is what it was when the #silence
    # call was made
    assert logger.level == ::Logger::INFO, "Expected #{::Logger::INFO}, got #{logger.level}"
  end
end