1
0
Fork 0
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:
Carl P. Corliss 2015-06-09 22:38:53 -04:00
parent 2ad6deb534
commit 629efb6057
4 changed files with 120 additions and 4 deletions

View file

@ -1252,6 +1252,7 @@ class BasicsTest < ActiveRecord::TestCase
original_logger = ActiveRecord::Base.logger original_logger = ActiveRecord::Base.logger
log = StringIO.new log = StringIO.new
ActiveRecord::Base.logger = ActiveSupport::Logger.new(log) 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" } ActiveRecord::Base.benchmark("Logging", :level => :debug, :silence => false) { ActiveRecord::Base.logger.debug "Quiet" }
assert_match(/Quiet/, log.string) assert_match(/Quiet/, log.string)
ensure ensure

View file

@ -46,6 +46,20 @@ module ActiveSupport
super super
@formatter = SimpleFormatter.new @formatter = SimpleFormatter.new
@broadcast_messages = true @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 end
# Simple formatter which only displays the message. # Simple formatter which only displays the message.

View file

@ -1,22 +1,42 @@
require 'active_support/concern' require 'active_support/concern'
require 'active_support/core_ext/module/attribute_accessors' require 'active_support/core_ext/module/attribute_accessors'
require 'concurrent'
module LoggerSilence module LoggerSilence
extend ActiveSupport::Concern extend ActiveSupport::Concern
included do included do
cattr_accessor :silencer cattr_accessor :silencer
attr_reader :local_levels
self.silencer = true self.silencer = true
end 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. # Silences the logger for the duration of the block.
def silence(temporary_level = Logger::ERROR) def silence(temporary_level = Logger::ERROR)
if silencer if silencer
begin 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 yield self
ensure 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 end
else else
yield self yield self

View file

@ -3,6 +3,7 @@ require 'multibyte_test_helpers'
require 'stringio' require 'stringio'
require 'fileutils' require 'fileutils'
require 'tempfile' require 'tempfile'
require 'concurrent/atomics'
class LoggerTest < ActiveSupport::TestCase class LoggerTest < ActiveSupport::TestCase
include MultibyteTestHelpers include MultibyteTestHelpers
@ -113,6 +114,7 @@ class LoggerTest < ActiveSupport::TestCase
end end
def test_buffer_multibyte def test_buffer_multibyte
@logger.level = Logger::INFO
@logger.info(UNICODE_STRING) @logger.info(UNICODE_STRING)
@logger.info(BYTE_STRING) @logger.info(BYTE_STRING)
assert @output.string.include?(UNICODE_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?("NOT THERE")
assert @output.string.include?("THIS IS HERE") assert @output.string.include?("THIS IS HERE")
end 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 end