From 9d9744d78ac9dbfc76c7d218dfe3fba7a860f9a4 Mon Sep 17 00:00:00 2001 From: Luke Adams Date: Mon, 24 Sep 2018 17:32:41 -0600 Subject: [PATCH 1/2] fix log record ids --- base/logging.jl | 18 +++++++++++------- 1 file changed, 11 insertions(+), 7 deletions(-) diff --git a/base/logging.jl b/base/logging.jl index 9034460a4dfe2..38bfcdc24c049 100644 --- a/base/logging.jl +++ b/base/logging.jl @@ -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{String, 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, string(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) @@ -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 @@ -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 @@ -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 + 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...)) From bc1b5f341517919d89c38d4c2c0038f9f7d42e15 Mon Sep 17 00:00:00 2001 From: Luke Adams Date: Tue, 25 Sep 2018 09:38:45 -0600 Subject: [PATCH 2/2] fix bug and add tests --- base/logging.jl | 4 ++-- stdlib/Logging/test/runtests.jl | 20 ++++++++++++++++++++ test/logging.jl | 19 ++++++++++++++++++- 3 files changed, 40 insertions(+), 3 deletions(-) diff --git a/base/logging.jl b/base/logging.jl index 38bfcdc24c049..d3664b3eeeb5e 100644 --- a/base/logging.jl +++ b/base/logging.jl @@ -221,7 +221,7 @@ macro error(exs...) logmsg_code((@_sourceinfo)..., :Error, exs...) end @eval @doc $_logmsg_docs :(@warn) @eval @doc $_logmsg_docs :(@error) -_log_record_ids = Dict{String, 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 @@ -230,7 +230,7 @@ _log_record_ids = Dict{String, Symbol}() # itself doesn't change. function log_record_id(_module, file, line, level, message_ex) modname = _module === nothing ? "" : join(fullname(_module), "_") - get!(_log_record_ids, string(modname, file, line), + get!(_log_record_ids, (modname, file, line), new_log_record_id(modname, level, message_ex)) end diff --git a/stdlib/Logging/test/runtests.jl b/stdlib/Logging/test/runtests.jl index e22c54a23cf2a..240f00fee23b8 100644 --- a/stdlib/Logging/test/runtests.jl +++ b/stdlib/Logging/test/runtests.jl @@ -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") diff --git a/test/logging.jl b/test/logging.jl index 2c53aee129e9a..a25e39c58eee8 100644 --- a/test/logging.jl +++ b/test/logging.jl @@ -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 @@ -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