last_error() and last_trace() don't work by default

[krlmlr]

library(rlang)

fn_body(3)
#> Error: `fn` is not a closure
last_error()
#> Error: Can't show last error because no error was recorded yet
last_trace()
#> Error: Can't show last error because no error was recorded yet

^{Created on 2020-03-18 by the reprex package (v0.3.0)}

Workaround

Setting the rlang:::force_unhandled_error option seems to help, I'm not sure if this is the right approach. CC @lionel-.

library(rlang)

options("rlang:::force_unhandled_error" = TRUE)

fn_body(3)
#> Error: `fn` is not a closure
#> Backtrace:
#>     █
#>  1. └─rlang::fn_body(3)
last_error()
#> <error/rlang_error>
#> `fn` is not a closure
#> Backtrace:
#>  1. rlang::fn_body(3)
#> Run `rlang::last_trace()` to see the full context.
last_trace()
#> <error/rlang_error>
#> `fn` is not a closure
#> Backtrace:
#>     █
#>  1. └─rlang::fn_body(3)

^{Created on 2020-03-18 by the reprex package (v0.3.0)}

[jennybc]

Related things have been in the dev version for a while:

e3fcadb
240515d

I've asked @lionel- to look over the rlang backtrace settings and confirm they're in the "best" state. I will do a release soon.

Here's what currently see:

library(rlang)

#options(`rlang:::force_unhandled_error` = TRUE)

fn_body(3)
#> Error: `fn` is not a closure
#> Backtrace:
#>     █
#>  1. └─rlang::fn_body(3)
last_error()
#> <error/rlang_error>
#> `fn` is not a closure
#> Backtrace:
#>  1. rlang::fn_body(3)
#> Run `rlang::last_trace()` to see the full context.
last_trace()
#> <error/rlang_error>
#> `fn` is not a closure
#> Backtrace:
#>     █
#>  1. └─rlang::fn_body(3)

^{Created on 2020-08-06 by the reprex package (v0.3.0.9001)}

I think we're good?

[lionel-]

I read the abort() code again to be sure.

The side effect of forcing unhandled errors is that the backtrace footer (by default a reminder to run last-error or in this case the full backtrace as per the set option) will be included in all error messages emitted by abort(), even those which are handled by a condition handler.

I think this will be problematic with any kind of error catching + rethrowing. We do this a lot in dplyr since 1.0.0 for instance. I think in that case we'll see the backtrace included in the error message multiple times.

The proper way to fix this would be to teach evaluate about condition handlers. Then we'd use entrace() from a calling handler to force entracing. I have a branch in the evaluate repo to implement just this IIRC.

[jennybc]

So you @lionel- want me to reverse this and make it FALSE? In fact, I suppose I would just comment it out.

reprex/R/reprex_render.R

Line 87 in 9594ee9

`rlang:::force_unhandled_error` = TRUE,

And I should tell people to set it directly in their reprex, as @krlmlr did originally here, until evaluate changes?

[lionel-]

Yes it's probably better to set it on a case by case basis for now.

[hadley]

last_error() seems to work for me regardless of whether the option is set to TRUE or FALSE:

f <- function() g()
g <- function() rlang::abort("error")

options("rlang:::force_unhandled_error" = TRUE)
f()
#> Error: error
#> Backtrace:
#>     █
#>  1. └─global::f()
#>  2.   └─global::g()
rlang::last_error()
#> <error/rlang_error>
#> error
#> Backtrace:
#>  1. global::f()
#>  2. global::g()
#> Run `rlang::last_trace()` to see the full context.

options("rlang:::force_unhandled_error" = FALSE)
f()
#> Error: error
rlang::last_error()
#> <error/rlang_error>
#> error
#> Backtrace:
#>  1. global::f()
#>  2. global::g()
#> Run `rlang::last_trace()` to see the full context.

^{Created on 2020-08-19 by the reprex package (v0.3.0)}

[jennybc]

This is interesting.

I can use rlang::last_error() and rlang::last_trace() as long as the rlang:::force_unhandled_error option is not NULL. But it can be either TRUE or FALSE. This is with dev reprex, HEAD currently at f75bdd2.

What do you make of this @lionel- (or others)?

getOption("rlang:::force_unhandled_error")
#> NULL

f <- function() g()
g <- function() h()
h <- function() rlang::abort("oh no!")

f()
#> Error: oh no!
rlang::last_error()
#> Error: Can't show last error because no error was recorded yet
rlang::last_trace()
#> Error: Can't show last error because no error was recorded yet

options("rlang:::force_unhandled_error" = TRUE)
getOption("rlang:::force_unhandled_error")
#> [1] TRUE

f()
#> Error: oh no!
#> Backtrace:
#>     █
#>  1. └─global::f()
#>  2.   └─global::g()
#>  3.     └─global::h()
rlang::last_error()
#> <error/rlang_error>
#> oh no!
#> Backtrace:
#>  1. global::f()
#>  2. global::g()
#>  3. global::h()
#> Run `rlang::last_trace()` to see the full context.
rlang::last_trace()
#> <error/rlang_error>
#> oh no!
#> Backtrace:
#>     █
#>  1. └─global::f()
#>  2.   └─global::g()
#>  3.     └─global::h()

options("rlang:::force_unhandled_error" = FALSE)
getOption("rlang:::force_unhandled_error")
#> [1] FALSE

f()
#> Error: oh no!
rlang::last_error()
#> <error/rlang_error>
#> oh no!
#> Backtrace:
#>  1. global::f()
#>  2. global::g()
#>  3. global::h()
#> Run `rlang::last_trace()` to see the full context.
rlang::last_trace()
#> <error/rlang_error>
#> oh no!
#> Backtrace:
#>     █
#>  1. └─global::f()
#>  2.   └─global::g()
#>  3.     └─global::h()

^{Created on 2020-08-19 by the reprex package (v0.3.0.9001)}

[jennybc]

Also @lionel- can you come up with a concrete example to test your theory that setting options("rlang:::force_unhandled_error" = TRUE) would cause bad things to happen when reprexing, e.g., with dplyr?

I'd love to see a specific example of the downside of setting this option. I had this option set in the dev version for half a year and never experienced a problem.

[lionel-]

@hadley @jennybc I think this is because you first test with TRUE and then FALSE. When it is FALSE the last error does not get updated, and so when you inspect it you find the old error still in there. It might be better to test this behaviour with:

options(
  `rlang:::force_unhandled_error` = TRUE,
  rlang_backtrace_on_error = "full"
)

@jennybc

Indeed with the normal rethrowing usage there is mostly no issue:

options(
  `rlang:::force_unhandled_error` = TRUE,
  rlang_backtrace_on_error = "full"
)

f <- function() g()
g <- function() h()
h <- function() abort("low level")

normal_rethrowing <- function() {
  withCallingHandlers(
    error = function(cnd) abort("high level", parent = cnd),
    f()
  )
}

normal_rethrowing()
#> Error: high level
#> Backtrace:
#>     █
#>  1. └─global::normal_rethrowing()
#>  2.   ├─base::withCallingHandlers(...)
#>  3.   └─global::f()
#>  4.     └─global::g()
#>  5.       └─global::h()

However the backtrace will be duplicated whenever conditionMessage() is called:

fancy_rethrowing <- function() {
  withCallingHandlers(
    error = function(cnd) abort(conditionMessage(cnd), "my_class"),
    f()
  )
}

fancy_rethrowing()
#> Error: low level
#> Backtrace:
#>     █
#>  1. └─global::fancy_rethrowing()
#>  2.   ├─base::withCallingHandlers(...)
#>  3.   └─global::f()
#>  4.     └─global::g()
#>  5.       └─global::h()
#> Backtrace:
#>     █
#>  1. ├─global::fancy_rethrowing()
#>  2. │ ├─base::withCallingHandlers(...)
#>  3. │ └─global::f()
#>  4. │   └─global::g()
#>  5. │     └─global::h()
#>  6. │       └─rlang::abort("low level")
#>  7. │         └─rlang::signal_abort(cnd) R/cnd-abort.R:162:2
#>  8. │           └─base::stop(fallback) R/cnd-abort.R:207:2
#>  9. └─(function (cnd) ...

This is also the case when using try():

I_am_trying <- function() try(f())

I_am_trying()
#> Error : low level
#> Backtrace:
#>     █
#>  1. └─global::I_am_trying()
#>  2.   ├─base::try(f())
#>  3.   │ └─base::tryCatch(...)
#>  4.   │   └─base:::tryCatchList(expr, classes, parentenv, handlers)
#>  5.   │     └─base:::tryCatchOne(expr, names, parentenv, handlers[[1L]])
#>  6.   │       └─base:::doTryCatch(return(expr), name, parentenv, handler)
#>  7.   └─global::f()
#>  8.     └─global::g()
#>  9.       └─global::h()

For reference, the correct behaviour in that case is:

options(
  `rlang:::force_unhandled_error` = FALSE
)

I_am_trying()
#> Error : low level

I agree that it's not as bad as I thought, so if you feel comfortable setting this option please go ahead. We'll keep the option in rlang until it's possible to register calling handlers in evaluate() and knit().

[jennybc]

OK, just to make this thread complete, here's my reprex again confirming what you say about the effect of the order in which I set the option:

getOption("rlang:::force_unhandled_error")
#> NULL

f <- function() g()
g <- function() h()
h <- function() rlang::abort("oh no!")

f()
#> Error: oh no!
rlang::last_error()
#> Error: Can't show last error because no error was recorded yet
rlang::last_trace()
#> Error: Can't show last error because no error was recorded yet

options("rlang:::force_unhandled_error" = FALSE)
getOption("rlang:::force_unhandled_error")
#> [1] FALSE

f()
#> Error: oh no!
rlang::last_error()
#> Error: Can't show last error because no error was recorded yet
rlang::last_trace()
#> Error: Can't show last error because no error was recorded yet

options("rlang:::force_unhandled_error" = TRUE)
getOption("rlang:::force_unhandled_error")
#> [1] TRUE

f()
#> Error: oh no!
#> Backtrace:
#>     █
#>  1. └─global::f()
#>  2.   └─global::g()
#>  3.     └─global::h()
rlang::last_error()
#> <error/rlang_error>
#> oh no!
#> Backtrace:
#>  1. global::f()
#>  2. global::g()
#>  3. global::h()
#> Run `rlang::last_trace()` to see the full context.
rlang::last_trace()
#> <error/rlang_error>
#> oh no!
#> Backtrace:
#>     █
#>  1. └─global::f()
#>  2.   └─global::g()
#>  3.     └─global::h()

^{Created on 2020-08-20 by the reprex package (v0.3.0.9001)}

[lionel-]

Here is a simple example that produces weird behaviour.

options(
  `rlang:::force_unhandled_error` = TRUE,
  rlang_backtrace_on_error = "full"
)

f <- function() g()
g <- function() h()
h <- function() rlang::abort("low level")

dplyr::mutate(data.frame(), foo = f())
#> Error: Problem with `mutate()` input `foo`.
#> ✖ low level
#> Backtrace:
#>     █
#>  1. ├─dplyr::mutate(data.frame(), foo = f())
#>  2. ├─dplyr:::mutate.data.frame(data.frame(), foo = f())
#>  3. │ └─dplyr:::mutate_cols(.data, ...)
#>  4. │   ├─base::withCallingHandlers(...)
#>  5. │   └─mask$eval_all_mutate(dots[[i]])
#>  6. └─global::f()
#>  7.   └─global::g()
#>  8.     └─global::h()
#> ℹ Input `foo` is `f()`.
#> Backtrace:
#>      █
#>   1. ├─dplyr::mutate(data.frame(), foo = f())
#>   2. ├─dplyr:::mutate.data.frame(data.frame(), foo = f())
#>   3. │ └─dplyr:::mutate_cols(.data, ...)
#>   4. │   ├─base::withCallingHandlers(...)
#>   5. │   └─mask$eval_all_mutate(dots[[i]])
#>   6. ├─global::f()
#>   7. │ └─global::g()
#>   8. │   └─global::h()
#>   9. │

This is because dplyr inlines the original error message which now contains a backtrace because unhandled errors are forced. I'm not sure why the second backtrace is truncated.