Printing stack trace and continuing after error oc

Question

I'm writing some R code that calls other code that may fail. If it does, I want to print a stack trace (to track down what went wrong), then carry on regardless. However, the traceback() function only provides information about uncaught exceptions. I can get the result I want via a rather complex, natty construction involving tryCatch and dump.frames, but is there not an easier way of doing this?

Answer 1

Have you tried the

 options(error=recover)

setting? Chambers 'Software for Data Analysis' has some useful hints on debugging.

Answer 2

I wrote a solution that works like try, except that it also returns the call stack.

tryStack <- function(
expr,
silent=FALSE
)
{
tryenv <- new.env()
out <- try(withCallingHandlers(expr, error=function(e)
  {
  stack <- sys.calls()
  stack <- stack[-(2:7)]
  stack <- head(stack, -2)
  stack <- sapply(stack, deparse)
  if(!silent && isTRUE(getOption("show.error.messages"))) 
    cat("This is the error stack: ", stack, sep="\n")
  assign("stackmsg", value=paste(stack,collapse="\n"), envir=tryenv)
  }), silent=silent)
if(inherits(out, "try-error")) out[2] <- tryenv$stackmsg
out
}

lower <- function(a) a+10
upper <- function(b) {plot(b, main=b) ; lower(b) }

d <- tryStack(upper(4))
d <- tryStack(upper("4"))
cat(d[2])

More info in my answer here: https://stackoverflow.com/a/40899766/1587132

Answer 3

no line numbers but this is the closest I found so far:

run = function() {
    // Your code here...
}
withCallingHandlers(run(), error=function(e)cat(conditionMessage(e), sapply(sys.calls(),function(sc)deparse(sc)[1]), sep="\n   ")) 

Answer 4

This is a followup to @chrispy's answer above where he presented a withJavaLogging function. I commented that his solution is inspirational, but for me, is marred by some output at the start of the stack trace that I do not want to see.

To illustrate, consider this code:

f1 = function() {
        # line #2 of the function definition; add this line to confirm that the stack trace line number for this function is line #3 below
        catA("f2 = ", f2(), "\n", sep = "")
    }

    f2 = function() {
        # line #2 of the function definition; add this line to confirm that the stack trace line number for this function is line #4 below
        # line #3 of the function definition; add this line to confirm that the stack trace line number for this function is line #4 below
        stop("f2 always causes an error for testing purposes")
    }

If I execute the line withJavaLogging( f1() ) I get the output

2017-02-17 17:58:29.556 FATAL f2 always causes an error for testing purposes
      at .handleSimpleError(function (obj) 
    {
        level = sapply(class(obj), switch, debug = "DEBUG", message = "INFO", warning = "WARN", caughtError = "ERROR", error = if (stopIsFatal) 
            "FATAL"
        else "ERROR", "")
        level = c(level[level != ""], "ERROR")[1]
        simpleMessage = switch(level, DEBUG = , INFO = TRUE
      at #4: stop("f2 always causes an error for testing purposes")
      at f2()
      at catA.R#8: cat(...)
      at #3: catA("f2 = ", f2(), "\n", sep = "")
      at f1()
      at withVisible(expr)
      at #43: withCallingHandlers(withVisible(expr), debug = logger, message = logger, warning = logger, caughtError = logger, error = logger)
      at withJavaLogging(f1())
    Error in f2() : f2 always causes an error for testing purposes

I do not want to see that at .handleSimpleError(function (obj) line followed by the source code of the logger function defined inside the withJavaLogging function. I commented above that I could suppress that undesired output by changing trace = trace[length(trace):1] to trace = trace[(length(trace) - 1):1]

For the convenience of anyone else reading this, here is a complete version of the function that I now use (renamed from withJavaLogging to logFully, and slightly reformatted to fit my readability preferences):

logFully = function(expr, silentSuccess = FALSE, stopIsFatal = TRUE) {
    hasFailed = FALSE
    messages = list()
    warnings = list()

    logger = function(obj) {
        # Change behaviour based on type of message
        level = sapply(
            class(obj),
            switch,
            debug = "DEBUG",
            message = "INFO",
            warning = "WARN",
            caughtError = "ERROR",
            error = if (stopIsFatal) "FATAL" else "ERROR",
            ""
        )
        level = c(level[level != ""], "ERROR")[1]
        simpleMessage = switch(level, DEBUG = TRUE, INFO = TRUE, FALSE)
        quashable = switch(level, DEBUG = TRUE, INFO = TRUE, WARN = TRUE, FALSE)

        # Format message
        time = format(Sys.time(), "%Y-%m-%d %H:%M:%OS3")
        txt = conditionMessage(obj)
        if (!simpleMessage) txt = paste(txt, "\n", sep = "")
        msg = paste(time, level, txt, sep = " ")
        calls = sys.calls()
        calls = calls[1:length(calls) - 1]
        trace = limitedLabels(c(calls, attr(obj, "calls")))
        if (!simpleMessage && length(trace) > 0) {
            trace = trace[(length(trace) - 1):1]
            msg = paste(msg, "  ", paste("at", trace, collapse = "\n  "), "\n", sep = "")
        }

        # Output message
        if (silentSuccess && !hasFailed && quashable) {
            messages <<- append(messages, msg)
            if (level == "WARN") warnings <<- append(warnings, msg)
        } else {
            if (silentSuccess && !hasFailed) {
                cat(paste(messages, collapse = ""))
                hasFailed <<- TRUE
            }
            cat(msg)
        }

        # Muffle any redundant output of the same message
        optionalRestart = function(r) { res = findRestart(r); if (!is.null(res)) invokeRestart(res) }
        optionalRestart("muffleMessage")
        optionalRestart("muffleWarning")
    }

    vexpr = withCallingHandlers( withVisible(expr), debug = logger, message = logger, warning = logger, caughtError = logger, error = logger )

    if (silentSuccess && !hasFailed) {
        cat(paste(warnings, collapse = ""))
    }

    if (vexpr$visible) vexpr$value else invisible(vexpr$value)
}

If I execute the line logFully( f1() ) I get the output I desire, which is simply

2017-02-17 18:05:05.778 FATAL f2 always causes an error for testing purposes
  at #4: stop("f2 always causes an error for testing purposes")
  at f2()
  at catA.R#8: cat(...)
  at #3: catA("f2 = ", f2(), "\n", sep = "")
  at f1()
  at withVisible(expr)
  at logFully.R#110: withCallingHandlers(withVisible(expr), debug = logger, message = logger, warning = logger, caughtError = logger, error = logger)
  at logFully(f1())
Error in f2() : f2 always causes an error for testing purposes

Answer 5

I wrote this code about a week ago to help me track down errors that come primarily from non-interactive R sessions. It's still a little rough, but it prints a stack trace and continues on. Let me know if this is useful, I'd be interested in how you would make this more informative. I'm also open into cleaner ways to get this information.

options(warn = 2, keep.source = TRUE, error = quote({
  # Debugging in R
  #   http://www.stats.uwo.ca/faculty/murdoch/software/debuggingR/index.shtml
  #
  # Post-mortem debugging
  #   http://www.stats.uwo.ca/faculty/murdoch/software/debuggingR/pmd.shtml
  #
  # Relation functions:
  #   dump.frames
  #   recover
  # >>limitedLabels  (formatting of the dump with source/line numbers)
  #   sys.frame (and associated)
  #   traceback
  #   geterrmessage
  #
  # Output based on the debugger function definition.

  # TODO: setup option for dumping to a file (?)
  # Set `to.file` argument to write this to a file for post-mortem debugging    
  dump.frames()  # writes to last.dump
  n <- length(last.dump)
  if (n > 0) {
    calls <- names(last.dump)
    cat("Environment:\n", file = stderr())
    cat(paste0("  ", seq_len(n), ": ", calls), sep = "\n", file = stderr())
    cat("\n", file = stderr())
  }

  if (!interactive()) q()
}))

PS: you might not want warn=2 (warnings converted to errors)

Answer 6

I think that you will need to use tryCatch(). You can do whatever you want in the tryCatch() function, so it's not clear to me why you are viewing this as complex. Maybe post your code example?