-
Notifications
You must be signed in to change notification settings - Fork 21.4k
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Fixes LoggerSilence#silence threadsafety #20507
Changes from all commits
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
Original file line number | Diff line number | Diff line change |
---|---|---|
|
@@ -3,6 +3,7 @@ | |
require 'stringio' | ||
require 'fileutils' | ||
require 'tempfile' | ||
require 'concurrent/atomics' | ||
|
||
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 = 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 | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. I still find this test with the threads hard to understand, and I'm scared we might run into timing issues (might be overblown). Could There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. I haven't looked at the rest of this PR, but you want latch. |
||
# 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) | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. These two lines should be swapped, this way the check for the |
||
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 | ||
|
||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. ✂️ this line and indent under private. |
||
def assert_level(level) | ||
assert_equal level, @logger.level, "Expected level #{level_name(level)}, got #{level_name(@logger.level)}" | ||
end | ||
end |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Why are you checking
@logdev.nil?
? Isn't it an i-var Rails has no control over?There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
ActiveSupport::Logger inherits from Logger, so it does have "control" over
@logdev
. The reason it's checked here is because it's replicating the behavior of the super method. I personally see no problem short-circuiting here instead of adding another method call to the stack (viasuper
) but, if you feel super strongly about it, I'll be honest - I don't care, and will remove it.