Stacktrace gripes

[antoine-levitt]

Stacktraces are in general pretty hard to read. Here's a list of gripes. I'm not posting this as separate issues because I don't know what is bug and what is feature here. All tests are on 1.3alpha from an official release. This is related but not the same as #25375, which is about formatting.

Let's start small:

julia> sqrt(-2)
ERROR: DomainError with -2.0:
sqrt will only return a complex result if called with a complex argument. Try sqrt(Complex(x)).
Stacktrace:
 [1] throw_complex_domainerror(::Symbol, ::Float64) at ./math.jl:32
 [2] sqrt at ./math.jl:492 [inlined]
 [3] sqrt(::Int64) at ./math.jl:518
 [4] top-level scope at REPL[4]:1

• Where is ./math.jl?
• I don't care that [2] is inlined
• The last frame is unnecessary (the :1 definitely is, and I don't know what the [4] is)

Now a stdlib:

julia> lu([0 0;0 0])
ERROR: SingularException(1)
Stacktrace:
 [1] checknonsingular at /buildworker/worker/package_linux64/build/usr/share/julia/stdlib/v1.3/LinearAlgebra/src/factorization.jl:19 [inlined]
 [2] #lu!#128(::Bool, ::typeof(lu!), ::Array{Float64,2}, ::Val{true}) at /buildworker/worker/package_linux64/build/usr/share/julia/stdlib/v1.3/LinearAlgebra/src/lu.jl:85
 [3] #lu! at ./none:0 [inlined]
 [4] #lu#134(::Bool, ::typeof(lu), ::Array{Int64,2}) at /buildworker/worker/package_linux64/build/usr/share/julia/stdlib/v1.3/LinearAlgebra/src/lu.jl:295
 [5] lu(::Array{Int64,2}) at /buildworker/worker/package_linux64/build/usr/share/julia/stdlib/v1.3/LinearAlgebra/src/lu.jl:286
 [6] top-level scope at REPL[2]:1

• The paths are bad; that means that nice things like ctrl-q will not work, and neither will the functionality in some editors that go to the path.
• The keyword arguments lowering, which should really be an implementation detail, is exposed here, and confusing (wtf is [3]?)

included user files:

julia> include("scratch.jl")
ERROR: LoadError: UndefVarError: qsd not defined
Stacktrace:
 [1] f() at /home/antoine/scratch.jl:2
 [2] top-level scope at /home/antoine/scratch.jl:4
 [3] include at ./boot.jl:328 [inlined]
 [4] include_relative(::Module, ::String) at ./loading.jl:1094
 [5] include(::Module, ::String) at ./Base.jl:31
 [6] include(::String) at ./client.jl:432
 [7] top-level scope at REPL[3]:1
in expression starting at /home/antoine/scratch.jl:4

• Five frames for the include are hard to read
• Having the information at the bottom is confusing: where am I supposed to find the source of the error? In the stacktrace or at the bottom?
• The LoadError: UndefVarError is annoying (it gets worse for more complex cases, ie multiple includes)

Failing tests:

ERROR: LoadError: LoadError: LoadError: DomainError with -2.0:
sqrt will only return a complex result if called with a complex argument. Try sqrt(Complex(x)).
Stacktrace:
 [1] throw_complex_domainerror(::Symbol, ::Float64) at ./math.jl:32
 [2] sqrt at ./math.jl:492 [inlined]
 [3] sqrt(::Int64) at ./math.jl:518
 [4] @SArray(::LineNumberNode, ::Module, ::Any) at /home/antoine/.julia/packages/StaticArrays/3KEjZ/src/SArray.jl:83
 [5] include at ./boot.jl:328 [inlined]
 [6] include_relative(::Module, ::String) at ./loading.jl:1094
 [7] include(::Module, ::String) at ./Base.jl:31
 [8] include(::String) at ./client.jl:432
 [9] top-level scope at /home/antoine/.julia/packages/StaticArrays/3KEjZ/test/runtests.jl:19
 [10] include at ./boot.jl:328 [inlined]
 [11] include_relative(::Module, ::String) at ./loading.jl:1094
 [12] include(::Module, ::String) at ./Base.jl:31
 [13] include(::String) at ./client.jl:432
 [14] top-level scope at none:5
in expression starting at /home/antoine/.julia/packages/StaticArrays/3KEjZ/test/SArray.jl:30
in expression starting at /home/antoine/.julia/packages/StaticArrays/3KEjZ/test/SArray.jl:1
in expression starting at /home/antoine/.julia/packages/StaticArrays/3KEjZ/test/runtests.jl:19
ERROR: Package StaticArrays errored during testing

I'm a bit confused about what's going on here to be honest...

I did not try with the other ways of including code, macros, etc. So, to sum up, in subjective increasing order of seriousness

• There are minor printing things that could be nicer: REPL frames, LoadError nesting, inline, ./ path for base
• The keyword argument lowering is a bit nasty
• The paths on official releases should be corrected
• The stacktraces with include are very hard to parse. This is possibly the most controversial issue because enhancing this would mean "lying" to the user, ie treating include as a special function

[KristofferC]

It is a bit hard to understand what is rhetorical questions and what are actual questions so just throwing some answers out there.

Where is ./math.jl?

Everything in Base is written like this. Writing the full path would be kinda annoying but perhaps there could be a better way to write it.

The last frame is unnecessary (the :1 definitely is, and I don't know what the [4] is)

It isn't, see #25467. Why would the :1 be unnecessary, we need it in e.g. the debugger. The [4] is the execution count number of the REPL.

The paths are bad; that means that nice things like ctrl-q will not work, and neither will the functionality in some editors that go to the path.

This is #26314.

There is always a contention between showing the truth and what most users would find useful. Personally, I think that hiding stuff like keyword argument wrapper functions by default is the right thing to do.

[antoine-levitt]

It isn't, see #25467. Why would the :1 be unnecessary, we need it in e.g. the debugger. The [4] is the execution count number of the REPL.

Ah, didn't think of multiline input, thanks. Makes sense to print it along with the frame then. The [4] could maybe go?

Everything in Base is written like this. Writing the full path would be kinda annoying but perhaps there could be a better way to write it.

I agree that it would be annoying to have full paths. Why not use ./ as the julia path (ie the top level in the source distribution)? Then base could be ./base/whatever.jl and stdlib ./stdlib/Lib/src/, fixing #26314 also.

[timholy]

I don't care that [2] is inlined

It says that because inlining breaks the ability to show the type information. (Compare the output for the non-inlined calls, there you see the argument types.)

Five frames for the include are hard to read

Julia's dispatch sometimes goes pretty deep. It's both a strength (it's the foundation of abstraction) and a curse (makes things complicated). Not showing the truth has obvious downsides.

There do seem to be a couple of actionable items:

• someone should fix edit and less fail for stdlib functions in distribution binaries  #26314, which seems to be done by workaround wrong paths reported for stdlib functions  #32763. @antoine-levitt, would you care to help out by tacking @which? That seems to be the holdup to merging it.
• tricky to decide about showing the internals of kw dispatch. I'd actually lean towards suppressing it by default, subject to an ENV variable. It's potentially breaking, though, for packages that test the returned stacktrace.

[KristofferC]

#32763 doesn't actually help with stacktraces. But it could probably be extended to do that.

[StefanKarpinski]

• tricky to decide about showing the internals of kw dispatch. I'd actually lean towards suppressing it by default, subject to an ENV variable. It's potentially breaking, though, for packages that test the returned stacktrace.

Can't we keep keyword calls in the stacktrace object but just not print them?

[KristofferC]

Can't we keep keyword calls in the stacktrace object but just not print them?

Yes, we are for example already scrubbing the backtrace before printing it:

julia/base/client.jl

Lines 82 to 101 in cef655a

	function ip_matches_func(ip, func::Symbol)
	for fr in StackTraces.lookup(ip)
	if fr === StackTraces.UNKNOWN || fr.from_c
	return false
	end
	fr.func === func && return true
	end
	return false
	end
	function scrub_repl_backtrace(bt)
	if bt !== nothing
	# remove REPL-related frames from interactive printing
	eval_ind = findlast(addr->ip_matches_func(addr, :eval), bt)
	if eval_ind !== nothing
	return bt[1:eval_ind-1]
	end
	end
	return bt
	end

.

[antoine-levitt]

It says that because inlining breaks the ability to show the type information. (Compare the output for the non-inlined calls, there you see the argument types.)

I see, thanks! How about [2] sqrt(inlined) at ./math.jl:492 to make that more explicit?

Julia's dispatch sometimes goes pretty deep. It's both a strength (it's the foundation of abstraction) and a curse (makes things complicated). Not showing the truth has obvious downsides.

Which practical downsides would that be in this particular example, if we, say, replaced

julia> include("scratch.jl")
ERROR: LoadError: UndefVarError: qsd not defined
Stacktrace:
 [1] f() at /home/antoine/scratch.jl:2
 [2] top-level scope at /home/antoine/scratch.jl:4
 [3] include at ./boot.jl:328 [inlined]
 [4] include_relative(::Module, ::String) at ./loading.jl:1094
 [5] include(::Module, ::String) at ./Base.jl:31
 [6] include(::String) at ./client.jl:432
 [7] top-level scope at REPL[3]:1
in expression starting at /home/antoine/scratch.jl:4

by

julia> include("scratch.jl")
ERROR: LoadError: UndefVarError: qsd not defined
Stacktrace:
 [1] f() at /home/antoine/scratch.jl:2
 [2] top-level scope at /home/antoine/scratch.jl:4
     included from REPL[3]:1
 [3] top-level scope at REPL[3]:1

or similar ?

Sure, it's nice to know that include is just a plain julia function, but do I really need to be reminded of that every time I look at a stacktrace? Given that we already scrub the stacktraces for other purposes, why not do it here? That means accepting that the stacktraces print differently from their internal representation (which we already do), more annoying hacking on include, and having to maintain some code that relies on the internal representation of include. That code is modified very infrequently, so that seems like a small to pay for massively improving stacktraces for everyone.

someone should fix #26314, which seems to be done by #32763. @antoine-levitt, would you care to help out by tacking @which? That seems to be the holdup to merging it.

I think the proper fix here is to use relative paths, which would also fix the consistency with base, see comment above.

To be clear, this thread is not entirely about me complaining idly. If there's a relative consensus (or at least an indication that a PR might be merged) on the easy items proposed above (inline, REPL execution counts), I can do a PR. I can try to do relative paths also, with no promises on timeframe. Kwargs and include are above my paygrade.

[timholy]

All good points. I have definitely seen folks be turned off by the complexity of our stacktraces, this seems to be a necessary discussion.

How about [2] sqrt(inlined) at ./math.jl:492 to make that more explicit?

An even more radical proposal: suppress type information for all calls. That would solve problems like this:

julia> @noinline foo(A) = error("fake")
foo (generic function with 1 method)

julia> foo(img)
ERROR: fake
Stacktrace:
 [1] error(::String) at ./error.jl:33
 [2] foo(::ImageMetadata.ImageMeta{FixedPointNumbers.Normed{UInt16,14},3,AxisArrays.AxisArray{FixedPointNumbers.Normed{UInt16,14},3,SharedArrays.SharedArray{FixedPointNumbers.Normed{UInt16,14},3},Tuple{AxisArrays.Axis{:x,StepRangeLen{Quantity{Float64,𝐋,Unitful.FreeUnits{(μm,),𝐋,nothing}},Base.TwicePrecision{Quantity{Float64,𝐋,Unitful.FreeUnits{(μm,),𝐋,nothing}}},Base.TwicePrecision{Quantity{Float64,𝐋,Unitful.FreeUnits{(μm,),𝐋,nothing}}}}},AxisArrays.Axis{:l,StepRangeLen{Quantity{Float64,𝐋,Unitful.FreeUnits{(μm,),𝐋,nothing}},Base.TwicePrecision{Quantity{Float64,𝐋,Unitful.FreeUnits{(μm,),𝐋,nothing}}},Base.TwicePrecision{Quantity{Float64,𝐋,Unitful.FreeUnits{(μm,),𝐋,nothing}}}}},AxisArrays.Axis{:time,StepRangeLen{Quantity{Float64,𝐓,Unitful.FreeUnits{(s,),𝐓,nothing}},Base.TwicePrecision{Quantity{Float64,𝐓,Unitful.FreeUnits{(s,),𝐓,nothing}}},Base.TwicePrecision{Quantity{Float64,𝐓,Unitful.FreeUnits{(s,),𝐓,nothing}}}}}}},Dict{String,Any}}) at ./REPL[32]:1
 [3] top-level scope at REPL[33]:1

I'm going to start trying to notice whether I find the type information in the stack trace useful in my own debugging. We do have other tools for this available now, it may be less important than it once might have been.

[antoine-levitt]

That's a very nice idea, which would reduce (but not completely solve) the problem of huge type names, aka the StridedArray of doom (cf #32470). Should we just print the argument name instead? ie foo(A) here (although possibly that information is not available?)

[pfitzseb]

I'm going to start trying to notice whether I find the type information in the stack trace useful in my own debugging. We do have other tools for this available now, it may be less important than it once might have been.

FWIW, Juno has been suppressing type info in stacktrace for a long time now, and I don't think anyone ever complained about it.

I think everyone will agree that

is much clearer than

julia> loss(x, w, cdims)
ERROR: AssertionError: DimensionMismatch("Kernel output channel count (10 vs. 1)")
Stacktrace:
 [1] check_dims(::NTuple{5,Int64}, ::NTuple{5,Int64}, ::NTuple{5,Int64}, ::DenseConvDims{3,(3, 3, 1),3,1,(1, 1, 1),(0, 0, 0, 0, 0, 0),(1, 1, 1),false}) at C:\Users\Basti\.julia\packages\NNlib\mxWRT\src\dim_helpers\DenseConvDims.jl:68
 [2] #conv_im2col!#231(::Array{Float64,2}, ::Float64, ::Float64, ::Function, ::Array{Float64,5}, ::Array{Float64,5}, ::Array{Float64,5}, ::DenseConvDims{3,(3, 3, 1),3,1,(1, 1, 1),(0, 0, 0, 0,0, 0),(1, 1, 1),false}) at C:\Users\Basti\.julia\packages\NNlib\mxWRT\src\impl\conv_im2col.jl:30
 [3] conv_im2col! at C:\Users\Basti\.julia\packages\TimerOutputs\7zSea\src\TimerOutput.jl:198 [inlined]
 [4] macro expansion at C:\Users\Basti\.julia\packages\NNlib\mxWRT\src\conv.jl:51 [inlined]
 [5] #conv!#37 at C:\Users\Basti\.julia\packages\TimerOutputs\7zSea\src\TimerOutput.jl:190 [inlined]
 [6] conv!(::Array{Float64,5}, ::Array{Float64,5}, ::Array{Float64,5}, ::DenseConvDims{3,(3, 3, 1),3,1,(1, 1, 1),(0, 0, 0, 0, 0, 0),(1, 1, 1),false}) at C:\Users\Basti\.julia\packages\TimerOutputs\7zSea\src\TimerOutput.jl:198
 [7] #conv!#56(::Base.Iterators.Pairs{Union{},Union{},Tuple{},NamedTuple{(),Tuple{}}}, ::Function, ::Array{Float64,4}, ::Array{Float64,4}, ::Array{Float64,4}, ::DenseConvDims{2,(3, 3),3,1,(1,1),(0, 0, 0, 0),(1, 1),false}) at C:\Users\Basti\.julia\packages\NNlib\mxWRT\src\conv.jl:68
 [8] conv!(::Array{Float64,4}, ::Array{Float64,4}, ::Array{Float64,4}, ::DenseConvDims{2,(3, 3),3,1,(1, 1),(0, 0, 0, 0),(1, 1),false}) at C:\Users\Basti\.julia\packages\NNlib\mxWRT\src\conv.jl:68
 [9] #conv#97(::Base.Iterators.Pairs{Union{},Union{},Tuple{},NamedTuple{(),Tuple{}}}, ::Function, ::Array{Float64,4}, ::Array{Float64,4}, ::DenseConvDims{2,(3, 3),3,1,(1, 1),(0, 0, 0, 0),(1, 1),false}) at C:\Users\Basti\.julia\packages\NNlib\mxWRT\src\conv.jl:114
 [10] conv at C:\Users\Basti\.julia\packages\TimerOutputs\7zSea\src\TimerOutput.jl:198 [inlined]
 [11] loss(::Array{Float64,4}, ::Array{Float64,4}, ::DenseConvDims{2,(3, 3),3,1,(1, 1),(0, 0, 0, 0),(1, 1),false}) at .\untitled-dbb830fbb211cb3810c5451763348f52:4
 [12] top-level scope at none:0

and you can get the type info quickly by opening the file (which should be easy both in the REPL and in Juno).

Juno also shows everything in packages/base/stdlibs with less contrast than user code, which does add a little to clarity as well.

[vchuravy]

I find type-information incredibly useful and would surely miss them. They answer the question how/why did I get there and a MethodError without type-information is useless.

[c42f]

The LoadError annoyance would be addressed by #31882. I plan to come back to that once I've addressed the related but difficult problem of making sure that errors in any top level expression get into the backtrace. There are various cases where this doesn't work right now.

[c42f]

Sure, it's nice to know that include is just a plain julia function, but do I really need to be reminded of that every time I look at a stacktrace?

This is an excellent point. I've often wished that we would scrub include from backtraces.

In general we won't be able to please everybody though with a single default; some parts of Base a user may find "interesting" and other parts are "non-interesting". Some users may even be annoyed to see package code in their backtrace. On the other hand @vchuravy wants to see types, and I'm sure he's wanted to see C frames in there on occasion — I know I have.

I think a good approach would be an interactive user interface for the REPL which allows the last stack trace to be re-printed with increasing or decreasing verbosity based on some keyboard commands.

Then if we have a set of heuristics which label frames with a verbosity, something like from most to least verbose:

C > kw frames / other lowering? > REPL/loading/... > rest of Base > Packages > non-package code

the REPL and other interfaces like Juno can use a consistent shared ordering in their interfaces — much the same way that all editors agree on the set of julia LaTeX completions because the REPL defines a standard.

[JeffBezanson]

There are definitely several good points here.

Ah, didn't think of multiline input, thanks. Makes sense to print it along with the frame then. The [4] could maybe go?

I think the problem is more on the opposite end --- that repl inputs aren't labeled so you can't easily tell which input it's referring to. Maybe we should change the default prompt to be more like the numbered prompts in IJulia?

We could improve the include situation very quickly by just changing the implementation not to do so many layers of dispatch. That might seem a bit undisciplined but I think it's actually easier to maintain than trying to patch it up during stack trace display.

Agreed on keyword arguments; I'll think about it.

I'm also sympathetic to not showing argument types by default; they can indeed be way too verbose. I think I would be ok with it if there were something like ^Q to easily show the types when wanted.