diff --git a/R/basic_config.R b/R/basic_config.R index 901b99f9..70a333c2 100644 --- a/R/basic_config.R +++ b/R/basic_config.R @@ -2,7 +2,7 @@ #' #' A quick and easy way to configure the root logger. This is less powerful #' then using [`lgr$config()` or `lgr$set_*()`][Logger], but reduces the -#' most common configrations to a single line of code. +#' most common configurations to a single line of code. #' #' @param file `character` scalar: If not `NULL` a [AppenderFile] will be #' created that logs to this file. If the filename ends in `.jsonl`, the diff --git a/cran-comments.md b/cran-comments.md index d69a9113..82d5add5 100644 --- a/cran-comments.md +++ b/cran-comments.md @@ -10,4 +10,8 @@ 0 errors | 0 warnings | 0 notes -adds appender that can write to syslog +Adds appender that can write to syslog. This introduces an optional dependency +on the linux-only rsyslog package, so checks fail on windows if suggests are +forced. Running the tests/examples of this package will write a few lines to +the syslog on linux systems, if this is an undesired side effect I can disable +the tests. diff --git a/docs/articles/lgr.html b/docs/articles/lgr.html index 7bed1005..5403736a 100644 --- a/docs/articles/lgr.html +++ b/docs/articles/lgr.html @@ -92,10 +92,10 @@
# the root logger is called "lgr"
lgr$info("Vampire stories are generally located in Styria.")
-#> INFO [10:58:38.648] 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 [10:58:38.691] Vampires generally arrive in carriages drawn by 2 black horses.
tf <- tempfile(fileext = ".info")
lgr$add_appender(AppenderFile$new(tf), name = "file")
lgr$info("You must think I am joking")
-#> INFO [10:58:38.710] You must think I am joking
+#> INFO [15:05:39.698] You must think I am joking
readLines(tf)
-#> [1] "INFO [2019-08-20 10:58:38.710] 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 [10:58:38.720] No, I am quite serious
+#> INFO [15:05:39.711] No, I am quite serious
readLines(tf)
-#> [1] "INFO [2019-08-20 10:58:38.710] You must think I am joking"
-#> [2] "INFO [August 20 10:58:38] No, I am quite serious"
+#> [1] "INFO [2019-08-20 15:05:39.698] You must think I am joking"
+#> [2] "INFO [August 20 15:05:39] No, I am quite serious"
#cleanup
unlink(tf)
JSON is still somewhat human readable
cat(readLines(tf))
-#> {"level":400,"timestamp":"2019-08-20 10:58:38","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-08-20 10:58:38 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":"2019-08-20 10:58:38","logger":"root","caller":"eval","msg":"We lived in Styria"}
+#> {"level":400,"timestamp":"2019-08-20 15:05:39","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 2019-08-20 10:58:38 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.
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 [10:58:38.939] Styria has {poultry: [capons, turkeys]}
+#> INFO [15:05:39.951] Styria has {poultry: [capons, turkeys]}
# JSON can store most R objects quite naturally
read_json_lines(tf)
#> level timestamp logger caller msg
-#> 1 400 2019-08-20 10:58:38 root eval We lived in Styria
-#> 2 400 2019-08-20 10:58:38 root eval Styria has
+#> 1 400 2019-08-20 15:05:39 root eval We lived in Styria
+#> 2 400 2019-08-20 15:05:39 root eval Styria has
#> poultry
#> 1 NULL
#> 2 capons, turkeys
@@ -267,18 +267,18 @@
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 [10:58:38.992] This is an important message about ->something<- going wrong
+#> FATAL [15:05:40.002] 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 [10:58:38.996] Unless we lower the threshold
+#> TRACE [15:05:40.005] Unless we lower the threshold
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 [10:58:39.005] The sky was the color of television, tuned to a dead chanel
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 [10:58:39.011] Vampire stories are generally located in Styria
+#> INFO [15:05:40.021] Vampire stories are generally located in Styria
lgr$last_event # a summary output of the event
-#> INFO [2019-08-20 10:58:39] Vampire stories are generally located in Styria
+#> INFO [2019-08-20 15:05:40] 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-08-20 10:58:39 CEST"
+#> [1] "2019-08-20 15:05:40 CEST"
#>
#> $logger
#> [1] "root"
@@ -308,16 +308,16 @@
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 [10:58:39.022] Processing track 'track.gpx' with 32 waypoints
+#> INFO [15:05:40.032] 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 [10:58:39.027] Processing track {file: track.gpx, waypoints: 32}
+#> INFO [15:05:40.037] Processing track {file: track.gpx, waypoints: 32}
lgr$appenders$json$data
#> level timestamp logger caller msg file
-#> 1 400 2019-08-20 10:58:39 root eval Processing track track.gpx
+#> 1 400 2019-08-20 15:05:40 root eval Processing track track.gpx
#> waypoints
#> 1 32
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 [10:58:39.147] 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 [10:58:39.156] Glue is available from https://CRAN.R-project.org/package=glue
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.
#> level timestamp logger caller msg field numbers
-#> 1 400 2019-08-20 10:58:39 test eval JSON naturally custom NULL
-#> 2 400 2019-08-20 10:58:39 test eval supports custom <NA> 1, 2, 3
-#> 3 400 2019-08-20 10:58:39 test eval log fields <NA> NULL
+#> 1 400 2019-08-20 15:05:40 test eval JSON naturally custom NULL
+#> 2 400 2019-08-20 15:05:40 test eval supports custom <NA> 1, 2, 3
+#> 3 400 2019-08-20 15:05:40 test eval log fields <NA> NULL
#> use
#> 1 <NA>
#> 2 <NA>
@@ -527,9 +527,9 @@
-#> {"level":400,"timestamp":"2019-08-20 10:58:39","logger":"test","caller":"eval","msg":"JSON naturally ","field":"custom"}
-#> {"level":400,"timestamp":"2019-08-20 10:58:39","logger":"test","caller":"eval","msg":"supports custom","numbers":[1,2,3]}
-#> {"level":400,"timestamp":"2019-08-20 10:58:39","logger":"test","caller":"eval","msg":"log fields","use":"JSON"}
+#> {"level":400,"timestamp":"2019-08-20 15:05:40","logger":"test","caller":"eval","msg":"JSON naturally ","field":"custom"}
+#> {"level":400,"timestamp":"2019-08-20 15:05:40","logger":"test","caller":"eval","msg":"supports custom","numbers":[1,2,3]}
+#> {"level":400,"timestamp":"2019-08-20 15:05:40","logger":"test","caller":"eval","msg":"log fields","use":"JSON"}
# cleanup
lg$config(NULL)
#> <Logger> [all] test
@@ -558,17 +558,17 @@
# display info on the backups of tf
lg$appenders$rotating$backups
#> path name sfx ext size
-#> 1 /tmp/RtmpFwi8NS/file1f9845d36ba6.1.log file1f9845d36ba6 1 log 10608
-#> 2 /tmp/RtmpFwi8NS/file1f9845d36ba6.2.log file1f9845d36ba6 2 log 10608
-#> 3 /tmp/RtmpFwi8NS/file1f9845d36ba6.3.log file1f9845d36ba6 3 log 10608
-#> 4 /tmp/RtmpFwi8NS/file1f9845d36ba6.4.log file1f9845d36ba6 4 log 10608
-#> 5 /tmp/RtmpFwi8NS/file1f9845d36ba6.5.log file1f9845d36ba6 5 log 10608
+#> 1 /tmp/RtmpWQn7ry/file34b5325c3d3b.1.log file34b5325c3d3b 1 log 10608
+#> 2 /tmp/RtmpWQn7ry/file34b5325c3d3b.2.log file34b5325c3d3b 2 log 10608
+#> 3 /tmp/RtmpWQn7ry/file34b5325c3d3b.3.log file34b5325c3d3b 3 log 10608
+#> 4 /tmp/RtmpWQn7ry/file34b5325c3d3b.4.log file34b5325c3d3b 4 log 10608
+#> 5 /tmp/RtmpWQn7ry/file34b5325c3d3b.5.log file34b5325c3d3b 5 log 10608
#> isdir mode mtime ctime atime
-#> 1 FALSE 664 2019-08-20 10:58:39 2019-08-20 10:58:39 2019-08-20 10:58:39
-#> 2 FALSE 664 2019-08-20 10:58:39 2019-08-20 10:58:39 2019-08-20 10:58:39
-#> 3 FALSE 664 2019-08-20 10:58:39 2019-08-20 10:58:39 2019-08-20 10:58:39
-#> 4 FALSE 664 2019-08-20 10:58:39 2019-08-20 10:58:39 2019-08-20 10:58:39
-#> 5 FALSE 664 2019-08-20 10:58:39 2019-08-20 10:58:39 2019-08-20 10:58:39
+#> 1 FALSE 664 2019-08-20 15:05:40 2019-08-20 15:05:40 2019-08-20 15:05:40
+#> 2 FALSE 664 2019-08-20 15:05:40 2019-08-20 15:05:40 2019-08-20 15:05:40
+#> 3 FALSE 664 2019-08-20 15:05:40 2019-08-20 15:05:40 2019-08-20 15:05:40
+#> 4 FALSE 664 2019-08-20 15:05:40 2019-08-20 15:05:40 2019-08-20 15:05:40
+#> 5 FALSE 664 2019-08-20 15:05:40 2019-08-20 15:05:40 2019-08-20 15:05:40
#> uid gid uname grname index
#> 1 1000 1000 hoelk hoelk 1
#> 2 1000 1000 hoelk hoelk 2
@@ -599,14 +599,14 @@
#> <Logger> [all] mypackage
#>
#> appenders:
-#> [[1]]: <AppenderFile> [all] -> /tmp/RtmpFwi8NS/file1f981922ddee
+#> [[1]]: <AppenderFile> [all] -> /tmp/RtmpWQn7ry/file34b53c5a2647
#>
#> inherited 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:
+#> INFO [15:05:40.780] A test message for lg
If we do not want lg
to dispatch to the root Logger, we can set propagate
to FALSE
.
When we take a look at the Logger again, we now see that it does not inherit any Appenders anymore
@@ -614,7 +614,7 @@Consequently, lg
no longer outputs log messages to he console
# cleanup
@@ -650,12 +650,12 @@
# An event of level 'error' or 'fatal' triggers flushing of the buffer
lg$error("But the days grow short when you reach September")
-#> DEBUG [10:58:39.796] April
-#> DEBUG [10:58:39.797] May
-#> DEBUG [10:58:39.797] June
-#> DEBUG [10:58:39.797] July
-#> DEBUG [10:58:39.797] August
-#> ERROR [10:58:39.799] But the days grow short when you reach September
The result is the same in both cases:
-#> INFO [10:58:40.091] cleaning data {dataset_id: dataset1}
-#> INFO [10:58:40.092] processing data {dataset_id: dataset1}
-#> INFO [10:58:40.093] outputing data {dataset_id: dataset1}
+#> INFO [15:05:41.199] cleaning data {dataset_id: dataset1}
+#> INFO [15:05:41.201] processing data {dataset_id: dataset1}
+#> INFO [15:05:41.201] outputing data {dataset_id: dataset1}
You can use with_log_level()
and FilterForceLevel
in a similar fashion to modify the log level of events conveniently.
To log an event with with lgr we call lgr$<logging function>()
. Unnamed arguments to the logging function are interpreted by sprintf()
. For a way to create loggers that glue instead please refer to the vignette.
lgr$fatal("A critical error")
-#> FATAL [10:58:13.871] A critical error
+#> FATAL [15:05:15.521] A critical error
lgr$error("A less severe error")
-#> ERROR [10:58:13.911] A less severe error
+#> ERROR [15:05:15.566] A less severe error
lgr$warn("A potentially bad situation")
-#> WARN [10:58:13.921] A potentially bad situation
+#> WARN [15:05:15.576] A potentially bad situation
lgr$info("iris has %s rows", nrow(iris))
-#> INFO [10:58:13.923] iris has 150 rows
+#> INFO [15:05:15.578] iris has 150 rows
# the following log levels are hidden by default
lgr$debug("A debug message")
@@ -126,15 +126,15 @@
tf <- tempfile()
lgr$add_appender(AppenderFile$new(tf, layout = LayoutJson$new()))
lgr$info("cars has %s rows", nrow(cars))
-#> INFO [10:58:13.940] cars has 50 rows
+#> INFO [15:05:15.595] cars has 50 rows
cat(readLines(tf))
-#> {"level":400,"timestamp":"2019-08-20 10:58:13","logger":"root","caller":"eval","msg":"cars has 50 rows"}
+#> {"level":400,"timestamp":"2019-08-20 15:05:15","logger":"root","caller":"eval","msg":"cars has 50 rows"}
By passing a named argument to info()
, warn()
, and co you can log not only text but arbitrary R objects. Not all appenders handle such custom fields perfectly, but JSON does. This way you can create logfiles that are machine as well as (somewhat) human readable.
lgr$info("loading cars", "cars", rows = nrow(cars), cols = ncol(cars))
-#> INFO [10:58:13.962] loading cars {rows: 50, cols: 2}
+#> INFO [15:05:15.614] loading cars {rows: 50, cols: 2}
cat(readLines(tf), sep = "\n")
-#> {"level":400,"timestamp":"2019-08-20 10:58:13","logger":"root","caller":"eval","msg":"cars has 50 rows"}
-#> {"level":400,"timestamp":"2019-08-20 10:58:13","logger":"root","caller":"eval","msg":"loading cars","rows":50,"cols":2}
For more examples please see the package vignette and documentation