Structured Logging

Updated as of 2021-11-03

Traditionally, messages emitted from R packages or scripts are unstructured messages, like this one from the shiny package:

Listening on http://localhost:8080

A richer, more structured representation of this log message might be:

level=INFO ts=2021-10-21T20:21:01Z message="starting Shiny" host=localhost port=8080 shiny_version=1.6.0 appdir=projects/mycoolapp

This second message uses structured logging, attaching relevant metadata to a log message as standalone fields.

Structured logs have two advantages:

log4r includes support for two of the most popular structured logging formats:

To use these formats, you can pass additional arguments to the existing logging functions info(), warn() and error().

JSON Logs

The most popular format for structured logging is probably JSON, which you can configure as follows:

logger <- logger(appenders = console_appender(json_log_layout()))

As an example, suppose you are logging unauthorised requests to a Plumber API. You might have a log message with fields like the following:

# Here "req" and "res" are slightly fake request & response objects.
info(
  logger, message = "authentication failed",
  method = req$REQUEST_METHOD,
  path = req$PATH_INFO,
  params = sub("^\\?", "", req$QUERY_STRING),
  user_agent = req$HTTP_USER_AGENT,
  remote_addr = req$REMOTE_ADDR,
  status = res$status
)
#> {"message":"authentication failed","method":"POST","path":"/upload","params":"","user_agent":"curl/7.58.0","remote_addr":"124.133.52.161","status":401,"level":"INFO","time":"2021-11-03T16:36:59Z"}

logfmt Logs

An alternative to JSON is the popular, more human-friendly logfmt style, which you can configure as follows:

logger <- logger(appenders = console_appender(logfmt_log_layout()))

As an example, you might have the following in a script that processes many CSV files:

info(
  logger, message = "processed entries", file = filename,
  entries = nrow(entries),
  elapsed = unclass(difftime(Sys.time(), start, units = "secs"))
)
#> level=INFO ts=2021-11-03T16:36:59Z message="processed entries" file=catpics_01.csv entries=4124 elapsed=0.03846