Logging and error handling in operational systems

Operational systems, by definition, need to work without human input. Systems are considered “operational” after they have ben 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 and error handling. The MazamaCoreUtils R package helps with these tasks.

Operational Code

At Mazama Science we build production quality data systems primarily using R. Our packages and scripts lie at the heart of operational systems such as the USFS AirFire Monitoring site which displays real-time air quality data associated with wildfire smoke. This system processes data from thousands of monitors in near real-time and, during periods of intense wildfire smoke, experiences multiple thousands of hits per hour. It is expected to have >99% uptime. It is an excellent example of an operational system.

Over the years we have learned how to impose some operational rigor on R code that might have begun as an exploratory analysis. Our best practices for operationalizing R code include:

1. generate logs
2. handle errors
3. add versioning
4. put your code in a package
5. add unit tests
6. add functional tests
7. add examples
8. write documentation
9. create a web service
10. put the web service in a docker container
11. host the container in the cloud with load-balancing

We found few solutions for logging and error handling that we liked, so we built our own in the MazamaCoreUtils package.

Logging in java and python

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")

Logging in R

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")

The package supports logging at different levels and creating log files that capture logging output at different levels. The logging vignette describes best practices for logging in an operational system.

If you have ever longed for python style logging in R — here it is.

Error Handling in java and python

Other languages used in operational settings have language statements to help with error handling. The code to handle errors looks very similar in java and python:

java

try {
  myFunc(a)
} catch (abcException e) {
  // handle abcException
} catch (defException e) {
  // handle defException
} finally {
  // always executed after handlers
}

python

try:
  myFunc(a)
except abcError:
  # handle abcError
except defError:
  # handle defError
finally:
  # always executed after handlers

Error Handling in R

Not surprisingly, a functional language like R does things differently:

1. no language statements for error handling
2. tryCatch() is a function
3. need to define warning handler function
4. need to define error handling function
5. complicated scope issues

Nevertheless, R’s error handling functions can be made to look similar to java and python:

result <- tryCatch({
  myFunc(a)
}, warning = function(w) {
  # handle all warnings
}, error = function(e) {
  # handle all errors
}, finally = {
  # always executed after handlers
}

For more details see:

• Basic Error Handling with tryCatch
• Exceptions and debugging – Advanced R

Simpler Error Handling in R

In our experience, R’s error handling is too complicated for simple use and requires too much from folks who don’t consider themselves R-gurus.

Instead, we recommend wrapping any block of code that needs error handling in a try({…}) block and then testing the result to see if an error occurred. (Note that R considers everything between enclosing curly braces {…} as an expression.) The package stopOnError() function makes it much easier for junior R programmers to add error handling to their code. All they need to do is place any chunk of R code within a “try block” with the following minimal syntax:

result <- try({
  # ...
  # lines of R code
  # ...
}, silent = FALSE)
stopOnError(result, err_msg = "...")

The stopOnError() function tests result and, if an error occurred, uses logger.error() to log the err_msg. If no message is provided, the string returned by geterrmessage() is logged. The error-handling vignette describes best practices for error handling in an operational system and includes a working example.

There is no longer any excuse to avoid error handling — just wrap everything in a try block and finish with stopOnError().

Best of luck operationalizing your R code with production quality logging and error handling from the MazamaCoreUtils package!

---

A previous version of this article originally appeared in 2018 at WorkingwithData.