Printing stack trace and continuing after error occurs in R

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)


I ended up writing a general-purpose logger that produces Java-like logging messages when the standard R "message", "warning" and "stop" methods are called. It includes timestamps, and stack traces for warnings and above.

Many thanks to Man Group for permission to distribute this! Thanks also to Bob Albright, whose answer gave me a leg-up to what I was looking for.

withJavaLogging = 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=,INFO=TRUE, FALSE)
        quashable = switch(level, DEBUG=,INFO=,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]
            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)
}

To use it, just wrap it around your code:

withJavaLogging({
  // Your code here...
})

For a quieter output in the absence of errors (useful for tests!), set the silentSuccess flag. Messages will only be output if an error occurs, to give context to the failure.

To achieve the original goal (dump stack trace + carry on), just use try:

try(withJavaLogging({
  // Your code here...
}, stopIsFatal=FALSE))

If something that triggers on option(error...) is of interest, you can also do this:

options(error=traceback)

From what I can tell, it does most of what Bob's suggested solution do, but has the advantage of being much shorter.

(Feel free to combine with keep.source=TRUE, warn=2, etc. as needed.)

Tags:

Debugging

R