Julia: Regression in stacktrace collection with macros

[timholy]

This comes from one of Rebugger's tests.

On a recent master:

$ julia-master --startup-file=no
               _
   _       _ _(_)_     |  Documentation: https://docs.julialang.org
  (_)     | (_) (_)    |
   _ _   _| |_  __ _   |  Type "?" for help, "]?" for Pkg help.
  | | | | | | |/ _` |  |
  | | |_| | | | (_| |  |  Version 1.3.0-DEV.98 (2019-04-24)
 _/ |\__'_|_|_|\__'_|  |  Commit 98b34fd0a9* (1 day old master)
|__/                   |

julia> using Colors

julia> ex = :(@colorant_str "hsl(80%, 20%, 15%)")
:(#= REPL[2]:1 =# @colorant_str "hsl(80%, 20%, 15%)")

julia> try
           eval(ex)
       catch err
           @show err
           stacktrace(catch_backtrace())
       end
err = LoadError("REPL[2]", 1, ErrorException("hue cannot end in %"))
7-element Array{Base.StackTraces.StackFrame,1}:
 eval at boot.jl:330 [inlined]                                           
 eval(::Expr) at client.jl:432                                           
 top-level scope at REPL[3]:2                                            
 eval(::Module, ::Any) at boot.jl:330                                    
 eval_user_input(::Any, ::REPL.REPLBackend) at REPL.jl:86                
 macro expansion at REPL.jl:118 [inlined]                                
 (::getfield(REPL, Symbol("##26#27")){REPL.REPLBackend})() at task.jl:268

Note the first entry is eval, and contains nothing about the actual functions that threw the error when the macro was evaluated.

Compare julia 1.1:

$ julia --startup-file=no
               _
   _       _ _(_)_     |  Documentation: https://docs.julialang.org
  (_)     | (_) (_)    |
   _ _   _| |_  __ _   |  Type "?" for help, "]?" for Pkg help.
  | | | | | | |/ _` |  |
  | | |_| | | | (_| |  |  Version 1.1.1-pre.0 (2019-01-22)
 _/ |\__'_|_|_|\__'_|  |  release-1.1/a84cf6f56c* (fork: 70 commits, 138 days)
|__/                   |

julia> using Colors

julia> ex = :(@colorant_str "hsl(80%, 20%, 15%)")
:(#= REPL[2]:1 =# @colorant_str "hsl(80%, 20%, 15%)")

julia> try
           eval(ex)
       catch err
           @show err
           stacktrace(catch_backtrace())
       end
err = LoadError("REPL[2]", 1, ErrorException("hue cannot end in %"))
13-element Array{Base.StackTraces.StackFrame,1}:
 error(::String) at error.jl:33                                          
 parse_hsl_hue at parse.jl:26 [inlined]                                  
 _parse_colorant(::String) at parse.jl:75                                
 _parse_colorant at parse.jl:112 [inlined]                               
 parse(::Type{Colorant}, ::String) at parse.jl:140                       
 @colorant_str(::LineNumberNode, ::Module, ::Any) at parse.jl:147        
 eval at boot.jl:328 [inlined]                                           
 eval(::Expr) at client.jl:404                                           
 top-level scope at REPL[3]:2                                            
 eval(::Module, ::Any) at boot.jl:328                                    
 eval_user_input(::Any, ::REPL.REPLBackend) at REPL.jl:85                
 macro expansion at REPL.jl:117 [inlined]                                
 (::getfield(REPL, Symbol("##26#27")){REPL.REPLBackend})() at task.jl:259

Here we see references to parse_hsl_hue etc.

[timholy]

In my travis logs, the most recent julia version that passed Rebugger's tests was 1.2.0-DEV.516 (March 20).

[timholy]

git bisect blames #30900, specifically d3dbe86f49da6779c2f3af8354c6a3933f48fcad. CC @c42f.

Here's the standalone test I used for the bisection:

f() = error("oops")
macro g()
    f()
    nothing
end
ex = :(@g)
err, trace = try
    eval(ex)
catch err
    err, stacktrace(catch_backtrace())
end
@assert err.error == ErrorException("oops")
@assert any(sf->sf.func == :f, trace)

[c42f]

Hi Tim, good example + sleuthing, cheers!

I guess this would be due to the change in jl_invoke_julia_macro where I rewrote jl_rethrow_other -> jl_throw. Essentially this pushes the LoadError onto the exception stack and preserves the original exception as the root cause on the stack.

That is, I think the previous behavior would be recovered by reverting the change to the following line which was introduced in d3dbe86:
https://github.com/JuliaLang/julia/blob/dc6c7c7e6f14e7835e1e3cae6a0a20a7d36b75c1/src/ast.c#L1053-L1054

Now, the intention of this change was to stop pretending that the LoadError came from a program location which it in fact did not come from. I still think that's good in principle but it means the LoadError stacktrace on the top of the exception stack won't include f as the LoadError is not the root cause. On the other hand, the full relevant backtrace will be printed with the exception stack by the default error printing code. To illuminate what's going on, try the following:

f() = error("oops")
macro g()
    f()
    nothing
end
ex = :(@g)

stk = try
    eval(ex)
catch
    Base.catch_stack()
end

for (i,(err,trace)) in reverse(collect(enumerate(stk)))
    println("**** Exception number $i ($(typeof(err)))")
    Base.showerror(stdout, err, trace, backtrace=true)
    println()
end

Output (note that Base.showerror() doesn't show backtraces for LoadError)

**** Exception number 2 (LoadError)
Error while loading expression starting at /home/chris/dev/julia/test.jl:6
**** Exception number 1 (ErrorException)
oops
Stacktrace:
 [1] error(::String) at ./error.jl:33
 [2] f() at /home/chris/dev/julia/test.jl:1
 [3] @g(::LineNumberNode, ::Module) at /home/chris/dev/julia/test.jl:3
 [4] eval at ./boot.jl:330 [inlined]
 [5] eval(::Expr) at ./client.jl:432
 [6] top-level scope at /home/chris/dev/julia/test.jl:9
 [7] include at ./boot.jl:328 [inlined]
 [8] include_relative(::Module, ::String) at ./loading.jl:1094
 [9] include(::Module, ::String) at ./Base.jl:31
 [10] exec_options(::Base.JLOptions) at ./client.jl:295
 [11] _start() at ./client.jl:464

So while this is not exactly a bug, it's certainly a change in behavior. I wonder what the best approach is.

[timholy]

Oh, very interesting. I am so short on time these days that I didn't have time to dig into this change, so I really appreciate your guidance. Given these constraints, I can't intelligently comment ATM on what approach should be taken to deal with this as a regression; the two options appear to be change how it works or to document it. If we keep it (and at first glance does seem nice), AFAICT there does not seem to be a NEWS entry about this; since it is breaking, at least a NEWS entry would seem essential for the Julia 1.2 release.

If the new behavior is retained, you've given me enough to introduce some VERSION-dependent code in Rebugger that will enable it to work across Julia versions. I'll be watching for the verdict.

[c42f]

There's at least two problems here:

• We didn't yet think of a good "natural feeling" API for exception stacks which isn't a breaking change. See discussion at https://github.com/JuliaLang/julia/pull/29901#issuecomment-437152442 for example.
• LoadError is kind of vestigial and largely unnecessary (@JeffBezanson has noted this in several places, perhaps most recently https://github.com/JuliaLang/julia/issues/31257#issuecomment-469827014)

So there's a few possible solutions:

1. Revert the few lines which change jl_rethrow_other to jl_throw + LoadError printing as causing more problems than they solve.
2. Document the new behavior in NEWS
3. Remove LoadError and let the original exception propagate as you might actually expect. Also solves https://github.com/JuliaLang/julia/issues/31257. Would be somewhat breaking if people have code which depends on detecting LoadError specifically though such code might be fragile in any case (?)

As a matter of moving forward I prefer the third of these. This requires that our backtraces are reliable enough that this is not a step backward in error reporting. I'm convinced this is true on linux, but I can't comment on other platforms.

[c42f]

I looked into removing LoadError, but I'm afraid that just doing this in a compatible way is not straightforward. The reason is unfortunate: reasonably many packages (informal survey - 8/350 installed locally) have tests which look like:

@test_throws LoadError macroexpand(#= something =#)

In this case the LoadError itself provides nothing of value but regardless of that it's hardcoded into various package tests. It occurs to me that we could lessen the impact of this by detecting it as a special case in @test_throws and allowing LoadError to stand for any exception.

Notably, LoadError occurs in very little package src directories in my informal survey. For the cases that do occur, it's generally to just unwrap the LoadError before further processing.

[c42f]

Well, I've put up a PR for removing LoadError as one possible way to move forward fixing this, including grandfathering rules for @test_throws to avoid breakage as much as possible.

Sticking point is whether this can be considered a minor change or is just too breaking.

[c42f]

It took a bit of work, but deprecating LoadError is looking surprisingly encouraging (https://github.com/JuliaLang/julia/pull/31882#issuecomment-488224367).

[pfitzseb]

This also breaks Juno's stacktrace display (see https://github.com/JunoLab/Juno.jl/issues/242), because we use a very similar pattern to what Tim shows above:

julia/usr/bin on release-1.2
λ julia --quiet
julia> code = """
       f(x) = x//x
       g(x) = f(x) 
       f(0) 
       """
"f(x) = x//x\ng(x) = f(x) \nf(0) \n"

julia> try
         include_string(Main, code, "blah.jl")
       catch err
         @show err
         stacktrace(catch_backtrace())
       end
err = LoadError("blah.jl", 3, ArgumentError("invalid rational: zero(Int64)//zero(Int64)"))
6-element Array{Base.StackTraces.StackFrame,1}:
 include_string(::Module, ::String, ::String) at loading.jl:1064         
 top-level scope at REPL[14]:2                                           
 eval(::Module, ::Any) at boot.jl:330                                    
 eval_user_input(::Any, ::REPL.REPLBackend) at REPL.jl:86                
 macro expansion at REPL.jl:118 [inlined]                                
 (::getfield(REPL, Symbol("##26#27")){REPL.REPLBackend})() at task.jl:268

It would be easy enough to change this to e.g.

julia> err = try
         include_string(Main, code, "blah.jl")
       catch err
         @show err
         stacktrace(Base.catch_stack()[1][2])
       end
err = LoadError("blah.jl", 3, ArgumentError("invalid rational: zero(Int64)//zero(Int64)"))
12-element Array{Base.StackTraces.StackFrame,1}:
 __throw_rational_argerror(::Type) at rational.jl:18                     
 Type at rational.jl:13 [inlined]                                        
 Type at rational.jl:20 [inlined]                                        
 // at rational.jl:43 [inlined]                                          
 f(::Int64) at blah.jl:1                                                 
 top-level scope at blah.jl:3                                            
 include_string(::Module, ::String, ::String) at loading.jl:1064         
 top-level scope at REPL[16]:2                                           
 eval(::Module, ::Any) at boot.jl:330                                    
 eval_user_input(::Any, ::REPL.REPLBackend) at REPL.jl:86                
 macro expansion at REPL.jl:118 [inlined]                                
 (::getfield(REPL, Symbol("##26#27")){REPL.REPLBackend})() at task.jl:268

But we definitely need one of the suggested solutions for the 1.2 release, even if it's only a NEWS.md entry.

[c42f]

For julia-1.2, I have now created #31963 to fix this and keep things stable while we decide on exactly how to go ahead with #31882.