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.

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

Fix log record IDs #29355

Closed
wants to merge 2 commits into from
Closed
Show file tree
Hide file tree
Changes from all commits
Commits
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
18 changes: 11 additions & 7 deletions base/logging.jl
Original file line number Diff line number Diff line change
Expand Up @@ -221,15 +221,20 @@ macro error(exs...) logmsg_code((@_sourceinfo)..., :Error, exs...) end
@eval @doc $_logmsg_docs :(@warn)
@eval @doc $_logmsg_docs :(@error)

_log_record_ids = Set{Symbol}()
_log_record_ids = Dict{Any, Symbol}()
# Generate a unique, stable, short, human readable identifier for a logging
# statement. The idea here is to have a key against which log records can be
# filtered and otherwise manipulated. The key should uniquely identify the
# source location in the originating module, but should be stable across
# versions of the originating module, provided the log generating statement
# itself doesn't change.
function log_record_id(_module, level, message_ex)
function log_record_id(_module, file, line, level, message_ex)
modname = _module === nothing ? "" : join(fullname(_module), "_")
get!(_log_record_ids, (modname, file, line),
new_log_record_id(modname, level, message_ex))
end

function new_log_record_id(modname, level, message_ex)
# Use (1<<31) to fit well within an (arbitriraly chosen) eight hex digits,
# as we increment h to resolve any collisions.
h = hash(string(modname, level, message_ex)) % (1<<31)
Expand All @@ -239,8 +244,7 @@ function log_record_id(_module, level, message_ex)
# compilation, to ensure uniqueness of ids. Note that this state will
# only persist during module compilation so it will be empty when a
# precompiled module is loaded.
if !(id in _log_record_ids)
push!(_log_record_ids, id)
if !(id in values(_log_record_ids))
return id
end
h += 1
Expand Down Expand Up @@ -290,7 +294,7 @@ function logmsg_code(_module, file, line, level, message, exs...)
end

# Note that it may be necessary to set `id` and `group` manually during bootstrap
id = something(id, :(log_record_id(_module, level, $exs)))
id = something(id, :(log_record_id(_module, file, line, level, $exs)))
if group == nothing
group = if isdefined(Base, :basename) && isa(file, String)
# precompute if we can
Expand All @@ -311,12 +315,12 @@ function logmsg_code(_module, file, line, level, message, exs...)
_module = $_module
logger = current_logger_for_env(std_level, group, _module)
if !(logger === nothing)
file = $file
Copy link
Member

Choose a reason for hiding this comment

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

Why were these moved?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Those values are needed to compute id.

line = $line
id = $id
# Second chance at an early bail-out (before computing the message),
# based on arbitrary logger-specific logic.
if shouldlog(logger, level, _module, group, id)
file = $file
line = $line
try
msg = $(esc(message))
handle_message(logger, level, msg, _module, group, id, file, line; $(kwargs...))
Expand Down
20 changes: 20 additions & 0 deletions stdlib/Logging/test/runtests.jl
Original file line number Diff line number Diff line change
Expand Up @@ -21,6 +21,26 @@ import Logging: min_enabled_level, shouldlog, handle_message
handle_message(logger, Logging.Info, "msg", Base, :group, :asdf, "somefile", 1, maxlog=2)
@test shouldlog(logger, Logging.Info, Base, :group, :asdf) === false

# Check that maxlog works without an explicit ID
buf = IOBuffer()
io = IOContext(buf, :displaysize=>(30,80), :color=>false)
logger = ConsoleLogger(io)
with_logger(logger) do
for i in 1:2
@info "test" maxlog=1
end
end
@test String(take!(buf)) ==
"""
[ Info: test
"""
with_logger(logger) do
for i in 1:2
@info "test" maxlog=0
end
end
@test String(take!(buf)) == ""

@testset "Default metadata formatting" begin
@test Logging.default_metafmt(Logging.Debug, Base, :g, :i, expanduser("~/somefile.jl"), 42) ==
(:blue, "Debug:", "@ Base ~/somefile.jl:42")
Expand Down
19 changes: 18 additions & 1 deletion test/logging.jl
Original file line number Diff line number Diff line change
Expand Up @@ -62,7 +62,7 @@ end
@test record.file == Base.source_path()
@test record.line == kwargs[:real_line]
@test record.id isa Symbol
@test occursin(r"^.*logging_[[:xdigit:]]{8}$", String(record.id))
@test occursin(r"^.*[[:xdigit:]]{8}$", String(record.id))

# User-defined metadata
@test kwargs[:bar_val] === bar_val
Expand Down Expand Up @@ -338,4 +338,21 @@ end
@test_logs (:warn, "a", Base) (@warn "a" _module=Base)
end

@testset "ID generation" begin
id1 = Base.CoreLogging.log_record_id(Main, "test.jl", 42, Info, ())
id2 = Base.CoreLogging.log_record_id(Main, "test.jl", 42, Info, ())
@test id1 == id2

logs,_ = collect_test_logs() do
for i in 1:2
@info "test"
@info "test"
end
end
@test length(logs) == 4
@test logs[1].id == logs[3].id
@test logs[2].id == logs[4].id
@test logs[1].id != logs[2].id
end

end