From 05549626c6774f1a18812cbf11a161aae3d5d108 Mon Sep 17 00:00:00 2001 From: Nathan Daly Date: Thu, 16 May 2024 10:05:14 -0600 Subject: [PATCH 1/3] Make TestLogger thread-safe (introduce a lock) - Lock around concurrent accesses to .logs and .message_limits - Copy the vector out of the logger at the end, to shield against dangling Tasks. --- stdlib/Test/src/logging.jl | 25 +++++++++++++++++-------- 1 file changed, 17 insertions(+), 8 deletions(-) diff --git a/stdlib/Test/src/logging.jl b/stdlib/Test/src/logging.jl index 42d3eaf8eaa48..62278b36af466 100644 --- a/stdlib/Test/src/logging.jl +++ b/stdlib/Test/src/logging.jl @@ -35,11 +35,12 @@ struct Ignored ; end #------------------------------------------------------------------------------- # Logger with extra test-related state mutable struct TestLogger <: AbstractLogger - logs::Vector{LogRecord} + lock::ReentrantLock + logs::Vector{LogRecord} # Guarded by lock. min_level::LogLevel catch_exceptions::Bool shouldlog_args - message_limits::Dict{Any,Int} + message_limits::Dict{Any,Int} # Guarded by lock. respect_maxlog::Bool end @@ -84,7 +85,8 @@ TestLogger(; min_level=Info, catch_exceptions=false, respect_maxlog=true) = Logging.min_enabled_level(logger::TestLogger) = logger.min_level function Logging.shouldlog(logger::TestLogger, level, _module, group, id) - if get(logger.message_limits, id, 1) > 0 + + if @lock(logger.lock, get(logger.message_limits, id, 1)) > 0 logger.shouldlog_args = (level, _module, group, id) true else @@ -98,12 +100,17 @@ function Logging.handle_message(logger::TestLogger, level, msg, _module, if logger.respect_maxlog maxlog = get(kwargs, :maxlog, nothing) if maxlog isa Core.BuiltinInts - remaining = get!(logger.message_limits, id, Int(maxlog)::Int) - logger.message_limits[id] = remaining - 1 - remaining > 0 || return + @lock logger.lock begin + remaining = get!(logger.message_limits, id, Int(maxlog)::Int) + logger.message_limits[id] = remaining - 1 + remaining > 0 || return + end end end - push!(logger.logs, LogRecord(level, msg, _module, group, id, file, line, kwargs)) + r = LogRecord(level, msg, _module, group, id, file, line, kwargs) + @lock logger.lock begin + push!(logger.logs, r) + end end # Catch exceptions for the test logger only if specified @@ -112,7 +119,9 @@ Logging.catch_exceptions(logger::TestLogger) = logger.catch_exceptions function collect_test_logs(f; kwargs...) logger = TestLogger(; kwargs...) value = with_logger(f, logger) - logger.logs, value + @lock logger.lock begin + return copy(logger.logs), value + end end From 0053794621357f018bd0a285bc852df109a1e3db Mon Sep 17 00:00:00 2001 From: Nathan Daly Date: Thu, 16 May 2024 10:23:25 -0600 Subject: [PATCH 2/3] Guard `shouldlog_args` too..... --- stdlib/Test/src/logging.jl | 18 ++++++++++-------- 1 file changed, 10 insertions(+), 8 deletions(-) diff --git a/stdlib/Test/src/logging.jl b/stdlib/Test/src/logging.jl index 62278b36af466..00ebe1aa464ea 100644 --- a/stdlib/Test/src/logging.jl +++ b/stdlib/Test/src/logging.jl @@ -2,6 +2,7 @@ using Logging: Logging, AbstractLogger, LogLevel, Info, with_logger import Base: occursin +using Base: @lock #------------------------------------------------------------------------------- """ @@ -39,7 +40,7 @@ mutable struct TestLogger <: AbstractLogger logs::Vector{LogRecord} # Guarded by lock. min_level::LogLevel catch_exceptions::Bool - shouldlog_args + shouldlog_args # Guarded by lock. message_limits::Dict{Any,Int} # Guarded by lock. respect_maxlog::Bool end @@ -81,16 +82,17 @@ Test Passed ``` """ TestLogger(; min_level=Info, catch_exceptions=false, respect_maxlog=true) = - TestLogger(LogRecord[], min_level, catch_exceptions, nothing, Dict{Any, Int}(), respect_maxlog) + TestLogger(ReentrantLock(), LogRecord[], min_level, catch_exceptions, nothing, Dict{Any, Int}(), respect_maxlog) Logging.min_enabled_level(logger::TestLogger) = logger.min_level function Logging.shouldlog(logger::TestLogger, level, _module, group, id) - - if @lock(logger.lock, get(logger.message_limits, id, 1)) > 0 - logger.shouldlog_args = (level, _module, group, id) - true - else - false + @lock logger.lock begin + if get(logger.message_limits, id, 1) > 0 + logger.shouldlog_args = (level, _module, group, id) + return true + else + return false + end end end From b1c471020a6987c28d2c3614edf69ad31df6722a Mon Sep 17 00:00:00 2001 From: Nathan Daly Date: Wed, 22 May 2024 08:47:02 -0600 Subject: [PATCH 3/3] Add comments explaining that shouldlog_args is not logically thread-safe --- stdlib/Test/src/logging.jl | 3 +++ 1 file changed, 3 insertions(+) diff --git a/stdlib/Test/src/logging.jl b/stdlib/Test/src/logging.jl index 00ebe1aa464ea..b224d79e47cd9 100644 --- a/stdlib/Test/src/logging.jl +++ b/stdlib/Test/src/logging.jl @@ -40,6 +40,9 @@ mutable struct TestLogger <: AbstractLogger logs::Vector{LogRecord} # Guarded by lock. min_level::LogLevel catch_exceptions::Bool + # Note: shouldlog_args only maintains the info for the most recent log message, which + # may not be meaningful in a multithreaded program. See: + # https://github.com/JuliaLang/julia/pull/54497#discussion_r1603691606 shouldlog_args # Guarded by lock. message_limits::Dict{Any,Int} # Guarded by lock. respect_maxlog::Bool