Regression in stacktrace collection with macros #31830

timholy · 2019-04-25T13:27:09Z

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.

The text was updated successfully, but these errors were encountered:

timholy · 2019-04-25T13:30:44Z

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

timholy · 2019-04-26T13:42:38Z

git bisect blames #30900, specifically d3dbe86. 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 · 2019-04-27T09:41:41Z

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:

julia/src/ast.c

Lines 1053 to 1054 in dc6c7c7

 jl_throw(jl_new_struct(jl_loaderror_type, margs[0], margs[1], 

 jl_current_exception()));

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 · 2019-04-27T15:47:05Z

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 · 2019-04-29T05:15:19Z

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 Refine exception stack API #29901 (comment) for example.
LoadError is kind of vestigial and largely unnecessary (@JeffBezanson has noted this in several places, perhaps most recently Display of exception stacks could be better #31257 (comment))

So there's a few possible solutions:

Revert the few lines which change jl_rethrow_other to jl_throw + LoadError printing as causing more problems than they solve.
Document the new behavior in NEWS
Remove LoadError and let the original exception propagate as you might actually expect. Also solves Display of exception stacks could be better #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 · 2019-04-29T06:34:33Z

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 · 2019-04-30T05:26:44Z

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 · 2019-05-01T09:10:35Z

It took a bit of work, but deprecating LoadError is looking surprisingly encouraging (#31882 (comment)).

pfitzseb · 2019-05-02T10:01:53Z

This also breaks Juno's stacktrace display (see JunoLab/Juno.jl#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 · 2019-05-08T02:09:05Z

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.

timholy added the kind:regression Regression in behavior compared to a previous version label Apr 25, 2019

timholy mentioned this issue Apr 25, 2019

Support different response styles on different Julia versions timholy/Rebugger.jl#69

Merged

timholy assigned c42f Apr 26, 2019

This was referenced Apr 30, 2019

Ensure syntax error locations appear in backtraces #31881

Merged

Soft deprecation of LoadError in runtime #31882

Open

timholy modified the milestone: 1.2 May 2, 2019

c42f mentioned this issue May 3, 2019

[BUG] Fix stacktraces on 1.3 JunoLab/Juno.jl#242

Open

c42f added this to the 1.2 milestone May 3, 2019

c42f mentioned this issue May 8, 2019

Revert "Don't use jl_rethrow_other for LoadError/InitError" (fix #31830) #31963

Merged

JeffBezanson closed this as completed in #31963 May 8, 2019

KristofferC mentioned this issue May 9, 2019

Backports for 1.2-RC1 #31727

Closed

58 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Regression in stacktrace collection with macros #31830

Regression in stacktrace collection with macros #31830

timholy commented Apr 25, 2019

timholy commented Apr 25, 2019 •

edited

Loading

timholy commented Apr 26, 2019

c42f commented Apr 27, 2019

timholy commented Apr 27, 2019

c42f commented Apr 29, 2019

c42f commented Apr 29, 2019

c42f commented Apr 30, 2019

c42f commented May 1, 2019

pfitzseb commented May 2, 2019 •

edited

Loading

c42f commented May 8, 2019

Regression in stacktrace collection with macros #31830

Regression in stacktrace collection with macros #31830

Comments

timholy commented Apr 25, 2019

timholy commented Apr 25, 2019 • edited Loading

timholy commented Apr 26, 2019

c42f commented Apr 27, 2019

timholy commented Apr 27, 2019

c42f commented Apr 29, 2019

c42f commented Apr 29, 2019

c42f commented Apr 30, 2019

c42f commented May 1, 2019

pfitzseb commented May 2, 2019 • edited Loading

c42f commented May 8, 2019

timholy commented Apr 25, 2019 •

edited

Loading

pfitzseb commented May 2, 2019 •

edited

Loading