-
Notifications
You must be signed in to change notification settings - Fork 1.9k
Stack traces in R
Stack traces are a critically important tool for Shiny app authors to find sources of errors in their apps.
Out of the box, R has "tracebacks", which are of limited utility for Shiny. Tracebacks contain the same information as stack traces, but they are only collected when an error hits the top-level. Exceptions that are caught before the top-level do not have any traceback information available, and since Shiny doesn't want most errors to escape to the top-level (halting the app) we need a different way to get this info.
Since version 0.13.0, Shiny has had features for capturing and printing stack traces when errors occur in most places in a Shiny app. Significant improvements were made in Shiny 1.1 (promises support, CST pruning, colored output). These features are part of the Shiny package itself currently, but make sense to extract to a separate package to support other runloop-style packages like plumber, fiery, and OpenCPU.
We can decompose the stack trace handling in Shiny into three parts: capturing, denoising, and formatting.
Most other programming languages capture stack trace information at the time an error is generated, and that information is included in the error object. R doesn't do this, but fortunately it gives us the two tools we need to do it ourselves:
-
withCallingHandlers()lets us set up a callback that will be invoked at the time an error is created, before the stack is unwound; -
sys.calls()gives us the call stack.
So we set up a calling handler that calls sys.calls() and saves it on the error object, then rethrows the error:
captureStackTraces <- function(expr) {
withCallingHandlers(
expr,
error = function(e) {
if (is.null(attr(e, "stack.trace", exact = TRUE))) {
attr(e, "stack.trace") <- sys.calls()
stop(e)
}
}
)
}Note that if the stack trace info has already been captured, then the calling handler is a no-op. This allows captureStackTraces to be re-entrant, and you can also rethrow an error multiple times without losing its original stack trace (as the original stack trace is likely to be the most relevant one).
Be aware that withCallingHandlers cannot pierce tryCatch calls; that is, if the expr above involves a tryCatch somewhere inside of it, the calling handler will not be invoked. Therefore, everywhere Shiny uses tryCatch it must also use captureStackTraces directly inside.
Shiny's support for promises significantly complicates the stack trace story. Consider the following example:
1. asyncOp1 <- function() {
2. future({ cars }) %...>% {
3. stop("boom")
4. }
5. }
6.
7. asyncOp2 <- function() {
8. asyncOp1() %...>%
9. print()
10. }If this code is run in Shiny, a promises-naive stack trace will include the top part of the stack, up to Shiny's run-loop (serviceApp) or so, and then immediately descend into some promise-related machinery, then point to the error at line 3. We miss the fact that asyncOp2 and asyncOp1 are conceptually the callers, because they are no longer on R's stack at the time the error is actually created.
Deep stack traces give us the ability to track a promise's caller hierarchy even across %...>% invocations. It does this by maintaining a list of stack traces in .globals$deepStack. Whenever a %...>% (or then, etc.) is encountered (i.e. "subscription time") then a local snapshot of .globals$deepStack is taken. When the bound handler is actually invoked ("fulfill/reject time"), its local snapshot (again, a list of stack traces) is appended with list(sys.calls()) (the current stack trace) and this combined value temporarily replaces .globals$deepStack.
The code in question is implemented in createStackTracePromiseDomain and it looks like this (see Promise Domains if you're not familiar with how they work):
wrapOnFulfilled = function(onFulfilled) {
force(onFulfilled)
# Subscription time
if (deepStacksEnabled()) {
currentStack <- formatStackTrace(sys.calls())
currentDeepStack <- .globals$deepStack
}
function(...) {
# Fulfill time
if (deepStacksEnabled()) {
origDeepStack <- .globals$deepStack
.globals$deepStack <- c(currentDeepStack, list(currentStack))
on.exit(.globals$deepStack <- origDeepStack, add = TRUE)
}
withCallingHandlers(
onFulfilled(...),
error = doCaptureStack
)
}
}and wrapOnRejected is almost identical.
When an error actually occurs (doCaptureStack) then the value of .globals$deepStack is copied into an attribute on the condition object, just like we did with stack.trace above. This gives us all the information we will need in the denoising and printing steps.
The key insight to making this all work is the separation of subscription time and fulfill time. By taking a snapshot at subscription time and applying it at fulfill time, we get a relationship that looks a whole lot like lexical scoping. My original thought was to take a snapshot whenever later::later() was invoked, and apply it at later::run_now time. But it turns out that this approach does not capture asyncOp1 and asyncOp2 in the calls above, as they are not part of the call stack when the future completion is noticed by its promise object.
Unlike, say, Java programmers, R users are not accustomed to huge call stacks with tons of framework and library functions. We try to hide as much of the call stack as possible, to be less intimidating to the user at what is likely a stressful moment in their day.
Increasing the signal/noise ratio of the call stack inherently means we are being less accurate about what is actually running at the time of the error. What we value is the ability for them to determine where in their code the problem is likely to lie.
We take a multipart approach to denoising, using a combination of heuristics and manual instrumentation.
-
Trim information-free frames from the bottom. Most stack traces end with some combination of
stop,.handleSimpleError, andh. These do not provide any distinct information, so we drop them. (Implemented indropTrivialFrames()) -
Look for
..stacktraceoff..and..stacktraceon..calls, and trim all the stack trace frames between them (inclusive). These are calls that are manually inserted by the Shiny maintainers (although they can in theory be inserted by anyone). More details below. -
Use
lobstr::cststyle tree pruning. More details below.
Shiny includes two exported functions, ..stacktraceoff/on.., whose entire implementation is literally:
..stacktraceoff.. <- function(expr) expr
..stacktraceon.. <- function(expr) exprThey are used for no other reason than to take up a stack frame, providing hints for the denoiser code. The denoiser starts out at the top of the stack (assuming stacks grow downward) with a counter value of 1. Every ..stacktraceoff.. call decreases the counter value by one, and every ..stacktraceon.. call increases it by one. Any stack frames encountered while the counter value <= 0 are dropped. (Implemented in stripStackTraces() and stripOneStackTrace())
Shiny calls ..stacktraceoff.. pretty soon after runApp, and calls ..stacktraceon.. only when entering into output renderers, reactive expressions/observers, and other generally user-provided code blocks.
This approach works, but it's fragile, and isn't precise enough to remove every last frame we'd like it to.
Deep stack traces present an additional challenge for ..stacktraceoff/on.., as you can see in the following example:
read_data_async <- function(user_provided_callback) {
..stacktraceoff..(
future({ ... }) %...>% {
..stacktraceon..(user_provided_callback(.))
}
)
}The ..stacktraceoff../..stacktraceon.. are intended to pair up, but ..stacktraceoff.. and ..stacktraceon.. are actually never on the same stack trace--the former will be on one of the deep stack traces when user_provided_callback is invoked. Therefore, for stacktraceoff/on purposes, the active stack trace and all of its corresponding deep stack traces are all lined up end-to-end, starting with the oldest, and the same on/off counter variable is shared across all the traces. In the example above, everything after ..stacktraceoff.. on the deep stack and leading up to the ..stacktraceon.. on the active stack will be stripped.
One last complication: Shiny calls ..stacktraceoff.. pretty close to the top of the stack, right around runApp. Somewhere in the middle, it calls later::run_now (via shiny::serviceApp and httpuv::service). The run_now call is ground zero for any async callbacks (such as promise handlers), so conceptually the stack trace for an async callback should start at run_now. But with Shiny, the stack trace starts at runApp, includes ..stacktraceoff.., a bunch of other stuff, and finally run_now; this chunk of stack trace will be present in every active stack and every deep stack produced by a working Shiny app. When we line up the active stack trace and its deep stack traces end-to-end, as described in the previous paragraph, we don't want to retain this "common" chunk, because 1) it's unnecessary noise and 2) it has a ..stacktraceoff.. that will throw off our counts. For all but the oldest deep stack, we want to remove it. To accomplish this, we add another marker function ..stacktracefloor..() and put that around the level of later::run_now; and for all but the oldest deep stack, we strip from the top of the stack trace to ..stacktracefloor...
Hadley had the insight that whenever you use sys.calls(), you can also grab sys.parents() and use it to turn the traditionally linear stack trace into a tree. Each frame of the stack trace has two different types of parents: 1) the immediately preceding stack frame is what caused the current call to be evaluated, and 2) the sys.parents() is the stack frame where the current call is evaluated.
For most frames, these two types of parents are in fact the same frame, that is, the stack frame that caused the current call to be evaluated is also the environment where that call is evaluated. If this is the case down the whole stack frame, you get a pretty linear tree, basically a linked list:
a <- function() {
lobstr::cst()
}
b <- function() {
a()
}
c <- function() {
b()
}> c()
█
└─c()
└─b()
└─a()
└─lobstr::cst()
What can cause the identities of the two parents to diverge, is delayed evaluation of function arguments. In the following example, we've moved the call to lobstr::cst() out of a; instead, it's passed into a by b.
a <- function(x) {
x
}
b <- function() {
a(lobstr::cst())
}
c <- function() {
b()
}> c()
█
└─c()
└─b()
├─a(lobstr::cst())
└─lobstr::cst()
Because the evaluation of lobstr::cst() is performed in b(), its lexical scope, but it is evaluated while a() is on the stack, we now have a tree instead of a linked list.
The second insight Hadley had was that when you're viewing these call stack trees, only the last branch of every node is likely to be interesting when you're trying to track down an error. In a call like foo(bar()), if bar() throws an error, it's unlikely that you'll lose much information by removing foo() from the call stack. Empirically, it seems like in these cases, the discarded (foo()) function is usually something like try, tryCatch, withCallingHandlers, with_promise_domain; these functions add a lot of noise to the stack but aren't much help in tracking down the source of the error.
While this type of pruning is inspired by lobstr::cst, we don't actually take a lobstr dependency, but have our own implementation in pruneStackTrace().
The stack trace formatting and printing features are much simpler than the capturing and denoising.
In most programming languages, each line of a stack trace shows the function that's executing, along with (when possible) a filename and line number. The line number points to a location within the function, generally at or near the call that comes next in the call stack. But in R, each element of sys.calls() is a call, and the filename/line number points to the location of the call in source.
For example, if the following code is in a file test.R:
1. foo <- function() {
2. stop("boom")
3. }
4. foo()The R traceback looks like:
6: stop("boom") at foo.R#2
5: foo() at foo.R#4
[snip]
Frame 5 of the traceback says foo() at foo.R#4; looking at line 4 of the code, that's the call to foo(), not the body of foo.
Personally I found this less intuitive than seeing the names of executing functions, and locations within the bodies of those functions. Here's what the stack trace looks like with Shiny:
12: stop
11: foo [~/foo.R#2]
We do this by simply offsetting the source references by stack frame; the final frame gets no source reference.
If you prefer no offsetting, you can opt out of this behavior with options(shiny.stacktraceoffset=FALSE).
Note also in the two preceding outputs, that the Shiny stack trace only includes the function name, not the arguments. I found that including the arguments was distracting and could often have large amounts of code. See the getCallNames function to see how this is implemented; there are also code paths for anonymous functions and delayed evaluation promises (the R kind, not the async kind).
New with Shiny 1.1, we attempt to color specific lines in the stack trace to make them more prominent, if we think R is running on a tty. In particular, we want to highlight what we believe is user code, display package functions in a neutral color, and base/recommended functions in a de-emphasized color.