Include stack trace for errors

[jeroen]

It would be a really cool if evaluate would have an option to include a stack trace for errors. I can see this useful for debugging the call that was evaluated. Kurt mentions the tools:::.try_quietly function on r-devel as an example implementation in this (really old) email: https://stat.ethz.ch/pipermail/r-devel/2005-September/034546.html.

The tricky thing is to have the traceback only include the stack trace starting from evaluate(). I guess that by default you would also get the stack that led to evaluate() call itself.

[hadley]

It's not too hard to filter the traceback - see try_capture_stack. How would you want it returned?

[jeroen]

I guess the most natural way would be to add is as an additional attribute to the error object (alongside the standard err$message and err$call). That way it also works if stoponerror is true, and we can extract the information from the error object after stop() has been called on it.

[jeroen]

I never got this to work... honestly I don't really understand the withCallingHandlers function. Do you have a suggestion on how to edit evaluate_call such that it captures the error stacks as in try_capture_stack? Specifically to make it work for stop_on_error=2L.

[scottkosty]

I would extend this request to return/save a frame dump (from which of course you can get a stack trace). I'm currently using a local patch for evaluate to dump frames, but it would be nice to have this option directly in knitr/evaluate.

I'm curious how everyone has been debugging when using knitr all this time. One can purl the R code out and run in R but there are many reasons why that's not sufficient (cached chunks will not be loaded; sometimes I get an error that only happens when running in knitr; and sometimes it is annoying to go through the steps of purling out the R code, re-evaluating everything to get to the point of error, etc.). Having a frame dump has now made debugging with knitr the same as usual.

[yihui]

@scottkosty When I need to debug a knitr document, I turn off the chunk option error (i.e. error=FALSE). In that case, you have full access to the call stack because evaluate will not protect your calls in try(). Then you are in a normal R world, and all debugging tools will work as expected.

[scottkosty]

Ah, nice! I didn't even think of trying that. Thanks for letting me know, Yihui.

[oliverbock]

After inspecting the evaluate source code I noticed that the error callback is chained off withCallingHandlers()'s error callback, which means that you can call sys.calls() and get a stack that way:

error=function(cond) {
    calls_of_interest <- head(sys.calls()[-seq_len(frame+22)], -3)
    formatted_stack <- paste(format(calls_of_interest), collapse="\n")
    stack_trace <<- formatted_stack
    #signalCondition(cond)  # Normally one would continue error propagation here
    cond  # But I just return the condition because that is what the default error handler does - identity
}

[flying-sheep]

what’s frame here?

[oliverbock]

frame is the count of the stack depth. You record it before the call to evaluate()

frame <- sys.nframe()

and then adjust the constant to omit the calls relating to the implementation of evaluate.

[flying-sheep]

hmm, that doesn’t work for me.

e.g. i have this traceback:

1. IRkernel::main()
2. kernel$run()   # at line 296 of file /home/angerer/Dev/R/IRkernel/R/kernel.r
3. handle_shell()   # at line 273 of file /home/angerer/Dev/R/IRkernel/R/kernel.r
4. executor$execute(msg)   # at line 110-118 of file /home/angerer/Dev/R/IRkernel/R/kernel.r
5. tryCatch(evaluate(request$content$code, envir = .GlobalEnv, output_handler = oh, 
 .     stop_on_error = 1L), interrupt = function(cond) interrupted <<- TRUE, 
 .     error = handle_error)   # at line 235-242 of file /home/angerer/Dev/R/IRkernel/R/execution.r
6. tryCatchList(expr, classes, parentenv, handlers)
7. tryCatchOne(tryCatchList(expr, names[-nh], parentenv, handlers[-nh]), 
 .     names[nh], parentenv, handlers[[nh]])
8. doTryCatch(return(expr), name, parentenv, handler)
9. tryCatchList(expr, names[-nh], parentenv, handlers[-nh])
10. tryCatchOne(expr, names, parentenv, handlers[[1L]])
11. doTryCatch(return(expr), name, parentenv, handler)
12. evaluate(request$content$code, envir = .GlobalEnv, output_handler = oh, 
  .     stop_on_error = 1L)
13. evaluate_call(expr, parsed$src[[i]], envir = envir, enclos = enclos, 
  .     debug = debug, last = i == length(out), use_try = stop_on_error != 
  .         2L, keep_warning = keep_warning, keep_message = keep_message, 
  .     output_handler = output_handler)   # at line 60-65 of file /home/angerer/Dev/R/evaluate/R/eval.r
14. handle(ev <- withCallingHandlers(withVisible(eval(expr, envir, 
  .     enclos)), warning = wHandler, error = eHandler, message = mHandler))   # at line 154-156 of file /home/angerer/Dev/R/evaluate/R/eval.r
15. try(f, silent = TRUE)   # at line 147 of file /home/angerer/Dev/R/evaluate/R/eval.r
16. tryCatch(expr, error = function(e) {
  .     call <- conditionCall(e)
  .     if (!is.null(call)) {
  .         if (identical(call[[1L]], quote(doTryCatch))) 
  .             call <- sys.call(-4L)
  .         dcall <- deparse(call)[1L]
  .         prefix <- paste("Error in", dcall, ": ")
  .         LONG <- 75L
  .         msg <- conditionMessage(e)
  .         sm <- strsplit(msg, "\n")[[1L]]
  .         w <- 14L + nchar(dcall, type = "w") + nchar(sm[1L], type = "w")
  .         if (is.na(w)) 
  .             w <- 14L + nchar(dcall, type = "b") + nchar(sm[1L], 
  .                 type = "b")
  .         if (w > LONG) 
  .             prefix <- paste0(prefix, "\n  ")
  .     }
  .     else prefix <- "Error : "
  .     msg <- paste0(prefix, conditionMessage(e), "\n")
  .     .Internal(seterrmessage(msg[1L]))
  .     if (!silent && identical(getOption("show.error.messages"), 
  .         TRUE)) {
  .         cat(msg, file = stderr())
  .         .Internal(printDeferredWarnings())
  .     }
  .     invisible(structure(msg, class = "try-error", condition = e))
  . })
17. tryCatchList(expr, classes, parentenv, handlers)
18. tryCatchOne(expr, names, parentenv, handlers[[1L]])
19. doTryCatch(return(expr), name, parentenv, handler)
20. withCallingHandlers(withVisible(eval(expr, envir, enclos)), warning = wHandler, 
  .     error = eHandler, message = mHandler)
21. withVisible(eval(expr, envir, enclos))
22. eval(expr, envir, enclos)
23. eval(expr, envir, enclos)
24. throw()
25. f2()   # at line 2 of file <text>
26. stop("deep error")   # at line 1 of file <text>
27. .handleSimpleError(function (e) 
  . {
  .     handle_condition(e)
  .     output_handler$error(structure(e, nframe = nframe))
  . }, "deep error", quote(f2()))
28. h(simpleError(msg, call))
29. output_handler$error(structure(e, nframe = nframe))   # at line 136 of file /home/angerer/Dev/R/evaluate/R/eval.r

sys.nframe() yields 11 there, and the evaluated code’s trace starts at 24 – there’s not 22 calls between 11 and 24.

[oliverbock]

@flying-sheep, the constant (22 in my case) will vary depending on how you are calling evaluate(). It may also change if the implementation of any intermediate methods change. In your case it looks like the code being evaluated starts at frame 24. Since sys.nframe() is 11 before the call then your constant would be 13, or thereabouts. Experiment until you see just the bit of the stack you want.

[flying-sheep]

i tried to reason about the number:

mainly, it’s

• the stack depth in the body of evaluate
• + a constant for handle(ev <- withCallingHandlers(withVisible(eval(expr, ...)), ...)), which should be 4 (?)
• + optionally the stack depth of try if use_try is TRUE, which is 5: try + tryCatch + tryCatchList + tryCatchOne + doTryCatch

something’s off though (off by 1 to be precise): why 2 times the eval expression?

(the following code belongs directly into the body of evaluate)

# handle, withCallingHandlers, withVisible, eval
STACK_OVERHEAD <- 4L
# try (+ tryCatch + tryCatchList + tryCatchOne + doTryCatch)
USE_TRY_OVERHEAD <- 5L

nframe <- sys.nframe() + STACK_OVERHEAD
if (use_try) {
  nframe <- nframe + USE_TRY_OVERHEAD
}

@hadley @yihui would you be OK with adding that code and then passing it to the handlers here?

output_handler$error(structure(e, nframe = nframe))

then people can use attr(e, 'nframe') to retrieve it inside of error handlers.

[jeroen]

Maybe https://github.com/MangoTheCat/tracer

[saurfang]

For anyone who is looking for ways to attach stacktrace in rmarkdown under non-interactive mode, this worked for me (stealing from try_capture_stack and tracer):

        knit_hooks = list(
          evaluate = function(..., output_handler) {
            output_handler$error <- function(e) {
              # Capture call stack, removing last three calls from end (added by
              # withCallingHandlers), and first frame + 13 calls from start (added by
              # evaluate etc)
              frame_offset <- frame + 13
              calls <- head(sys.calls()[-seq_len(frame_offset)], -2)
              funcs <- lapply(seq_along(calls) + frame_offset, sys.function)
              dump <- tracer:::dumper2(calls, funcs, gettext(e))
              tracer:::format_trace(dump)

              e
            }
            frame <- sys.nframe()

            evaluate::evaluate(
              ...,
              output_handler = output_handler
            )
          }
        )

[hadley]

Closing because I now think this will be handled as part of #98