Log all warnings with futile.logger

Question

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

Somewhat satisfied with this for dealing with errors:

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 separate between stderr, stdout and log file, so it's not a problem. It's certainly not pretty, there is an additional "wrapup" error message somehow caused by the final stop() that I don't understand, so I'm open to suggestions.

I cannot 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 best practices that I am unknowingly ignoring?

Answer 1

The way you should use futile.logger is shown in its documentation. Here us a quick example, of how it typically is used, and how to set the 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!")

Answer 2

How 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 3

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:

1. Wrap your code with withCallingHandlers for a basic solution
2. 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)))