mirror of
https://github.com/rails/rails.git
synced 2022-11-09 12:12:34 -05:00
Fixes LoggerSilence#silence threadsafety
- uses instance defined level if no custom local log level defined - Keeps track of local log level per [ thread + object-instance ] - prevents memory leakage by removing local level hash key/value on #silence method exit - avoids the use of Thread local variables
This commit is contained in:
parent
2ad6deb534
commit
629efb6057
4 changed files with 120 additions and 4 deletions
|
@ -1252,6 +1252,7 @@ class BasicsTest < ActiveRecord::TestCase
|
|||
original_logger = ActiveRecord::Base.logger
|
||||
log = StringIO.new
|
||||
ActiveRecord::Base.logger = ActiveSupport::Logger.new(log)
|
||||
ActiveRecord::Base.logger.level = Logger::DEBUG
|
||||
ActiveRecord::Base.benchmark("Logging", :level => :debug, :silence => false) { ActiveRecord::Base.logger.debug "Quiet" }
|
||||
assert_match(/Quiet/, log.string)
|
||||
ensure
|
||||
|
|
|
@ -46,6 +46,20 @@ module ActiveSupport
|
|||
super
|
||||
@formatter = SimpleFormatter.new
|
||||
@broadcast_messages = true
|
||||
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.
|
||||
|
|
|
@ -1,22 +1,42 @@
|
|||
require 'active_support/concern'
|
||||
require 'active_support/core_ext/module/attribute_accessors'
|
||||
require 'concurrent'
|
||||
|
||||
module LoggerSilence
|
||||
extend ActiveSupport::Concern
|
||||
|
||||
included do
|
||||
cattr_accessor :silencer
|
||||
attr_reader :local_levels
|
||||
self.silencer = true
|
||||
end
|
||||
|
||||
def after_initialize
|
||||
@local_levels = Concurrent::Map.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
|
||||
|
|
|
@ -3,6 +3,7 @@ require 'multibyte_test_helpers'
|
|||
require 'stringio'
|
||||
require 'fileutils'
|
||||
require 'tempfile'
|
||||
require 'concurrent/atomics'
|
||||
|
||||
class LoggerTest < ActiveSupport::TestCase
|
||||
include MultibyteTestHelpers
|
||||
|
@ -113,6 +114,7 @@ class LoggerTest < ActiveSupport::TestCase
|
|||
end
|
||||
|
||||
def test_buffer_multibyte
|
||||
@logger.level = Logger::INFO
|
||||
@logger.info(UNICODE_STRING)
|
||||
@logger.info(BYTE_STRING)
|
||||
assert @output.string.include?(UNICODE_STRING)
|
||||
|
@ -130,4 +132,83 @@ class LoggerTest < ActiveSupport::TestCase
|
|||
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 = Concurrent::CountDownLatch.new
|
||||
latch2 = Concurrent::CountDownLatch.new
|
||||
|
||||
t = Thread.new do
|
||||
latch.wait
|
||||
assert_level(Logger::INFO)
|
||||
latch2.count_down
|
||||
end
|
||||
|
||||
@logger.silence(Logger::ERROR) do
|
||||
assert_level(Logger::ERROR)
|
||||
latch.count_down
|
||||
latch2.wait
|
||||
end
|
||||
|
||||
t.join
|
||||
end
|
||||
|
||||
def test_logger_level_local_thread_safety
|
||||
@logger.level = Logger::INFO
|
||||
assert_level(Logger::INFO)
|
||||
|
||||
thread_1_latch = Concurrent::CountDownLatch.new
|
||||
thread_2_latch = Concurrent::CountDownLatch.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.wait 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.count_down
|
||||
thread_1_latch.wait
|
||||
end
|
||||
assert_level(Logger::DEBUG)
|
||||
end
|
||||
end
|
||||
|
||||
# allow thread 1 to finish
|
||||
assert_level(Logger::INFO)
|
||||
thread_1_latch.count_down 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
|
||||
|
|
Loading…
Reference in a new issue