# Introduction

lgr is a logging framework for R inspired by Apache Log4j and Python logging. It follows an 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 flexible and easy to extend.

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.

## 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.

### Logging to the console

# the root logger is called "lgr"
lgr$info("Vampire stories are generally located in Styria.") #> INFO [15:23:23.844] 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 [15:23:23.873] Vampires generally arrive in carriages drawn by 2 black horses.

### Logging to plaintext 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 [15:23:23.892] You must think I am joking readLines(tf) #> [1] "INFO [2020-01-02 15:23:23.892] 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 [15:23:23.911] No, I am quite serious readLines(tf) #> [1] "INFO [2020-01-02 15:23:23.892] You must think I am joking" #> [2] "INFO [January 02 15:23:23] No, I am quite serious" #cleanup unlink(tf) ### 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 [15:23:23.939] We lived in Styria JSON is still somewhat human readable cat(readLines(tf)) #> {"level":400,"timestamp":"2020-01-02 15:23:23","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 2020-01-02 15:23:23 root eval We lived in Styria Many Appenders provide either a $show() method and a $data active binding convenience, and so you do not have to call readLines() & co manually. # show is a method and takes some extra arguments, like maximum number of lines # to show lgr$appenders$json$show()
#> {"level":400,"timestamp":"2020-01-02 15:23:23","logger":"root","caller":"eval","msg":"We lived in Styria"}

# $data always returns a data.frame if available. It is an active binding # rather than a method, so no extra arguments are possible lgr$appenders$json$data
#>   level           timestamp logger caller                msg
#> 1   400 2020-01-02 15:23:23   root   eval We lived in Styria

Please note that under the hood, AppenderJson is just an AppenderFile with LayoutJson. The only difference is AppenderJson provides a $data() method while AppenderFile does not. ### Custom Fields Unlike many others Loggers for R, lgr treats a LogEvent 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  [15:23:24.148] Styria has {poultry: [capons, turkeys]}

# JSON can store most R objects quite naturally
#>   level           timestamp logger caller                msg         poultry
#> 1   400 2020-01-02 15:23:23   root   eval We lived in Styria            NULL
#> 2   400 2020-01-02 15:23:24   root   eval         Styria has capons, turkeys

## 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 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
NA all Tells a Logger or Appender to process all log events

off and all are valid thresholds for Appenders and Loggers, but not valid levels for LogEvents; e.g. lgr$set_threshold(NA) makes sense, but lgr$log("all", "an example message") does not.

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.

## 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.

### 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 [15:23:24.202] This is an important message about ->something<- going wrong lgr$trace("Trace messages are still hidden")
lgr$set_threshold("trace") lgr$trace("Unless we lower the threshold")
#> TRACE [15:23:24.205] Unless we lower the threshold

### 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 [15:23:24.210] The sky was the color of television, tuned to a dead chanel ## LogEvents: 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  [15:23:24.216] Vampire stories are generally located in Styria
lgr$last_event # a summary output of the event #> INFO [2020-01-02 15:23:24] 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] "2020-01-02 15:23:24 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 [15:23:24.228] 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  [15:23:24.236] Processing track {file: track.gpx, waypoints: 32}
lgr$appenders$json$data #> level timestamp logger caller msg file waypoints #> 1 400 2020-01-02 15:23:24 root eval Processing track track.gpx 32 ## 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 [15:23:24.258] no! is it a bird? # since this is not a very useful filter, we better remove it again lgr$set_filters(NULL)

## 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  [15:23:24.278] Another informational message
lgr$debug("A debug message not shown by the console appender") readLines(tf) #> [1] "INFO [2020-01-02 15:23:24.278] Another informational message" #> [2] "DEBUG [2020-01-02 15:23:24.280] A debug message not shown by the console appender" # Remove the appender again lgr$remove_appender("file")
unlink(tf)

## 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 and ?logger_tree. The common use cases are pretty easy to understand and illustrate the how and why pretty well.

Example hierarchy for the package fancymodel that provides a model along with a plumber API and a shiny web-interface to the package.

# prints a tree structure of all registered loggers
logger_tree()
root [info] -> 1 appenders
└─fancymodel
├─plumber
└─#shiny
├─server [trace] -> 2 appenders
└─ui -> 1 appenders

### 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.

## 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 [15:23:24.326] glue automatically pastes together unnamed arguments and evaluates arbitray expressions inside braces 2020-01-02 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  [15:23:24.356] 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 [15:23:24.362] Glue is available from https://CRAN.R-project.org/package=glue # Configuration ## With setters There are several different ways to configure loggers. The most straight forward one is to use setters to specify the Loggers properties. lg <- get_logger("test") lg$config(NULL)  # resets logger to unconfigured state
#> <Logger> [all] test
#>
#> inherited appenders:
#>   appenders.console: <AppenderConsole> [info] -> console
lg$set_threshold("fatal") lgr sets up Loggers in a way so that R6 piping with $ is possible. This works similar to the magrittr (#%>#) pipes.

lg$set_threshold("info")$
set_appenders(AppenderConsole$new(threshold = "info"))$
set_propagate(FALSE)

## With a list object

lg$config(list( threshold = "info", propagate = FALSE, appenders = AppenderConsole$new(threshold = "info")
))
#> <Logger> [info] test
#>
#> appenders:
#>   [[1]]: <AppenderConsole> [info] -> console

## With YAML or JSON

You can use YAML and JSON config files with lgr.

lg$config("path/to/config.yaml") lg$config("path/to/config.json")

You can also pass in YAML/JSON directly as a character string (or vector with one element per line)

# Via YAML
cfg <- "
Logger:
threshold: info
propagate: false
appenders:
AppenderConsole:
threshold: info
"
lg$config(cfg) #> <Logger> [info] test #> #> appenders: #> AppenderConsole: <AppenderConsole> [info] -> console # Examples ## 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 [15:23:24.431] the default format lg$appenders$cons$layout$set_fmt("%L (%n) [%t] %c(): !! %m !!") lg$info("A more involved custom format")
#> INFO  (400) [15:23:24.433] 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.

## 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  use
#> 1   400 2020-01-02 15:23:24   test   eval JSON naturally  custom    NULL <NA>
#> 2   400 2020-01-02 15:23:24   test   eval supports custom   <NA> 1, 2, 3 <NA>
#> 3   400 2020-01-02 15:23:24   test   eval      log fields   <NA>    NULL 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":"2020-01-02 15:23:24","logger":"test","caller":"eval","msg":"JSON naturally ","field":"custom"} #> {"level":400,"timestamp":"2020-01-02 15:23:24","logger":"test","caller":"eval","msg":"supports custom","numbers":[1,2,3]} #> {"level":400,"timestamp":"2020-01-02 15:23:24","logger":"test","caller":"eval","msg":"log fields","use":"JSON"} # cleanup lg$config(NULL)
#> <Logger> [all] test
#>
#> inherited appenders:
#>   appenders.console: <AppenderConsole> [info] -> console
unlink(tf)

## Logging to rotating files

lgr can also log to rotating files. The following example logs to a file that is reset and backed-up once it reaches a size of 10kb. Only the last 5 backups of the logfile are kept.

# install.packages("rotor")
tf <- tempfile(fileext = ".log")

lg <- get_logger("test")$set_propagate(FALSE)$
set_appenders(list(rotating = AppenderFileRotating$new( file = tf, size = "10 kb", max_backups = 5)) ) for (i in 1:100) lg$info(paste(LETTERS, sep = "-"))

# display info on the backups of tf
lg$appenders$rotating$backups #> path name sfx ext size isdir #> 1 /tmp/Rtmp47HPXL/file524b523defe7.1.log file524b523defe7 1 log 10608 FALSE #> 2 /tmp/Rtmp47HPXL/file524b523defe7.2.log file524b523defe7 2 log 10608 FALSE #> 3 /tmp/Rtmp47HPXL/file524b523defe7.3.log file524b523defe7 3 log 10608 FALSE #> 4 /tmp/Rtmp47HPXL/file524b523defe7.4.log file524b523defe7 4 log 10608 FALSE #> 5 /tmp/Rtmp47HPXL/file524b523defe7.5.log file524b523defe7 5 log 10608 FALSE #> mode mtime ctime atime uid gid #> 1 664 2020-01-02 15:23:24 2020-01-02 15:23:24 2020-01-02 15:23:24 1032 1032 #> 2 664 2020-01-02 15:23:24 2020-01-02 15:23:24 2020-01-02 15:23:24 1032 1032 #> 3 664 2020-01-02 15:23:24 2020-01-02 15:23:24 2020-01-02 15:23:24 1032 1032 #> 4 664 2020-01-02 15:23:24 2020-01-02 15:23:24 2020-01-02 15:23:24 1032 1032 #> 5 664 2020-01-02 15:23:24 2020-01-02 15:23:24 2020-01-02 15:23:24 1032 1032 #> uname grname index #> 1 fleck fleck 1 #> 2 fleck fleck 2 #> 3 fleck fleck 3 #> 4 fleck fleck 4 #> 5 fleck fleck 5 # manually delete all backups invisible(lg$appenders$rotating$prune(0))
lg$appenders$rotating$backups #> [1] path name sfx ext size isdir mode mtime ctime atime #> [11] uid gid uname grname index #> <0 rows> (or 0-length row.names) #cleanup unlink(tf) ## 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/Rtmp47HPXL/file524b55ef73ef #> #> inherited appenders: #> appenders.console: <AppenderConsole> [info] -> console 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  [15:23:24.806] 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/Rtmp47HPXL/file524b55ef73ef Consequently, lg no longer outputs log messages to he console lg$info("Nothing to see here")
# cleanup
lg$config(NULL) #> <Logger> [all] mypackage #> #> inherited appenders: #> appenders.console: <AppenderConsole> [info] -> console unlink(tf) ## 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$set_threshold(NA)$
set_propagate(FALSE)$set_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) )) # 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 [15:23:24.861] April #> DEBUG [15:23:24.861] May #> DEBUG [15:23:24.862] June #> DEBUG [15:23:24.862] July #> DEBUG [15:23:24.862] August #> ERROR [15:23:24.863] But the days grow short when you reach September ## 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. As of lgr 0.4.0, database appenders are part of the lgrExtra package that has to be installed sepparetely. # install.packages("RSQLite") lg <- get_logger("db_logger") lg$
set_propagate(FALSE)$add_appender( name = "db", lgrExtra::AppenderDbi$new(
conn = DBI::dbConnect(RSQLite::SQLite()),
table = "log",
buffer_size = 2L
)
)

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() lg$info("Now as the buffer is rotated, all events are output to the db")
lg$appenders$db$show() ## 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")

## Creating a Layout that mimics NodeJS Winston logstash

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