Skip to content

Commit 0437210

Browse files
authored
Make TestLogger thread-safe (introduce a lock) (#54497)
Fixes #54439. - Lock around concurrent accesses to .logs, .message_limits, and .shouldlog_args. - Copy the vector out of the logger at the end, to shield against dangling Tasks. Before: ```julia julia> Threads.nthreads() 8 julia> function foo(n) @info "Doing foo with n=$n" @sync for i=1:n Threads.@Spawn @info "Iteration $i" end 42 end foo (generic function with 1 method) julia> for _ in 1:1000 @test_logs (:info,"Doing foo with n=10000") match_mode=:any foo(10_000) end julia+RAI(56155,0x1f5157ac0) malloc: double free for ptr 0x128248000 julia+RAI(56155,0x1f5157ac0) malloc: *** set a breakpoint in malloc_error_break to debug [56155] signal (6): Abort trap: 6 in expression starting at REPL[8]:1 signal (6) thread (1) __pthread_kill at /usr/lib/system/libsystem_kernel.dylib (unknown line) Allocations: 54370881 (Pool: 54363911; Big: 6970); GC: 119 [1] 56154 abort julia -tauto ``` After: ```julia julia> Threads.nthreads() 8 julia> function foo(n) @info "Doing foo with n=$n" @sync for i=1:n Threads.@Spawn @info "Iteration $i" end 42 end foo (generic function with 1 method) julia> for _ in 1:1000 @test_logs (:info,"Doing foo with n=10000") match_mode=:any foo(10_000) end ``` (no crash) :)
1 parent e89c21b commit 0437210

File tree

1 file changed

+28
-14
lines changed

1 file changed

+28
-14
lines changed

stdlib/Test/src/logging.jl

Lines changed: 28 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -2,6 +2,7 @@
22

33
using Logging: Logging, AbstractLogger, LogLevel, Info, with_logger
44
import Base: occursin
5+
using Base: @lock
56

67
#-------------------------------------------------------------------------------
78
"""
@@ -35,11 +36,15 @@ struct Ignored ; end
3536
#-------------------------------------------------------------------------------
3637
# Logger with extra test-related state
3738
mutable struct TestLogger <: AbstractLogger
38-
logs::Vector{LogRecord}
39+
lock::ReentrantLock
40+
logs::Vector{LogRecord} # Guarded by lock.
3941
min_level::LogLevel
4042
catch_exceptions::Bool
41-
shouldlog_args
42-
message_limits::Dict{Any,Int}
43+
# Note: shouldlog_args only maintains the info for the most recent log message, which
44+
# may not be meaningful in a multithreaded program. See:
45+
# https://github.com/JuliaLang/julia/pull/54497#discussion_r1603691606
46+
shouldlog_args # Guarded by lock.
47+
message_limits::Dict{Any,Int} # Guarded by lock.
4348
respect_maxlog::Bool
4449
end
4550

@@ -80,15 +85,17 @@ Test Passed
8085
```
8186
"""
8287
TestLogger(; min_level=Info, catch_exceptions=false, respect_maxlog=true) =
83-
TestLogger(LogRecord[], min_level, catch_exceptions, nothing, Dict{Any, Int}(), respect_maxlog)
88+
TestLogger(ReentrantLock(), LogRecord[], min_level, catch_exceptions, nothing, Dict{Any, Int}(), respect_maxlog)
8489
Logging.min_enabled_level(logger::TestLogger) = logger.min_level
8590

8691
function Logging.shouldlog(logger::TestLogger, level, _module, group, id)
87-
if get(logger.message_limits, id, 1) > 0
88-
logger.shouldlog_args = (level, _module, group, id)
89-
true
90-
else
91-
false
92+
@lock logger.lock begin
93+
if get(logger.message_limits, id, 1) > 0
94+
logger.shouldlog_args = (level, _module, group, id)
95+
return true
96+
else
97+
return false
98+
end
9299
end
93100
end
94101

@@ -98,12 +105,17 @@ function Logging.handle_message(logger::TestLogger, level, msg, _module,
98105
if logger.respect_maxlog
99106
maxlog = get(kwargs, :maxlog, nothing)
100107
if maxlog isa Core.BuiltinInts
101-
remaining = get!(logger.message_limits, id, Int(maxlog)::Int)
102-
logger.message_limits[id] = remaining - 1
103-
remaining > 0 || return
108+
@lock logger.lock begin
109+
remaining = get!(logger.message_limits, id, Int(maxlog)::Int)
110+
logger.message_limits[id] = remaining - 1
111+
remaining > 0 || return
112+
end
104113
end
105114
end
106-
push!(logger.logs, LogRecord(level, msg, _module, group, id, file, line, kwargs))
115+
r = LogRecord(level, msg, _module, group, id, file, line, kwargs)
116+
@lock logger.lock begin
117+
push!(logger.logs, r)
118+
end
107119
end
108120

109121
# Catch exceptions for the test logger only if specified
@@ -112,7 +124,9 @@ Logging.catch_exceptions(logger::TestLogger) = logger.catch_exceptions
112124
function collect_test_logs(f; kwargs...)
113125
logger = TestLogger(; kwargs...)
114126
value = with_logger(f, logger)
115-
logger.logs, value
127+
@lock logger.lock begin
128+
return copy(logger.logs), value
129+
end
116130
end
117131

118132

0 commit comments

Comments
 (0)