Skip to content

Commit

Permalink
add trace to log if JULIA_LOG_TRACE or kw include_trace=true
Browse files Browse the repository at this point in the history
  • Loading branch information
IanButterworth committed Jan 20, 2023
1 parent 6d8f54a commit 10d87ca
Show file tree
Hide file tree
Showing 4 changed files with 72 additions and 10 deletions.
39 changes: 32 additions & 7 deletions base/logging.jl
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
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
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
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
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

0 comments on commit 10d87ca

Please sign in to comment.