Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Display exception stacks #30900

Merged
merged 4 commits into from
Feb 2, 2019
Merged

Display exception stacks #30900

merged 4 commits into from
Feb 2, 2019

Conversation

c42f
Copy link
Member

@c42f c42f commented Jan 30, 2019

This PR contains the display-related changes from #29901, in particular:

  • Enhance display_error to print exception stacks coming from Base.catch_stack().
  • Use this new display_error to show the full exception stack in both the REPL and when running scripts via _start.
  • Use jl_throw rather than jl_rethrow_other for LoadError and InitError simplifying the printing of these exceptions while allowing the exception stack to tell the story of the root cause. This will allow us to remove the captured exception fields from LoadError and InitError in the future (Refine exception stack API #29901 (comment))

Here's a picture showing how display_error currently formats the exception stack:
display_exception_stacks

Currently the formatting has the properties:

  • For single exceptions, printing is the same as the current display_error
  • For multiple exceptions the stack is printed from top to bottom so that the root cause is printed last, right next to the user's REPL prompt.
  • For multiple exceptions, the exceptions are separated by a line printed in light grey with the text caused by [exception $n] with excstack[n] following

Here's an example showing how LoadError prints with these changes:
load_error_display

@c42f
Copy link
Member Author

c42f commented Jan 30, 2019

FreeBSD CI error seems to be network related.

@c42f c42f mentioned this pull request Jan 30, 2019
11 tasks
@c42f
Copy link
Member Author

c42f commented Jan 30, 2019

Linux failures are #27788. Again.

print(io, "\nduring initialization of module ", ex.mod)
end
showerror(io::IO, ex::InitError) = showerror(io, ex, [])
showerror(io::IO, ex::LoadError) = print(io, "LoadError in expression starting at ", ex.file, ":", ex.line)
Copy link
Sponsor Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think it would be clearer to say "Error while loading expression starting at ..."; LoadError is just a derived exception and not really a kind of error on its own. It also seems to be unnecessary to show the backtrace for a LoadError; I think it's always a prefix of the nested exception?

Also, it's nice to note that our backtrace machinery is now good enough that LoadError may be entirely unnecessary 🎉

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think it would be clearer to say "Error while loading expression starting at ..."

Sure.

It also seems to be unnecessary to show the backtrace for a LoadError; I think it's always a prefix of the nested exception?

Yes. This isn't really specific to LoadError and @vtjnash had a good suggestion over at #29901 (comment).

@c42f
Copy link
Member Author

c42f commented Jan 31, 2019

our backtrace machinery is now good enough that LoadError may be entirely unnecessary

This also applies to InitError in a sense. Having said that, the exception stack seems a good way of communicating extra information which is available in the intermediate frames between where you threw the original error and where you want to catch it. For LoadError and InitError, this isn't strictly required because the important info (file,line) and module can be inferred from the backtrace.

But in general perhaps we should have a construct like

struct ExceptionContext <: Exception
    message
    vars
end   

ExceptionContext(message=nothing; kwargs...) = ExceptionContext(message, kwargs.data)

function Base.showerror(io::IO, ex::ExceptionContext)
    print(io, "Exception context:")
    if !isnothing(ex.message)
        print(io, " ", ex.message)
    end   
    for (k,v) in pairs(ex.vars)
        print(io, "\n  ", k, " = ", v)
    end
end

Fake example:

bar(y) = baz(y)
baz(y) = sqrt(y)

function foo(x)
    try
        bar(x^2 - 4)
    catch
        throw(ExceptionContext(x=x))
    end
end

foo(1.5)

There seems to be two rather different uses people might have for the system:

  1. To add context to a propagating exception, by throwing an ExceptionContext-like thing.
  2. To avoid loosing the root cause when an exception is thrown while handling an exception.

Unfortunately the best ordering for printing the stack seems somewhat at odds in these cases.

For (1), you'd presumably like to print the root cause first and truncate the common prefix of its stack trace, interspersing the ExceptionContext and printing more of the stack as you go. Something like the following mockup for the example above:

exception_context

For (2) I have a little firsthand experience in digging through java exception stacks to find the root cause. I remember it was always annoying to have to scroll to the top of the log file to find the root cause rather than just finding it at the bottom. The current ordering is designed around the idea that people would like to see the root cause next to their REPL prompt.

@c42f
Copy link
Member Author

c42f commented Jan 31, 2019

The ExceptionContext style printing lends itself very well to LoadError, and arguably makes things clearer by separating the internal julia frames from user defined code. Here's a mockup of how that might look:

load_error2

thoughts? This does make it very clear that the information bundled into LoadError is superfluous provided our backtraces are always this good (they seem to be on linux... not so sure about other platforms).

For the "exception while handling exception" use case, the stack traces might diverge a lot more than what we see here.

@JeffBezanson
Copy link
Sponsor Member

I like the printing order the way you have it now; it matches the way we print stack traces (with the chronologically first thing at the bottom).

LoadError is common enough that I think it's worth special-casing for now and just suppressing its backtrace. Not a big deal though. For other cases it's fine to just print everything.

@c42f
Copy link
Member Author

c42f commented Jan 31, 2019

That's an interesting point about chronology.

Anyhow, I've done the simplest change for now: suppress stacktrace printing in LoadError and rewrite the error message as suggested. Further refinements can always be explored later.

Example of the simplified printing:
load_error

@c42f
Copy link
Member Author

c42f commented Feb 1, 2019

Comments addressed (I think!) and CI has passed.

@fredrikekre fredrikekre added the domain:error handling Handling of exceptions by Julia or the user label Feb 1, 2019
@JeffBezanson
Copy link
Sponsor Member

Beautiful, this is great!

These are printed as a list, with the top of the stack first, down to
the root cause.
This required a bit of refactoring to disentangle and factor out some of
the error handling in the various REPL code paths.
* Use display_error with the exception stack to provide more complete
  root cause info.
* Provide a way to define the error stream in the fallback REPL so it
  can be tested.
* Use the logging system for "out of band" system errors in fallback
  REPL
* Add some actual tests
This is now somewhat redundant, given the exception stack system keeps
the root cause live until the LoadError/InitError is dealt with. Also
simplify the printing of these exceptions, allowing the exception stack
mechanism to tell the story instead.
@c42f c42f force-pushed the cjf/show-exception-stacks-take2 branch from 95066d5 to d3dbe86 Compare February 1, 2019 21:07
@c42f c42f merged commit 538fd8a into master Feb 2, 2019
@c42f c42f deleted the cjf/show-exception-stacks-take2 branch February 2, 2019 05:07
@c42f
Copy link
Member Author

c42f commented Feb 2, 2019

Thanks for the review Jeff!

@KristofferC
Copy link
Sponsor Member

Did this break showing the stacktrace in some cases?

Im getting something like:

Main tests: Error During Test at /mnt/c/Users/Kristoffer/Debugging/Debugger/test/runtests.jl:9
  Got exception outside of a @test
  Error while loading expression starting at /mnt/c/Users/Kristoffer/Debugging/Debugger/test/misc.jl:20
Test Summary: | Pass  Error  Total
Main tests    |    2      1      3
ERROR: Error while loading expression starting at /mnt/c/Users/Kristoffer/Debugging/Debugger/test/runtests.jl:9
caused by [exception 1]
Some tests did not pass: 2 passed, 0 failed, 1 errored, 0 broken.
ERROR: Package Debugger errored during testing

now, while previously, I was sure I got a backtrace of the error in the testset.

@c42f
Copy link
Member Author

c42f commented Feb 15, 2019

@KristofferC Yes it looks like that problem was probably brought on by this PR, because this PR changed showerror with LoadError under the assumption that the root cause would always be available on the exception stack.

But this apparently has a failure mode when a piece of code captures the LoadError and backtrace (ignoring the root cause further down the stack) and then later prints only the LoadError (the backtrace being suppressed). Possible fixes:

  • Capture the whole exception stack for failures in Test
  • Revert the LoadError printing
  • Remove the use of LoadError completely, as discussed above

This is reproduced by the code:

file2.jl

error("Blah")

file1.jl

using Test
@testset "x" begin

include("file2.jl")

end

@JeffBezanson
Copy link
Sponsor Member

  • Capture the whole exception stack for failures in Test

Sounds like the right answer?

@c42f
Copy link
Member Author

c42f commented Feb 16, 2019

True, that's something which should be done regardless of whether LoadError is removed. (I'd like to remove LoadError, but not sure we're ready. Some platforms like FreeBSD don't have reliable backtraces yet I think.)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
domain:error handling Handling of exceptions by Julia or the user
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants