1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173 174 175 176 177 178 179 180 181 182 183 184 185 186 187 188 189 190 191 192 193 194 195 196 197 198 199 200 201 202 203 204 205 206 207 208 209 210 211 212 213 214 215 216 217 218 219 220 221 222 223 224 225 226 227 228 229 230 231 232 233 234 235 236 237 238 239 240 241 242 243 244 245 246 247 248 249 250 251 252 253 254 255 256 257 258 259 260 261 262 263 264 265 266 267 268 269 270 271 272 273 274 275 276 277 278 279 280 281 282 283 284 285 286 287 288 289 290 291 292 293 294 295 296 297 298 299 300 301 302 303 304 305 306 307 308 309 310 311 312 313 314 315 316 317 318 319 320 321 322 323 324 325 326 327 328 329 330 331 332 333 334 335 336 337 338 339 340 341 342 343 344 345 346 347 348 349 350 351 352 353 354 355 356 357 358 359 360 361 362 363 364 365 366 367 368 369 370 371 372 373 374 375 376 377 378 379 380 381 382 383 384 385 386 387 388 389 390 391 392 393 394 395 396 397 398 399 400 401 402 403 404 405 406 407 408 409 410 411 412 413 414 415 416 417 418 419 420 421 422 423 424 425 426 427 428 429 430 431 432 433 434 435 436 437 438 439 440 441 442 443 444 445 446 447 448 449 450 451 452 453 454 455 456 457 458 459 460 461 462 463 464 465 466 467 468 469 470 471 472 473 474 475 476 477 478 479 480 481 482 483 484 485 486 487 488 489 490 491 492 493 494 495 496 497 498 499 500 501 502 503 504 505 506 507 508 509 510 511 512 513 514 515 516 517 518 519 520 521 522 523 524 525 526 527 528 529 530 531 532 533 534 535 536 537 538 539 540 541 542 543 544 545 546 547 548 549 550 551 552 553 554 555 556 557 558 559 560 561 562 563 564 565 566 567 568 569 570 571 572 573 574 575 576 577 578 579 580 581 582 583 584 585 586 587 588 589 590 591 592 593 594 595 596 597 598 599 600 601 602 603 604 605 606 607 608 609 610 611 612 613 614 615 616 617 618 619 620 621 622
|
#' Stack trace manipulation functions
#'
#' Advanced (borderline internal) functions for capturing, printing, and
#' manipulating stack traces.
#'
#' @return `printError` and `printStackTrace` return
#' `invisible()`. The other functions pass through the results of
#' `expr`.
#'
#' @examples
#' # Keeps tryCatch and withVisible related calls off the
#' # pretty-printed stack trace
#'
#' visibleFunction1 <- function() {
#' stop("Kaboom!")
#' }
#'
#' visibleFunction2 <- function() {
#' visibleFunction1()
#' }
#'
#' hiddenFunction <- function(expr) {
#' expr
#' }
#'
#' # An example without ..stacktraceon/off.. manipulation.
#' # The outer "try" is just to prevent example() from stopping.
#' try({
#' # The withLogErrors call ensures that stack traces are captured
#' # and that errors that bubble up are logged using warning().
#' withLogErrors({
#' # tryCatch and withVisible are just here to add some noise to
#' # the stack trace.
#' tryCatch(
#' withVisible({
#' hiddenFunction(visibleFunction2())
#' })
#' )
#' })
#' })
#'
#' # Now the same example, but with ..stacktraceon/off.. to hide some
#' # of the less-interesting bits (tryCatch and withVisible).
#' ..stacktraceoff..({
#' try({
#' withLogErrors({
#' tryCatch(
#' withVisible(
#' hiddenFunction(
#' ..stacktraceon..(visibleFunction2())
#' )
#' )
#' )
#' })
#' })
#' })
#'
#'
#' @name stacktrace
#' @rdname stacktrace
#' @keywords internal
NULL
getCallNames <- function(calls) {
sapply(calls, function(call) {
if (is.function(call[[1]])) {
"<Anonymous>"
} else if (inherits(call[[1]], "call")) {
paste0(format(call[[1]]), collapse = " ")
} else if (typeof(call[[1]]) == "promise") {
"<Promise>"
} else {
paste0(as.character(call[[1]]), collapse = " ")
}
})
}
getLocs <- function(calls) {
vapply(calls, function(call) {
srcref <- attr(call, "srcref", exact = TRUE)
if (!is.null(srcref)) {
srcfile <- attr(srcref, "srcfile", exact = TRUE)
if (!is.null(srcfile) && !is.null(srcfile$filename)) {
loc <- paste0(srcfile$filename, "#", srcref[[1]])
return(paste0(" [", loc, "]"))
}
}
return("")
}, character(1))
}
getCallCategories <- function(calls) {
vapply(calls, function(call) {
srcref <- attr(call, "srcref", exact = TRUE)
if (!is.null(srcref)) {
srcfile <- attr(srcref, "srcfile", exact = TRUE)
if (!is.null(srcfile)) {
if (!is.null(srcfile$original)) {
return("pkg")
} else {
return("user")
}
}
}
return("")
}, character(1))
}
#' @details `captureStackTraces` runs the given `expr` and if any
#' *uncaught* errors occur, annotates them with stack trace info for use
#' by `printError` and `printStackTrace`. It is not necessary to use
#' `captureStackTraces` around the same expression as
#' `withLogErrors`, as the latter includes a call to the former. Note
#' that if `expr` contains calls (either directly or indirectly) to
#' `try`, or `tryCatch` with an error handler, stack traces therein
#' cannot be captured unless another `captureStackTraces` call is
#' inserted in the interior of the `try` or `tryCatch`. This is
#' because these calls catch the error and prevent it from traveling up to the
#' condition handler installed by `captureStackTraces`.
#'
#' @param expr The expression to wrap.
#' @rdname stacktrace
#' @export
captureStackTraces <- function(expr) {
promises::with_promise_domain(createStackTracePromiseDomain(),
expr
)
}
#' @include globals.R
.globals$deepStack <- NULL
getCallStackDigest <- function(callStack, warn = FALSE) {
dg <- attr(callStack, "shiny.stack.digest", exact = TRUE)
if (!is.null(dg)) {
return(dg)
}
if (isTRUE(warn)) {
rlang::warn(
"Call stack doesn't have a cached digest; expensively computing one now",
.frequency = "once",
.frequency_id = "deepstack-uncached-digest-warning"
)
}
rlang::hash(getCallNames(callStack))
}
saveCallStackDigest <- function(callStack) {
attr(callStack, "shiny.stack.digest") <- getCallStackDigest(callStack, warn = FALSE)
callStack
}
# Appends a call stack to a list of call stacks, but only if it's not already
# in the list. The list is deduplicated by digest; ideally the digests on the
# list are cached before calling this function (you will get a warning if not).
appendCallStackWithDedupe <- function(lst, x) {
digests <- vapply(lst, getCallStackDigest, character(1), warn = TRUE)
xdigest <- getCallStackDigest(x, warn = TRUE)
stopifnot(all(nzchar(digests)))
stopifnot(length(xdigest) == 1)
stopifnot(nzchar(xdigest))
if (xdigest %in% digests) {
return(lst)
} else {
return(c(lst, list(x)))
}
}
createStackTracePromiseDomain <- function() {
# These are actually stateless, we wouldn't have to create a new one each time
# if we didn't want to. They're pretty cheap though.
d <- promises::new_promise_domain(
wrapOnFulfilled = function(onFulfilled) {
force(onFulfilled)
# Subscription time
if (deepStacksEnabled()) {
currentStack <- sys.calls()
currentParents <- sys.parents()
attr(currentStack, "parents") <- currentParents
currentStack <- saveCallStackDigest(currentStack)
currentDeepStack <- .globals$deepStack
}
function(...) {
# Fulfill time
if (deepStacksEnabled()) {
origDeepStack <- .globals$deepStack
.globals$deepStack <- appendCallStackWithDedupe(currentDeepStack, currentStack)
on.exit(.globals$deepStack <- origDeepStack, add = TRUE)
}
withCallingHandlers(
onFulfilled(...),
error = doCaptureStack
)
}
},
wrapOnRejected = function(onRejected) {
force(onRejected)
# Subscription time
if (deepStacksEnabled()) {
currentStack <- sys.calls()
currentParents <- sys.parents()
attr(currentStack, "parents") <- currentParents
currentStack <- saveCallStackDigest(currentStack)
currentDeepStack <- .globals$deepStack
}
function(...) {
# Fulfill time
if (deepStacksEnabled()) {
origDeepStack <- .globals$deepStack
.globals$deepStack <- appendCallStackWithDedupe(currentDeepStack, currentStack)
on.exit(.globals$deepStack <- origDeepStack, add = TRUE)
}
withCallingHandlers(
onRejected(...),
error = doCaptureStack
)
}
},
wrapSync = function(expr) {
withCallingHandlers(expr,
error = doCaptureStack
)
},
onError = doCaptureStack
)
}
deepStacksEnabled <- function() {
getOption("shiny.deepstacktrace", TRUE)
}
doCaptureStack <- function(e) {
if (is.null(attr(e, "stack.trace", exact = TRUE))) {
calls <- sys.calls()
parents <- sys.parents()
attr(calls, "parents") <- parents
calls <- saveCallStackDigest(calls)
attr(e, "stack.trace") <- calls
}
if (deepStacksEnabled()) {
if (is.null(attr(e, "deep.stack.trace", exact = TRUE)) && !is.null(.globals$deepStack)) {
attr(e, "deep.stack.trace") <- .globals$deepStack
}
}
stop(e)
}
#' @details `withLogErrors` captures stack traces and logs errors that
#' occur in `expr`, but does allow errors to propagate beyond this point
#' (i.e. it doesn't catch the error). The same caveats that apply to
#' `captureStackTraces` with regard to `try`/`tryCatch` apply
#' to `withLogErrors`.
#' @rdname stacktrace
#' @export
withLogErrors <- function(expr,
full = get_devmode_option("shiny.fullstacktrace", FALSE),
offset = getOption("shiny.stacktraceoffset", TRUE)) {
withCallingHandlers(
{
result <- captureStackTraces(expr)
# Handle expr being an async operation
if (promises::is.promise(result)) {
result <- promises::catch(result, function(cond) {
# Don't print shiny.silent.error (i.e. validation errors)
if (cnd_inherits(cond, "shiny.silent.error")) {
return()
}
if (isTRUE(getOption("show.error.messages"))) {
printError(cond, full = full, offset = offset)
}
})
}
result
},
error = function(cond) {
# Don't print shiny.silent.error (i.e. validation errors)
if (cnd_inherits(cond, "shiny.silent.error")) return()
if (isTRUE(getOption("show.error.messages"))) {
printError(cond, full = full, offset = offset)
}
}
)
}
#' @details `printError` prints the error and stack trace (if any) using
#' `warning(immediate.=TRUE)`. `printStackTrace` prints the stack
#' trace only.
#'
#' @param cond An condition object (generally, an error).
#' @param full If `TRUE`, then every element of `sys.calls()` will be
#' included in the stack trace. By default (`FALSE`), calls that Shiny
#' deems uninteresting will be hidden.
#' @param offset If `TRUE` (the default), srcrefs will be reassigned from
#' the calls they originated from, to the destinations of those calls. If
#' you're used to stack traces from other languages, this feels more
#' intuitive, as the definition of the function indicated in the call and the
#' location specified by the srcref match up. If `FALSE`, srcrefs will be
#' left alone (traditional R treatment where the srcref is of the callsite).
#' @rdname stacktrace
#' @export
printError <- function(cond,
full = get_devmode_option("shiny.fullstacktrace", FALSE),
offset = getOption("shiny.stacktraceoffset", TRUE)) {
warning(call. = FALSE, immediate. = TRUE, sprintf("Error in %s: %s",
getCallNames(list(conditionCall(cond))), conditionMessage(cond)))
printStackTrace(cond, full = full, offset = offset)
}
#' @rdname stacktrace
#' @export
printStackTrace <- function(cond,
full = get_devmode_option("shiny.fullstacktrace", FALSE),
offset = getOption("shiny.stacktraceoffset", TRUE)) {
stackTraces <- c(
attr(cond, "deep.stack.trace", exact = TRUE),
list(attr(cond, "stack.trace", exact = TRUE))
)
# Stripping of stack traces is the one step where the different stack traces
# interact. So we need to do this in one go, instead of individually within
# printOneStackTrace.
if (!full) {
stripResults <- stripStackTraces(lapply(stackTraces, getCallNames))
} else {
# If full is TRUE, we don't want to strip anything
stripResults <- rep_len(list(TRUE), length(stackTraces))
}
mapply(
seq_along(stackTraces),
rev(stackTraces),
rev(stripResults),
FUN = function(i, trace, stripResult) {
if (is.integer(trace)) {
noun <- if (trace > 1L) "traces" else "trace"
message("[ reached getOption(\"shiny.deepstacktrace\") -- omitted ", trace, " more stack ", noun, " ]")
} else {
if (i != 1) {
message("From earlier call:")
}
printOneStackTrace(
stackTrace = trace,
stripResult = stripResult,
full = full,
offset = offset
)
}
# No mapply return value--we're just printing
NULL
},
SIMPLIFY = FALSE
)
invisible()
}
printOneStackTrace <- function(stackTrace, stripResult, full, offset) {
calls <- offsetSrcrefs(stackTrace, offset = offset)
callNames <- getCallNames(stackTrace)
parents <- attr(stackTrace, "parents", exact = TRUE)
should_drop <- !full
should_strip <- !full
should_prune <- !full
if (should_drop) {
toKeep <- dropTrivialFrames(callNames)
calls <- calls[toKeep]
callNames <- callNames[toKeep]
parents <- parents[toKeep]
stripResult <- stripResult[toKeep]
}
toShow <- rep(TRUE, length(callNames))
if (should_prune) {
toShow <- toShow & pruneStackTrace(parents)
}
if (should_strip) {
toShow <- toShow & stripResult
}
# If we're running in testthat, hide the parts of the stack trace that can
# vary based on how testthat was launched. It's critical that this is not
# happen at the same time as dropTrivialFrames, which happens before
# pruneStackTrace; because dropTrivialTestFrames removes calls from the top
# (or bottom? whichever is the oldest?) of the stack, it breaks `parents`
# which is based on absolute indices of calls. dropTrivialFrames gets away
# with this because it only removes calls from the opposite side of the stack.
toShow <- toShow & dropTrivialTestFrames(callNames)
st <- data.frame(
num = rev(which(toShow)),
call = rev(callNames[toShow]),
loc = rev(getLocs(calls[toShow])),
category = rev(getCallCategories(calls[toShow])),
stringsAsFactors = FALSE
)
if (nrow(st) == 0) {
message(" [No stack trace available]")
} else {
width <- floor(log10(max(st$num))) + 1
formatted <- paste0(
" ",
formatC(st$num, width = width),
": ",
mapply(paste0(st$call, st$loc), st$category, FUN = function(name, category) {
if (category == "pkg")
crayon::silver(name)
else if (category == "user")
crayon::blue$bold(name)
else
crayon::white(name)
}),
"\n"
)
cat(file = stderr(), formatted, sep = "")
}
invisible(st)
}
stripStackTraces <- function(stackTraces, values = FALSE) {
score <- 1L # >=1: show, <=0: hide
lapply(seq_along(stackTraces), function(i) {
res <- stripOneStackTrace(stackTraces[[i]], i != 1, score)
score <<- res$score
toShow <- as.logical(res$trace)
if (values) {
as.character(stackTraces[[i]][toShow])
} else {
as.logical(toShow)
}
})
}
stripOneStackTrace <- function(stackTrace, truncateFloor, startingScore) {
prefix <- logical(0)
if (truncateFloor) {
indexOfFloor <- utils::tail(which(stackTrace == "..stacktracefloor.."), 1)
if (length(indexOfFloor)) {
stackTrace <- stackTrace[(indexOfFloor+1L):length(stackTrace)]
prefix <- rep_len(FALSE, indexOfFloor)
}
}
if (length(stackTrace) == 0) {
return(list(score = startingScore, character(0)))
}
score <- rep.int(0L, length(stackTrace))
score[stackTrace == "..stacktraceon.."] <- 1L
score[stackTrace == "..stacktraceoff.."] <- -1L
score <- startingScore + cumsum(score)
toShow <- score > 0 & !(stackTrace %in% c("..stacktraceon..", "..stacktraceoff..", "..stacktracefloor.."))
list(score = utils::tail(score, 1), trace = c(prefix, toShow))
}
# Given sys.parents() (which corresponds to sys.calls()), return a logical index
# that prunes each subtree so that only the final branch remains. The result,
# when applied to sys.calls(), is a linear list of calls without any "wrapper"
# functions like tryCatch, try, with, hybrid_chain, etc. While these are often
# part of the active call stack, they rarely are helpful when trying to identify
# a broken bit of code.
pruneStackTrace <- function(parents) {
# Detect nodes that are not the last child. This is necessary, but not
# sufficient; we also need to drop nodes that are the last child, but one of
# their ancestors is not.
is_dupe <- duplicated(parents, fromLast = TRUE)
# The index of the most recently seen node that was actually kept instead of
# dropped.
current_node <- 0
# Loop over the parent indices. Anything that is not parented by current_node
# (a.k.a. last-known-good node), or is a dupe, can be discarded. Anything that
# is kept becomes the new current_node.
#
# jcheng 2022-03-18: Two more reasons a node can be kept:
# 1. parent is 0
# 2. parent is i
# Not sure why either of these situations happen, but they're common when
# interacting with rlang/dplyr errors. See issue rstudio/shiny#3250 for repro
# cases.
include <- vapply(seq_along(parents), function(i) {
if ((!is_dupe[[i]] && parents[[i]] == current_node) ||
parents[[i]] == 0 ||
parents[[i]] == i) {
current_node <<- i
TRUE
} else {
FALSE
}
}, FUN.VALUE = logical(1))
include
}
dropTrivialFrames <- function(callnames) {
# Remove stop(), .handleSimpleError(), and h() calls from the end of
# the calls--they don't add any helpful information. But only remove
# the last *contiguous* block of them, and then, only if they are the
# last thing in the calls list.
hideable <- callnames %in% c(".handleSimpleError", "h", "base$wrapOnFulfilled")
# What's the last that *didn't* match stop/.handleSimpleError/h?
lastGoodCall <- max(which(!hideable))
toRemove <- length(callnames) - lastGoodCall
c(
rep_len(TRUE, length(callnames) - toRemove),
rep_len(FALSE, toRemove)
)
}
dropTrivialTestFrames <- function(callnames) {
if (!identical(Sys.getenv("TESTTHAT_IS_SNAPSHOT"), "true")) {
return(rep_len(TRUE, length(callnames)))
}
hideable <- callnames %in% c(
"test",
"devtools::test",
"test_check",
"testthat::test_check",
"test_dir",
"testthat::test_dir",
"test_file",
"testthat::test_file",
"test_local",
"testthat::test_local"
)
firstGoodCall <- min(which(!hideable))
toRemove <- firstGoodCall - 1L
c(
rep_len(FALSE, toRemove),
rep_len(TRUE, length(callnames) - toRemove)
)
}
offsetSrcrefs <- function(calls, offset = TRUE) {
if (offset) {
srcrefs <- getSrcRefs(calls)
# Offset calls vs. srcrefs by 1 to make them more intuitive.
# E.g. for "foo [bar.R:10]", line 10 of bar.R will be part of
# the definition of foo().
srcrefs <- c(utils::tail(srcrefs, -1), list(NULL))
calls <- setSrcRefs(calls, srcrefs)
}
calls
}
getSrcRefs <- function(calls) {
lapply(calls, function(call) {
attr(call, "srcref", exact = TRUE)
})
}
setSrcRefs <- function(calls, srcrefs) {
mapply(function(call, srcref) {
structure(call, srcref = srcref)
}, calls, srcrefs)
}
stripStackTrace <- function(cond) {
conditionStackTrace(cond) <- NULL
}
#' @details `conditionStackTrace` and `conditionStackTrace<-` are
#' accessor functions for getting/setting stack traces on conditions.
#'
#' @param cond A condition that may have previously been annotated by
#' `captureStackTraces` (or `withLogErrors`).
#' @rdname stacktrace
#' @export
conditionStackTrace <- function(cond) {
attr(cond, "stack.trace", exact = TRUE)
}
#' @param value The stack trace value to assign to the condition.
#' @rdname stacktrace
#' @export
`conditionStackTrace<-` <- function(cond, value) {
attr(cond, "stack.trace") <- value
invisible(cond)
}
#' @details The two functions `..stacktraceon..` and
#' `..stacktraceoff..` have no runtime behavior during normal execution;
#' they exist only to create artifacts on the stack trace (sys.call()) that
#' instruct the stack trace pretty printer what parts of the stack trace are
#' interesting or not. The initial state is 1 and we walk from the outermost
#' call inwards. Each ..stacktraceoff.. decrements the state by one, and each
#' ..stacktraceon.. increments the state by one. Any stack trace frame whose
#' value is less than 1 is hidden, and finally, the ..stacktraceon.. and
#' ..stacktraceoff.. calls themselves are hidden too.
#'
#' @rdname stacktrace
#' @export
..stacktraceon.. <- function(expr) expr
#' @rdname stacktrace
#' @export
..stacktraceoff.. <- function(expr) expr
..stacktracefloor.. <- function(expr) expr
|