5 min read

A simple way to show stack trace on error in R

2020-03-31

In many programming languages, if an error occurs, the error message typically includes stack trace that helps user indentify the root cause of that error. In R, however, the default error message only contains the last call where error occurs and the error message. This is not very helpful if there are multiple levels of calling stack.

The following is a simple example:

foo <- function(x, y) {
  x + y
}

bar <- function(x, y) {
  foo(x + y, x - y)
}

An argument of the incompatible type would make the function call fail.

bar(1, "a")

Error in x + y : non-numeric argument to binary operator

Unfortunately, it is not quite helpful since we don’t see anything like x + y if we don’t read the source code of bar and foo. Even if we do, it might still be confusing which one actually causes the error since both functions contain the same expression x + y in them.

Let’s see what Python shows for the equivalent code:

def foo(x, y):
    return x + y

def bar(x, y):
    return foo(x + y, x - y)

bar(1, "a")

Traceback (most recent call last):
  File "/Users/ken/Workspaces/test/err.py", line 7, in <module>
    bar(1, "a")
  File "/Users/ken/Workspaces/test/err.py", line 5, in bar
    foo(x + y, x - y)
TypeError: unsupported operand type(s) for +: 'int' and 'str'

The error message contains detailed source information and can be helpful for user to identify the line of code that the error occurs.

Following is the equivalent code in Julia:

function foo(x, y)
    x + y
end

function bar(x, y)
    foo(x + y, x - y)
end

bar(1, "a")

The error message is quite verbose but still helpful for indentifying the line of code with error:

ERROR: LoadError: MethodError: no method matching +(::Int64, ::String)
Closest candidates are:
  +(::Any, ::Any, !Matched::Any, !Matched::Any...) at operators.jl:424
  +(::T<:Union{Int128, Int16, Int32, Int64, Int8, UInt128, UInt16, UInt32, UInt64, UInt8}, !Matched::T<:Union{Int128, Int16, Int32, Int64, Int8, UInt128, UInt16, UInt32, UInt64, UInt8}) where T<:Union{Int128, Int16, Int32, Int64, Int8, UInt128, UInt16, UInt32, UInt64, UInt8} at int.jl:32
  +(::Integer, !Matched::Ptr) at pointer.jl:128
  ...
Stacktrace:
 [1] bar(::Int64, ::String) at /home/cg/root/4781527/main.jl:6
while loading /home/cg/root/4781527/main.jl, in expression starting on line 9

Although R provides some mechanisms (e.g. recover, debugger) to allow user to get detailed information on error, or simply browser to allow user to inspect the environment where it is stopped, traceback is the simplest way to show stack trace on error:

options(error = function() traceback(3))
bar(1, "a")

Now the error message contains the stack trace.

Error in x + y : non-numeric argument to binary operator
2: foo(x + y, x - y) at #2
1: bar(1, "a")

However, it has some pitfalls:

  1. The stack trace is not printed to standard error stream along with the error message. If the standard output and standard error are redirected separately, then we won’t see the error message and error stack trace together.
  2. If such an error function is specified, an error will not terminate the process with zero exit code by default, so the operating system will treat the program as a successful run. Therefore, we need to explicitly quit the session with non-zero exit code in an non-interactive session.
  3. In some cases, the deeply nested stack trace may contain a number of anonymous functions with very long body. Printing those functions in full text is usually not helpful.

To fix them, we may use the following:

options(error = function() {
  sink(stderr())
  on.exit(sink(NULL))
  traceback(3, max.lines = 1L)
  if (!interactive()) {
    q(status = 1)
  }
})

If you need to customize the stack trace message, you may try the following version that allows you to modify anything you want. For example, I prefer the number of level to be ascending and not showing No traceback available on simple error.

options(error = function() {
  calls <- sys.calls()
  if (length(calls) >= 2L) {
    sink(stderr())
    on.exit(sink(NULL))
    cat("Backtrace:\n")
    calls <- rev(calls[-length(calls)])
    for (i in seq_along(calls)) {
      cat(i, ": ", deparse(calls[[i]], nlines = 1L), "\n", sep = "")
    }
  }
  if (!interactive()) {
    q(status = 1)
  }
})

The error function simply prints the calling stack on error in a reversed order yet with ascending number of levels.

bar(1, "a")

Error in x + y : non-numeric argument to binary operator
Backtrace:
1: foo(x + y, x - y)
2: bar(1, "a")

You may put the script that sets up options(error=) to your ~/.Rprofile so that you can see the stack trace whenever there is an uncaught error in your R session.

You may also take a look at rlang error handling suggested at https://rlang.r-lib.org/reference/entrace.html.

options(error = rlang::entrace)
bar(1, "a")

Now the error message becomes

Error in x + y : non-numeric argument to binary operator
Run `rlang::last_error()` to see where the error occurred.

We need to run the following to see the error:

rlang::last_error()

Now it shows a simple stack trace with information of the namespace of each function call. global:: means these functions are defined in the global environment.

<error/rlang_error>
Error in x + y : non-numeric argument to binary operator
Backtrace:
 1. global::bar(1, "a")
 2. global::foo(x + y, x - y)
Run `rlang::last_trace()` to see the full context.

For more details, run the following:

rlang::last_trace()

Then we can see the detailed stack trace in a more structured way.

<error/rlang_error>
Error in x + y : non-numeric argument to binary operator
Backtrace:
    █
 1. └─global::bar(1, "a")
 2.   └─global::foo(x + y, x - y)

Anyway, I still prefer my simple script which is straightforward, customizable, does not need extra input, and does not have any dependencies on other packages.