In can contribute two options to log R conditions like warnings with futile.logger and catch all warnings no matter how deep the function call stack is:
- Wrap your code with
withCallingHandlers for a basic solution
- Use my package tryCatchLog for an advanced solution (for compliance reason: I am the author)
To explain the solutions I have created a simple R script that produces warnings and errors:
# Store this using the file name "your_code_file.R"
# This could be your code...
f1 <- function(value) {
print("f1() called")
f2(value) # call another function to show what happens
print("f1() returns")
}
f2 <- function(value) {
print("f2() called")
a <- log(-1) # This throws a warning: "NaNs produced"
print(paste("log(-1) =", a))
b <- log(value) # This throws an error if you pass a string as value
print("f2() returns")
}
f1(1) # produces a warning
f1("not a number") # produces a warning and an error
Executed "as is" (without logging) this code produces this output:
[1] "f1() called"
[1] "f2() called"
[1] "log(-1) = NaN"
[1] "f2() returns"
[1] "f1() returns"
[1] "f1() called"
[1] "f2() called"
[1] "log(-1) = NaN"
Error in log(value) : non-numeric argument to mathematical function
Calls: source -> withVisible -> eval -> eval -> f1 -> f2
In addition: Warning messages:
1: In log(-1) : NaNs produced
2: In log(-1) : NaNs produced
Solution 1 (withCallingHandlers)
Create a new R file that is called by R and sources your unchanged (!) original R script:
# Store this using the file name "logging_injector_withCallingHandlers.R"
# Main function to inject logging of warnings without changing your original source code
library(futile.logger)
flog.threshold(INFO)
# Injecting the logging of errors and warnings:
tryCatch(withCallingHandlers({
source("your_code_file.R") # call your unchanged code by sourcing it!
}, error = function(e) {
call.stack <- sys.calls() # "sys.calls" within "withCallingHandlers" is like a traceback!
log.message <- e$message
flog.error(log.message) # let's ignore the call.stack for now since it blows-up the output
}, warning = function(w) {
call.stack <- sys.calls() # "sys.calls" within "withCallingHandlers" is like a traceback!
log.message <- w$message
flog.warn(log.message) # let's ignore the call.stack for now since it blows-up the output
invokeRestart("muffleWarning") # avoid warnings to "bubble up" to being printed at the end by the R runtime
})
, error = function(e) {
flog.info("Logging injector: The called user code had errors...")
})
If you execute this wrapper code the R output is:
$ Rscript logging_injector_withCallingHandlers.R
NULL
[1] "f1() called"
[1] "f2() called"
WARN [2017-06-08 22:35:53] NaNs produced
[1] "log(-1) = NaN"
[1] "f2() returns"
[1] "f1() returns"
[1] "f1() called"
[1] "f2() called"
WARN [2017-06-08 22:35:53] NaNs produced
[1] "log(-1) = NaN"
ERROR [2017-06-08 22:35:53] non-numeric argument to mathematical function
INFO [2017-06-08 22:35:53] Logging injector: The called user code had errors...
As you can see
- warnings are logged now
- the call stack could be output too (I have disabled this to avoid flooding this answer)
References: https://stackoverflow.com/a/19446931/4468078
Solution 2 - package tryCatchLog (I am the author)
Solution 1 has some drawbacks, mainly:
- The stack trace ("traceback") does not contain file names and line numbers
- The stack trace is flooded with internal function calls you don't want to see (believe me or try it with your non-trival R scripts ;-)
Instead of copying&pasting the above code snippet again and again I have developed a package that encapsulates the above withCallingHandlers logic in a function and adds additional features like
- logging of errors, warnings and messages
- identifying the origin of errors and warnings by logging a stack trace with a reference to the source file name and line number
- support 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!
To wrap the above R script file using tryCatchLog create a wrapper file
# Store this using the file name "logging_injector_tryCatchLog.R"
# Main function to inject logging of warnings without changing your original source code
# install.packages("devtools")
# library(devtools)
# install_github("aryoda/tryCatchLog")
library(tryCatchLog)
library(futile.logger)
flog.threshold(INFO)
tryCatchLog({
source("your_code_file.R") # call your unchanged code by sourcing it!
#, dump.errors.to.file = TRUE # Saves a dump of the workspace and the call stack named dump_<YYYYMMDD_HHMMSS>.rda
})
and execute it via Rscript to get this (shortened!) result:
# $ Rscript -e "options(keep.source = TRUE); source('logging_injector_tryCatchLog.R')" > log.txt
[1] "f1() called"
[1] "f2() called"
WARN [2017-06-08 23:13:31] NaNs produced
Compact call stack:
1 source("logging_injector_tryCatchLog.R")
2 logging_injector_tryCatchLog.R#12: tryCatchLog({
3 logging_injector_tryCatchLog.R#13: source("your_code_file.R")
4 your_code_file.R#18: f1(1)
5 your_code_file.R#6: f2(value)
6 your_code_file.R#12: .signalSimpleWarning("NaNs produced", quote(log(-1)))
Full call stack:
1 source("logging_injector_tryCatchLog.R")
2 withVisible(eval(ei, envir))
...
<a lot of logging output omitted here...>
As you can see clearly at the call stack level 6 the source code file name and line number (#12) is logged as the source of the warning together with the source code snippet throwing the warning:
6 your_code_file.R#12 .signalSimpleWarning("NaNs produced", quote(log(-1)))
