Record all warnings with futile.logger

Question

Trying to log all errors and warnings with futile.logger .

Somewhat satisfied with this for troubleshooting:

 library(futile.logger) options(error = function() { flog.error(geterrmessage()) ; traceback() ; stop() }) log("a") # Error in log("a") : argument non numérique pour une fonction mathématique # ERROR [2016-12-01 21:12:07] Error in log("a") : argument non numérique pour une fonction mathématique # # No traceback available # Erreur pendant l'emballage (wrapup) : 

There is redundancy, but I can easily split between stderr , stdout and the log file, so this is not a problem. This, of course, is not very, there is an additional error message "wrapp" caused by the last stop() , which I do not understand, therefore I am open to suggestions.

I can not find a similar solution for warnings. What I tried:

 options(warn = 1L) options(warning.expression = expression(flog.warn(last.warning))) log(- 1) # [1] NaN 

But to no avail.

Follow-up question: are there any best practices that I unknowingly ignore?

Answer 1

What about:

 options(warning.expression = quote({ if(exists("last.warning",baseenv()) && !is.null(last.warning)){ txt = paste0(names(last.warning),collapse=" ") try(suppressWarnings(flog.warn(txt))) cat("Warning message:\n",txt,'\n',sep = "") } })) 

Answer 2

You can make two choices for registering R conditions, such as 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 tryCatchLog package for an advanced solution (due to compliance: I am the author)

To explain the solutions, I created a simple R script that generates 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 the source of the unmodified (!) 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 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 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 output of R 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
• a call stack may also be output (I disabled this to avoid flooding this answer)

Links: fooobar.com/questions/693635 / ...

Solution 2 - tryCatchLog package (I am the author)

Solution 1 has some disadvantages, mainly:

• The stack trace ("trace") does not contain file names or line numbers
• The stack trace is flooded with internal calls to functions that you do not want to see (believe me or try using your non-trivial R-scripts ;-)

Instead of copying and re-adding the above code snippet, I developed a package that encapsulates the above withCallingHandlers logic in a function and adds additional functions, such as

• logging errors, warnings and messages
• determining the origin of errors and warnings logging a stack trace with a link to the source file name and line number
• support post-mortem analysis after errors by creating a dump file with all the variables of the global environment (workspace) and each function called (via dump.frames) - very useful 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 through Rscript to get the result (shortened!):

 # $ 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 clearly see at call stack level 6, the source code file name and line number (# 12) are written as the source of the warning along with the source code fragment, causing a warning:

6 your_code_file.R # 12..signalSimpleWarning ("Created by NaN", quote (log (-1)))

Answer 3

The way to use futile.logger is shown in the documentation. Here's a quick example of how it is commonly used and how to set a threshold.

 # set log file to write to flog.appender (appender.file ("mylog.log")) # set log threshold, this ensures only logs at or above this threshold are written. flog.threshold(WARN) flog.info("DOES NOT LOG") flog.warn ("Logged!")