Write a formatted backtrace to IOBuffer

mrufsvold · June 11, 2024, 9:22pm

I want to catch an error, construct the backtrace that would normally be written to the REPL, and add it to a JSON blob instead. However, I can’t seem to get simple logger to write to an IOBuffer.

MWE:

julia> ch1 = Channel() do ch
           for i in 1:3
               put!(ch, i)
           end
           error("inner error!")
       end
Channel{Any}(0) (1 item available)

julia> ch2 = Channel() do ch
           for i in ch1
               put!(ch, i)
           end
       end
Channel{Any}(0) (1 item available)

julia> try
           collect(ch2)
       catch e
           @error "My task errored!" exception=(e, catch_backtrace())
       end
┌ Error: My task errored!
│   exception =
│    TaskFailedException
│    Stacktrace:
│      [1] try_yieldto(undo::typeof(Base.ensure_rescheduled))
│        @ Base .\task.jl:931
│      [2] wait()
│        @ Base .\task.jl:995
│      [3] wait(c::Base.GenericCondition{ReentrantLock}; first::Bool)
│        @ Base .\condition.jl:130
│      [4] wait
│        @ Base .\condition.jl:125 [inlined]
│      [5] take_unbuffered(c::Channel{Any})
│        @ Base .\channels.jl:494
│      [6] take!
│        @ Base .\channels.jl:471 [inlined]
│      [7] iterate(c::Channel{Any}, state::Nothing)
│        @ Base .\channels.jl:613
│      [8] _collect(cont::UnitRange{Int64}, itr::Channel{Any}, ::Base.HasEltype, isz::Base.SizeUnknown)
│        @ Base .\array.jl:772
│      [9] collect(itr::Channel{Any})
│        @ Base .\array.jl:759
│     [10] top-level scope
│        @ c:\Users\mrufsvold\Projects\DIL-price-transparency-psd\TableConsolidator.jl\playground.jl:121
│     [11] eval
│        @ .\boot.jl:385 [inlined]
│     [12] include_string(mapexpr::typeof(REPL.softscope), mod::Module, code::String, filename::String)
│        @ Base .\loading.jl:2070
│     [13] invokelatest(::Any, ::Any, ::Vararg{Any}; kwargs::@Kwargs{})
│        @ Base .\essentials.jl:887
│     [14] invokelatest(::Any, ::Any, ::Vararg{Any})
│        @ Base .\essentials.jl:884
│     [15] inlineeval(m::Module, code::String, code_line::Int64, code_column::Int64, file::String; softscope::Bool)
│        @ VSCodeServer c:\Users\mrufsvold\.vscode\extensions\julialang.language-julia-1.79.2\scripts\packages\VSCodeServer\src\eval.jl:271
│     [16] (::VSCodeServer.var"#69#74"{Bool, Bool, Bool, Module, String, Int64, Int64, String, VSCodeServer.ReplRunCodeRequestParams})()
│        @ VSCodeServer c:\Users\mrufsvold\.vscode\extensions\julialang.language-julia-1.79.2\scripts\packages\VSCodeServer\src\eval.jl:181
│     [17] withpath(f::VSCodeServer.var"#69#74"{Bool, Bool, Bool, Module, String, Int64, Int64, String, VSCodeServer.ReplRunCodeRequestParams}, path::String)
│        @ VSCodeServer c:\Users\mrufsvold\.vscode\extensions\julialang.language-julia-1.79.2\scripts\packages\VSCodeServer\src\repl.jl:276
│     [18] (::VSCodeServer.var"#68#73"{Bool, Bool, Bool, Module, String, Int64, Int64, String, VSCodeServer.ReplRunCodeRequestParams})()
│        @ VSCodeServer c:\Users\mrufsvold\.vscode\extensions\julialang.language-julia-1.79.2\scripts\packages\VSCodeServer\src\eval.jl:179
│     [19] hideprompt(f::VSCodeServer.var"#68#73"{Bool, Bool, Bool, Module, String, Int64, Int64, String, VSCodeServer.ReplRunCodeRequestParams})
│        @ VSCodeServer c:\Users\mrufsvold\.vscode\extensions\julialang.language-julia-1.79.2\scripts\packages\VSCodeServer\src\repl.jl:38
│     [20] (::VSCodeServer.var"#67#72"{Bool, Bool, Bool, Module, String, Int64, Int64, String, VSCodeServer.ReplRunCodeRequestParams})()
│        @ VSCodeServer c:\Users\mrufsvold\.vscode\extensions\julialang.language-julia-1.79.2\scripts\packages\VSCodeServer\src\eval.jl:150
│     [21] with_logstate(f::Function, logstate::Any)
│        @ Base.CoreLogging .\logging.jl:515
│     [22] with_logger
│        @ .\logging.jl:627 [inlined]
│     [23] (::VSCodeServer.var"#66#71"{VSCodeServer.ReplRunCodeRequestParams})()
│        @ VSCodeServer c:\Users\mrufsvold\.vscode\extensions\julialang.language-julia-1.79.2\scripts\packages\VSCodeServer\src\eval.jl:263
│     [24] #invokelatest#2
│        @ Base .\essentials.jl:887 [inlined]
│     [25] invokelatest(::Any)
│        @ Base .\essentials.jl:884
│     [26] (::VSCodeServer.var"#64#65")()
│        @ VSCodeServer c:\Users\mrufsvold\.vscode\extensions\julialang.language-julia-1.79.2\scripts\packages\VSCodeServer\src\eval.jl:34
│ 
│        nested task error: TaskFailedException
│        Stacktrace:
│         [1] check_channel_state
│           @ Base .\channels.jl:188 [inlined]
│         [2] take_unbuffered(c::Channel{Any})
│           @ Base .\channels.jl:492
│         [3] take!
│           @ Base .\channels.jl:471 [inlined]
│         [4] iterate(c::Channel{Any}, state::Nothing)
│           @ Base .\channels.jl:613
│         [5] (::var"#89#90")(ch::Channel{Any})
│           @ Main c:\Users\mrufsvold\Projects\DIL-price-transparency-psd\TableConsolidator.jl\playground.jl:116
│         [6] (::Base.var"#651#652"{var"#89#90", Channel{Any}})()
│           @ Base .\channels.jl:142
│ 
│            nested task error: inner error!
│            Stacktrace:
│             [1] error(s::String)
│               @ Base .\error.jl:35
│             [2] (::var"#87#88")(ch::Channel{Any})
│               @ Main c:\Users\mrufsvold\Projects\DIL-price-transparency-psd\TableConsolidator.jl\playground.jl:110
│             [3] (::Base.var"#651#652"{var"#87#88", Channel{Any}})()
│               @ Base .\channels.jl:142
└ @ Main c:\Users\mrufsvold\Projects\DIL-price-transparency-psd\TableConsolidator.jl\playground.jl:123

Now, I want to capture that output and send it as an SQS message:

julia> ch1 = Channel() do ch
           for i in 1:3
               put!(ch, i)
           end
           error("inner error!")
       end
Channel{Any}(0) (1 item available)

julia> ch2 = Channel() do ch
           for i in ch1
               put!(ch, i)
           end
       end
Channel{Any}(0) (1 item available)

julia> try
           collect(ch2)
       catch e
           io = IOBuffer()
           simple_logger = Base.SimpleLogger(io)
           Base.with_logger(simple_logger) do
               @error "My task errored!" exception=(e, catch_backtrace())
           end
           x = String(take!(io))

           # I would replace this with a different function that sends the stack trace to SQS
           println(x)
       end
┌ Error: My task errored!
│   exception = (TaskFailedException(Task (failed) @0x0000018e6db95750), Union{Ptr{Nothing}, Base.InterpreterIP}[Ptr{Nothing} @0x00007fffe5c2fa84, Ptr{Nothing} @0x00007fffe5bbf658, Ptr{Nothing} @0x00007fffe49378ee, Ptr{Nothing} @0x00007fffe5a0935c, Ptr{Nothing} @0x00007fffe5dd063c, Ptr{Nothing} @0x0000018e1895737e, Ptr{Nothing} @0x0000018e1895748b, Ptr{Nothing} @0x0000018e189574cb, Ptr{Nothing} @0x00007ffffa24626a, Ptr{Nothing} @0x00007ffffa245d9c, Ptr{Nothing} @0x00007ffffa246928, Ptr{Nothing} @0x00007ffffa246ec7, Ptr{Nothing} @0x00007ffffa24772e, Base.InterpreterIP in top-level CodeInfo for Main at statement 1, Ptr{Nothing} @0x00007ffffa26306b, Ptr{Nothing} @0x00007ffffa2639de, Ptr{Nothing} @0x00007ffffa2649ff, Ptr{Nothing} @0x0000018e6a87e2a0, Ptr{Nothing} @0x00007ffffa23695a, Ptr{Nothing} @0x00007ffffa238951, Ptr{Nothing} @0x00007fffe6548ed8, Ptr{Nothing} @0x00007ffffa238951, Ptr{Nothing} @0x00007fffe4f0e79e, Ptr{Nothing} @0x00007ffffa238951, Ptr{Nothing} @0x0000018e6a8569fb, Ptr{Nothing} @0x0000018e6a856acc, Ptr{Nothing} @0x0000018e6a8582cf, Ptr{Nothing} @0x0000018e6a85ac77, Ptr{Nothing} @0x0000018e6a884918, Ptr{Nothing} @0x0000018e6a884c86, Ptr{Nothing} @0x0000018e6a88666d, Ptr{Nothing} @0x0000018e6a8866ab, Ptr{Nothing} @0x00007fffe60fbcbb, Ptr{Nothing} @0x0000018e6a88642d, Ptr{Nothing} @0x0000018e6a88653b, Ptr{Nothing} @0x00007ffffa23695a, Ptr{Nothing} @0x0000018e6a855c2e, Ptr{Nothing} @0x0000018e6a855c6b, Ptr{Nothing} @0x00007ffffa238951, Ptr{Nothing} @0x0000018e6a83b237, Ptr{Nothing} @0x0000018e6a83b4b4, Ptr{Nothing} @0x00007ffffa24bcbb])
└ @ Main c:\Users\mrufsvold\Projects\DIL-price-transparency-psd\TableConsolidator.jl\playground.jl:132

Side note: I get this transient behavior where sometimes this code returns Int[1,2,3] without an error at all… but that is probably a question for a separate post.

ericphanson · June 11, 2024, 11:17pm

That’s because ConsoleLogger is doing additional formatting of the backtrace to print it. You can do that manually by logging exception = sprint(Base.display_error, e, catch_backtrace()) instead of the tuple.

But if you want JSON in the end, probably the easiest way to do that is to use LoggingFormats.jl:

julia> with_logger(FormatLogger(LoggingFormats.JSON(), stderr)) do
              try
                  sqrt(-1)
              catch e
                  @error "My task errored!" exception=(e, catch_backtrace())
              end
        end
{"level":"error","msg":"My task errored!","module":"Main","file":"REPL[8]","line":5,"group":"REPL[8]","id":"Main_ff590be1","kwargs":{"exception":"ERROR: DomainError with -1.0:\nsqrt was called with a negative real argument but will only return a complex result if called with a complex argument. Try sqrt(Complex(x)).\nStacktrace:\n  [1] throw_complex_domainerror(f::Symbol, x::Float64)\n    @ Base.Math ./math.jl:33\n  [2] sqrt\n    @ ./math.jl:686 [inlined]\n  [3] sqrt(x::Int64)\n    @ Base.Math ./math.jl:1578\n  [4] (::var\"#9#10\")()\n    @ Main ./REPL[8]:3\n  [5] with_logstate(f::Function, logstate::Any)\n    @ Base.CoreLogging ./logging.jl:515\n  [6] with_logger(f::Function, logger::FormatLogger)\n    @ Base.CoreLogging ./logging.jl:627\n  [7] top-level scope\n    @ REPL[8]:1\n  [8] eval\n    @ ./boot.jl:385 [inlined]\n  [9] eval_user_input(ast::Any, backend::REPL.REPLBackend, mod::Module)\n    @ REPL ~/.julia/juliaup/julia-1.10.3+0.aarch64.apple.darwin14/share/julia/stdlib/v1.10/REPL/src/REPL.jl:150\n [10] repl_backend_loop(backend::REPL.REPLBackend, get_module::Function)\n    @ REPL ~/.julia/juliaup/julia-1.10.3+0.aarch64.apple.darwin14/share/julia/stdlib/v1.10/REPL/src/REPL.jl:246\n [11] start_repl_backend(backend::REPL.REPLBackend, consumer::Any; get_module::Function)\n    @ REPL ~/.julia/juliaup/julia-1.10.3+0.aarch64.apple.darwin14/share/julia/stdlib/v1.10/REPL/src/REPL.jl:231\n [12] run_repl(repl::REPL.AbstractREPL, consumer::Any; backend_on_current_task::Bool, backend::Any)\n    @ REPL ~/.julia/juliaup/julia-1.10.3+0.aarch64.apple.darwin14/share/julia/stdlib/v1.10/REPL/src/REPL.jl:389\n [13] run_repl(repl::REPL.AbstractREPL, consumer::Any)\n    @ REPL ~/.julia/juliaup/julia-1.10.3+0.aarch64.apple.darwin14/share/julia/stdlib/v1.10/REPL/src/REPL.jl:375\n [14] (::Base.var\"#1013#1015\"{Bool, Bool, Bool})(REPL::Module)\n    @ Base ./client.jl:432\n [15] #invokelatest#2\n    @ ./essentials.jl:892 [inlined]\n [16] invokelatest\n    @ ./essentials.jl:889 [inlined]\n [17] run_main_repl(interactive::Bool, quiet::Bool, banner::Bool, history_file::Bool, color_set::Bool)\n    @ Base ./client.jl:416\n [18] exec_options(opts::Base.JLOptions)\n    @ Base ./client.jl:333\n [19] _start()\n    @ Base ./client.jl:552\n"}}

Note the backtrace is formatted automatically, since there is handling for that.

mrufsvold · June 11, 2024, 11:19pm

That is clutch! Thank you!