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

Jump to bottom

Add option to add backtrace to log messages #48282

Closed
wants to merge 1 commit into from
Closed

Add option to add backtrace to log messages #48282

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
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: 32 additions & 7 deletions base/logging.jl
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -319,14 +319,32 @@ function issimplekw(@nospecialize val)
return false
end

# Generate code for logging macros
function log_trace(kwargs)
do_trace = if Base.get_bool_env("JULIA_LOG_TRACE", false)
true
elseif get(kwargs, :include_trace, false) === true
kwargs = Base.structdiff(kwargs, NamedTuple{(:include_trace,)})
true
else
false
end
if do_trace
try
error()
catch
return stacktrace(catch_backtrace()), kwargs
end
Comment on lines +332 to +336
Copy link
Sponsor Member

Choose a reason for hiding this comment

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

Suggested change
try
error()
catch
return stacktrace(catch_backtrace()), kwargs
end
return stacktrace(), kwargs

else
return nothing, kwargs
end
end
function logmsg_code(_module, file, line, level, message, exs...)
@nospecialize
log_data = process_logmsg_exs(_module, file, line, level, message, exs...)
if !isa(message, Symbol) && issimple(message) && isempty(log_data.kwargs)
logrecord = quote
msg = $(message)
kwargs = (;)
trace, kwargs = log_trace((;))
true
end
elseif issimple(message) && all(issimplekw, log_data.kwargs)
Expand All @@ -346,7 +364,7 @@ function logmsg_code(_module, file, line, level, message, exs...)
let err = $checkerrors
if err === nothing
msg = $(message)
kwargs = (;$(log_data.kwargs...))
trace, kwargs = log_trace((;$(log_data.kwargs...)))
true
else
@invokelatest logging_error(logger, level, _module, group, id, file, line, err, false)
Expand All @@ -358,7 +376,7 @@ function logmsg_code(_module, file, line, level, message, exs...)
logrecord = quote
try
msg = $(esc(message))
kwargs = (;$(log_data.kwargs...))
trace, kwargs = log_trace((;$(log_data.kwargs...)))
true
catch err
@invokelatest logging_error(logger, level, _module, group, id, file, line, err, true)
Expand All @@ -384,10 +402,10 @@ function logmsg_code(_module, file, line, level, message, exs...)
file = Base.fixup_stdlib_path(file)
end
line = $(log_data._line)
local msg, kwargs
local msg, kwargs, trace
$(logrecord) && invokelatest(handle_message,
logger, level, msg, _module, group, id, file, line;
kwargs...)
trace, kwargs...)
end
end
end
Expand Down Expand Up @@ -662,7 +680,7 @@ min_enabled_level(logger::SimpleLogger) = logger.min_level
catch_exceptions(logger::SimpleLogger) = false

function handle_message(logger::SimpleLogger, level::LogLevel, message, _module, group, id,
filepath, line; kwargs...)
filepath, line; trace=nothing, kwargs...)
@nospecialize
maxlog = get(kwargs, :maxlog, nothing)
if maxlog isa Core.BuiltinInts
Expand All @@ -678,6 +696,13 @@ function handle_message(logger::SimpleLogger, level::LogLevel, message, _module,
iob = IOContext(buf, stream)
levelstr = level == Warn ? "Warning" : string(level)
msglines = eachsplit(chomp(convert(String, string(message))::String), '\n')
if !isnothing(trace)
push!(msglines, "Stacktrace:")
for line in trace[4:end] # skip the first two which will fall in logger code
line.file == Symbol("./boot.jl") && line.func == :eval && break
push!(msglines, " " * sprint(show,line))
end
end
msg1, rest = Iterators.peel(msglines)
println(iob, "┌ ", levelstr, ": ", msg1)
for msg in rest
Expand Down
9 changes: 8 additions & 1 deletion stdlib/Logging/src/ConsoleLogger.jl
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -104,7 +104,7 @@ function termlength(str)
end

function handle_message(logger::ConsoleLogger, level::LogLevel, message, _module, group, id,
filepath, line; kwargs...)
filepath, line; trace=nothing, kwargs...)
@nospecialize
hasmaxlog = haskey(kwargs, :maxlog) ? 1 : 0
maxlog = get(kwargs, :maxlog, nothing)
Expand Down Expand Up @@ -152,6 +152,13 @@ function handle_message(logger::ConsoleLogger, level::LogLevel, message, _module
msglines[end].indent + termlength(msglines[end].msg) +
(isempty(suffix) ? 0 : length(suffix)+minsuffixpad)
justify_width = min(logger.right_justify, dsize[2])
if !isnothing(trace)
push!(msglines, (indent=0, msg="Stacktrace:"))
for line in trace[4:end] # skip the first two which will fall in logger code
line.file == Symbol("./boot.jl") && line.func == :eval && break
push!(msglines, (indent=2, msg=SubString(sprint(show,line))))
end
end
if nonpadwidth > justify_width && !isempty(suffix)
push!(msglines, (indent=0, msg=SubString("")))
minsuffixpad = 0
Expand Down
29 changes: 29 additions & 0 deletions stdlib/Logging/test/runtests.jl
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4,6 +4,18 @@ using Test, Logging

import Logging: min_enabled_level, shouldlog, handle_message

macro capture_stderr(ex)
quote
mktemp() do fname, f
redirect_stderr(f) do
$(esc(ex))
end
seekstart(f)
read(f, String)
end
end
end

@noinline func1() = backtrace()

@testset "Logging" begin
Expand Down Expand Up @@ -257,6 +269,23 @@ end
\e[36m\e[1m└ \e[22m\e[39m\e[90mSUFFIX\e[39m
"""

@testset "Log with optional stacktrace via JULIA_LOG_TRACE=true" begin
withenv("JULIA_LOG_TRACE" => true) do
str = @capture_stderr @info "msg"
@test startswith(str, "┌ Info: msg\n│ Stacktrace:\n│")
str = @capture_stderr @warn "msg"
@test startswith(str, "┌ Warning: msg\n│ Stacktrace:\n│")
str = @capture_stderr @error "msg"
@test startswith(str, "┌ Error: msg\n│ Stacktrace:\n│")
end
str = @capture_stderr @info "msg" include_trace = true
@test startswith(str, "┌ Info: msg\n│ Stacktrace:\n│")
str = @capture_stderr @warn "msg" include_trace = true
@test startswith(str, "┌ Warning: msg\n│ Stacktrace:\n│")
str = @capture_stderr @error "msg" include_trace = true
@test startswith(str, "┌ Error: msg\n│ Stacktrace:\n│")
end

end

@testset "exported names" begin
Expand Down
5 changes: 3 additions & 2 deletions stdlib/Test/src/logging.jl
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -26,6 +26,7 @@ struct LogRecord
id
file
line
trace
kwargs
end
LogRecord(args...; kwargs...) = LogRecord(args..., kwargs)
Expand Down Expand Up @@ -93,7 +94,7 @@ function Logging.shouldlog(logger::TestLogger, level, _module, group, id)
end

function Logging.handle_message(logger::TestLogger, level, msg, _module,
group, id, file, line; kwargs...)
group, id, file, line; trace=nothing, kwargs...)
@nospecialize
if logger.respect_maxlog
maxlog = get(kwargs, :maxlog, nothing)
Expand All @@ -103,7 +104,7 @@ function Logging.handle_message(logger::TestLogger, level, msg, _module,
remaining > 0 || return
end
end
push!(logger.logs, LogRecord(level, msg, _module, group, id, file, line, kwargs))
push!(logger.logs, LogRecord(level, msg, _module, group, id, file, line, trace, kwargs))
end

# Catch exceptions for the test logger only if specified
Expand Down