Python-style Logging in R

This entry is part 20 of 21 in the series Using R

We are increasingly using R in “operational” settings that require robust error handling and logging. In this post we describe a quick-and-dirty way to get python style multi-level log files by wrapping the futile.logger package.

Making Messy Data Pretty

Our real world scenario involves R scripts that process raw smoke monitoring data that is updated hourly. The raw data comes from various different instruments, set up by different agencies and transmitted over at least two satellites before eventually arriving on our computers.

Data can be missing, delayed or corrupted for a variety of reasons before it gets to us. And then our R scripts perform QC based on various columns available in the raw (aka “engineering level”) data.

Ultimately, the cleaned up data gets displayed in a user interface here.

monitoring_v3_mapNo one needs to know all of the hard work that goes into cleaning and QC’ing the data that goes into this map. Our goal, after all, is to make it easier for stakeholders to make decisions without having to worry about the fussy details of raw data.

Logging When Things Go Wrong

However, neither the incoming data nor the R scripts we have written to process it are perfect. Things occasionally go wrong in a variety of ways and, when decision makers depend on the data being available, phone calls and text messages are next.

Bhuddist teacher Pema Chödrön’s book When Things Fall Apart has several advice categories that actually apply in this situation. We will focus on one:

  • Using painful emotions to cultivate wisdom, compassion, and courage
  • Communicating so as to encourage others to open up rather than shut down
  • Practices for reversing habitual patterns
  • Methods for working with chaotic situations
  • Ways for creating effective social action

One of the methods for working with chaotic situations in operational software is to have lots and Lots and LOTS of logging.

Python has the brilliant “logging” module that allows us to quickly set up separate output files for log statements at different levels: DEBUG, INFO, WARNING, ERROR, WARNING, CRITICAL. Inside our operational code we only need to issue single calls like:

and this information will automatically be written out to both the DEBUG and the INFO log files if we have set them up.

In our situation it makes sense to write out three log files for quick perusal by authorized personnel:

  • ~_DEBUG.log — for programmers needing to debug what went wrong
  • ~_INFO.log — for managers trying to understand the overall situation
  • ~_ERROR.log — (hopefully zero length!) for programmers and managers

These files get written to a uniform directory every time a data processing script runs with the ‘~’ replaced by the name of the processing script.

Wrapping futile.logger

Luckily, most of the functionality we need is provided by futile.logger package (CRAN or github). Unfortunately, this package does not currently support multiple “appenders” per “logger” so we found ourselves initializing multiple named loggers to mimic the natural behavior of Python’s logging module:

Then, inside the code, we created logging and error handling blocks like this:

Yuck!

After writing just a few lines like this we tried a different approach and came up with a simple py_logging.R script that can be used to wrap futile.logger calls and give us the python style behavior we want. Setup is a cinch:

And logging is much more natural:

Output from our logger looks great!

At the end of the day, we can only hope we have succeeded at one or another other of:

  • Using painful emotions to cultivate wisdom, compassion, and courage
  • Communicating so as to encourage others to open up rather than shut down

Best wishes for excellent logging!

Series NavigationWhen k-means Clustering FailsImproved Python-style Logging in R
This entry was posted in R, Toolbox and tagged , . Bookmark the permalink.

Leave a Reply

Your email address will not be published. Required fields are marked *