tryCatchLog: Try an expression with condition logging and error handling

Description

This function evaluates an expression passed in the expr parameter, logs all conditions and executes the condition handlers passed in ... (if any).

Usage

tryCatchLog(
  expr,
  ...,
  execution.context.msg = "",
  finally = NULL,
  write.error.dump.file = getOption("tryCatchLog.write.error.dump.file", FALSE),
  write.error.dump.folder = getOption("tryCatchLog.write.error.dump.folder", "."),
  silent.warnings = getOption("tryCatchLog.silent.warnings", FALSE),
  silent.messages = getOption("tryCatchLog.silent.messages", FALSE),
  include.full.call.stack = getOption("tryCatchLog.include.full.call.stack", TRUE),
  include.compact.call.stack = getOption("tryCatchLog.include.compact.call.stack",
    TRUE),
  logged.conditions = getOption("tryCatchLog.logged.conditions", NULL)
)

Arguments

expr

R expression to be evaluated

...

condition handler functions (as in tryCatch). The following condition names are mainly used in R: error, warning, message and interrupt. A handler for user-defined conditions can be established for the generic condition super class. All condition handlers are passed to tryCatch as is (no filtering, wrapping or changing of semantics).

execution.context.msg

a text identifier (eg. the PID or a variable value) that will be added to msg.text for catched conditions. This makes it easier to identify the runtime state that caused a condition esp. in parallel execution scenarios. The value must be of length 1 and will be coerced to character. Expressions are not allowed. The added output has the form: {execution.context.msg: your_value}

finally

expression to be evaluated at the end (after executing the expressiond and calling the matching handler).

write.error.dump.file

TRUE: Saves a dump of the workspace and the call stack named dump_<YYYYMMDD>_at_<HHMMSS.sss>_PID_<process id>.rda. This dump file name pattern shall ensure unique file names in parallel processing scenarios.

write.error.dump.folder

path: Saves the dump of the workspace in a specific folder instead of the working directory

silent.warnings

TRUE: Warnings are logged only, but not propagated to the caller. FALSE: Warnings are logged and treated according to the global setting in getOption("warn"). See also warning.

silent.messages

TRUE: Messages are logged, but not propagated to the caller. FALSE: Messages are logged and propagated to the caller.

include.full.call.stack

Flag of type logical: Shall the full call stack be included in the log output? Since the full call stack may be very long and the compact call stack has enough details normally the full call stack can be omitted by passing FALSE. The default value can be changed globally by setting the option tryCatchLog.include.full.call.stack. The full call stack can always be found via last.tryCatchLog.result.

include.compact.call.stack

Flag of type logical: Shall the compact call stack (including only calls with source code references) be included in the log output? Note: If you ommit both the full and compact call stacks the message text will be output without call stacks. The default value can be changed globally by setting the option tryCatchLog.include.compact.call.stack. The compact call stack can always be found via last.tryCatchLog.result.

logged.conditions

NULL: Conditions are not logged. vector of strings: Only conditions whose class name is contained in this vector are logged. NA: All conditions are logged.

Value

the value of the expression passed in as parameter "expr"

Best practices

To avoid that too many dump files filling your disk space you should omit the write.error.dump.file parameter and instead set its default value using the option tryCatchLog.write.error.dump.file in your .Rprofile file instead (or in a startup R script that sources your actual script). In case of an error (that you can reproduce) you set the option to TRUE and re-run your script. Then you are able to examine the program state that led to the error by debugging the saved dump file.

To see the source code references (source file names and line numbers) in the stack traces you must set this option before executing your code: options(keep.source = TRUE)

You can execute your code as batch with Rscript using this shell script command: Rscript -e "options(keep.source = TRUE); source('my_main_function.R')"

Details

The finally expression is then always evaluated at the end.

Condition handlers work as in base R's tryCatch.

Conditions are also logged including the function call stack with file names and line numbers (if available).

By default the maximum number of source code rows that are printed per call in the full stack trace is 10. You can change this via the option tryCatchLog.max.lines.per.call (see example).

This function shall overcome some drawbacks of the standard tryCatch function. For more details see https://github.com/aryoda/tryCatchLog.

If the package futile.logger is installed it will be used for writing logging output, otherwise an internal basic logging output function is used.

Before you call tryCatchLog for the first time you should initialize the logging framework you are using (e. g.futile.logger to control the log output (log to console or file etc.):

  library(futile.logger)
  flog.appender(appender.file("my_app.log"))
  flog.threshold(INFO)    # TRACE, DEBUG, INFO, WARN, ERROR, FATAL

If you are using the futile.logger package tryCatchLog calls these log functions for the different R conditions to log them:

error -> flog.error
warning -> flog.warn
message -> flog.info
interrupt -> flog.info

`tryCatchLog` does log all conditions (incl. user-defined conditions).

Since the interrupt condition does not have an error message attribute tryCatchLog uses "User-requested interrupt" as message in the logs.

The log contains the call stack with the file names and line numbers (if available).

R does track source code references of scripts only if you set the option keep.source to TRUE via options(keep.source = TRUE). Without this option this function cannot enrich source code references.

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 that sets this option and sources your actual R script then.

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 options(keep.source.pkgs = TRUE) before you install a package.

Setting the parameter tryCatchLog.write.error.dump.file to TRUE allows a post-mortem analysis of the program state that led to the error. The dump contains the workspace and in the variable "last.dump" the call stack (sys.frames). This feature is very helpful for non-interactive R scripts ("batches").

Setting the parameter tryCatchLog.write.error.dump.folder to a specific path allows to save the dump in a specific folder. If not set, the dump will be saved in the working directory.

To start a post-mortem analysis after an error open a new R session and enter: load("dump_20161016_164050.rda") # replace the dump file name with your real file name debugger(last.dump)

Note that the dump does not contain the loaded packages when the dump file was created and a dump loaded into memory does therefore not use exactly the same search path. This means:

the program state is not exactly reproducible if objects are stored within a package namespace
you cannot step through your source code in a reproducible way after loading the image if your source code calls functions of non-default packages

References

http://adv-r.had.co.nz/beyond-exception-handling.html https://stackoverflow.com/questions/39964040/r-catch-errors-and-continue-execution-after-logging-the-stacktrace-no-tracebac

Examples

Run this code

# NOT RUN {
tryCatchLog(log(-1))   # logs a warning (logarithm of a negative number is not possible)
tryLog(log(-1), execution.context.msg = Sys.getpid())

# set and unset an option
options("tryCatchLog.write.error.dump.folder" = "my_log")
options("tryCatchLog.write.error.dump.folder" = NULL)

options(tryCatchLog.max.lines.per.call = 30)

# }
# NOT RUN {
# Use case for "execution.context.msg" argument: Loops and parallel execution
library(foreach)       # support parallel execution (requires an parallel execution plan)
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 = i)
}
# }

Run the code above in your browser using DataLab