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

Add option to add backtrace to log messages #48282

Closed
wants to merge 1 commit into from

Conversation

IanButterworth
Copy link
Sponsor Member

@IanButterworth IanButterworth commented Jan 15, 2023

Tracking down why a log message is happening can be hard from just the call site info.

The idea here is to expose a way to inject stack traces into the log message without having to edit the code site to manually add an error. For instance in CI where adding an env var is easier than editing code in a dependency that logs.

test.jl including

foo() = bar()
bar() = @error "hello"

This PR:

julia> include("test.jl")

julia> foo()
┌ Error: hello
└ @ Main ~/test.jl:2

julia> ENV["JULIA_LOG_TRACE"]=1
1

julia> foo()
┌ Error: hello
│ Stacktrace:
│   bar() at test.jl:2
│   foo() at test.jl:1
│   top-level scope at REPL[25]:1
└ @ Main ~/test.jl:2

julia> ENV["JULIA_DEBUG"]="loading"
"loading"

julia> using CSV
┌ Debug: Loading object cache file /Users/ian/.julia/compiled/v1.10/Preferences/pWSk8_wG2DL.dylib for Preferences [21216c6a-2e73-6563-6e65-726566657250]
│ Stacktrace:
│   _include_from_serialized(pkg::Base.PkgId, path::String, ocachepath::String, depmods::Vector{Any}) at loading.jl:1000
│   _tryrequire_from_serialized(modkey::Base.PkgId, path::String, ocachepath::String, sourcepath::String, depmods::Vector{Any}) at loading.jl:1298
│   _require_search_from_serialized(pkg::Base.PkgId, sourcepath::String, build_id::UInt128) at loading.jl:1401
│   _require(pkg::Base.PkgId, env::String) at loading.jl:1690
│   _require_prelocked(uuidkey::Base.PkgId, env::String) at loading.jl:1567
│   macro expansion at loading.jl:1555 [inlined]
│   macro expansion at lock.jl:267 [inlined]
│   require(into::Module, mod::Symbol) at loading.jl:1518
└ @ Base loading.jl:1000
...

Ignoring the stackframes from inside the logging code gen might be too crude.

Also, ignoring past an eval as a way to ignore the repl internals might be too, as Base.scrub_repl_backtrace didn't work for some reason.

base/logging.jl Outdated Show resolved Hide resolved
@IanButterworth
Copy link
Sponsor Member Author

IanButterworth commented Jan 18, 2023

@oxinabox would this break logging extensions like https://github.com/JuliaLogging/LoggingExtras.jl ?

Edit: Just checked and tests pass with and without JULIA_LOG_TRACE=true

Comment on lines +332 to +336
try
error()
catch
return stacktrace(catch_backtrace()), kwargs
end
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

@KristofferC
Copy link
Sponsor Member

KristofferC commented Jan 20, 2023

Shouldn't this be done with a custom logger? Or does that not work here? An env variable should be a last resort of setting an option imo.

@oxinabox
Copy link
Contributor

I agree with Kristoffer, I think this can and thus should be done with a custom logger.
I will put one together after my meeting

@oxinabox
Copy link
Contributor

oxinabox commented Feb 10, 2023

Very basic one, not super-pretty but:
It can be done better by calling into the existing code for stacktraces displaying.

using LoggingExtras

foo() = bar()
bar() = qux()
qux() = @info "Hi"

stacklogger = TransformerLogger(global_logger()) do log
    st = stacktrace()[5:end]  # skip stuff from the logging system  
    pretty_st = ["[$ii] $frame" for (ii, frame) in enumerate(st)]
    kwargs = (;log.kwargs..., stacktrace=pretty_st)
    return merge(log,(;kwargs))
end;


with_logger(stacklogger) do
    foo()
end

screenshot of output

More generally i think this goes well with other kind of LoggingExtras stuff, like you probably want to do with with some filters, so only certain modules and certain levels (e.g. warn) are displayed with stacktraces.

@IanButterworth
Copy link
Sponsor Member Author

That's awesome. Thanks. Yeah makes more sense in LoggingExtras

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
logging The logging framework
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

6 participants