Operational systems, by definition, need to work without human input. Systems are considered “operational” after they have been thoroughly tested and shown to work properly with a variety of input.
However, no software is perfect and no real-world system operates with 100% availability or 100% consistent input. Things occasionally go wrong – perhaps intermittently. In a situation with occasional failures it is vitally important to have good logging information for forensic analysis.
Other languages used in operational settings support logging at different levels of information density. The code to write out logs at these different levels looks very similar in java and python:
java
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.apache.commons.logging.impl.Jdk14Logger;… ugly setup of log files …
log.error("ERROR level message");
log.warn("WARN level message");
log.info("INFO level message");
log.debug("DEBUG level message");
log.trace("TRACE level message");python
import logging
logging.basicConfig(filename="my_INFO.log",
level=logging.INFO)
logging.error("ERROR level message")
logging.warning("WARNING level message")
logging.info("INFO level message")
logging.debug("DEBUG level message")
logging.trace("TRACE level message")The MazamaCoreUtils package provides functions so that R logging can look very similar:
library(MazamaCoreUtils)
logger.setup(infoLog="my_INFO.log")
logger.error("ERROR level message")
logger.warn("WARN level message")
logger.info("INFO level message")
logger.debug("DEBUG level message")
logger.trace("TRACE level message")This functionality is built on top of the excellent futile.logger package.
When used properly, logging at different levels lets you create log files that help you quickly navigate to the specific part of your code base that generated an error.
Different log levels also allow problems to be dealt with by staff with different skill levels. Core developers don’t need to be dragged in whenever anything goes wrong. If a real-time web site is non-responsive, non-technical staff can be assigned to look at logs to assess the situation.
ERROR or WARN logs report that no
data was obtained from an upstream source, the problem is not with the R
code.INFO log reports that incoming data was properly
obtained but that none of it passed QC thresholds, the problem is not
with the R code.Here are our best practices for how to use the different log levels:
ERROR log statements should only be generated
immediately before a stop() is issued. The
ERROR.log file should only have entries when R code failed
to complete.
WARN log statements imply that something unexpected
happened but that R code is able to complete, perhaps with unpredictable
results. An appropriate use would be after testing the response of an
internet request. R code may be able to trap and handle a failed request
but should comment on the failure in the logs.
INFO log statements are useful for a general overview of
how your R code is proceeding, reflecting top level code structure and
perhaps ending with a final:
logger.info("Successfully completed ...")
logger.info("\n=============== THE END ===============\n")DEBUG log statements are best used to map out the path
taken through the code. We recommend including DEBUG level
statements inside of top level loops and beginning each function with
the following:
logger.debug("----- FUNCTION_NAME() -----")The following minimal example demonstrates the use of logging statements and their output.
library(MazamaCoreUtils)
# Set up logging
tmpDir <- tempdir()
logger.setup(
errorLog = file.path(tmpDir,"ERROR.log"),
infoLog = file.path(tmpDir,"INFO.log"),
traceLog = file.path(tmpDir,"TRACE.log")
)
# Begin main program
logger.info("Begin loggingExample ...")
# Try something that might fail
outputSums <- list()
for ( column in names(iris) ) {
logger.trace("Working on: %s", column)
result <- try({
outputSums[[column]] <-
paste0("Sum of ", column, " = ", sum(iris[[column]]))
}, silent = FALSE)
if ( "try-error" %in% class(result) ) {
logger.warn("Oops: %s", geterrmessage())
}
}
#> Error in Summary.factor(structure(c(1L, 1L, 1L, 1L, 1L, 1L, 1L, 1L, 1L, :
#> 'sum' not meaningful for factors
# Successful completion
logger.error("NO ERRORS")
logger.info("Successfully completed loggingExample")
logger.info("\n=============== THE END ===============\n")
# Check the output
str(outputSums)
#> List of 4
#> $ Sepal.Length: chr "Sum of Sepal.Length = 876.5"
#> $ Sepal.Width : chr "Sum of Sepal.Width = 458.6"
#> $ Petal.Length: chr "Sum of Petal.Length = 563.7"
#> $ Petal.Width : chr "Sum of Petal.Width = 179.9"Here is what is generated in the log files:
#> INFO [2024-02-07 10:48:03] Begin loggingExample ...
#> WARN [2024-02-07 10:48:03] Oops: Error in Summary.factor(structure(c(1L, 1L, 1L, 1L, 1L, 1L, 1L, 1L, 1L, :
#> 'sum' not meaningful for factors
#>
#> ERROR [2024-02-07 10:48:03] NO ERRORS
#> INFO [2024-02-07 10:48:03] Successfully completed loggingExample
#> INFO [2024-02-07 10:48:03]
#> =============== THE END ===============#> INFO [2024-02-07 10:48:03] Begin loggingExample ...
#> TRACE [2024-02-07 10:48:03] Working on: Sepal.Length
#> TRACE [2024-02-07 10:48:03] Working on: Sepal.Width
#> TRACE [2024-02-07 10:48:03] Working on: Petal.Length
#> TRACE [2024-02-07 10:48:03] Working on: Petal.Width
#> TRACE [2024-02-07 10:48:03] Working on: Species
#> WARN [2024-02-07 10:48:03] Oops: Error in Summary.factor(structure(c(1L, 1L, 1L, 1L, 1L, 1L, 1L, 1L, 1L, :
#> 'sum' not meaningful for factors
#>
#> ERROR [2024-02-07 10:48:03] NO ERRORS
#> INFO [2024-02-07 10:48:03] Successfully completed loggingExample
#> INFO [2024-02-07 10:48:03]
#> =============== THE END ===============Two more utility functions need to be mentioned
logger.setLevel()
This function sets the log level used in the console. By default this
level is set to FATAL which basically means “only when R
crashes”. If you are debugging code interactively you may wish to see
log messages as the are generated by entering the following command:
logger.setLevel(TRACE)initializeLogging()
This function is a wrapper for our typical usage. It accepts a
logDir parameter and looks for TRACE,
DEBUG INFO and ERROR logs in that
directory. If they are found, they are renamed as
paste0(logLevel,".log.",timestamp). After renaming, new log
files are setup.
This is particularly useful for operational code run inside docker containers which may be automatically rebooted.