tryCatchLog

R code for better error handling incl. logging with a full (!) stack trace incl. line numbers, post-mortem analysis and support for parallel processing

aryoda

tryCatchLog

An R package to improve the error handling of the standard tryCatch and try function

Current version: See the NEWS for the most recent changes.

Overview
Tutorial slides
Installation
Usage
Demo
FAQ
Build the package from source using RStudio
How can I contribute?
Links
License

Overview

This repository provides the source code of an advanced tryCatch function for the programming language R called tryCatchLog.

The main advantages of the tryCatchLog function over tryCatch are

Easy logging of errors, warnings and messages into a file or console
supports code with parallel execution logic
Complete stack trace with references to the source file names and line numbers
to identify the source of errors and warnings
(R’s traceback does not contain the full stack trace if you catch errors and warnings!)
allows post-mortem analysis after errors by creating a dump file with all variables of the global environment (workspace) and each function called (via dump.frames) - very helpful for batch jobs that you cannot debug on the server directly to reproduce the error!
Logs warnings (and other non-error conditions)
without stopping the execution of the evaluated expression
(unlike tryCatch does if you pass a warning handler function, see this example)

This package was initially created as an answer to the stackoverflow question.

R: Catch errors and continue execution while logging the stacktrace (no traceback available with tryCatch)

Tutorial slides for condition handling with standard R and `tryCatchLog`

You can find a tutorial slide deck here:

https://aryoda.github.io/tutorials/tryCatchLog/tryCatchLog-intro-slides.html

It is a single self-contained HTML file (made with revealjs, see https://revealjs.com)
so you can save it locally to read it offline.

If you have installed the vignette of the package on your local computer
you can also read the tutorial offline via

# devtools::install(build_vignettes = TRUE)   # workaround to install the vignette if you build via RStudio
browseVignettes("tryCatchLog")

Important:

The vignette is only installed automatically if you install tryCatchLog from CRAN.
RStudio does currently not install the vignette HTML file if you “build and install”.

Workaround manually to build and install the vignette in RStudio:
devtools::install(build_vignettes = TRUE)

Installation

Option 1: Install the stable version from CRAN

install.packages("tryCatchLog")
# browseVignettes("tryCatchLog")  # to show the vignette(s)

Option 2: Install a stable version from github

This is the recommended installation procedure for using (beta) releases that are not
yet published at CRAN but already stable enough (not in active development)!

Pick a (beta) release from the list of Github releases (git tags)
Install the version by specifying the tag name, eg.

# install.packages("devtools")
library(devtools)
install_github("aryoda/tryCatchLog", ref = "v1.1.7")`

Option 3: Install the most recent development version from github

This is the recommended installation procedure for the up-to-date development version!

To install the package using the source code at github you can use the package devtools:

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

If you want to install the vignette (tutorial) on your local computer
you can build it during the installation
(make sure you have installed the suggested packages of the DESCRIPTION file before):

devtools::install_github("aryoda/tryCatchLog", build_vignettes = TRUE)
# browseVignettes("tryCatchLog")  # to show the vignette(s)

Dependencies

tryCatchLog has minimal dependencies: Only base R and utils.

It optionally (= if installed) uses the package
futile.logger
or lgr
to write logging messages in a nice and structured format.

You can find the source code of futile.logger here: https://github.com/zatonovo/futile.logger

Note: To use your own logging functionality you just have to register your logging functions
via set.logging.functions() which uses by default the very basic internal logging function log2console()
(that does not support any convenience functionality like setting the verbosity level but minimizes the dependencies from any other logging framework).

For a list of supported logging packages see feature request #42 (add convenience functions to activate other logging packages).
Since version 1.3.2 there is a new function set.logging.package() for that.

Usage

`tryCatchLog` function

library(tryCatchLog)
library(futile.logger)
tryCatchLog(log("abc"))

results in a log entry that shows the function call hierarchy with the last call (number 5 in the compact call stack)
showing the R code line causing the error:

ERROR [2016-11-13 17:53:35] non-numeric argument to mathematical function
Compact call stack:
  1 source("~/dev/R/tryCatchLog/demo/tryCatchLog_demo.R", echo = TRUE)
  2 tryCatchLog_demo.R#46: tryCatchLog({
  3 tryCatchLog.R#228: tryCatch(withCallingHandlers(expr, error = function(e) {
  4 tryCatchLog_demo.R#48: bad.function(a.string)
  5 tryCatchLog_demo.R#42: .handleSimpleError(function (e)
Full call stack:
  1 source("~/dev/R/tryCatchLog/demo/tryCatchLog_demo.R", echo = TRUE)
  2 withVisible(eval(ei, envir))
  3 eval(ei, envir)
  4 eval(expr, envir, enclos)
  5 tryCatchLog_demo.R#46: tryCatchLog({
        bad.function(a.negative.number)
        bad.function(a.string)
    }, error = function(e) {
        print("Error handling starts now...")
    }, finally = {
        print("Finally...")
    })
  6 tryCatchLog.R#228: tryCatch(withCallingHandlers(expr, error = function(e) {
  ...
  <omitted>
  ...
  11 tryCatchLog_demo.R#48: bad.function(a.string)
  12 tryCatchLog_demo.R#42: .handleSimpleError(function (e) 
    {
        call.stack <- sys.calls()
        log.message <- e$message
        if (write.error.dump.file == TRUE) {
            dump.file.name <- format(Sys.time(), format = "dump_%Y%m%d_%H%M%S")
            dump.frames()
            save.image(file = paste0(dump.file.name, ".rda"))
            log.message <- paste0(log.message, "\nEnvironment dumped into file: ", dump.file.name, ".rda")
        }
        flog.error(buildLogMessage(log.message, call.stack, 1))
    }, "non-numeric argument to mathematical function", quote(log(value)))

`tryLog` function

The pendant to try in R is the tryLog function which evaluates an expression and traps errors without
stopping the script execution:

print("Start")
tryLog(log("not a number!"))
print("Errors cannot stop me")

results in

> print("Start")
[1] "Start"
> tryLog(log("not a number!"))
ERROR [2016-11-26 23:32:04] non-numeric argument to mathematical function
Compact call stack:
  1 tryLog(log("not a number!"))
  2 tryCatchLog.R#319: tryCatchLog(expr = expr, write.error.dump.file = write.error.dump.file, error = function(e) {
  3 tryCatchLog.R#247: tryCatch(withCallingHandlers(expr, error = function(e) {
Full call stack:
  1 tryLog(log("not a number!"))
  2 tryCatchLog.R#319: tryCatchLog(expr = expr, write.error.dump.file = write.error.dump.file, error = function(e) {
<... omitted ...>
> print("Errors cannot stop me")
[1] "Errors cannot stop me"
>

Observe that the error did not stop the execution of the script so that the next line has been executed too.

You could have achived similar behaviour (but with more code and without logging) using

print("Start")
tryCatchLog(log("not a number!"), error = function(e) {})
print("Errors cannot stop me")

Demo

To learn how tryCatchLog works you should open the demo source file that includes many
explanatory comments and run it.

To run the demo source code open the file in the demo sub folder of the source code

demo/tryCatchLog_demo.R

with the RStudio IDE.

If you have installed tryCatchLog as a package you could also run a demo with

demo(package = "tryCatchLog")                               # see a list of all demos
demo(package = "tryCatchLog", topic = "tryCatchLog_demo")   # start a demo

FAQ

How do I find bug reports, feature requests and other issues?

You can browse and add your own issues at https://github.com/aryoda/tryCatchLog/issues

What’s the problem with `tryCatch`?

tryCatch unwinds the call stack back to the level of the tryCatch call in case of an error, warning or other catched conditions.

This means

you cannot use traceback to identify the source code line that cause the problem
(see the help ?traceback: Errors which are caught via try or tryCatch do not generate a traceback…)

if you catch non-error conditions like warnings (e. g. to write them to a log file) the execution
of the evaluated expression is stopped (canceled)
but normally you do not want to stop after warnings but log the warning only and continue with the
normal program flow:

fw <- function() {
  print("before warning")
  warning("a warning message")
  print("after warning")
}

fw()
# [1] "before warning"
# [1] "after warning"
# Warning message:
# In fw() : a warning message

tryCatch(fw(), warning = function(w) print("+ warning catched"))
# [1] "before warning"
# [1] "+ warning catched"  

try(fw())
# [1] "before warning"
# [1] "after warning"

To overcome the drawbacks of tryCatch you must use a combination of an outer tryCatch call that executes
the expression within and inner withCallingHandlers function call. This creates a lot of boilerplate code
that is used again and again. You could encapsulte and reuse this boilerplate code in your own myTryCatch function
and this is exactly what tryCatchLog does!

How can I write the log output into a file instead of the console?

Please read the documentation of the logging package you are using.

Eg. for futile.logger you can redirect the log into a file with this code:

library(futile.logger)

# log to a file (not the console  which is the default target of futile.logger).
# You could also redirect console output into a file if start your R script with a shell script using Rscript!
flog.appender(appender.file("my_app.log"))

How can I reduce the amount of logged conditions?

Please read the documentation of the logging package you are using on how the change the logging level (threshold).

Eg. to set the threshold of the futile.logger use:

library(futile.logger)

# Log only errors (not warnings or info messages)
flog.threshold(ERROR)    # TRACE, DEBUG, INFO, WARN, ERROR, FATAL

How can I suppress the full (and even the compact) call stack trace to simplify my log?

Since version 1.1.5 (Oct. 2019) tryCatchLog and tryLog have two additional arguments named
include.full.call.stack and include.compact.call.stack which can also be configured globally
via options.

tryCatchLog(log(-1), include.full.call.stack = FALSE)  # specify per call
tryCatchLog(log(-1), include.full.call.stack = FALSE, include.compact.call.stack = FALSE)  # shows only the message
options(include.full.call.stack = FALSE)               # or configure it globally
tryCatchLog(log(-1))                                   # is the same as the first call above

The stack trace does not contain script file names and line number. How can I enable this?

You have to set the option keep.source to TRUE in your .Rprofile file (or the in the Rscript command
line if you call your R script via command line):

options(keep.source = TRUE)

Important: If you add this option to your R script file the line numbers will be wrong since R seems to count
the line numbers only after this option has been set to TRUE. It is better to set this option
in the .Rprofile file or use a start script the sets this option and sources your R script then.

If this doesn’t work you can also play around with the option show.error.locations (see help("options")).

The stack trace does not contain R file names and line number for my packages. How can I enable this?

To see the file name and line numbers of conditions thrown in your own (or other packages) installed from source
you have

to enable the keep.source.pkgs option before (you install the packages!)
```
options(keep.source.pkgs = TRUE)
```
install the packages from a source package (binary packages do not have source code included at all)

How to show line numbers for conditions (errors) when sourcing an R file?

You have to enable the keep.source option and source the R file with the keep.source parameter
set to TRUE (or more precisely: Take care not to pass FALSE - the default value is taken from the option):

options(keep.source = TRUE)
source('demo/tryCatchLog_demo.R', keep.source = TRUE)

How to show file names and line numbers in log messages when using `Rscript` to run my R file?

Enter the following command in a shell console (or via a shell script like bash or Windows .CMD file):

Rscript -e "options(keep.source = TRUE); source('demo/tryCatchLog_demo.R')"  # source your own script

Does `tryCatchLog` work in parallelized processing scenarios?

Yes. tryCatchLog is agnostic of parallel oder multi-threading scenarios.

Since version 1.1.7 (April 2020) the new argument execution.context.msg makes it possible
to add runtime information like a thread or process information to the message of catched conditions
(see the help in ?tryCatchLog and the FAQ entry for execution.context.msg for details and an example).

Basically you have to consider these things:

Enable the logging of the process ID (PID) to be able to identify the process that caused problems
(eg. use the process ID in the logging file name or in the log output - see the PID FAQ below for an example)
Configure the used logging framework for each parallel process to not overwrite the
log file of another process (eg. by adding the PID to the logging file name)
Be aware that theoretically a dump file could be overwritten by another dump file if
you have two errors within the same millisecond within the same PID
This is very very unlikely by could happen!

Beware:

You should not initiate parallel execution logic with the code expression passed as expr argument
to tryCatchLog or tryLog since this is untested (there are so many different parallel execution packages).
Instead you should start the parallel execution from outside and within the same process you can
use tryCatchLog and tryLog as usual.

How can I add the process ID (PID) to the logging output?

This depends on the logging framework you are using (read the documentation of the according package).

Normally you don’t need the PID in the logs since R uses a single process only.
If you are using a package that supports parallel processing it makes sense to log the PID too.

For futile.logger you can enable the PID logging with this code snippet:

# The CRAN version of futile.logger is quite old (v1.4.3 from 2016-07-10 as of today/March 17, 2020):
# The github version has quite more features. To install it use:
# devtools::install_github("zatonovo/futile.logger")  # installs version 1.4.4
library(futile.logger)
library(tryCatchLog)
flog.layout(layout.simple.parallel)     # Use a default format with a process id
flog.info(paste0("PID=", Sys.getpid())) # The logged PID should be the R PID
tryCatchLog(warning("Something is strange..."), include.full.call.stack = FALSE, include.compact.call.stack = FALSE)

A typical logging entry does now show the PID after the timestamp:

> flog.info(paste0("PID=", Sys.getpid()))
INFO [2020-03-17 21:33:11 30423] PID=30423
> tryCatchLog(warning("Something is strange..."))
WARN [2020-03-17 21:33:11 30423] [WARN] Something is strange...
...
Warning message:
In withCallingHandlers(expr, error = cond.handler, warning = cond.handler,  :
  Something is strange...
...

How can I use the argument `execution.context.msg` for better debugging of loops or parallel execution?

The tryCatchLog package helps to catch and log condition messages and the code lines causing the condition.

What is missing is the program state during execution as context to narrow down the context that caused an error.

A typical example are loops:

library(tryCatchLog)
library(foreach)  # support parallel execution (if you provice an parallel execution engine too)
options(tryCatchLog.include.full.call.stack = FALSE) # reduce the ouput for demo purposes
res <- foreach(i = 1:12) %dopar% {
         tryCatchLog(log(10 - i), execution.context.msg = as.character(i))   # try to find the bug (logarithm of a negative number is not allowed)!
}

which shows the “loop number” then in the condition message which helps you to narrow down
the problem during debugging:

WARN [2020-04-06 22:40:36] [WARN] NaNs produced {execution.context.msg: 11}

Compact call stack:
  1 foreach(i = 1:12) %dopar% {
  2 #2: tryCatchLog(log(10 - i), execution.context.msg = as.character(i))
...

WARN [2020-04-06 22:40:36] [WARN] NaNs produced {execution.context.msg: 12}
...

Without the loop number debugging would be more time consuming to find the execution state
that causes the problem.

How do I perform a post-mortem analysis of my crashed R script?

“Post-mortem analyis” means to examine the variables and functions calls (“call stack”) that led
to a “crash” (= stop of R script execution due to an error) after the R script has stopped.

This is most helpful in production environments with batch jobs where you cannot debug interactively
to step through your R code to reproduce and fix the error.

tryCatchLog therefore has the feature to create a “memory” dump file that contains the workspace
and the object values along the call stack
(stored in the variable “last.dump” which is created by calling the R function “sys.frames”).

Note: tryCatchLog does also allow you to write a memory dump for every catched error that did not stop the execution
(to allow you to analyse the error later after the R script has finished).

Steps

Wrap your R code with calls to tryCatchLog (or tryLog).
If your R code does not yet use tryCatchLog it would be enough to add a single tryCatchLog call
at the main level as long as you did not use any try or tryCatch calls that would catch and handle
errors (so that tryCatchLog does not see your errors).
Set the parameter write.error.dump.file to TRUE (or change the default value of this parameter globally
via options("tryCatchLog.write.error.dump.file" = TRUE))
to enable a “memory” dump into a file if your R script throws an error that is catched by tryCatchLog.
Run your code that produces an error
Start a new R session on your local computer
Load the dump file (or click on the .rda file in RStudio)
```
load("dump_20161016_164050.rda"  # insert your .rda file name which is contained in the log file in the logged error message!
```
You can see now all the objects in the global workspace that existed when the error occured.
You also see a variable last.dump that was injected by tryCatchLog and contains
the call stack and the variables visible within each function call.

Start the debugger

debugger(last.dump)

Note: The debugger does only allow you to examine the visible variables within the different call stack levels.
You cannot step through the source code interactively as the word “debugger” does imply.

You will now see the error message and the full stack trace (list of function calls up to the point
the error occured in your R script), e. g.:

Message:  non-numeric argument to mathematical functionAvailable environments had calls:
1: source("~/tryCatchLog/demo/tryCatchLog_demo.R", echo = TRUE)
2: withVisible(eval(ei, envir))
3: eval(ei, envir)
4: eval(expr, envir, enclos)
5: tryCatchLog_demo.R#76: tryCatchLog(log("not a number!"), error = function(e) {
})
6: tryCatchLog.R#250: tryCatch(withCallingHandlers(expr, error = function(e) {
    call.stack <- sys.calls()
    log.message <- e$message
    if (dump.err
7: tryCatchList(expr, classes, parentenv, handlers)
8: tryCatchOne(expr, names, parentenv, handlers[[1]])
9: doTryCatch(return(expr), name, parentenv, handler)
10: withCallingHandlers(expr, error = function(e) {
    call.stack <- sys.calls()
    log.message <- e$message
    if (write.error.dump.file == TRUE) {
     
11: .handleSimpleError(function (e) 
{
    call.stack <- sys.calls()
    log.message <- e$message
    if (write.error.dump.file == TRUE) {
        dump.file.
12: h(simpleError(msg, call))

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

Walk through the call stack and examine the variable values

You can now enter a number (and press ) to switch into the environment
of a function call to see the visible variables in RStudio or by entering ls() in the console.
By entering the variable name into the console you can see the current value.

To go back to the call stack menu type “f” (= “finish”) into the console at the Browse[1]> prompt
and choose a new call stack environment.

To learn more about the concept of an R environment you can read the excellent tutorial
of Suraj Gupta:
http://blog.obeautifulcode.com/R/How-R-Searches-And-Finds-Stuff/
Identify reason for the error

Since the call stack printed by debugger contains the source code file name and line number
(if you enabled the keep.source and keep.source.pkgs options)
you can narrow down the reason for the error and fix it.

Build the `tryCatchLog` package from source code using RStudio

If you want to inspect or modify the source code you should clone the project
using RStudio IDE.

Clone the github repository:

Open the RStudio IDE and select the menu items

File > New Project… > Version Control > Git

Then enter

https://github.com/aryoda/tryCatchLog.git

into the text field “Repository URL”.

Build the `tryCatchLog` package

Open the included tryCatchLog.Rproj project file with the RStudio IDE
Increment the package’s version number in the file DESCRIPTION (Attribute Version).
Choose Build > Test package and then Build < Check package
and fix any error that occur.
Select the menu item Build > Build source package

The package installation file is now available in the parent folder of the project root folder.

Install the generated package on other computers

Copy the package file generated in the parent folder of the project on the target computer,
start R and enter:

install.packages("../tryCatchLog_0.9.1.tar.gz", repos = NULL, type = "source")  # adjust the file name!

How can I contribute?

Everyone can help:

Write an issue to report bugs, suggest improvements and request new features
improves the unit tests (implemented with testthat)
helps programming (eg. send pull requests)
…

To contribute code changes and extensions:

Fork this project (https://github.com/aryoda/tryCatchLog/fork).
A fork is a copy of a repository that allows you to experiment with changes without affecting the original repository.
Create your feature branch (git checkout -b my-new-feature)
Commit your changes (git commit -am ‘Add some feature’)
Push to the branch (git push origin my-new-feature)
Create a new Pull Request in github

License

This code is released under the GNU GENERAL PUBLIC LICENSE Version 3

To get a quick overview over this license you can read A Quick Guide to GPLv3

Another good overview gives https://tldrlegal.com/license/gnu-general-public-license-v3-(gpl-3)

Further links:

Internal notes

How to submit a new version to CRAN

Always check the CRAN policies first!
CI/CD (travis etc. at Github must work without any issue for all R versions, even R-devel!)
R CMD check must run without any finding (not even a note!)
Increase the version number in the DESCRIPTION file and document the CRAN release in the NEWS.md
Build and test on OS X too!
Build source package and upload the release candiate (*tar.gz file) at win-builder to check for errors.
(see instructions: https://win-builder.r-project.org/). There is an upload page for R-release, R-devel and R-oldrelease.
Finally upload the release candiate file to CRAN via their submission page: https://cran.r-project.org/submit.html
and check your email and spam folder for the CRAN email with the confirmation link.
Re-submission is done in the same way as submission, using the ‘Optional comment’ field on the web form to explain how the feedback on previous submission(s) has been addressed.
Updates to previously-published packages must have an increased version.
Increasing the version number at each submission reduces confusion so is preferred even when a previous submission was not accepted.

How to build the package using R-devel (development version of R)

To debug problems with the most-recent development version of R you can install R-devel from subversion.

This link provides good instructions on how to do this on Ubuntu Linux with RStudio:

https://www.r-bloggers.com/2015/10/installing-r-devel-on-linux-ubuntu-mint/

(see ~/svn/build-R-devel or into your ~/.profile 😉

Working with Git and Github (esp. merging of feature branches and conflict handling)

http://r-pkgs.had.co.nz/git.html

Add a local branch to the remote (github) repo:

git checkout <branch-name>
git push --set-upstream origin <branch-name>

Merge a (feature or bugfix) branch back into the master, then delete the branch:

git checkout master
git merge --no-ff <branch-name>
git branch -d <branch-name>
git push origin master

Pull request: How to create a new branch, apply changes and merge back into master:

# See the "command line instructions" link in every pull request...
# Eg.:

# Step 1: From your project repository, check out a new branch and test the changes.

git checkout -b <my_new_branch_name>
git pull [email protected]:<pull request user name>/tryCatchLog.git <remote branch name>

# Step 2: Merge the changes and update on GitHub.

git checkout master
git merge --no-ff <my_new_branch_name>
git push origin master

tryCatchLog

tryCatchLog

Table of contents

Overview

Tutorial slides for condition handling with standard R and tryCatchLog

Installation

Option 1: Install the stable version from CRAN

Option 2: Install a stable version from github

Option 3: Install the most recent development version from github

Dependencies

Usage

tryCatchLog function

tryLog function

Demo

FAQ

How do I find bug reports, feature requests and other issues?

What’s the problem with tryCatch?

How can I write the log output into a file instead of the console?

How can I reduce the amount of logged conditions?

How can I suppress the full (and even the compact) call stack trace to simplify my log?

The stack trace does not contain script file names and line number. How can I enable this?

The stack trace does not contain R file names and line number for my packages. How can I enable this?

How to show line numbers for conditions (errors) when sourcing an R file?

How to show file names and line numbers in log messages when using Rscript to run my R file?

Does tryCatchLog work in parallelized processing scenarios?

How can I add the process ID (PID) to the logging output?

How can I use the argument execution.context.msg for better debugging of loops or parallel execution?

How do I perform a post-mortem analysis of my crashed R script?

Build the tryCatchLog package from source code using RStudio

Clone the github repository:

Build the tryCatchLog package

Install the generated package on other computers

How can I contribute?

Links

Background on R condition handling

Logging packages

License

Internal notes

How to submit a new version to CRAN

How to build the package using R-devel (development version of R)

Working with Git and Github (esp. merging of feature branches and conflict handling)

Tutorial slides for condition handling with standard R and `tryCatchLog`

`tryCatchLog` function

`tryLog` function

What’s the problem with `tryCatch`?

How to show file names and line numbers in log messages when using `Rscript` to run my R file?

Does `tryCatchLog` work in parallelized processing scenarios?

How can I use the argument `execution.context.msg` for better debugging of loops or parallel execution?

Build the `tryCatchLog` package from source code using RStudio

Build the `tryCatchLog` package