For a slide version of this vignette (e. g. for trainings and presentations) see:
https://aryoda.github.io/tutorials/tryCatchLog/tryCatchLog-intro-slides.html
Copyright (C) 2016++ Jürgen Altfeld ([email protected])
This program is free software: you can redistribute it and/or modify it under the terms of the GNU General Public License as published by the Free Software Foundation, either version 3 of the License, or (at your option) any later version.
This program is distributed in the hope that it will be useful, but WITHOUT ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for more details.
You should have received a copy of the GNU General Public License along with this program. If not, see https://www.gnu.org/licenses/.
The tryCatchLog
package provides an advanced tryCatch
function for the programming language R.
The main advantages of the tryCatchLog
function over tryCatch
are:
traceback
does not contain the full stack trace if you catch errors and warnings!)dump.frames
) to enable the analysis of “crashed” batch jobs that you cannot debug on the server directly to reproduce the error!tryCatch
does if you pass a warning handler function)Part 1: tryCatch
in standard R
Introduction into conditions in standard R Throw your own conditions Handling conditions in R The drawbacks of tryCatch Workaround 1: Interactive debugging Workaround 2: withCallingHandlers + tryCatch
Part 2: Package tryCatchLog
Better error handling with the tryCatchLog package Post-mortem analysis tryCatchLog Function Reference tryCatchLog Best Practices
The execution of an R script can be interrupted to signal special states (conditions) like:
For details see the R help: ?conditions
An error condition:
## Error in log("text"): non-numeric argument to mathematical function
A warning condition:
## Warning in log(-1): NaNs produced
## [1] NaN
Note: This text will never be shown due to a “limitation by design” of pandoc:
https://stackoverflow.com/a/31778080/4468078
Use stop
to throw an error “condition” to signal an invalid program state:
## Error in eval(expr, envir, enclos): something is wrong
Or shorter (but without a way to specify an error text):
## Error: 1 == 2 is not TRUE
stopifnot
is quite often used to ensure pre-conditions in function calls.
## Warning: bad weather today, don't forget your umbrella
Scroll down for examples…
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.
try
to ignore errorsWith the try
function you can handle errors to continue the execution (by ignoring the error):
## [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
.
tryCatch
to handle errorsWith 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
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:
## [1] "Hey, a warning"
tryCatch
can handle all conditions 2/2You 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"
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
tryCatch
is not perfectHave you discovered the problem in the previous examples?
See the next chapter for the answer!
tryCatch
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 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
tryCatch
commandIf 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
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.
tryCatch
You can not find out the exact reason for errors because the full stack trace is truncated
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…
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.
Interactive debugging is very difficult in case of
withCallingHandlers
+ tryCatch
withCallingHandlers
workswithCallingHandlers
works similar to tryCatch
but
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 restartsRestarts 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…
withCallingHandlers
and tryCatch
tryCatch | withCallingHandlers | |
---|---|---|
Program execution | breaks and continues with the first expression after the tryCatch function call |
resumes the execution at the code line that throwed the condition |
Call stack (traceback and sys.calls ) |
unwinds the call stack up to the tryCatch function call |
keeps the full call stack down to the code line that throwed the condition |
Rethrowing of conditions | Conditions are consumed by the called handler function (do not bubble up) | Conditions bubble up (are not consumed by the called handler function) |
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)!
withCallingHandlers
with tryCatch
The requirements for better condition handling in R are:
Solution:
withCallingHandlers
to log them with the full stack tracewithCallingHandlers
to resume after a non-error conditiontryCatch
to recover from the error and continue execution after the tryCatch
function callAn 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!
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!
tryCatchLog
packageTo install the package tryCatchLog
from the source code use:
For more details see the Project site at: https://github.com/aryoda/tryCatchLog
The tryCatchLog
package improves the standard R’s try
and tryCatch
functions by offering extended functions:
Condition handling strategy | Standard R | tryCatchLog package |
---|---|---|
Return an error object in case of errors | try() |
tryLog() |
Call condition handler functions | tryCatch() |
tryCatchLog() |
Improvements:
tryLog
example with an errorErrors 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 warningtryLog
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 errorUse 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!
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:
Interactive debugging using an IDE or the console is very difficult in case of
Post-mortem analysis means to create a dump file in case of an error that contains
dump.frames
)so that you can
to find out the reason for the error.
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)
...
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)
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.
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:
For more details see: https://github.com/aryoda/tryCatchLog/issues/12
tryCatchLog
Function ReferenceFunction 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.
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.
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)
tryCatchLog
Best PracticesJust 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"))
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.
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