Improved Python-style Logging in R

Last August, in Python-style Logging in R, we described using an R script as a wrapper around the futile.logger package to generate log files for an operational R data processing script. Today, we highlight an improved, documented version that can be sourced by your R scripts or dropped into your package’s R/ directory to provide easy file and console logging.

The improved pylogging.R script enables the following use case:

1. set up log files for different log levels
2. set console log level
3. six available log levels: TRACE, DEBUG, INFO, WARN, ERROR, FATAL

All of these capabilities depend upon the excellent futile.logger package (CRAN or github). This script just wraps this package to get python-style file logging. Please see futile.logger’s documentation for details on output formatting, etc.

The pylogging.R script is fully documented with roxygen2 comments and can be incorporated into packages as long as their DESCRIPTION file adds a dependency on futile.logger.  For those developing operational processing pipelines using R, python style logging can be very useful.

To demonstrate log files and console output you can download pylogging.R and the following sleepy.R script:

# sleepy.R

logger.info("Getting sleepy ...")
Sys.sleep(1)
logger.warn("Getting really tired ...")
Sys.sleep(2)
logger.error("Having trouble staying awake ...")
Sys.sleep(3)
logger.fatal("Not gonna marzlmurrrzzzzz ...")
stop("Snap out of it!")

The following R session demonstrates the general functionality:

> list.files()
[1] "pylogger.R" "sleepy.R"
> # Nothing up my sleeve 
>
> source("pylogger.R")
> source("sleepy.R")
Error: You must initialize with 'logger.setup()' before issuing logger statements.
> # Setup is required
> 
> logger.setup()
> source("sleepy.R")
FATAL [2017-03-15 16:34:15] Not gonna marzlmurrrzzzzz ...
Error in eval(expr, envir, enclos) : Snap out of it!!
> # The console log level is set to FATAL by default
>
> list.files()
[1] "pylogger.R" "sleepy.R" 
> # No log files created
> 
> # Now modify console log level
> logger.setLevel(ERROR)
> source("sleepy.R")
ERROR [2017-03-15 16:35:29] Having trouble staying awake ...
FATAL [2017-03-15 16:35:32] Not gonna marzlmurrrzzzzz ...
Error in eval(expr, envir, enclos) : Snap out of it!!
> # Got ERROR and higher
>
> logger.setLevel(DEBUG)
> source("sleepy.R")
INFO [2017-03-15 16:35:42] Getting sleepy ...
WARN [2017-03-15 16:35:43] Getting really tired ...
ERROR [2017-03-15 16:35:45] Having trouble staying awake ...
FATAL [2017-03-15 16:35:48] Not gonna marzlmurrrzzzzz ...
Error in eval(expr, envir, enclos) : Snap out of it!!
> # Got DEBUG and higher
>
> list.files()
[1] "pylogger.R" "sleepy.R"  
> # Still no log files
>
> # Set up log files for two levels
> logger.setup(debugLog="debug.log",errorLog="error.log")
> logger.setLevel(FATAL)
> source("sleepy.R")
FATAL [2017-03-15 16:36:43] Not gonna marzlmurrrzzzzz ...
Error in eval(expr, envir, enclos) : Snap out of it!!
> # Expected console output
>
> list.files()
[1] "debug.log"  "error.log"  "pylogger.R" "sleepy.R"  
> readr::read_lines("debug.log")
[1] "INFO [2017-03-15 16:36:37] Getting sleepy ..."               
[2] "WARN [2017-03-15 16:36:38] Getting really tired ..."         
[3] "ERROR [2017-03-15 16:36:40] Having trouble staying awake ..."
[4] "FATAL [2017-03-15 16:36:43] Not gonna marzlmurrrzzzzz ..."   
> readr::read_lines("error.log")
[1] "ERROR [2017-03-15 16:36:40] Having trouble staying awake ..."
[2] "FATAL [2017-03-15 16:36:43] Not gonna marzlmurrrzzzzz ..." 
>
> # Got two log files containing DEBUG-and-higher and ERROR-and-higher

Best Wishes for Better Logging!