Skip to content
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.

Sign up for GitHub

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

Make TestLogger thread-safe (introduce a lock) #54497

Merged
merged 4 commits into from
May 22, 2024
Merged

Make TestLogger thread-safe (introduce a lock) #54497

Changes from 2 commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
0554962
Make TestLogger thread-safe (introduce a lock)
NHDaly May 16, 2024
0053794
Guard `shouldlog_args` too.....
NHDaly May 16, 2024
31e4ac1
Merge remote-tracking branch 'origin/master' into nhd-test-logs-threa…
NHDaly May 22, 2024
b1c4710
Add comments explaining that shouldlog_args is not logically thread-safe
NHDaly May 22, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
39 changes: 25 additions & 14 deletions stdlib/Test/src/logging.jl
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,7 @@

using Logging: Logging, AbstractLogger, LogLevel, Info, with_logger
import Base: occursin
using Base: @lock

#-------------------------------------------------------------------------------
"""
Expand Down Expand Up @@ -35,11 +36,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}
shouldlog_args # Guarded by lock.
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Oh no, I just realized that this field is also mutated in Logging.shouldlog. I've added a lock around it, but i'm not sure that it makes logical sense, since another thread may overwrite the value right after it's set...

@c42f: Is there any chance you remember what this field is used for? I don't see that it's used anywhere. I think this is the only reason the struct is mutable, is so that we can set that from shouldlog, but I don't see why it's being set.

It's tested here:

julia/test/corelogging.jl

Lines 130 to 134 in 449c7a2

# Test consistency with shouldlog() function arguments
@test record.level == logger.shouldlog_args[1]
@test record._module == logger.shouldlog_args[2]
@test record.group == logger.shouldlog_args[3]
@test record.id == logger.shouldlog_args[4]

But that test doesn't really explain it either. It seems like it would only be retaining the shouldlog args for the last invocation.... So what should this even mean with multiple threads logging?

Could we remove this field entirely?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

For now, I have just added a comment that this field is not logically thread-safe, which is no worse than how things were before this PR, while the rest of the data-races are fixed.

So this PR is a strict improvement.

message_limits::Dict{Any,Int} # Guarded by lock.
respect_maxlog::Bool
end

Expand Down Expand Up @@ -80,15 +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 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

Expand All @@ -98,12 +102,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
Expand All @@ -112,7 +121,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


Expand Down