Corrupt linenumber in stacktraces for functions with macros

[ronisbr]

Hi guys!

I am seeing a strange problem with both Julia v0.7 and v1.0. Sometimes, when an error occurs, the line indicated by Julia is not the line in which the error happened. Unfortunately, I failed to construct a minimal working example to show the behavior. Hence, I forked my package so that we can reproduce it.

Steps to reproduce

First, add the package in https://github.com/ronisbr/MGEO-test.jl.git

]add https://github.com/ronisbr/MGEO-test.jl.git

Now, execute the following script:

using MGEO

function f_obj1(vars)
    x1 = vars[1]

    f = [exp(-x1) + 1.4*exp(-x1*x1);
         exp(+x1) + 1.4*exp(-x1*x1)]

    (true, f)
end

design_vars = conf_design_vars(MGEO_Real(), 1, -10.0, +10.0, 1.0)
mgeod = conf_mgeo(2, 0.5, 8000, 50, design_vars)
@time pf = mgeo_run(mgeod, f_obj1, false)

Julia will output:

ERROR: setindex!(::StaticArrays.SArray{Tuple{1},Float64,1,1}, value, ::Int) is not defined.
Stacktrace:
 [1] error(::String) at ./error.jl:33
 [2] setindex!(::StaticArrays.SArray{Tuple{1},Float64,1,1}, ::Float64, ::Int64) at /Users/ronan.arraes/.julia/packages/StaticArrays/Ze5H/src/indexing.jl:3
 [3] mgeo_run(::MGEO_Structure{1,2,Design_Variable_MGEO_Real}, ::typeof(f_obj1), ::Bool) at /Users/ronan.arraes/.julia/packages/MGEO/NqrPJ/src/mgeo_real.jl:100
 [4] top-level scope at util.jl:156

However, look what we have at the line 100 of the file mgeo_real.jl:

 95    @inbounds for run = 1:mgeod.run_max
 96        if show_debug
 97            println("--------------------------------------------------------------------------------")
 98            println("RUN = $run")
 99            println("")
100            println("Generations ($ngen_max_per_run):")
101            print("    0%")
102        end

The error is more likely in line 138:

135            for i=1:Nv
136                # Modify the i-th design variable.
137                vars_i               = copy(vars)
138                @inbounds vars_i[i] += mgeod.design_vars[i].σ*randn()

Because vars is a SVector.

[hpoit]

What would you see if you did https://docs.julialang.org/en/v0.6.1/manual/stacktraces/#Comparison-with-[backtrace()](@ref)-1 ?

[ronisbr]

Not sure if I did this right, but I saw this:

julia> trace = backtrace()
11-element Array{Union{Ptr{Nothing}, InterpreterIP},1}:
 Ptr{Nothing} @0x00000001099c3a78
 Ptr{Nothing} @0x00000001099c253c
 Ptr{Nothing} @0x00000001099c2a88
 Base.InterpreterIP(CodeInfo(
 1 ─ %1 = backtrace()                                                       │
 │        trace = %1                                                        │
 └──      return %1                                                         │
), 0x0000000000000000)
 Ptr{Nothing} @0x00000001099c2ae0
 Ptr{Nothing} @0x0000000109830749
 Ptr{Nothing} @0x0000000109810882
 Ptr{Nothing} @0x0000000112bbf542
 Ptr{Nothing} @0x000000011322b1c6
 Ptr{Nothing} @0x000000011322b414
 Ptr{Nothing} @0x000000010981ab70

julia> stacktrace(trace)
5-element Array{Base.StackTraces.StackFrame,1}:
 top-level scope at none:0
 eval(::Module, ::Any) at boot.jl:319
 eval_user_input(::Any, ::REPL.REPLBackend) at REPL.jl:85
 macro expansion at REPL.jl:117 [inlined]
 (::getfield(REPL, Symbol("##28#29")){REPL.REPLBackend})() at task.jl:262

julia> stacktrace(trace,true)
14-element Array{Base.StackTraces.StackFrame,1}:
 do_call at interpreter.c:324
 eval_stmt_value at interpreter.c:363 [inlined]
 eval_body at interpreter.c:686
 jl_interpret_toplevel_thunk_callback at interpreter.c:799
 top-level scope at none:0
 jl_interpret_toplevel_thunk at interpreter.c:808
 jl_toplevel_eval_flex at toplevel.c:831
 jl_toplevel_eval_in at builtins.c:633
 eval(::Module, ::Any) at boot.jl:319
 eval_user_input(::Any, ::REPL.REPLBackend) at REPL.jl:85
 macro expansion at REPL.jl:117 [inlined]
 (::getfield(REPL, Symbol("##28#29")){REPL.REPLBackend})() at task.jl:262
 jl_apply at julia.h:1538 [inlined]
 start_task at task.c:268

[hpoit]

Have a look at this denizyuret/Knet.jl#305 (comment) and let's continue tomorrow!

[ronisbr]

OK @hpoit

But the problem is not the error message itself (I have already corrected). The problem is that Julia v0.7 and v1.0 is telling me that the error is in a wrong line. This is making debugging very difficult.

[timholy]

Are you using Revise or not? (Revise now corrects line numbers, so it would help to know who is at fault.)

[ronisbr]

No, I am not using Revise.

Actually this was tested in a fresh environment of Julia. Only the dependencies of MGEO were installed.

[hpoit]

Oh I assumed you were using Revise, in that case, have a look at this too https://youtu.be/l0Go2S_L95M?t=4m53s

[timholy]

Reading my comment again, I see I was very unclear, so for the sake of both future readers and Julia developers let me try again: I wasn't trying to suggest that Revise could fix this problem for you, I was instead concerned about whether Revise might be causing it. When I said "Revise corrects line numbers," what I really meant is that Revise "tries to correct line numbers in code that you've edited since Julia or the package was built." It can't correct errors that happen by some other mechanism.

Of course it's always possible that Revise has a bug, and that in attempting to improve things it actually makes it worse. So now (unfortunately) every time someone reports inaccurate line numbers, the proper procedure is first to ask whether Revise is being used and what happens if the user disables it, e.g., if Revise is being run from the .julia/config/startup.jl file then start julia with

julia --startup-file=no

One can test for certain whether Revise is running by typing Revise at the command prompt and hitting enter; if it errors, you're not using Revise. (It's also relevant to ask, "do you have any local modifications to the file?" but that's a separate issue.)

If the line number mistake only happens when you're using Revise (and it's reproducible when you do), please file it as a Revise bug rather than as a Julia bug.

[ronisbr]

Hi @timholy ,

I understood, but no, I definitely was not using Revise.

[ronisbr]

By the way, the error was reproducible using macOS and Linux.

[hpoit]

I wonder what this does

julia/src/toplevel.c

Line 787 in 59977eb

result = jl_interpret_toplevel_thunk(m, thk);

and this

julia/src/interpreter.c

Lines 781 to 808 in 1fa57f3

	struct jl_interpret_toplevel_thunk_args {
	jl_module_t *m;
	jl_code_info_t *src;
	};
	SECT_INTERP CALLBACK_ABI void *jl_interpret_toplevel_thunk_callback(interpreter_state *s, void *vargs) {
	struct jl_interpret_toplevel_thunk_args *args =
	(struct jl_interpret_toplevel_thunk_args*)vargs;
	jl_array_t *stmts = args->src->code;
	assert(jl_typeis(stmts, jl_array_any_type));
	jl_value_t **locals;
	JL_GC_PUSHARGS(locals, jl_source_nslots(args->src) + jl_source_nssavalues(args->src));
	s->src = args->src;
	s->locals = locals;
	s->module = args->m;
	s->sparam_vals = jl_emptysvec;
	s->continue_at = 0;
	s->mi = NULL;
	size_t last_age = jl_get_ptls_states()->world_age;
	jl_value_t *r = eval_body(stmts, s, 0, 1);
	jl_get_ptls_states()->world_age = last_age;
	JL_GC_POP();
	return (void*)r;
	}
	SECT_INTERP jl_value_t *jl_interpret_toplevel_thunk(jl_module_t *m, jl_code_info_t *src)
	{
	struct jl_interpret_toplevel_thunk_args args = { m, src };
	return (jl_value_t *)enter_interpreter_frame(jl_interpret_toplevel_thunk_callback, (void*)&args);

[KristofferC]

@hpoit Please do not derail the discussion. This issue is about a specific thing (erroneous line numbers), linking to videos about Revise and random lines of code is not helpful.

[hpoit]

I am trying to see a solution to the problem, Kris. What's causing the incorrect line number, a macro expansion? What's your workflow in this case? Is https://github.com/StephenVavasis/ErrorLineNumber.jl still applicable?

[ronisbr]

Aha! I finally found a very minimal working example. The problem is with the macro @error. Look a this code:

using StaticArrays

function teste(b)

    a = SVector{3, Float64}(0.,0.,0.)

    (b < 3) && @error("This is an error!")

    a[1] = b
end

teste(3)

It gives:

julia> include("teste_line_num.jl")
ERROR: LoadError: setindex!(::SArray{Tuple{3},Float64,1,3}, value, ::Int) is not defined.
Stacktrace:
 [1] error(::String) at ./error.jl:33
 [2] setindex!(::SArray{Tuple{3},Float64,1,3}, ::Int64, ::Int64) at /Users/ronan.arraes/.julia/packages/StaticArrays/Ze5H3/src/indexing.jl:3
 [3] macro expansion at ./logging.jl:307 [inlined]
 [4] teste(::Int64) at /Users/ronan.arraes/tmp/LineNum/teste_line_num.jl:7
 [5] top-level scope at none:0
 [6] include at ./boot.jl:317 [inlined]
 [7] include_relative(::Module, ::String) at ./loading.jl:1038
 [8] include(::Module, ::String) at ./sysimg.jl:29
 [9] include(::String) at ./client.jl:398
 [10] top-level scope at none:0
in expression starting at /Users/ronan.arraes/tmp/LineNum/teste_line_num.jl:12

Indicating that the error is in line 7, but should be in line 9. However, if I change @error to error:

julia> include("teste_line_num.jl")
ERROR: LoadError: setindex!(::SArray{Tuple{3},Float64,1,3}, value, ::Int) is not defined.
Stacktrace:
 [1] error(::String) at ./error.jl:33
 [2] setindex!(::SArray{Tuple{3},Float64,1,3}, ::Int64, ::Int64) at /Users/ronan.arraes/.julia/packages/StaticArrays/Ze5H3/src/indexing.jl:3
 [3] teste(::Int64) at /Users/ronan.arraes/tmp/LineNum/teste_line_num.jl:9
 [4] top-level scope at none:0
 [5] include at ./boot.jl:317 [inlined]
 [6] include_relative(::Module, ::String) at ./loading.jl:1038
 [7] include(::Module, ::String) at ./sysimg.jl:29
 [8] include(::String) at ./client.jl:398
 [9] top-level scope at none:0
in expression starting at /Users/ronan.arraes/tmp/LineNum/teste_line_num.jl:12

which is correct!

Notice that the same occurs when using @warn, @info, and @debug.

[ronisbr]

By the way, this seems to affect other macros as well. Take a look in this example using Parameter.jl:

using Parameters

@with_kw struct Teste{T}
    a::T
end

function calcular(i::Teste{T}) where T
    @unpack a = T

    c = a*b

    c
end

calcular(Teste{Float64}(1.0))

It leads to the following error:

ERROR: LoadError: UndefVarError: b not defined
Stacktrace:
 [1] macro expansion at /Users/ronan.arraes/.julia/packages/Parameters/KpYO6/src/Parameters.jl:764 [inlined]
 [2] calcular(::Teste{Float64}) at /Users/ronan.arraes/tmp/teste_lineerr.jl:8
 [3] top-level scope at none:0
 [4] include at ./boot.jl:317 [inlined]
 [5] include_relative(::Module, ::String) at ./loading.jl:1038
 [6] include(::Module, ::String) at ./sysimg.jl:29
 [7] include(::String) at ./client.jl:398
 [8] top-level scope at none:0
in expression starting at /Users/ronan.arraes/tmp/teste_lineerr.jl:15

The error is in line 10.

[fredrikekre]

It is also weird that the error is thrown from macro expansion and not from the calcular function.

[fredrikekre]

git bisect suggests a0de85d as the first bad commit, cc @JeffBezanson. The following file

$ cat macrobug.jl
function test()
    @info ""
    a = b
    return a
end
test()

results in wrong linenumber (macrobug.jl:2) and error is thrown from macro expansion

$ ./julia macrobug.jl
[ Info: 
ERROR: LoadError: UndefVarError: b not defined
Stacktrace:
 [1] macro expansion at ./logging.jl:317 [inlined]
 [2] test() at /home/fredrik/julia-master/macrobug.jl:2
 [3] top-level scope at none:0
 [4] include at ./boot.jl:318 [inlined]
 [5] include_relative(::Module, ::String) at ./loading.jl:1071
 [6] include(::Module, ::String) at ./sysimg.jl:29
 [7] macro expansion at ./task.jl:244 [inlined]
 [8] macro expansion at ./task.jl:242 [inlined]
 [9] exec_options(::Base.JLOptions) at ./client.jl:251
 [10] _start() at ./client.jl:427
in expression starting at /home/fredrik/julia-master/macrobug.jl:6

on a0de85d (and master for that matter) but results in correct linenumber (macrobug.jl:3) and error thrown from test

$ ./julia macrobug.jl
[ Info: 
ERROR: LoadError: UndefVarError: b not defined
Stacktrace:
 [1] test() at /home/fredrik/julia-master/macrobug.jl:3
 [2] top-level scope
 [3] include at ./boot.jl:314 [inlined]
 [4] include_relative(::Module, ::String) at ./loading.jl:1071
 [5] include(::Module, ::String) at ./sysimg.jl:29
 [6] exec_options(::Base.JLOptions) at ./client.jl:267
 [7] _start() at ./client.jl:427
in expression starting at /home/fredrik/julia-master/macrobug.jl:6

on 2c68f09.

[fredrikekre]

See also #27959 (caused by the same commit) and the fix #27967

[fredrikekre]

Bumpity bump, this issue makes it extremely difficult to find bugs in functions just because they happen to have a macro call somewhere.

[tkluck]

In the spirit of the test case added in #27967, let me add this test case that exhibits the issue:

using Test

let bt, found = false
    @info ""
    bt = backtrace()
    for frame in map(StackTraces.lookup, bt)
        if frame[1].line == @__LINE__() - 2 && frame[1].file == Symbol(@__FILE__)
            found = true; break
        end
    end
    @test found
end

Interestingly, the issue does not appear when replacing @info "" by @test true. That led me to look into the difference between @macroexpand @info "" and @macroexpand @test true. One difference is that the former has visible line nodes whereas the latter doesn't:

julia> @macroexpand @info ""
quote
    #= logging.jl:305 =#
    #1#level = Base.CoreLogging.Info
    #= logging.jl:306 =#
    #2#std_level = (Base.CoreLogging.convert)(Base.CoreLogging.LogLevel, #1#level)
<snip>
julia> @macroexpand @test true
:((Test.do_test)(begin
          try
              (Test.Returned)(true, Test.nothing, $(QuoteNode(:(#= REPL[5]:1 =#))))
          catch #23#_e
<snip>

That may be related or it may be a red herring; just putting it out there.

[tkluck]

FYI, currently testing this patch here:

diff --git a/src/julia-syntax.scm b/src/julia-syntax.scm
index 904ad0164c..b82e03dfb6 100644
--- a/src/julia-syntax.scm
+++ b/src/julia-syntax.scm
@@ -4049,7 +4049,7 @@ f(x) = yt(x)
                                                    `(line ,current-line ,current-file)
                                                    `(line ,current-line ,current-file ,(caar locstack)))
                                                linetable))
-                         (set! current-loc (+ 1 current-loc)))))
+                         (set! current-loc (length linetable)))))
                   ((and (length> e 2) (eq? (car e) 'meta) (eq? (cadr e) 'push_loc))
                    (set! locstack (cons (list current-loc current-line current-file) locstack))
                    (set! current-file (caddr e))

[tkluck]

Update: it seems that patch isn't quite correct but was prompted by the correct diagnosis. A similar patch is now pull request #30011.

[vtjnash]

Closed by 8c5baf3 (#30011)