What is a condition?

The execution of an R script can be interrupted to signal special states (conditions) like:

• errors
• warnings
• info messages
• user requested interrupts (by hitting CTRL + C/BRK or ESC)

For details see the R help: ?conditions

Condition examples

An error condition:

log("text")   # calculating the logarithm of a string throws an error

## Error in log("text"): non-numeric argument to mathematical function

A warning condition:

log(-1)                # logarithm of a negative number throws a warning

## Warning in log(-1): NaNs produced

## [1] NaN

Throw an Error

Use stop to throw an error “condition” to signal an invalid program state:

if (1 != 2)
  stop("something is wrong")

## Error in eval(expr, envir, enclos): something is wrong

Or shorter (but without a way to specify an error text):

stopifnot(1 == 2)

## Error: 1 == 2 is not TRUE

stopifnot is quite often used to ensure pre-conditions in function calls.

Throw a Warning

warning("bad weather today, don't forget your umbrella")

## Warning: bad weather today, don't forget your umbrella

Throw a Message

message("good morning")

## good morning

Unhandled errors stop R

By default R will stop the execution if an error occurs:

options(error = NULL)  # switch to default behaviour of pure R

test <- function() {
  log("not a number")
  print("R does stop due to an error and never executes this line")
}

test()     # throws an error

## Error in log("not a number"): non-numeric argument to mathematical function

Note that the output does not show the print result since the execution stops in case of an error.

Use try to ignore errors

With the try function you can handle errors to continue the execution (by ignoring the error):

try(log("not a number"), silent = TRUE)
print("errors can't stop me")

## [1] "errors can't stop me"

Note: If an error occurs then the error message is printed to the stderr connection unless the call includes silent = TRUE.

Use tryCatch to handle errors

With tryCatch you can handle errors as you want:

an.error.occured <- FALSE
tryCatch( { result <- log("not a number"); print(res) }
          , error = function(e) {an.error.occured <<- TRUE})
print(an.error.occured)

## [1] TRUE

If you use an error handler function

• the error is not shown anymore and
• the execution continues after the tryCatch statement.

tryCatch can handle all conditions 1/2

… not only errors. Just use the condition name as parameter to handle conditions of this type, e. g. warnings:

tryCatch( { result <- log(-1); print(result) }
          , warning = function(w) { print("Hey, a warning") })

## [1] "Hey, a warning"

tryCatch can handle all conditions 2/2

You can use error, warning, message or interrupt as parameter name to assign a handler for these “standard” conditions, e. g. to catch messages:

last.message <- NULL
tryCatch( { message("please handle me"); print("Done") }
          , message = function(m) { last.message <<- m })
print(last.message$message)

## [1] "please handle me\n"

Advanced topic: User defined conditions

You can even define your own user-defined condition classes, but there is no built-in function to generate a new object of class condition. So do it yourself:*

condition <- function(subclass, message, call = sys.call(-1), ...) {
  structure( class = c(subclass, "condition"),
             list(message = message, call = call, ...))
}

tryCatch( { work <- condition("my.work.condition", "after work party")
            signalCondition(work); print("Done") }
          , my.work.condition = function(c) { print(c$message) })

## [1] "after work party"

User-defined condition classes are only required if you want to implement a specific recovery strategy for this condition. This is out of scope of this presentation.

*) Source: http://adv-r.had.co.nz/beyond-exception-handling.html

But tryCatch is not perfect

Have you discovered the problem in the previous examples?

See the next chapter for the answer!

Handling a condition stops the execution 1/2

Calling the function without a tryCatch handler does not stop the execution of the function f():

{ # required to execute the code as one block to summarize the output in this Rmd
  f <- function() {
    warning("deprecated function called")
    print("Hello world")
  }
  f()
  print("Done")
}

## Warning in f(): deprecated function called

## [1] "Hello world"
## [1] "Done"

but…

Handling a condition stops the execution 2/2

Handling a condition cancels the execution of the code block that raised (throwed) the condition:

f <- function() {
  warning("deprecated function called")
  print("Hello world")
}
tryCatch(f(), warning = function(w) { write.to.log(w) })
print("Done")

## [1] "Done"

Observe: Hello world is never printed just because we catched a warning!

If you catch a condition with tryCatch (even just a warning or message) then R

1. executes the condition handler function
2. aborts the execution of the code block that throwed the condition
3. continues the execution with the next command after the tryCatch command

Handling errors unrolls the stack trace 1/2

If you do not catch an error R stops and you can get the complete function call stack using traceback to identify the code that throwed the error:

options(error=function() traceback(2)) # http://stackoverflow.com/a/13119318/4468078
f <- function() {
  log("not a number")
  print("Hello world")
}
f()

Error in log("not a number") :
  non-numeric argument to mathematical function
6: (function ()
   traceback(2))() at f.R#3
5: f() at f.R#6
...
1: source("f.R")

Note: The call stack shows the line number after the file name and hash sign, e. g. file1.R#7 = line number 7

Handling errors unrolls the stack trace 2/2

But if you handle the error, the call stack is truncated:

f <- function() {
  log("not a number")
  print("Hello world")
}
tryCatch(f(), error = function(e) { traceback() })

8: value[[3L]](cond)
7: tryCatchOne(expr, names, parentenv, handlers[[1L]])
6: tryCatchList(expr, classes, parentenv, handlers)
5: tryCatch(f(), error = function(e) {
       traceback(2)
   }) at f.R#5
...
1: source("f.R")

The call stack ends basically with the tryCatch call but does not show you the code line in f() where the error was thrown.

Summary: The drawbacks of tryCatch

1. You can not find out the exact reason for errors because the full stack trace is truncated

2. Handling of warnings and messages (e. g. just to log them) cancels the execution of the code block that throwed the condition (what is unexpected!)

See the next chapters for possible work-arounds…

Interactive debugging

You can run and debug your R script interactively in the RGui or RStudio instead of condition handling with tryCatch.

For more details on interactive debugging see ?debug.

Note: Interactive debugging is out of scope of this presentation.

Limitations of interactive debugging

Interactive debugging is very difficult in case of

• errors that are not (easily) reproducible.
• errors that occur only after a long run time
• batch jobs running on a server (you have no interactive GUI then!)

How withCallingHandlers works

withCallingHandlers works similar to tryCatch but

1. remembers the call stack down to the point where the condition was signaled
2. resumes the execution after the point where the condition was signaled

f <- function() {
  warning("deprecated function called")
  print("Hello world")
}
withCallingHandlers(f(), warning = function(w) { write.to.log(sys.calls()) })

## Warning in f(): deprecated function called

## [1] "Hello world"

Note: Use sys.calls within withCallingHandlers to return the full call stack.

withCallingHandlers supports restarts

Restarts allow to recover from conditions using a predefined behaviour:

f <- function() {
  warning("deprecated function called")
  print("Hello old world")
}
withCallingHandlers(f(), warning = function(w) { write.to.log(sys.calls())
                                                 invokeRestart("muffleWarning")})
print("Done")

## [1] "Hello old world"
## [1] "Done"

invokeRestart("muffleWarning") has a simple recovery strategy: “Suppress the warning”.

It consumes the warning (so it does not “bubble up” to higher function call levels) and resumes the execution.

TODO: Mention other restarts and their behaviour…

Differences between withCallingHandlers and tryCatch

Note: tryCatch is different from Java’s try-catch statement: It unwinds the call stack (in Java you get the full call stack with the printStackTrace method)!

Combine withCallingHandlers with tryCatch

The requirements for better condition handling in R are:

• Get the full call stack for all catched conditions
• Resume execution after handling warnings and messages
• Catch errors and continue the execution after the handler function

Solution:

• Handle all conditions in withCallingHandlers to log them with the full stack trace
• Invoke a restart in withCallingHandlers to resume after a non-error condition
• Handle only errors in tryCatch to recover from the error and continue execution after the tryCatch function call

Code snippet for better error handling

An improved “error handler” in R looks similar to this code snippet:

f <- function() {
  warning("deprecated function called")
  print("A warning cannot stop me")
  log("not a number")
  print("Hello old world")
}

tryCatch(withCallingHandlers(f(), error=function(e) {write.to.log(sys.calls())}
                                , warning=function(w) {write.to.log(sys.calls())
                                                invokeRestart("muffleWarning")})
         , error = function(e) { print("recovered from error") })
print("Done")

## [1] "A warning cannot stop me"
## [1] "recovered from error"
## [1] "Done"

This is basically how the tryCatchLog package works internally!

How about usability?

Do you really want to use that much boilerplate code in your R scripts at every place where you have to catch errors and conditions?

If not: See the the next chapter to learn how the package tryCatchLog could make your life much easier!

Installation

To install the package tryCatchLog from the source code use:

# install.packages("devtools")
library(devtools)
install_github("aryoda/tryCatchLog")

For more details see the Project site at: https://github.com/aryoda/tryCatchLog

Overview

The tryCatchLog package improves the standard R’s try and tryCatch functions by offering extended functions:

Improvements:

1. Configurable logging (“for free”)
2. Logging of full or compact call stack with line numbers
3. Resume after warnings and messages
4. Support for post-mortem analysis after errors via dump files

tryLog example with an error

Errors are logged but the execution continues after the tryLog call:

library(tryCatchLog)
f <- function(value) {
  print("begin")
  log(value)            # negative number -> warning; string -> error
  print("end")
}
tryLog(f("not a number"))
print("Errors don't stop me!")

## [1] "begin"
## ERROR [2016-12-06 21:44:21] non-numeric argument to mathematical function
## Compact call stack:
##   1 test.R#7: tryLog(f("not a number"))
##   2 tryCatchLog.R#345: tryCatchLog(expr = expr, write.error.dump.file = write.error.dump.file, error = function(e) {
##   3 tryCatchLog.R#259: tryCatch(withCallingHandlers(expr, error = function(e) {
##   4 test.R#4: .handleSimpleError(function (e)
## ...
## [1] "Errors don't stop me!"

tryLog example with a warning

tryLog catches conditions and logs them onto console or into a file (depending of the settings of the logging framework futile.logger that is used internally):

library(tryCatchLog)
f <- function(value) {
  print("begin")
  log(value)            # negative number -> warning; string -> error
  print("end")
}
tryLog(f(-1))

## [1] "begin"
## WARN [2016-12-06 21:33:41] NaNs produced
## Compact call stack:
##   1 test.R#7: tryLog(f(-1))
##   2 tryCatchLog.R#345: tryCatchLog(expr = expr, write.error.dump.file = write.error.dump.file, error = function(e) {
##   3 tryCatchLog.R#259: tryCatch(withCallingHandlers(expr, error = function(e) {
##   4 test.R#4: .signalSimpleWarning("NaNs produced", quote(log(value)))
...
## [1] "end"

tryCatchLog example to log and recover from an error

Use tryCatchLog to establish an error handler:

library(tryCatchLog)

send.email <- function(receiver, body) { }  # dummy function (does nothing)

tryCatchLog(log("not a number"),
            error = function(e) { send.email("admin@home", e)
            })

The console shows the log output then and the execution continues:

ERROR [2017-01-22 22:04:56] non-numeric argument to mathematical function
Compact call stack:
  1 tryCatchLog_error_example.R#5: tryCatchLog(log("not a number"), error = function(e) {
  2 tryCatchLog.R#273: tryCatch(withCallingHandlers(expr, error = function(e) {
...

Note: send.email is a dummy function for demonstration purposes!

How to change the logging behaviour

To log to a file instead of the console or to change the logging level you call the usual futile.logger functions:

  library(futile.logger)

  flog.appender(appender.file("app.log"))

  flog.threshold(ERROR)    # TRACE, DEBUG, INFO, WARN, ERROR, FATAL

  try(log(-1))             # the warning will not be logged!

For more details about futile.logger see:

https://cran.r-project.org/package=futile.logger

Known limitations of interactive debugging in R

Interactive debugging using an IDE or the console is very difficult in case of

• errors that are not (easily) reproducible
• long running code that produces an error at the end
• batch jobs running on a server

Solution: Post-mortem analysis

Post-mortem analysis means to create a dump file in case of an error that contains

• all objects of the global environment (workspace) and
• all objects within the scope of each called function (via dump.frames)

so that you can

• use any computer
• to load the dump file into a new R session
• after the script has stopped the execution (“post-mortem”) and
• examine the call stack and object values (“analysis”)

to find out the reason for the error.

Enable post-mortem analysis

tryCatchLog supports post-mortem analysis by creating dump files in case of errors:

library(tryCatchLog)
f <- function(value) {
  log(value)
}
a <- "100"
tryLog(f(a), write.error.dump.file = TRUE)

ERROR [2016-12-12 22:29:52] non-numeric argument to mathematical function
Call stack environments dumped into file: dump_20161212_222952.rda
Compact call stack:
  1 source("~/R_trainings/tryCatchLog/src/test.R")
  2 test.R#6: tryLog(f(a), write.error.dump.file = TRUE)
  3 tryCatchLog.R#348: tryCatchLog(expr = expr, write.error.dump.file = write.error.dump.file, error = function(e) {
  4 tryCatchLog.R#262: tryCatch(withCallingHandlers(expr, error = function(e) {
  5 test.R#3: .handleSimpleError(function (e)
  ...

Start a post-mortem analysis

Open a new R session and start the post-mortem analysis of the error:

load("dump_20161212_222952.rda")    # load the dump into the global environment
debugger(last.dump)                 # start the post-mortem analysis

Message:  non-numeric argument to mathematical functionAvailable environments had calls:
1: source("test.R")
...
5: test.R#6: tryLog(f(a), write.error.dump.file = TRUE)
6: tryCatchLog.R#348: tryCatchLog(expr = expr, write.error.dump.file = dump.erro
7: tryCatchLog.R#262: tryCatch(withCallingHandlers(expr, error = function(e) {
...
12: f(a)
13: test.R#3: .handleSimpleError(function (e)
14: h(simpleError(msg, call))

Enter an environment number, or 0 to exit
Selection: <Cursor is waiting for your input here>

The function call #13 shows: The error was thrown in the file test.R at line #3: log(value)

Post-mortem debugging: Examine an environment

Switch into the environment of the function call #12 which called the function that throwed the error and examine the objects visible within this function:

Enter an environment number, or 0 to exit
Selection: 12
Browsing in the environment with call:
   f(a)
Called from: debugger.look(ind)
Browse[1]> ls()
[1] "value"
Browse[1]> value
[1] "100"
Browse[1]> typeof(value)
[1] "character"
Browse[1]>

By looking at the (function argument) variable value it is easy to identify the reason for the error: The passed value “100” had the wrong data type!

You can exit the debugger now with “Q” (or “f” followed by “0”) and fix the bug.

Post-mortem debugging: Limitations

R dump files (created with save.image) do not contain the loaded packages when the dump file was created.

Therefore a dump loaded into memory later does not load these packages automatically.

This means the program state as of the error is not exactly reproducible:

• Objects that were stored within a package namespace are not available
• The search path to find objects may be different during post-mortem analysis
• You cannot step through your source code after loading the image if your source code calls functions of non-default packages. You have to load these packages manually before starting the debugger

For more details see: https://github.com/aryoda/tryCatchLog/issues/12

tryCatchLog()

Function signature:

tryCatchLog(expr, ..., finally = NULL,
  write.error.dump.file = getOption("tryCatchLog.write.error.dump.file", FALSE),
  silent.warnings       = getOption("tryCatchLog.silent.warnings", FALSE),
  silent.messages       = getOption("tryCatchLog.silent.messages", FALSE))

This function evaluates the expression in expr and passes all condition handlers in ... to tryCatch as-is while error, warning and message conditions are logged together with the function call stack (including file names and line numbers).

The expression in finally is always evaluated at the end.

Warnings and messages can be “silenced” (only logged but not propagated to the caller) using the silent.* parameters.

The default values of some parameters can be set globally via options to avoid passing the same parameter values in each call and to support easy reconfiguration for all calls without changing the code.

tryLog()

Function signature:

tryLog(expr,
  write.error.dump.file = getOption("tryCatchLog.write.error.dump.file", FALSE),
  silent.warnings       = getOption("tryCatchLog.silent.warnings", FALSE),
  silent.messages       = getOption("tryCatchLog.silent.messages", FALSE))

This function is a short version of tryCatchLog() that traps any errors that occur during the evaluation of the expression expr without stopping the execution of the script (similar to try in R). Errors, warnings and messages are logged.

In contrast to tryCatchLog() it returns an object of the class “try-error” in case of an error and continues after the tryLog expression. Therefore tryLog does not support the error and finally parameters for passing custom handler functions.

The default values of some parameters can be set globally via options to avoid passing the same parameter values in each call and to support easy reconfiguration for all calls without changing the code.

Change global options of tryCatchLog

The default values of many options can be changed globally by configuring them once to reduce lengthy function calls later and support easy reconfiguration for all calls without changing the code:

# Initialize your own default values globally for tryLog and tryCatchLog
options(tryCatchLog.write.error.dump.file = FALSE)
options(tryCatchLog.silent.messages       = TRUE)
options(tryCatchLog.silent.warnings       = TRUE)

test <- function() {
  message("hello")
  warning("a warning")
}

# Use your own default values by ommiting those parameters...
tryLog(f())

# .. instead of the longer version which passes each parameter again and again
tryLog(f(), silent.warnings=TRUE, silent.messages=TRUE, write.error.dump.file=FALSE)

Easiest way to add logging of all conditions

Just wrap the call to the main function or main script with tryCatchLog():

library(futile.logger)
library(tryCatchLog)

options(keep.source = TRUE)        # source code file name and line number tracking
options("tryCatchLog.write.error.dump.file" = TRUE) # dump for post-mortem analysis

flog.appender(appender.file("my_app.log"))  # to log into a file instead of console
flog.threshold(INFO)    # TRACE, DEBUG, INFO, WARN, ERROR, FATAL

tryCatchLog(source("your_main_script.R"))

Enabling source code references (file names and line numbers)

To show file names and line numbers in the stack trace of the log output:

• For R script files

  R does track source code references of scripts only if you set options(keep.source = TRUE) before.

  If you use Rscript to start a non-interactive R script as batch job you have to set this option since it is FALSE by default.

  You can add this option to your .Rprofile file or use a startup R script as stub to set this option

• For installed packages

  By default, most packages are built without source reference information. Setting the environment variable R_KEEP_PKG_SOURCE=yes before installing a source package will tell R to keep the source references.

  You can also use set {options(keep.source.pkgs = TRUE) before you install a package.

FAQ

You can find a FAQ with best practices at:

https://github.com/aryoda/tryCatchLog#faq

References

Documentation of the futile.logger logging framework: https://github.com/zatonovo/futile.logger

Download of these slides: https://github.com/aryoda/R_trainings

Project home of the tryCatchLog package: https://github.com/aryoda/tryCatchLog

https://www.biostat.jhsph.edu/~rpeng/docs/R-debug-tools.pdf

https://journal.r-project.org/archive/2010-2/RJournal_2010-2_Murdoch.pdf