R, logger and working smarter

July 20 2020

logger R glue

The Forest

Imagine with me a moment.

You’ve spent all day writing killer R code. It has been a blur of data munging, model tweaks and picture perfect analysis outputs, using test data.

The clock hits 6pm, and you set your code running against the full dataset. By your estimate, it should take about 8 hours to run. Perfect! You can start fresh in the morning with a big, strong coffee. Only when you start the next day, you discover that the job has failed. Worse than that, the application crashed so you can’t even get any information on what caused the crash.

Uhoh… Time for a day of tinkering away at code, trying to figure out what went wrong. Maybe you make a few fixes and try again that night, only to discover it crashes again. At this point, you might as well swap the console for the 9-tails - it can’t be any more painful!

How about we work smarter rather than harder.

logger to the rescue! 🌲

Using the excellent logger package, you can gather way more information about jobs and simplify the debugging process. Once loaded we immediately have access to a suite of log_*() functions to track job progress.

if (!require("logger")) install.packages("logger")
library(logger)

log_debug("I'm a sneaky little log")
log_success("I'm a happy little log")
## SUCCESS [2020-07-24 16:12:41] I'm a happy little log
log_info("I'm a friendly little log")
## INFO [2020-07-24 16:12:41] I'm a friendly little log
log_warn("I'm a worrying little log")
## WARN [2020-07-24 16:12:41] I'm a worrying little log
log_error("I'm a scary little log")
## ERROR [2020-07-24 16:12:41] I'm a scary little log
log_fatal("Uhoh! I'm a dead little log")
## FATAL [2020-07-24 16:12:41] Uhoh! I'm a dead little log

Now you may be asking, why can’t you just use print() or message() like you always have? Well I’m glad you asked! Allow me to demonstrate some of the benefits.

The Benefits

First, the obvious. Every messages now has a timestamp, which can be incredibly useful for identifying and improving slow code. We also have a bunch of different severity levels for the messages which allow us to be much more nuanced with our logging. I find it useful to use log_debug() as I’m developing and just go totally nuts with how many logs I include. By default these messages won’t appear, however by changing the log threshold we can see them:

log_debug("Nyah, you can't see me!")
log_threshold(DEBUG)
log_debug("Oh noes!")
## DEBUG [2020-07-24 16:12:41] Oh noes!

String Interpolation

Now for some of the niftier features! The log functions come with glue strings enabled by default. glue adds Python-like string interpolation, which simply means we can refer to variables inside the string using {} marks. Anything inside of the brackets will get evaluated and, assuming its printable, added to the string.

for (i in 1:3) {
 log_info("i = {i}") 
}
## INFO [2020-07-24 16:12:41] i = 1
## INFO [2020-07-24 16:12:41] i = 2
## INFO [2020-07-24 16:12:41] i = 3

Suddenly we have a super easy way to track progress when processing large loops. Another great alternative for monitoring loops is the progress package, which Dan has a great intro to over here.

Log to File

Logging to console is all well and good, but in our scenario we’ve had a double calamity and our process has completely died. That means no more nice console messages. Fortunately we can simultaneously output to file and console at the same time with the nifty appender_tee().

log_appender(appender_tee("path/to/my/log_file.log"))

log_info("Woah, I'm in two places at once...")
## INFO [2020-07-24 16:12:41] Woah, I'm in two places at once...

When a process fails we now have a file we can look at. Also, it’s now possible for any member of a team to check on the status of a long running job.

If you want to get really fancy, you can even shoot the logs over to a Slack channel using appender_slack(). I would recommend only doing this for SUCCESS or ERROR level messages, otherwise you might end up with hella spam.

In Summary…

logger is awesome, and has saved me countless debugging hours. Check it out!

Mad props to daroczig. And keep on sharpening that sword! 🤺

Random Strolls