From bcd472f481f7b649096ee27829220d697e383f9e Mon Sep 17 00:00:00 2001 From: Chris Foster Date: Wed, 30 Jan 2019 14:45:11 +1000 Subject: [PATCH 1/4] Add exception stack display to display_error These are printed as a list, with the top of the stack first, down to the root cause. --- base/client.jl | 23 +++++++++++++++++++++++ test/choosetests.jl | 2 +- test/client.jl | 27 +++++++++++++++++++++++++++ 3 files changed, 51 insertions(+), 1 deletion(-) create mode 100644 test/client.jl diff --git a/base/client.jl b/base/client.jl index d7d7204561c2d..d9b01dc242357 100644 --- a/base/client.jl +++ b/base/client.jl @@ -99,6 +99,29 @@ function display_error(io::IO, er, bt) showerror(IOContext(io, :limit => true), er, bt) println(io) end +function display_error(io::IO, stack::Vector) + nexc = length(stack) + printstyled(io, "ERROR: "; bold=true, color=Base.error_color()) + # Display exception stack with the top of the stack first. This ordering + # means that the user doesn't have to scroll up in the REPL to discover the + # root cause. + for i = nexc:-1:1 + if nexc != i + printstyled(io, "caused by [exception ", i, "]\n", color=:light_black) + end + exc,bt = stack[i] + if bt != nothing + # remove REPL-related (or other) frames + eval_ind = findlast(addr->ip_matches_func(addr, :eval), bt) + if eval_ind !== nothing + bt = bt[1:eval_ind-1] + end + showerror(io, exc, bt, backtrace=bt!==nothing) + println(io) + end + end +end +display_error(stack::Vector) = display_error(stderr, stack) display_error(er, bt) = display_error(stderr, er, bt) display_error(er) = display_error(er, []) diff --git a/test/choosetests.jl b/test/choosetests.jl index 2ab565372c64d..4b0b8bcb0bc5f 100644 --- a/test/choosetests.jl +++ b/test/choosetests.jl @@ -46,7 +46,7 @@ function choosetests(choices = []) "mpfr", "broadcast", "complex", "floatapprox", "stdlib", "reflection", "regex", "float16", "combinatorics", "sysinfo", "env", "rounding", "ranges", "mod2pi", - "euler", "show", + "euler", "show", "client", "errorshow", "sets", "goto", "llvmcall", "llvmcall2", "grisu", "some", "meta", "stacktraces", "docs", "misc", "threads", "stress", diff --git a/test/client.jl b/test/client.jl new file mode 100644 index 0000000000000..51d82f42e2dd9 --- /dev/null +++ b/test/client.jl @@ -0,0 +1,27 @@ +nested_error_expr = quote + try + __not_a_binding__ + catch + 1 รท 0 # Generate error while handling error + end +end + +nested_error_pattern = r""" + ERROR: DivideError: integer division error + Stacktrace:.* + caused by \[exception 1\] + UndefVarError: __not_a_binding__ not defined + Stacktrace:.* + """s + +@testset "display_error" begin + # Display of errors which cause more than one entry on the exception stack + err_str = try + eval(nested_error_expr) + catch + excs = Base.catch_stack() + @test typeof.(first.(excs)) == [UndefVarError, DivideError] + sprint(Base.display_error, excs) + end + @test occursin(nested_error_pattern, err_str) +end From 87e903980ed17a74fdce450d70844bee37aa05e8 Mon Sep 17 00:00:00 2001 From: Chris Foster Date: Wed, 30 Jan 2019 14:50:50 +1000 Subject: [PATCH 2/4] Print exception stacks in the REPL using display_error This required a bit of refactoring to disentangle and factor out some of the error handling in the various REPL code paths. --- stdlib/REPL/src/REPL.jl | 92 +++++++++++++++++----------------------- stdlib/REPL/test/repl.jl | 3 +- 2 files changed, 41 insertions(+), 54 deletions(-) diff --git a/stdlib/REPL/src/REPL.jl b/stdlib/REPL/src/REPL.jl index facfa9909ab68..44a43b8c7e399 100644 --- a/stdlib/REPL/src/REPL.jl +++ b/stdlib/REPL/src/REPL.jl @@ -16,7 +16,8 @@ import Base: display, show, AnyDict, - == + ==, + catch_stack include("Terminals.jl") @@ -61,7 +62,7 @@ const JULIA_PROMPT = "julia> " mutable struct REPLBackend "channel for AST" repl_channel::Channel - "channel for results: (value, nothing) or (error, backtrace)" + "channel for results: (value, iserror)" response_channel::Channel "flag indicating the state of this backend" in_eval::Bool @@ -73,28 +74,28 @@ mutable struct REPLBackend end function eval_user_input(@nospecialize(ast), backend::REPLBackend) - iserr, lasterr = false, ((), nothing) + lasterr = nothing Base.sigatomic_begin() while true try Base.sigatomic_end() - if iserr - put!(backend.response_channel, lasterr) + if lasterr !== nothing + put!(backend.response_channel, (lasterr,true)) else backend.in_eval = true value = Core.eval(Main, ast) backend.in_eval = false # note: use jl_set_global to make sure value isn't passed through `expand` ccall(:jl_set_global, Cvoid, (Any, Any, Any), Main, :ans, value) - put!(backend.response_channel, (value, nothing)) + put!(backend.response_channel, (value,false)) end break catch err - if iserr + if lasterr !== nothing println("SYSTEM ERROR: Failed to report error to REPL frontend") println(err) end - iserr, lasterr = true, (err, catch_backtrace()) + lasterr = catch_stack() end end Base.sigatomic_end() @@ -134,20 +135,20 @@ function display(d::REPLDisplay, mime::MIME"text/plain", x) end display(d::REPLDisplay, x) = display(d, MIME("text/plain"), x) -function print_response(repl::AbstractREPL, @nospecialize(val), bt, show_value::Bool, have_color::Bool) - repl.waserror = bt !== nothing +function print_response(repl::AbstractREPL, @nospecialize(response), show_value::Bool, have_color::Bool) + repl.waserror = response[2] io = IOContext(outstream(repl), :module => Main) - print_response(io, val, bt, show_value, have_color, specialdisplay(repl)) + print_response(io, response, show_value, have_color, specialdisplay(repl)) nothing end -function print_response(errio::IO, @nospecialize(val), bt, show_value::Bool, have_color::Bool, specialdisplay=nothing) +function print_response(errio::IO, @nospecialize(response), show_value::Bool, have_color::Bool, specialdisplay=nothing) Base.sigatomic_begin() + val, iserr = response while true try Base.sigatomic_end() - if bt !== nothing - Base.invokelatest(Base.display_error, errio, val, bt) - iserr, lasterr = false, () + if iserr + Base.invokelatest(Base.display_error, errio, val) else if val !== nothing && show_value try @@ -163,15 +164,14 @@ function print_response(errio::IO, @nospecialize(val), bt, show_value::Bool, hav end end break - catch err - if bt !== nothing - println(errio, "SYSTEM: show(lasterr) caused an error") - println(errio, err) - Base.show_backtrace(errio, bt) + catch + if iserr + println(errio, "SYSTEM (REPL): showing an error caused an error") + println(errio, catch_stack()) break end - val = err - bt = catch_backtrace() + val = catch_stack() + iserr = true end end Base.sigatomic_end() @@ -207,7 +207,6 @@ function run_frontend(repl::BasicREPL, backend::REPLBackendRef) d = REPLDisplay(repl) dopushdisplay = !in(d,Base.Multimedia.displays) dopushdisplay && pushdisplay(d) - repl_channel, response_channel = backend.repl_channel, backend.response_channel hit_eof = false while true Base.reseteof(repl.terminal) @@ -238,17 +237,14 @@ function run_frontend(repl::BasicREPL, backend::REPLBackendRef) (isa(ast,Expr) && ast.head == :incomplete) || break end if !isempty(line) - put!(repl_channel, (ast, 1)) - val, bt = take!(response_channel) - if !ends_with_semicolon(line) - print_response(repl, val, bt, true, false) - end + response = eval_with_backend(ast, backend) + print_response(repl, response, !ends_with_semicolon(line), false) end write(repl.terminal, '\n') ((!interrupted && isempty(line)) || hit_eof) && break end # terminate backend - put!(repl_channel, (nothing, -1)) + put!(backend.repl_channel, (nothing, -1)) dopushdisplay && popdisplay(d) nothing end @@ -682,12 +678,9 @@ find_hist_file() = get(ENV, "JULIA_HISTORY", backend(r::AbstractREPL) = r.backendref -send_to_backend(ast, backend::REPLBackendRef) = - send_to_backend(ast, backend.repl_channel, backend.response_channel) - -function send_to_backend(ast, req, rep) - put!(req, (ast, 1)) - return take!(rep) # (val, bt) +function eval_with_backend(ast, backend::REPLBackendRef) + put!(backend.repl_channel, (ast, 1)) + take!(backend.response_channel) # (val, iserr) end function respond(f, repl, main; pass_empty = false) @@ -698,17 +691,14 @@ function respond(f, repl, main; pass_empty = false) line = String(take!(buf)) if !isempty(line) || pass_empty reset(repl) - local val, bt + local response try - response = Base.invokelatest(f, line) - val, bt = send_to_backend(response, backend(repl)) - catch err - val = err - bt = catch_backtrace() - end - if !ends_with_semicolon(line) || bt !== nothing - print_response(repl, val, bt, true, Base.have_color) + ast = Base.invokelatest(f, line) + response = eval_with_backend(ast, backend(repl)) + catch + response = (catch_stack(), true) end + print_response(repl, response, !ends_with_semicolon(line), Base.have_color) end prepare_next(repl) reset_state(s) @@ -848,8 +838,8 @@ function setup_interface( close(f) end hist_from_file(hp, f, hist_path) - catch e - print_response(repl, e, catch_backtrace(), true, Base.have_color) + catch + print_response(repl, (catch_stack(),true), true, Base.have_color) println(outstream(repl)) @info "Disabling history file for this session" repl.history_file = false @@ -1110,7 +1100,6 @@ function run_frontend(repl::StreamREPL, backend::REPLBackendRef) d = REPLDisplay(repl) dopushdisplay = !in(d,Base.Multimedia.displays) dopushdisplay && pushdisplay(d) - repl_channel, response_channel = backend.repl_channel, backend.response_channel while !eof(repl.stream) if have_color print(repl.stream,repl.prompt_color) @@ -1125,15 +1114,12 @@ function run_frontend(repl::StreamREPL, backend::REPLBackendRef) if have_color print(repl.stream, Base.color_normal) end - put!(repl_channel, (ast, 1)) - val, bt = take!(response_channel) - if !ends_with_semicolon(line) - print_response(repl, val, bt, true, have_color) - end + response = eval_with_backend(ast, backend) + print_response(repl, response, !ends_with_semicolon(line), have_color) end end # Terminate Backend - put!(repl_channel, (nothing, -1)) + put!(backend.repl_channel, (nothing, -1)) dopushdisplay && popdisplay(d) nothing end diff --git a/stdlib/REPL/test/repl.jl b/stdlib/REPL/test/repl.jl index 9aa34b68b54de..b18a0042da83e 100644 --- a/stdlib/REPL/test/repl.jl +++ b/stdlib/REPL/test/repl.jl @@ -759,7 +759,8 @@ mutable struct Error19864 <: Exception; end function test19864() @eval Base.showerror(io::IO, e::Error19864) = print(io, "correct19864") buf = IOBuffer() - REPL.print_response(buf, Error19864(), [], false, false, nothing) + fake_response = (Any[(Error19864(),[])],true) + REPL.print_response(buf, fake_response, false, false, nothing) return String(take!(buf)) end @test occursin("correct19864", test19864()) From 5563aa5a536a380688df22edba60325f6bbf3368 Mon Sep 17 00:00:00 2001 From: Chris Foster Date: Wed, 30 Jan 2019 14:31:13 +1000 Subject: [PATCH 3/4] Report exception stacks in _start and the fallback REPL * 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 --- base/client.jl | 38 ++++++++++++++++++++------------------ test/client.jl | 8 ++++++++ 2 files changed, 28 insertions(+), 18 deletions(-) diff --git a/base/client.jl b/base/client.jl index d9b01dc242357..fc02e3547d217 100644 --- a/base/client.jl +++ b/base/client.jl @@ -125,16 +125,18 @@ display_error(stack::Vector) = display_error(stderr, stack) display_error(er, bt) = display_error(stderr, er, bt) display_error(er) = display_error(er, []) -function eval_user_input(@nospecialize(ast), show_value::Bool) - errcount, lasterr, bt = 0, (), nothing +function eval_user_input(errio, @nospecialize(ast), show_value::Bool) + errcount = 0 + lasterr = nothing while true try if have_color print(color_normal) end - if errcount > 0 - invokelatest(display_error, lasterr, bt) - errcount, lasterr = 0, () + if lasterr !== nothing + invokelatest(display_error, errio, lasterr) + errcount = 0 + lasterr = nothing else ast = Meta.lower(Main, ast) value = Core.eval(Main, ast) @@ -146,23 +148,23 @@ function eval_user_input(@nospecialize(ast), show_value::Bool) try invokelatest(display, value) catch - println(stderr, "Evaluation succeeded, but an error occurred while showing value of type ", typeof(value), ":") + @error "Evaluation succeeded, but an error occurred while displaying the value" typeof(value) rethrow() end println() end end break - catch err + catch if errcount > 0 - println(stderr, "SYSTEM: show(lasterr) caused an error") + @error "SYSTEM: display_error(errio, lasterr) caused an error" end - errcount, lasterr = errcount+1, err + errcount += 1 + lasterr = catch_stack() if errcount > 2 - println(stderr, "WARNING: it is likely that something important is broken, and Julia will not be able to continue normally") + @error "It is likely that something important is broken, and Julia will not be able to continue normally" errcount break end - bt = catch_backtrace() end end isa(stdin, TTY) && println() @@ -303,8 +305,8 @@ function exec_options(opts) end try include(Main, PROGRAM_FILE) - catch err - invokelatest(display_error, err, catch_backtrace()) + catch + invokelatest(display_error, catch_stack()) if !is_interactive exit(1) end @@ -413,11 +415,11 @@ function run_main_repl(interactive::Bool, quiet::Bool, banner::Bool, history_fil # if we get back a list of statements, eval them sequentially # as if we had parsed them sequentially for stmt in ex.args - eval_user_input(stmt, true) + eval_user_input(stderr, stmt, true) end body = ex.args else - eval_user_input(ex, true) + eval_user_input(stderr, ex, true) end else while isopen(input) || !eof(input) @@ -426,7 +428,7 @@ function run_main_repl(interactive::Bool, quiet::Bool, banner::Bool, history_fil flush(stdout) end try - eval_user_input(parse_input_line(input), true) + eval_user_input(stderr, parse_input_line(input), true) catch err isa(err, InterruptException) ? print("\n\n") : rethrow() end @@ -472,8 +474,8 @@ function _start() @eval Main import Base.MainInclude: eval, include try exec_options(JLOptions()) - catch err - invokelatest(display_error, err, catch_backtrace()) + catch + invokelatest(display_error, catch_stack()) exit(1) end if is_interactive && have_color diff --git a/test/client.jl b/test/client.jl index 51d82f42e2dd9..fafb476be547c 100644 --- a/test/client.jl +++ b/test/client.jl @@ -25,3 +25,11 @@ nested_error_pattern = r""" end @test occursin(nested_error_pattern, err_str) end + +@testset "Fallback REPL" begin + # Fallback REPL should show errors with display_error + errio = IOBuffer() + Base.eval_user_input(errio, nested_error_expr, true) + err_str = String(take!(errio)) + @test occursin(nested_error_pattern, err_str) +end From d3dbe86f49da6779c2f3af8354c6a3933f48fcad Mon Sep 17 00:00:00 2001 From: Chris Foster Date: Fri, 7 Dec 2018 19:01:03 +1000 Subject: [PATCH 4/4] Don't use jl_rethrow_other for LoadError/InitError 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. --- base/errorshow.jl | 11 ++--------- src/ast.c | 8 ++++---- src/toplevel.c | 4 ++-- test/errorshow.jl | 14 ++++++++++++-- test/precompile.jl | 2 +- 5 files changed, 21 insertions(+), 18 deletions(-) diff --git a/base/errorshow.jl b/base/errorshow.jl index fb263c98435f1..42d1d15153808 100644 --- a/base/errorshow.jl +++ b/base/errorshow.jl @@ -85,18 +85,11 @@ function showerror(io::IO, ex, bt; backtrace=true) end function showerror(io::IO, ex::LoadError, bt; backtrace=true) - print(io, "LoadError: ") - showerror(io, ex.error, bt, backtrace=backtrace) - print(io, "\nin expression starting at $(ex.file):$(ex.line)") + print(io, "Error while loading expression starting at ", ex.file, ":", ex.line) end showerror(io::IO, ex::LoadError) = showerror(io, ex, []) -function showerror(io::IO, ex::InitError, bt; backtrace=true) - print(io, "InitError: ") - showerror(io, ex.error, bt, backtrace=backtrace) - print(io, "\nduring initialization of module ", ex.mod) -end -showerror(io::IO, ex::InitError) = showerror(io, ex, []) +showerror(io::IO, ex::InitError) = print(io, "InitError during initialization of module ", ex.mod) function showerror(io::IO, ex::DomainError, bt; backtrace=true) if isa(ex.val, AbstractArray) diff --git a/src/ast.c b/src/ast.c index 385aa55c913d6..e8fa38df24048 100644 --- a/src/ast.c +++ b/src/ast.c @@ -888,8 +888,8 @@ jl_value_t *jl_parse_eval_all(const char *fname, if (jl_loaderror_type == NULL) jl_rethrow(); else - jl_rethrow_other(jl_new_struct(jl_loaderror_type, form, result, - jl_current_exception())); + jl_throw(jl_new_struct(jl_loaderror_type, form, result, + jl_current_exception())); } JL_GC_POP(); return result; @@ -1046,8 +1046,8 @@ static jl_value_t *jl_invoke_julia_macro(jl_array_t *args, jl_module_t *inmodule else margs[0] = jl_cstr_to_string(""); margs[1] = jl_fieldref(lno, 0); // extract and allocate line number - jl_rethrow_other(jl_new_struct(jl_loaderror_type, margs[0], margs[1], - jl_current_exception())); + jl_throw(jl_new_struct(jl_loaderror_type, margs[0], margs[1], + jl_current_exception())); } } ptls->world_age = last_age; diff --git a/src/toplevel.c b/src/toplevel.c index 694689adf1d7b..60559afe1b958 100644 --- a/src/toplevel.c +++ b/src/toplevel.c @@ -78,8 +78,8 @@ void jl_module_run_initializer(jl_module_t *m) jl_rethrow(); } else { - jl_rethrow_other(jl_new_struct(jl_initerror_type, m->name, - jl_current_exception())); + jl_throw(jl_new_struct(jl_initerror_type, m->name, + jl_current_exception())); } } } diff --git a/test/errorshow.jl b/test/errorshow.jl index 5a85430516ffb..eebecb826b57a 100644 --- a/test/errorshow.jl +++ b/test/errorshow.jl @@ -156,15 +156,16 @@ end macro except_strbt(expr, err_type) errmsg = "expected failure, but no exception thrown for $expr" return quote - let err = nothing + let err = nothing, bt = nothing try $(esc(expr)) catch err + bt = catch_backtrace() end err === nothing && error($errmsg) @test typeof(err) === $(esc(err_type)) buf = IOBuffer() - showerror(buf, err, catch_backtrace()) + showerror(buf, err, bt) String(take!(buf)) end end @@ -554,3 +555,12 @@ let buf = IOBuffer() Base.show_method_candidates(buf, Base.MethodError(sin, Tuple{NoMethodsDefinedHere})) @test length(take!(buf)) !== 0 end + +@testset "Nested errors" begin + # LoadError and InitError used to print the nested exception. + # This is now dealt with via the exception stack so these print very simply: + @test sprint(Base.showerror, LoadError("somefile.jl", 10, ErrorException("retained for backward compat"))) == + "Error while loading expression starting at somefile.jl:10" + @test sprint(Base.showerror, InitError(:some_module, ErrorException("retained for backward compat"))) == + "InitError during initialization of module some_module" +end diff --git a/test/precompile.jl b/test/precompile.jl index e9ccf795bde00..448fc203ba532 100644 --- a/test/precompile.jl +++ b/test/precompile.jl @@ -359,7 +359,7 @@ try error("break me") end """) - @test_warn "ERROR: LoadError: break me\nStacktrace:\n [1] error" try + @test_warn r"ERROR: Error while loading expression starting at.*FooBar2.*caused by.*break me"s try Base.require(Main, :FooBar2) error("\"LoadError: break me\" test failed") catch exc