Fixed long stacktrace printing

[Liozou]

Fix #28442.

This PR makes long stacktrace printing work again by correcting #28328 in the case of stacktraces of length greater than BIG_STACKTRACE_SIZE = 50. However, it breaks the non-official API introduced in that same PR revolving around the possible modification of update_stackframes_callback[] by external packages to fix the number of lines:

• Before this PR, update_stackframes_callback[] was called only once, and updated in-place the entire vector of Tuple{StackFrame, Int} where Int was the number of repetitions of the stackframe.
• After this PR, update_stackframes_callback[] is called on each stackframe individually and should return a corrected stackframe.

I also removed the use of invokelatest since update_stackframes_callback is a Ref, thus update_stackframes_callback[] should automatically refer to the latest implementation of the updater. Feel free to correct me if I was wrong here. I would also like to remove the try...catch block around the updater call but since it was in the original PR, I kept it here.

Incidentally, this fixes a minor issue where cycles that were repeated only once were not shrunk.

@timholy I think you should review this. I checked the code from Revise which is broken by this new API but it seems only a few lines need to be changed in the definition of update_stacktrace_lineno!(namely: get rid of the loop and return t instead of modifying trace[i] in-place) so that shouldn't be too bad.

EDIT: see #28453 (comment)

[Liozou]

This fixes the issue with undetected cycles repeated only once.

[JeffBezanson]

Thanks for fixing this so quickly; would be really good to get this in before 1.0.

I like the new API more. Transforming one frame at a time seems simpler.

I also removed the use of invokelatest since update_stackframes_callback is a Ref, thus update_stackframes_callback[] should automatically refer to the latest implementation of the updater.

I don't think that's true. Whether the function comes from a Ref should not affect this.

[Liozou]

I believe the goal of invokelatest here was to call the latest version of update_stackframes_callback[]. But when packages change the value of update_stackframes_callback[] by a definition of the form update_stackframes_callback[] = updater, I think calling update_stackframes_callback[](frame) and invokelatest(update_stackframes_callback[], frame) yield the same result, which is updater(frame). Is that wrong?

[KristofferC]

It would be good to have tests here to prevent this from happening again.

[Liozou]

Regarding tests, this only affects printing, it does not modify the stacktraces themselves so I'm not sure how to test it.

[vchuravy]

AFAIK you will still need the invokelatest

[KristofferC]

Tests:

julia> f(c) = g(c + 1);

julia> g(c) = c > 10000 ? (return backtrace()) : f(c+1);

julia> bt = f(1);

julia> io = IOBuffer();

julia> Base.show_backtrace(io, bt);

julia> String(take!(io))
"\nStacktrace:\n ... (the last 2 lines are repeated 5000 more times)\n [10006] g(::Int64) at ./REPL[31]:1\n [10006] f(::Int64) at ./REPL[30]:1\n [10006] top-level scope at none:0\n [10006] eval(::Module, ::Any) at ./boot.jl:319\n [10006] eval_user_input(::Any, ::REPL.REPLBackend) at /Users/kristoffer/julia/usr/share/julia/stdlib/v1.0/REPL/src/REPL.jl:85\n [10006] macro expansion at /Users/kristoffer/julia/usr/share/julia/stdlib/v1.0/REPL/src/REPL.jl:117 [inlined]"

[Liozou]

@KristofferC as you can see in your example, the resulting String depends on "/Users/kristoffer" and "REPL", which is not reproducible in a test. Should I remove the last two lines of the output and call it a test (by making it more complete maybe)?

[Liozou]

Ach, even the two first lines depend on "REPL" though. Hm...

[KristofferC]

You don't need to test the exact string. Just that the numbers it starts with are correct.

(and that the the last 2 lines are repeated 5000 more time is present)

[Liozou]

OK, thanks for the idea, I'll try to design a good test.

[Liozou]

Regarding tests, there are two possible things to test:

• the number of the stackframes in the stacktrace. This is the original complaint of Stacktrace counter sometimes gets stuck and doesn't start at one #28442 with [53] starting each line.
• the correct printing with shrunk cycles. This is my additional complaint in Add a callback so packages can correct line numbers for "moving code" #28328 where the ordering of the printing was broken.

Testing the first issue is necessary. Should I also add a test for the second concern? It makes changes in error printing less easy, but maybe that's not really important (the tests can be changed too).

[KristofferC]

In the rare cases that someone changes the backtrace printing, I think it is fine that they need to update a test or two. Better than it accidentally regressing.

[Liozou]

All right, that's also how I feel.

[Liozou]

I basically pasted @KristofferC's idea for the tests. Maybe someone should review?

[timholy]

I think this is fine. This API indeed has advantages in efficiency, since you only correct those stackframes that you are going to show. One downside is that with the previous API, the recipient callback function got stacktraces as complete entities, and hence might be able to do more analysis. (With this API, the callback will just get a series of individual calls with no way to certainly associate them into complete stacktraces.)

But overall I think it's worth sacrificing that potential advantage of the old API. So once you synchronize LAST_SHOWN_LINE_INFOS I think this will be good to go.

[timholy]

I think you need to capture the corrected frame. Otherwise LAST_SHOWN_LINE_INFOS will be the "old" stacktrace, but what's displayed in the REPL will be the new one. Then when someone hits 15^Q to go to the point in the file they will wonder why edit opens the file to the wrong line number.

[Liozou]

Good catch! I'm now actually wondering why the line

push!(LAST_SHOWN_LINE_INFOS, (string(last_frame.file), last_frame.line))

is at this position anyway, shouldn't it be in show_trace_entry directly?

[Liozou]

I sort of assume here that anything which is shown through show_trace_entry is worth adding to LAST_SHOWN_LINE_INFOS, but I may be wrong. I still haven't grasped why show_backtrace(io::IO, t::Vector{Any}) did not add anything to LAST_SHOWN_LINE_INFOS

[Liozou]

I now tentatively update LAST_SHOWN_LINE_INFOS each time show_trace_entry is called, with the new stackframe given by the updater.
@timholy Seems good? You also didn't mention the invokelatest issue discussed above, have you checked it?

[timholy]

Didn't check the invokelatest directly, but I suspect it's necessary. I know from previous experience with the callbacks in loading.jl that it is necessary. You may be able to see it happen by creating a small package that both sets the callback function (have it increment all line numbers by 100 or something, so you can see whether it's working), and then have the package throw an error. I think you'll see it will fail to update the line numbers (the try/catch will obscure the world age error). EDIT: the error has to be thrown before you get back to the REPL (e.g., in the __init__ function), since the world-age updates then.

Hmm, calling invokelatest for each line individually could be another performance problem (in fact now that we're talking about it I think that was a major reason I designed the way I did). It might be worth capturing the "processed list" to a temporary array and then going back to the whole "correct the list all at once" approach.

[Liozou]

All right, back to editing code then

[Liozou]

Uh, actually the test @timholy just indicated passes: using

module FuzzLineno
    function updater(frame::Base.StackFrame)
        return Base.StackFrame(frame.func, frame.file, frame.line+10000, frame.linfo, frame.from_c, frame.inlined, frame.pointer)
    end
    Base.update_stackframes_callback[] = updater

    foo() = error("FOO")
end

I obtain:

julia> FuzzLineno.foo()
ERROR: FOO
Stacktrace:
 [1] error(::String) at ./error.jl:10033
 [2] foo() at /home/liozou/Documents/Boston/randomtests/callbacklatest.jl:10007
 [3] top-level scope at none:10000

julia> error("REPL")
ERROR: REPL
Stacktrace:
 [1] error(::String) at ./error.jl:10033
 [2] top-level scope at none:10000

julia> Base.update_stackframes_callback[] = identity
identity (generic function with 2 methods)

julia> error("REPL")
ERROR: REPL
Stacktrace:
 [1] error(::String) at ./error.jl:33
 [2] top-level scope at none:0

julia> include("/home/liozou/Documents/Boston/randomtests/callbacklatest.jl")
WARNING: replacing module FuzzLineno.
Main.FuzzLineno

julia> error("REPL")
ERROR: REPL
Stacktrace:
 [1] error(::String) at ./error.jl:10033
 [2] top-level scope at none:10000

So, no invokelatest finally ? ;)

[Liozou]

With an error directly in the package:

module FuzzLineno
    function updater(frame::Base.StackFrame)
        return Base.StackFrame(frame.func, frame.file, frame.line+10000, frame.linfo, frame.from_c, frame.inlined, frame.pointer)
    end
    Base.update_stackframes_callback[] = updater
    error("BAZ")
end

It yields

julia> include("/home/liozou/Documents/Boston/randomtests/callbacklatest.jl")
ERROR: LoadError: BAZ
Stacktrace:
 [1] error(::String) at ./error.jl:10033
 [2] top-level scope at none:10000
 [3] include at ./boot.jl:10317 [inlined]
 [4] include_relative(::Module, ::String) at ./loading.jl:11040
 [5] include(::Module, ::String) at ./sysimg.jl:10029
 [6] include(::String) at ./client.jl:10394
 [7] top-level scope at none:10000
in expression starting at /home/liozou/Documents/Boston/randomtests/callbacklatest.jl:6

[Liozou]

This seems intuitive to me: replacing the call to update_stackframes_callback[](frame) is always resolved at runtime, since the value of update_stackframes_callback[] cannot be inferred. Isn't it the point of having a Ref?
It's also true that I don't understand why invokelatest is necessary in loading.jl, but I haven't studied the case.

[Liozou]

I'm not sure I got the __init__ part but even with

module FuzzLineno
    function updater(frame::Base.StackFrame)
        return Base.StackFrame(frame.func, frame.file, frame.line+10000, frame.linfo, frame.from_c, frame.inlined, frame.pointer)
    end
    __init__() = error("BAZ")
    Base.update_stackframes_callback[] = updater
end

I still obtain the desired

julia> include("/home/liozou/Documents/Boston/randomtests/callbacklatest.jl")
ERROR: LoadError: InitError: BAZ
Stacktrace:
 [1] error(::String) at ./error.jl:10033
 [2] __init__() at /home/liozou/Documents/Boston/randomtests/callbacklatest.jl:10005
 [3] include at ./boot.jl:10317 [inlined]
 [4] include_relative(::Module, ::String) at ./loading.jl:11040
 [5] include(::Module, ::String) at ./sysimg.jl:10029
 [6] include(::String) at ./client.jl:10394
 [7] top-level scope at none:10000
during initialization of module FuzzLineno
in expression starting at /home/liozou/Documents/Boston/randomtests/callbacklatest.jl:6

All in all, it really seems to me that invokelatest is unnecessary here; at least, all those tests seem to indicate that.

[timholy]

I'll be getting on a plane soon, but I meant something like this (untested):

module FuzzLineno

function updater(frame::Base.StackFrame)
    return Base.StackFrame(frame.func, frame.file, frame.line+10000, frame.linfo, frame.from_c, frame.inlined, frame.pointer)
end
foo() = error("oh no")

function __init__()
    Base.update_stackframes_callback[] = updater
end

end # module

julia> using FuzzLineno; FuzzLineno.foo()

With precompilation (and that's an essential part of the problem we're discussing), module-body code only runs when the package is precompiled; when you using the package, it just loads a collection of pre-defined methods. Any code that actually needs to run during initialization must be inside the __init__. Consequently you don't require the definiton of updater to be in the __init__, but you must have the line that sets the callback within the __init__ function.

The world age problem is likely to be as follows: the errorshow code loads with julia, then you load FuzzLineno later. Consequently, you're calling at late-world method (updater) from an early-world method (e.g., show_trace_entry). If you hit the REPL after loading FuzzLineno then you'd be fine, because the world-age updates, so you have to test the consequences of what would happen if you throw an error earlier.

Of course, this could be a case where we don't care if the updater runs properly in such cases---because of the try/catch the worst that can happen is that the stacktraces may not be accurate. Consequently this isn't a first-order issue, the way it would be with a package-load callback.

[Liozou]

Your explanation makes sense... But I still can't obtain a faulty stacktrace with your example. I'll investigate into that when I have time, but I'm afraid I won't really have any before a few days.

[KristofferC]

Can we just add back the invokelatest for now?

[JeffBezanson]

It should be clear that it would be very bad if f(x) and Ref(f)[](x) could have different behavior. Yes, they might be inferred differently, but the whole point of world ages and invokelatest is so that the behavior of code does not depend on what we're able to infer.

[JeffBezanson]

cannot be inferred. Isn't it the point of having a Ref?

No, the point of it is to have a mutable 1-element container.

[Liozou]

I can add the invokelatest back, but I can't restore the original API for the time being, so there will be a try invokelatest(...) catch block called at each iteration, which is slow. It's for stacktrace printing so speed is probably not crucial but still. Everyone OK with this?

[JeffBezanson]

Yes, sounds fine.

[timholy]

Fine with me.

[Liozou]

OK so thank you all folks for your patience and sorry for having been so stubborn about the invokelatest thingy, I wasn't thinking straight.
I just did now what I should have done at the very beginning: I repositioned the cycle annotations at their correct place and patched the lacking frame incrementation, fixing #28442. In the end, the API introduced in #28328 is not changed anymore and update_stackframes_callback[] is called only once over the entire stacktrace as it used to, within a try invokelatest(...) catch block. If we want to change that unofficial API, it will be in a later PR. There is also now a test to make sure we don't break #28016 by inadvertence.
@timholy, @JeffBezanson: Everything looking good?

[Liozou]

I can squash the commits if you want.

[StefanKarpinski]

Travis failure is root on the CI machine shutting down the machine, only on x86-32 Linux.