Printing stack trace and continuing after error occurs in R

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?

score 26 · Answer 1 · edited Feb 27 '19 at 13:05

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 like this. To make it more informative, you could call `ls.str()` for each environmnent in `last.dump`. (This could make the output quite lengthy though.) — Richie Cotton, Jan 06 '10 at 11:28
Not quite what I was after, but it does at least address printing a stack trace. Thanks! — Alice Purcell, Jan 08 '10 at 10:12
Inspiring answer, thanks! But I found that some function arguments are not saved. Would you know what to do with this? [Some function arguments are not available in debugger() when examining the dump.frames()'s dump](https://stackoverflow.com/questions/61855935/some-function-arguments-are-not-available-in-debugger-when-examining-the-dump?noredirect=1&lq=1) — Tomas, May 17 '20 at 17:29

Alice Purcell · Accepted Answer · 2014-08-14T13:47:18.180

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))

Reminds me of Hadley's `evaluate` package, though I'm pretty sure that doesn't do the stack tracing. I don't see it mentioned here yet, though, and it certainly may prove useful to others who don't need the entire mechanism you provide here. — Aaron left Stack Overflow, Aug 14 '14 at 14:04
Excellent work! BTW: What is the intention for appending the "calls" attribute via `limitedLabels(c(calls, attr(obj, "calls")))`? When I examine the `attributes(obj)` I do only find an attribute named "call" (singular!)... — R Yoda, Oct 10 '16 at 19:23
@RYoda Weird, that worked for me when I wrote it. Then again, R is not the most consistent language on the planet. — Alice Purcell, Oct 25 '16 at 15:56
@chrispy: (...burned by the 5 min comment edit rule, now finishing...) The sole problem that I have when I use your code is that I get some really ugly output at the start of my stack trace. In particular, the first line is `at .handleSimpleError(function (obj)` followed by the first couple of lines of your logger inner function. I do not want to see that, so I found that I could suppress it by changing `trace = trace[length(trace):1]` to `trace = trace[(length(trace) - 1):1]`. I am going to follow up with a new answer that is a complete version. — HaroldFinch, Feb 17 '17 at 22:54

score 11 · Answer 3 · answered Oct 18 '11 at 19:41

11

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.)

answered Oct 18 '11 at 19:41

Christian Hudon

1,881
1
21
42

2

Unfortunately, I need to continue afterwards, i.e. run in a try() block, so it won't trigger on option(error=...). – Alice Purcell Aug 14 '14 at 14:12
Also it doesn’t (always) work. Where this gives me “no traceback available”, Bob’s solution gives me one. – flying sheep Feb 27 '19 at 12:56

score 7 · Answer 4 · answered Dec 29 '09 at 15:14

7

Have you tried the

 options(error=recover)

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

answered Dec 29 '09 at 15:14

Dirk Eddelbuettel

360,940
56
644
725

I don't want an interactive prompt, I want the program to print out the stack trace and carry on regardless. – Alice Purcell Dec 29 '09 at 16:29
Are you working with R code only or also with other languages you glue to R? – Dirk Eddelbuettel Dec 29 '09 at 17:26

score 2 · Answer 5 · edited Dec 17 '21 at 18:28

This is a followup to Alice's answer above where she presented a withJavaLogging function. I commented that her 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

score 1 · Answer 6 · answered Aug 12 '14 at 16:07

1

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   "))

answered Aug 12 '14 at 16:07

user1133275

2,642
27
31

score -1 · Answer 7 · answered Dec 29 '09 at 15:14

-1

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?

answered Dec 29 '09 at 15:14

Shane

98,550
35
224
217

1

Complex as compared to most other languages I use, e.g. Java or Python, in which printing a stack trace from an exception is a no-brain one-liner. – Alice Purcell Dec 29 '09 at 15:32
I still don't see why what you're describing would be much more than a one-liner. The only difficulty is if you're trying to throw a specific exception type, because that isn't readily supported. – Shane Dec 29 '09 at 15:37
2

Perhaps it's not -- if so, please post how you would do it! :) – Alice Purcell Dec 29 '09 at 16:36

score -1 · Answer 8 · edited May 23 '17 at 12:02

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

Printing stack trace and continuing after error occurs in R

8 Answers8

Linked