# 1 Introduction

lgr is a logging framework for R inspired by Apache Log4j and Python logging. It follows a traditional object oriented design implemented through R6 classes. This enables lgr to have a larger set of features than other logging packages for R, and makes it easy to extend for people that have experience with R6 classes. This also makes Logger configuration a bit more verbose than for other packages, but I hope also more flexible and transparent.

If you are not sure if lgr is the right package for you, take a look examples to see what lgr can do for you.

## 1.1 Quickstart

lgr comes with a so-called root logger that is ready to go after you install it. If you are a package developer you can (and should) set up a new Logger for your package, but more on that later. For many use cases the root Logger will suffice.

### 1.1.1 Logging to the Console

# the root logger is called "lgr"
lgr$info("Vampire stories are generally located in Styria.") #> INFO [12:46:18.487] Vampire stories are generally located in Styria. You can use formatting strings that are passed on to sprintf() in lgr. lgr$error("Vampires generally arrive in carriages drawn by %i black horses.", 2)
#> ERROR [12:46:18.494] Vampires generally arrive in carriages drawn by 2 black horses.

### 1.1.2 Logging to Plain Files

Usually you don’t (only) want to log to the console, you want to log to files. Output of Loggers is managed by Appenders. The root Logger is preconfigured with a console Appender (that is why we see output in the console). Let’s add a file Appender:

tf <- tempfile(fileext = ".info")
lgr$add_appender(AppenderFile$new(tf), name = "file")
lgr$info("You must think I am joking") #> INFO [12:46:18.507] You must think I am joking readLines(tf) #> [1] "INFO [2019-03-25 12:46:18.507] You must think I am joking" The various Appenders available in lgr are R6 classes. To instantiate an object of that class (i.e. create a new appender) you have to use the $new() function as in the example above. Whenever you see something in lgr that IsNamedLikeThis, you can be sure that it is such an R6 class.

If you look at the output, you see that the timestamp format of the file appender is slightly different to the timestamp format of the console Appender. Formatting is handled by Layouts, and each Appender has exactly one:

lgr$appenders$file$set_layout(LayoutFormat$new(timestamp_fmt = "%B %d %T"))
lgr$info("No, I am quite serious") #> INFO [12:46:18.519] No, I am quite serious readLines(tf) #> [1] "INFO [2019-03-25 12:46:18.507] You must think I am joking" #> [2] "INFO [March 25 12:46:18] No, I am quite serious" ### 1.1.3 Logging to JSON files If you log to files, you should not log normal text. If you want to analyse your logs later, it’s much better to log to a format like JSON: # cleanup behind the old Appender unlink(tf) lgr$remove_appender("file")

# setup a JSON appender
lgr$add_appender(AppenderJson$new(tf), name = "json")
lgr$info("We lived in Styria") #> INFO [12:46:18.538] We lived in Styria JSON is still somewhat human readable cat(readLines(tf)) #> {"level":400,"timestamp":"2019-03-25 12:46:18","logger":"root","caller":"eval","msg":"We lived in Styria"} and easy for machines to parse read_json_lines(tf) #> level timestamp logger caller msg #> 1 400 2019-03-25 12:46:18 root eval We lived in Styria ### 1.1.4 Logger configuration with $config()

The $config() method provides a flexible alternative to configuring loggers with their $set_*() methods.


# explicit setup with logger_config
lgr$config(logger_config( threshold = "info", appenders = AppenderFile$new(
file = "path/to/logfile",
layout = LayoutFormat(fmt = "[%L] %m")
)
))

You can also specify Logger configurations in yaml files

#### contents of path/to/config.yaml #####
# Logger:
#   name: test/blubb
#   threshold: info
#   appenders:
#     AppenderFile:
#       file: /path/to/logfile
#       LayoutFormat:
#          fmt: '[%L] %m'
lgr$config("path/to/config.yaml") ### 1.1.5 Custom Fields Unlike many others Loggers for R, lgr treats a log event as a unit of data, not just a message with a timestamp. A log event can contain arbitrary data, though not all Appenders can handle that well. The JSON appender we added above is particularly good at handling most R objects. # The default console appender displays custom fields as pseudo-json after the message lgr$info("Styria has", poultry = c("capons", "turkeys"))
#> INFO  [12:46:18.587] Styria has {poultry: [capons, turkeys]}

# JSON can store most R objects quite naturally
#>   level           timestamp logger caller                msg
#> 1   400 2019-03-25 12:46:18   root   eval We lived in Styria
#> 2   400 2019-03-25 12:46:18   root   eval         Styria has
#>           poultry
#> 1            NULL
#> 2 capons, turkeys

## 2.2 Log Levels

lgr supports the standard log4j Log Levels outlined bellow. The Log Level of an event represents its severity. The named log levels are really just nicknames for integer values, and you can use the character or integer representations interchangeably. You can also use arbitrary integer values (greater than 0), but you are encouraged to stick to the ones bellow.

Level Name Description
0 off A log level of 0/off tells a Logger or Appender to suspend all logging
100 fatal Critical error that leads to program abort. Should always indicate a stop() or similar
200 error A severe error that does not trigger program abort
300 warn A potentially harmful situation, like warning()
400 info An informational message on the progress of the application
500 debug Finer grained informational messages that are mostly useful for debugging
600 trace An even finer grained message than debug
NA all A log level of NA/all tells a Logger or Appender to process all log events

The list of named log levels is stored as a global option (getOption("lgr.log_levels")) and you can use add_log_levels() and remove_log_levels() to define your own named levels if you want to. There are only predefined logging methods (lgr$fatal(), etc..) for the standard log levels and you have to use lgr$log(level, message) to create a LogEvent with a custom log level.

## 2.3 Logging With the Root Logger

lgr comes with a pre-configured root Logger. It is called root because you can set up a tree of Loggers that descent from it, but for basic use you will not have to worry about that.

### 2.3.1 Logging Syntax

lgr Loggers are R6 objects with methods (functions) for logging. You can refer to the root logger with lgr.

lgr$fatal("This is an important message about %s going wrong", "->something<-") #> FATAL [12:46:18.650] This is an important message about ->something<- going wrong lgr$trace("Trace messages are still hidden")
lgr$appenders$console$set_threshold("trace") lgr$trace("Unless we lower the threshold")
#> TRACE [12:46:18.655] Unless we lower the threshold
lgr$appenders$memory$show(3) ### 2.3.2 Formatting Strings You can use sprintf() style formatting strings directly in log messages. lgr$info("The sky was the color of %s, tuned to a dead chanel", "television")
#> INFO  [12:46:18.665] The sky was the color of television, tuned to a dead chanel

## 2.4 Log Events: The Atomic Unit of Logging

LogEvents are objects that store all information collected by the Logger. They are passed on to Appenders that output them, but Appenders usually don’t utilize all the information present in a log event. The last event produced by a Logger is stored in its last_event field.

lgr$info("Vampire stories are generally located in Styria") #> INFO [12:46:18.672] Vampire stories are generally located in Styria lgr$last_event  # a summary output of the event
#> INFO  [2019-03-25 12:46:18] Vampire stories are generally located in Styria
lgr$last_event$values  # all values stored in the event as a list
#> $level #> [1] 400 #> #>$timestamp
#> [1] "2019-03-25 12:46:18 CET"
#>
#> $logger #> [1] "root" #> #>$caller
#> [1] "eval"
#>
#> $msg #> [1] "Vampire stories are generally located in Styria" LogEvents can contain not only these standard values, but an arbitrary number of extra values. These extra values are passed as named arguments to the logging function (as opposed as to parameters to sprintf(), which are passed as unnamed arguments). It is up to the Appender whether to process them further or not. You should consider making use of custom fields liberally and using output formats that support them (such as JSON), rather than producing elaborately formatted but hard to parse log messages. If you ever want to analyse your log data, you will thank me for this tip. # bad lgr$info("Processing track '%s' with %s waypoints", "track.gpx", 32)
#> INFO  [12:46:18.685] Processing track 'track.gpx' with 32 waypoints

# Good
tf <- tempfile()
lgr$add_appender(AppenderJson$new(tf), "json")
lgr$info("Processing track", file = "track.gpx", waypoints = 32) #> INFO [12:46:18.691] Processing track {file: track.gpx, waypoints: 32} lgr$appenders$json$data
#>   level           timestamp logger caller              msg      file
#> 1   400 2019-03-25 12:46:18   root   eval Processing track track.gpx
#>   waypoints
#> 1        32

## 2.5 Thresholds & Filters: Controlling Output Detail

To control the level of detail of the log output, you can set thresholds for Loggers and Appenders. A Logger with a threshold of warn will only create LogEvents of the priorities warn, error and fatal and dispatch them to its Appenders.

A threshold of a Logger or Appender is the minimum log level a LogEvent must have so that that Logger/Appender processes it.

If you require more complex logic to decide whether a LogEvent should be created/processed you can also assign filters to Loggers/Appenders. Filters are just functions that have exactly one argument, event (the LogEvent to be filtered), and return TRUE or FALSE. They will be applied after the threshold is checked. Alternatively there is also a formal R6 class for Filters (?EventFilter) that you can use, but this is usually not necessary.

examples:

f1 <- function(event) { grepl("bird", event$msg) } lgr$set_filters(list(f1))

lgr$info("is it a plane?") lgr$info("no! is it a bird?")
#> INFO  [12:46:18.717] no! is it a bird?

# since this is not a very useful filter, we better remove it again
lgr$set_filters(NULL) ## 2.6 Appenders: Managing Log Destinations The root logger only logs to the console by default. If you want to redirect the output to a file you can just add a file appender to lgr. tf <- tempfile() # Add a new appender to a logger. We don't have to supply a name, but that # makes it easier to remove later. lgr$add_appender(AppenderFile$new(file = tf), name = "file") # configure lgr so that it logs everything to the file, but only info and above # to the console lgr$set_threshold(NA)
lgr$appenders$console$set_threshold("info") lgr$appenders$file$set_threshold(NA)
lgr$info("Another informational message") #> INFO [12:46:18.737] Another informational message lgr$debug("A debug message not shown by the console appender")

#> [1] "INFO  [2019-03-25 12:46:18.737] Another informational message"
#> [2] "DEBUG [2019-03-25 12:46:18.740] A debug message not shown by the console appender"

# Remove the appender again
lgr$remove_appender("file") ## 2.7 Inheritance: Hierarchical Loggers Logger hierarchies are a powerful concept to organize logging for different parts of a larger system. This is mainly relevant for package developers. It is good practice to have a separate Logger for each package. Since it is not common in R to build complex systems of hierarchically organised packages, hierarchies will usually be pretty flat (i.e. most Loggers will only inherit from the root logger). Each newly created Logger is child to a parent Logger, derived from its name. So lg <- get_logger("foo/bar") creates the logger with the qualified name foo/bar whose parent is the logger foo whose parent is (implicitly) the root logger. If the logger foo does not exist in that scenario, it is created automatically. This behaviour might sound strange at first, but it mimics tried and tested behaviour of python logging. This way logging is decoupled from the business logic and your program will not abort if you forgot to initialize some logger up the hierarchy for whatever reason. A logger dispatches the LogEvents it creates not only to its own Appenders, but also to the Appenders of all its ancestral Loggers (ignoring the threshold and Filters of the ancestral Loggers, but not of the Appenders). When you define Loggers for your package, you should not configure them (with custom Appenders or thresholds); that should be left to the user of the package. If all this sounds confusing to you, take a look at the examples. The common use cases are pretty easy to understand and illustrate the how and why pretty well. ### 2.7.1 Log Flow The graph bellow outlines the flow of LogEvents through the logging system. This is an important reference if you want to work with Filters and Logger hierarchies. ## 2.8 Logging with LoggerGlue glue is very nicely designed package for string interpolation. It makes composing log messages more flexible and comfortable at the price of an additional dependency and slightly less performance than sprintf() (which is used by normal Loggers). To take advantage of glue, simply create a new LoggerGlue like this: # install.packages("glue") lg <- get_logger_glue("glue/logger") lg$info(
"glue automatically ",
"pastes together unnamed arguments ",
"and evaluates arbitray expressions inside braces {Sys.Date()}"
)
#> INFO  [12:46:18.792] glue automatically pastes together unnamed arguments and evaluates arbitray expressions inside braces 2019-03-25

Glue lets you define temporary variables inside the glue() call. As with the normal Logger, named arguments get turned into custom fields.

lg$info("For more info on glue see {website}", website = "https://glue.tidyverse.org/") #> INFO [12:46:18.824] For more info on glue see https://glue.tidyverse.org/ {website: https://glue.tidyverse.org/} You can suppress this behaviour by making named argument start with a ".". lg$info("Glue is available from {.cran}", .cran = "https://CRAN.R-project.org/package=glue")
#> INFO  [12:46:18.834] Glue is available from https://CRAN.R-project.org/package=glue

# 3 Examples

## 3.1 Logging to the console

lgr comes with simple but powerful formatting syntax for LogEvents. Please refer to ?format.LogEvent for the full list of available placeholders.

lg <- get_logger("test")
lg$set_appenders(list(cons = AppenderConsole$new()))
lg$set_propagate(FALSE) lg$info("the default format")
#> INFO  [12:46:18.853] the default format
lg$appenders$cons$layout$set_fmt("%L (%n) [%t] %c(): !! %m !!")
lg$info("A more involved custom format") #> INFO (400) [12:46:18.861] eval(): !! A more involved custom format !! If this is not enough for you, you can use LayoutGlue based on the awesome glue package. The syntax is a bit more verbose, and AppenderGlue is a bit less performant than AppenderFormat, but the possibilities are endless. # install.packages("glue") library(glue) lg$appenders$cons$set_layout(LayoutGlue$new( fmt = "{.logger$name} {level_name} {caller}: {toupper(msg)}"
))
lg$info("with glue") #> test info eval: WITH GLUE All fields of the [LogEvent] object are exposed through LayoutGlue, so please refer to ?LogEvent for a list of all available Fields. ## 3.2 Logging to JSON files JavaScript Object Notation (JSON) is an open-standard file format that uses human-readable text to transmit data objects consisting of attribute–value pairs and array data types (Wikipedia). JSON is the recommended text-based logging format when logging to files 1, as it is human- as well as machine readable. You should only log to a different format if you have very good reasons for it. The easiest way to log to JSON files is with AppenderJson2 # install.packages("jsonlite") tf <- tempfile() lg <- get_logger("test") lg$set_appenders(list(json = AppenderJson$new(file = tf))) lg$set_propagate(FALSE)

lg$info("JSON naturally ", field = "custom") lg$info("supports custom", numbers = 1:3)
lg$info("log fields", use = "JSON") JSON is easy to parse and analyse with R. lgr provides the function read_json_lines() that can be used to read JSON log files, but you can also use AppenderJson’s $data binding for an even more convenient method to read the logfile.

lg$appenders$json$data # same as read_json_lines(tf) #> level timestamp logger caller msg field numbers #> 1 400 2019-03-25 12:46:18 test eval JSON naturally custom NULL #> 2 400 2019-03-25 12:46:18 test eval supports custom <NA> 1, 2, 3 #> 3 400 2019-03-25 12:46:18 test eval log fields <NA> NULL #> use #> 1 <NA> #> 2 <NA> #> 3 JSON JSON is also human readable, though this vignette does not transport that fact very well because of the lack of horizontal space. lg$appenders$json$show()
# same as
cat(readLines(tf), sep = "\n")
#> {"level":400,"timestamp":"2019-03-25 12:46:18","logger":"test","caller":"eval","msg":"JSON naturally ","field":"custom"}
#> {"level":400,"timestamp":"2019-03-25 12:46:18","logger":"test","caller":"eval","msg":"supports custom","numbers":[1,2,3]}
#> {"level":400,"timestamp":"2019-03-25 12:46:18","logger":"test","caller":"eval","msg":"log fields","use":"JSON"}

## 3.3 Logger Hierarchies

The most common use cases for creating a new Logger rather than just using the root Logger is if you create a Package that should contain logging. This way you can have separate Appenders (e.g logfiles) and thresholds for each package.

# The logger name should be the same as the package name
tf <- tempfile()
lg <- get_logger("mypackage")
lg$add_appender(AppenderFile$new(tf))  

The print() method for Loggers gives a nice overview of the newly created Logger:

print(lg)
#> <Logger> [all] mypackage
#>
#> appenders:
#>   [[1]]: <AppenderFile> [all] -> /tmp/Rtmp3HbXjZ/file1f3220693b0d
#>
#> inherited appenders:
#>   console: <AppenderConsole> [info] -> console
#>   memory : <AppenderDt>      [ all] -> in memory data.table

This tells us that lg logs all events of at least level info. It does have a single (unnamed) Appender that logs to a temporary file, and dispatches all LogEvents it creates to the Appenders of the root Logger (ignoring the threshold and filters of the root Logger, but not of its Appenders).

We can use lg$fatal(), lg$info(), etc.. to log messages with this Logger:

lg$info("A test message for lg") #> INFO [12:46:18.947] A test message for lg If we do not want lg to dispatch to the root Logger, we can set propagate to FALSE. lg$set_propagate(FALSE)

When we take a look at the Logger again, we now see that it does not inherit any Appenders anymore

print(lg)
#> <Logger> [all] mypackage
#>
#> appenders:
#>   [[1]]: <AppenderFile> [all] -> /tmp/Rtmp3HbXjZ/file1f3220693b0d

Consequently, lg no longer outputs log messages to he console

lg$info("Nothing to see here") ## 3.4 Buffered Logging The main purpose of AppenderBuffer is to retain LogEvents in memory and write them to destinations at a later point in time, e.g. when the Buffer is full and needs to be flushed. For example, if you log to a remote database you can postpone this costly operation until after your analysis is finished. By setting a filter as a custom $should_flush() method for an AppenderBuffer, you can define more complex conditions to trigger flushing. For example, the will output the last 5 LogEvents that happened before an error occurred.

lg <- get_logger("buffer")

lg$config(logger_config( threshold = NA, propagate = FALSE, # to suppress console output appenders = AppenderBuffer$new(
threshold = NA,
buffer_size = 5, # can hold 5 events, the 6th will trigger flushing
flush_on_exit = FALSE,
flush_on_rotate = FALSE,
flush_threshold = "error",
appenders = AppenderConsole$new(threshold = NA) ) )) #> <Logger> [all] buffer #> #> appenders: #> [[1]]: <AppenderBuffer> [all] -> 1 child Appenders # The for loop below stores 8 log events in the Buffer for (nm in month.name[1:8]) lg$debug("%s", nm)

# An event of level 'error' or 'fatal' triggers flushing of the buffer
lg$error("But the days grow short when you reach September") #> DEBUG [12:46:19.006] April #> DEBUG [12:46:19.006] May #> DEBUG [12:46:19.006] June #> DEBUG [12:46:19.006] July #> DEBUG [12:46:19.006] August #> ERROR [12:46:19.008] But the days grow short when you reach September ## 3.5 Logging to Databases Logging to databases is simple, though a few aspects can be tricky to configure based on the backend used. For performance reasons database inserts are buffered by default. This works exactly identical as described above for AppenderBuffer. If you want to write each LogEvent directly to the database, just set the buffer size to 0. # install.packages("RSQLite") lg <- get_logger("db_logger") lg$set_propagate(FALSE)
lg$add_appender( name = "db", AppenderDbi$new(
conn = DBI::dbConnect(RSQLite::SQLite()),
table = "log",
buffer_size = 2L
)
)
#> Creating 'log' with manually specified column types

lg$info("Logging to databases uses a buffer") lg$info("As the buffer size is 2, no insert took place till now")
lg$appenders$db$show() #> [empty log] lg$info("Now as the buffer is rotated, all events are output to the db")
lg$appenders$db$show() #> INFO [2019-03-25 12:46:19] Logging to databases uses a buffer #> INFO [2019-03-25 12:46:19] As the buffer size is 2, no insert took place till now #> INFO [2019-03-25 12:46:19] Now as the buffer is rotated, all events are output to the db ## 3.6 Inject Values Into LogEvents By abusing Filters, lgr can modify LogEvents as they are processed. One example for when this is useful is assigning a grouping identifier to a series of log calls. # setup an example function clean <- function() lgr$info("cleaning data")
process <- function() lgr$info("processing data") output <- function() lgr$info("outputing data")

analyze <- function(){
clean()
process()
output()
}

with_log_value() provides a convenient wrapper to inject values into log calls.

with_log_value(
list(dataset_id = "dataset1"),
analyze()
)

An alternative way to achieve the same is to use one of the preconfigured Filters that come with lgr. This approach is more more comfortable for use within functions.

analyze <- function(id = "dataset1"){
lgr$add_filter(FilterInject$new(dataset_id = id), name = "inject")

# 4 References

Python Logging

Eric Stenbock: The True Story of A Vampire

1. Technically, the logger does not produce standard JSON files but JSON lines

2. AppenderJson is just an AppenderFile with LayotJson as default Layout and a few extra features