From 54cd709036a76bc805c8c60960c0c7284cf45f6f Mon Sep 17 00:00:00 2001 From: stefan-fleck Date: Mon, 2 May 2022 13:18:36 +0200 Subject: [PATCH 1/7] add hidden .rawMsg property to LogEvent for storing msg without string interpolation --- NEWS.md | 5 ++++ R/LogEvent.R | 12 ++++++-- R/Logger.R | 45 +++++++++++++++++----------- man/LogEvent.Rd | 6 +++- tests/testthat/test_Logger.R | 58 ++++++++++++++++++++++++++++++++---- 5 files changed, 99 insertions(+), 27 deletions(-) diff --git a/NEWS.md b/NEWS.md index 3ae441be..5b538862 100644 --- a/NEWS.md +++ b/NEWS.md @@ -4,6 +4,11 @@ `{knitr}` rendering process, log messages are now output to `stderr` instead of `stdout` by default, to avoid polluting markdown documents (#62, thx @gadenbuie). +* added hidden `.rawMsg` property to LogEvents to store message without + string interpolation (e.g. that still contains the placeholders from + `sprintf()` or `glue()`) (#60) + + # lgr 0.4.4 * `%k` and `%K` parameters in `format.LogEvent` now work as expected when using diff --git a/R/LogEvent.R b/R/LogEvent.R index 13a24c2f..d91c9880 100644 --- a/R/LogEvent.R +++ b/R/LogEvent.R @@ -53,6 +53,7 @@ LogEvent <- R6::R6Class( timestamp = Sys.time(), caller = NA, msg = NA, + .rawMsg = msg, ... ){ assert(inherits(logger, "Logger"), "Logger must be a object, not a ", class_fmt(logger)) @@ -64,6 +65,7 @@ LogEvent <- R6::R6Class( assign("timestamp", timestamp, self) assign("caller", caller, self) assign("msg", msg, self) + assign(".rawMsg", .rawMsg, self) # custom values if (!missing(...)){ @@ -94,18 +96,22 @@ LogEvent <- R6::R6Class( #' @field .logger [Logger]. A reference to the Logger that created the #' event (equivalent to `get_logger(event$logger)`). - .logger = NULL + .logger = NULL, + + #' @field .rawMsg `character`. The raw log message without string + #' interpolation. + .rawMsg = NULL ), active = list( #' @field values `list`. All values stored in the `LogEvent`, including - #' all *custom fields*, but not including `event$.logger`. + #' all *custom fields*, but not including `event$.logger` and `event$.rawMsg`. values = function(){ fixed_vals <- c("level", "timestamp", "logger", "caller", "msg") custom_vals <- setdiff( names(get(".__enclos_env__", self)[["self"]]), - c(".__enclos_env__", "level_name", "initialize", "clone", "values", + c(".__enclos_env__", "level_name", "initialize", "clone", "values", ".rawMsg", ".logger") ) valnames <- union(fixed_vals, custom_vals) # to enforce order of fixed_vals diff --git a/R/Logger.R b/R/Logger.R index 3ec723d3..89fde96f 100644 --- a/R/Logger.R +++ b/R/Logger.R @@ -226,6 +226,7 @@ Logger <- R6::R6Class( } force(caller) + rawMsg <- msg if (missing(...)){ vals <- list( @@ -233,7 +234,8 @@ Logger <- R6::R6Class( level = level, timestamp = timestamp, caller = caller, - msg = msg + msg = msg, + .rawMsg = rawMsg ) } else { dots <- list(...) @@ -245,7 +247,8 @@ Logger <- R6::R6Class( level = level, timestamp = timestamp, caller = caller, - msg = msg + msg = msg, + .rawMsg = rawMsg ) } else { not_named <- vapply(names(dots), is_blank, TRUE, USE.NAMES = FALSE) @@ -259,7 +262,8 @@ Logger <- R6::R6Class( level = level, timestamp = timestamp, caller = caller, - msg = msg + msg = msg, + .rawMsg = rawMsg ), dots[!not_named] ) @@ -882,6 +886,11 @@ LoggerGlue <- R6::R6Class( "Can only utilize vectorized logging if log level is the same for all entries" ) + assert( + !missing(...), + "No log message or structured logging fields supplied" + ) + dots <- list(...) if ("msg" %in% names(dots)){ @@ -909,6 +918,7 @@ LoggerGlue <- R6::R6Class( } }) + rawMsg <- dots[[1]] msg <- do.call(glue::glue, args = c(dots_msg, list(.envir = .envir))) # Check if LogEvent should be created @@ -921,22 +931,21 @@ LoggerGlue <- R6::R6Class( force(caller) - if (missing(...)){ - stop("No log message or structured logging fields supplied") - } else { - custom_fields <- !(grepl("^\\.", names(dots)) | is_blank(names(dots))) + # Create list that contains all values equired for the log event + custom_fields <- !(grepl("^\\.", names(dots)) | is_blank(names(dots))) + + vals <- c( + list( + logger = self, + level = level, + timestamp = timestamp, + caller = caller, + msg = msg, + .rawMsg = rawMsg + ), + dots[custom_fields] + ) - vals <- c( - list( - logger = self, - level = level, - timestamp = timestamp, - caller = caller, - msg = msg - ), - dots[custom_fields] - ) - } # This code looks really weird, but it really is just replacing all # instances of [[ with get() for minimal overhead. We want event diff --git a/man/LogEvent.Rd b/man/LogEvent.Rd index 56f845f8..2ebed31e 100644 --- a/man/LogEvent.Rd +++ b/man/LogEvent.Rd @@ -55,6 +55,9 @@ LogEvent was created.} \item{\code{.logger}}{\link{Logger}. A reference to the Logger that created the event (equivalent to \code{get_logger(event$logger)}).} + +\item{\code{.rawMsg}}{\code{character}. The raw log message without string +interpolation.} } \if{html}{\out{}} } @@ -62,7 +65,7 @@ event (equivalent to \code{get_logger(event$logger)}).} \if{html}{\out{
}} \describe{ \item{\code{values}}{\code{list}. All values stored in the \code{LogEvent}, including -all \emph{custom fields}, but not including \code{event$.logger}.} +all \emph{custom fields}, but not including \code{event$.logger} and \code{event$.rawMsg}.} \item{\code{level_name}}{\code{character}. The \link{log_level} / priority of the LogEvent labelled according to \code{getOption("lgr.log_levels")}} @@ -95,6 +98,7 @@ the \link{Appenders} and \link{Layouts} as if several separate events. timestamp = Sys.time(), caller = NA, msg = NA, + .rawMsg = msg, ... )}\if{html}{\out{
}} } diff --git a/tests/testthat/test_Logger.R b/tests/testthat/test_Logger.R index fbc9dfa3..477c7e28 100644 --- a/tests/testthat/test_Logger.R +++ b/tests/testthat/test_Logger.R @@ -1,6 +1,9 @@ context("Logger") +# Logger ------------------------------------------------------------------ + + test_that("logging conditions works", { e <- error("blahblah") @@ -379,11 +382,17 @@ test_that("$config works with lists", { +# Multi-Logger tests ------------------------------------------------------------- test_that("Logger$log() dispatches to all appenders, even if some throw an error", { ln <- Logger$new("normal", propagate = FALSE) lg <- LoggerGlue$new("glue", propagate = FALSE) + on.exit({ + ln$config(NULL) + lg$config(NULL) + }) + AppErr <- R6::R6Class( inherit = AppenderConsole, public = list( @@ -416,6 +425,11 @@ test_that("Logger error contains useful call object", { l <- get_logger("test") g <- get_logger_glue("testglue") + on.exit({ + l$config(NULL) + g$config(NULL) + }) + expect_warning(l$info("this will fail", e = stop()), "l\\$info") expect_warning(g$info("this will fail", e = stop()), "g\\$info") }) @@ -451,18 +465,52 @@ test_that("Appender error contains useful call object", { }) +test_that("Logger$log - with 'msg' argument - logs the message", { + l <- get_logger("test")$set_propagate(FALSE) + + on.exit({ + l$config(NULL) + }) + + expect_silent(l$log(level = "fatal", msg = "test")) +}) +test_that("LoggerGlue$log - with 'msg' argument - throws a warning", { + l <- get_logger_glue("testglue")$set_propagate(FALSE) -test_that("Logger$log 'msg' argument works as expected", { + on.exit({ + l$config(NULL) + }) + + expect_warning(l$log(level = "fatal", msg = "test"), "does not support") +}) + + +test_that("Logger$log - with string interpolation - adds .rawMsg to event", { l <- get_logger("test")$set_propagate(FALSE) - g <- get_logger_glue("testglue")$set_propagate(FALSE) on.exit({ l$config(NULL) - g$config(NULL) }) - expect_silent(l$log(level = "fatal", msg = "test")) - expect_warning(g$log(level = "fatal", msg = "test"), "does not support") + l$info("foo %s", "bar") + + expect_identical(l$last_event$msg, "foo bar") + expect_identical(l$last_event$.rawMsg, "foo %s") }) + + +test_that("LoggerGlue$log - with string interpolation - adds .rawMsg to event", { + l <- get_logger_glue("testglue")$set_propagate(FALSE) + + on.exit({ + l$config(NULL) + }) + + l$fatal("hash {x}", x = "baz") + + expect_identical(as.character(l$last_event$msg), "hash baz") + expect_identical(l$last_event$.rawMsg, "hash {x}") +}) + From ea0fba3937d513584a1529acfc495226174ec098 Mon Sep 17 00:00:00 2001 From: stefan-fleck Date: Wed, 8 Mar 2023 09:35:09 +0100 Subject: [PATCH 2/7] add CRAN-SUBMISSION to build ignore --- .Rbuildignore | 1 + CRAN-SUBMISSION | 3 +++ 2 files changed, 4 insertions(+) create mode 100644 CRAN-SUBMISSION diff --git a/.Rbuildignore b/.Rbuildignore index 9eb239c7..960d691e 100644 --- a/.Rbuildignore +++ b/.Rbuildignore @@ -17,3 +17,4 @@ ^\.httr-oauth$ ^revdep$ ^.github$ +^CRAN-SUBMISSION$ diff --git a/CRAN-SUBMISSION b/CRAN-SUBMISSION new file mode 100644 index 00000000..0e5d46f5 --- /dev/null +++ b/CRAN-SUBMISSION @@ -0,0 +1,3 @@ +Version: 0.4.4 +Date: 2022-09-05 21:01:18 UTC +SHA: c725c929678ac9d18a9f45a42f1147d41b7a13d5 From ec545e974452718d70abe8d6f50b302a830ab1f3 Mon Sep 17 00:00:00 2001 From: stefan-fleck Date: Wed, 8 Mar 2023 09:36:39 +0100 Subject: [PATCH 3/7] fix toString.LogEvent test --- tests/testthat/test_print_LogEvent.R | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/tests/testthat/test_print_LogEvent.R b/tests/testthat/test_print_LogEvent.R index e4ace0d8..7489c2de 100644 --- a/tests/testthat/test_print_LogEvent.R +++ b/tests/testthat/test_print_LogEvent.R @@ -67,10 +67,14 @@ test_that("toString.LogEvent works as expected", { letters = letters ) - toString(x) + expect_length(toString(x), 1L) + # just a rudimentary check because exact representation depends on console width + expect_match(toString(x), "level.*letters") }) + + test_that("toString.LogEvent without custom fields does not end in whitespace", { event_without_field <- LogEvent$new( logger = lgr::lgr, From d29ba42a43c4d514832714f0fcc7327c3d21c6a0 Mon Sep 17 00:00:00 2001 From: hoelk-yesod Date: Sun, 13 Jul 2025 09:23:31 +0000 Subject: [PATCH 4/7] update docs and tests --- NEWS.md | 2 + README.Rmd | 64 +++++++++------------- tests/testthat/test_AppenderFileRotating.R | 15 +++-- tests/testthat/test_parallel.R | 2 + 4 files changed, 39 insertions(+), 44 deletions(-) diff --git a/NEWS.md b/NEWS.md index 5b538862..67edb247 100644 --- a/NEWS.md +++ b/NEWS.md @@ -7,6 +7,8 @@ * added hidden `.rawMsg` property to LogEvents to store message without string interpolation (e.g. that still contains the placeholders from `sprintf()` or `glue()`) (#60) + +* updated Readnme # lgr 0.4.4 diff --git a/README.Rmd b/README.Rmd index e59648b8..efc6691b 100644 --- a/README.Rmd +++ b/README.Rmd @@ -19,7 +19,7 @@ basic_config(console_connection = stdout()) # ensure default config # lgr [![CRAN status](https://www.r-pkg.org/badges/version/lgr)](https://cran.r-project.org/package=lgr) -[![Lifecycle: maturing](https://img.shields.io/badge/lifecycle-maturing-blue.svg)](https://lifecycle.r-lib.org/articles/stages.html) +[![Lifecycle: maturing](https://img.shields.io/badge/lifecycle-stable-green.svg)](https://lifecycle.r-lib.org/articles/stages.html) lgr is a logging package for R built on the back of [R6](https://github.com/r-lib/R6) classes. It is designed to be flexible, @@ -144,14 +144,25 @@ file.remove(logfile) ## Development status -lgr in general is stable and safe for use, but **the following features are still experimental**: +lgr is stable and safe for use. I've been using it in production code for +several years myself. There has been very little recent development because +it's pretty stable and contains (nearly) all planned features. -* Database appenders which are available from the separate package - [lgrExtra](https://github.com/s-fleck/lgrExtra). -* yaml/json config files for loggers (do not yet support all planned features) -* The documentation in general. I'm still hoping for more R6-specific features - in [roxygen2](https://github.com/r-lib/roxygen2) before I invest more - time in object documentation. +Notable points that are not + +* Support for config files is heavily experimental and incomplete. + This is an important basic feature, but I have not yet found a great way to + support this in a generic way. For now, I recommend you come up with your own + solution if you need to lgr to work in a production environment that relies + on config files. + +* The documentation should be mostly complete, but is not perfect. If there's + something missing or something you don't understand - please ask (for example + via a github issue). + +* Please also check out the lgrExtra package for a variety of extra appenders + [lgrExtra](https://github.com/s-fleck/lgrExtra) (that might not be as stable + as the main lgr package itself). ## Dependencies @@ -169,7 +180,6 @@ lgr comes with a long list of optional dependencies that make a wide range of appenders possible. You only need the dependencies for the Appenders you actually want to use. Care was taken to choose packages that are slim, stable, have minimal dependencies, and are well maintained : - Extra appenders (in the main package): @@ -186,38 +196,16 @@ have minimal dependencies, and are well maintained : - [glue](https://glue.tidyverse.org/) for a more flexible formatting syntax via LoggerGlue and LayoutGlue. - Extra appenders via [lgrExtra](https://github.com/s-fleck/lgrExtra): - - - [DBI](https://github.com/r-dbi/DBI) for logging to databases. lgr is - confirmed to work with the following backends: - - [RSQLite](https://github.com/r-dbi/RSQLite), - - [RMariaDB](https://github.com/r-dbi/RMariaDB) for MariaDB and MySQL, - - [RPostgres](https://cran.r-project.org/package=RPostgres), - - [RJDBC](https://github.com/s-u/RJDBC) for DB2, and - - [odbc](https://github.com/r-dbi/odbc) also for DB2. - - In theory all DBI compliant database packages should work. If you - are using lgr with a database backend, please report your (positive and - negative) experiences, as database support is still somewhat experimental. - - - [gmailr](https://cran.r-project.org/package=gmailr) or - - - [sendmailR](https://cran.r-project.org/package=sendmailR) for email - notifications. - - - [RPushbullet](https://github.com/eddelbuettel/rpushbullet) for push - notifications. - - - [Rsyslog](https://cran.r-project.org/package=rsyslog) for logging to - syslog on POSIX-compatible systems. - - - [elastic](https://cran.r-project.org/package=elastic) for logging - to ElasticSearch + Extra appenders via lgrExtra: + - For support for Elasticsearch, Dynatrace, Push- and Email notifications, + etc... as well as the relevant dependencies please refer to the + documentation of [lgrExtra](https://github.com/s-fleck/lgrExtra) + Other extra features: - [yaml](https://CRAN.R-project.org/package=yaml) for configuring loggers - via YAML files + via YAML files (experimental) - [crayon](https://github.com/r-lib/crayon) for colored console output. - [whoami](https://github.com/r-lib/whoami/blob/master/DESCRIPTION) for guessing the user name from various sources. You can also set the user name @@ -257,8 +245,6 @@ features/appenders that you'd like to see, please feel free to post a feature request on the issue tracker. - - ## Acknowledgement * [diagrams.net](https://app.diagrams.net/) for the flow chart in the vignette diff --git a/tests/testthat/test_AppenderFileRotating.R b/tests/testthat/test_AppenderFileRotating.R index 869cb29e..f038ab47 100644 --- a/tests/testthat/test_AppenderFileRotating.R +++ b/tests/testthat/test_AppenderFileRotating.R @@ -14,11 +14,12 @@ teardown({ # AppenderFileRotating ----------------------------------------------------- test_that("AppenderFileRotating: works as expected", { - if (!is_zipcmd_available()) - skip("Test requires a workings system zip command") - skip_if_not_installed("rotor", "0.3.0") + if (!is_zipcmd_available()){ + skip("Test requires a workings system zip command") + } + tf <- file.path(td, "test.log") app <- AppenderFileRotating$new(file = tf, size = "1tb") @@ -69,8 +70,9 @@ test_that("AppenderFileRotating: works as expected", { test_that("AppenderFileRotating: works with different backup_dir", { - if (!is_zipcmd_available()) + if (!is_zipcmd_available()) { skip("Test requires a workings system zip command") + } skip_if_not_installed("rotor", "0.3.0") @@ -393,6 +395,8 @@ test_that("AppenderFileRotatingTime: works with different backup_dir", { test_that("AppenderFileRotatingTime: `size` and `age` arguments work as expected", { + skip_if_not_installed("rotor", "0.3.0") + #setup tf <- file.path(td, "test.log") app <- AppenderFileRotatingTime$new(file = tf)$set_age(-1) @@ -407,7 +411,7 @@ test_that("AppenderFileRotatingTime: `size` and `age` arguments work as expected app$rotate() expect_identical(nrow(app$backups), 0L) - app$set_size(file.size(tf) / 2) + app$set_size(floor(file.size(tf) / 2)) app$rotate(now = "2999-01-01") expect_identical(nrow(app$backups), 1L) @@ -425,6 +429,7 @@ test_that("AppenderFileRotatingTime: `size` and `age` arguments work as expected # Issues ------------------------------------------------------------------ test_that("AppenderFileRotatingTime: `size` and `age` arguments work as expected #39", { + skip_if_not_installed("rotor", "0.3.0") #setup tf <- file.path(td, "test.log") diff --git a/tests/testthat/test_parallel.R b/tests/testthat/test_parallel.R index 05ddc114..e5ac6991 100644 --- a/tests/testthat/test_parallel.R +++ b/tests/testthat/test_parallel.R @@ -4,6 +4,8 @@ for (strategy in c( # "multisession", # "cluster" )){ + skip_if_not_installed("future") + context(sprintf("future plan = '%s'", strategy)) if (!future::availableCores("multicore") > 1L){ From dcfcabd48aa90271b07203a8936c97a0c50e67ee Mon Sep 17 00:00:00 2001 From: hoelk-yesod Date: Sun, 13 Jul 2025 09:25:59 +0000 Subject: [PATCH 5/7] typo --- NEWS.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/NEWS.md b/NEWS.md index 67edb247..091f3a9e 100644 --- a/NEWS.md +++ b/NEWS.md @@ -8,7 +8,7 @@ string interpolation (e.g. that still contains the placeholders from `sprintf()` or `glue()`) (#60) -* updated Readnme +* updated Readme # lgr 0.4.4 From cadc0f56f7f10a4f335d91b055270a543541a67d Mon Sep 17 00:00:00 2001 From: hoelk-yesod Date: Sun, 13 Jul 2025 09:51:33 +0000 Subject: [PATCH 6/7] treat rawMsg like all other properties --- R/LogEvent.R | 12 ++++++------ R/Logger.R | 8 ++++---- tests/testthat/test_Logger.R | 8 ++++---- 3 files changed, 14 insertions(+), 14 deletions(-) diff --git a/R/LogEvent.R b/R/LogEvent.R index d91c9880..069c7a00 100644 --- a/R/LogEvent.R +++ b/R/LogEvent.R @@ -53,7 +53,7 @@ LogEvent <- R6::R6Class( timestamp = Sys.time(), caller = NA, msg = NA, - .rawMsg = msg, + rawMsg = msg, ... ){ assert(inherits(logger, "Logger"), "Logger must be a object, not a ", class_fmt(logger)) @@ -65,7 +65,7 @@ LogEvent <- R6::R6Class( assign("timestamp", timestamp, self) assign("caller", caller, self) assign("msg", msg, self) - assign(".rawMsg", .rawMsg, self) + assign("rawMsg", rawMsg, self) # custom values if (!missing(...)){ @@ -98,20 +98,20 @@ LogEvent <- R6::R6Class( #' event (equivalent to `get_logger(event$logger)`). .logger = NULL, - #' @field .rawMsg `character`. The raw log message without string + #' @field rawMsg `character`. The raw log message without string #' interpolation. - .rawMsg = NULL + rawMsg = NULL ), active = list( #' @field values `list`. All values stored in the `LogEvent`, including - #' all *custom fields*, but not including `event$.logger` and `event$.rawMsg`. + #' all *custom fields*, but not including `event$.logger`. values = function(){ fixed_vals <- c("level", "timestamp", "logger", "caller", "msg") custom_vals <- setdiff( names(get(".__enclos_env__", self)[["self"]]), - c(".__enclos_env__", "level_name", "initialize", "clone", "values", ".rawMsg", + c(".__enclos_env__", "level_name", "initialize", "clone", "values", "rawMsg", ".logger") ) valnames <- union(fixed_vals, custom_vals) # to enforce order of fixed_vals diff --git a/R/Logger.R b/R/Logger.R index 89fde96f..a4f1384e 100644 --- a/R/Logger.R +++ b/R/Logger.R @@ -235,7 +235,7 @@ Logger <- R6::R6Class( timestamp = timestamp, caller = caller, msg = msg, - .rawMsg = rawMsg + rawMsg = rawMsg ) } else { dots <- list(...) @@ -248,7 +248,7 @@ Logger <- R6::R6Class( timestamp = timestamp, caller = caller, msg = msg, - .rawMsg = rawMsg + rawMsg = rawMsg ) } else { not_named <- vapply(names(dots), is_blank, TRUE, USE.NAMES = FALSE) @@ -263,7 +263,7 @@ Logger <- R6::R6Class( timestamp = timestamp, caller = caller, msg = msg, - .rawMsg = rawMsg + rawMsg = rawMsg ), dots[!not_named] ) @@ -941,7 +941,7 @@ LoggerGlue <- R6::R6Class( timestamp = timestamp, caller = caller, msg = msg, - .rawMsg = rawMsg + rawMsg = rawMsg ), dots[custom_fields] ) diff --git a/tests/testthat/test_Logger.R b/tests/testthat/test_Logger.R index 477c7e28..1f5739cf 100644 --- a/tests/testthat/test_Logger.R +++ b/tests/testthat/test_Logger.R @@ -487,7 +487,7 @@ test_that("LoggerGlue$log - with 'msg' argument - throws a warning", { }) -test_that("Logger$log - with string interpolation - adds .rawMsg to event", { +test_that("Logger$log - with string interpolation - adds rawMsg to event", { l <- get_logger("test")$set_propagate(FALSE) on.exit({ @@ -497,11 +497,11 @@ test_that("Logger$log - with string interpolation - adds .rawMsg to event", { l$info("foo %s", "bar") expect_identical(l$last_event$msg, "foo bar") - expect_identical(l$last_event$.rawMsg, "foo %s") + expect_identical(l$last_event$rawMsg, "foo %s") }) -test_that("LoggerGlue$log - with string interpolation - adds .rawMsg to event", { +test_that("LoggerGlue$log - with string interpolation - adds rawMsg to event", { l <- get_logger_glue("testglue")$set_propagate(FALSE) on.exit({ @@ -511,6 +511,6 @@ test_that("LoggerGlue$log - with string interpolation - adds .rawMsg to event", l$fatal("hash {x}", x = "baz") expect_identical(as.character(l$last_event$msg), "hash baz") - expect_identical(l$last_event$.rawMsg, "hash {x}") + expect_identical(l$last_event$rawMsg, "hash {x}") }) From 0f237276523efaf93226e1cbec6ab4bb3351be44 Mon Sep 17 00:00:00 2001 From: hoelk-yesod Date: Sun, 13 Jul 2025 10:15:50 +0000 Subject: [PATCH 7/7] Various small updates to rawMsg handling --- NEWS.md | 5 +++-- R/LogEvent.R | 11 ++++++----- R/basic_config.R | 21 ++++++++++++--------- tests/testthat/test_Appender.R | 25 +++++++++++++------------ tests/testthat/test_read_json_log.R | 2 +- 5 files changed, 35 insertions(+), 29 deletions(-) diff --git a/NEWS.md b/NEWS.md index 091f3a9e..0465b507 100644 --- a/NEWS.md +++ b/NEWS.md @@ -4,9 +4,10 @@ `{knitr}` rendering process, log messages are now output to `stderr` instead of `stdout` by default, to avoid polluting markdown documents (#62, thx @gadenbuie). -* added hidden `.rawMsg` property to LogEvents to store message without +* BREAKING: added `rawMsg` property to LogEvents to store message without string interpolation (e.g. that still contains the placeholders from - `sprintf()` or `glue()`) (#60) + `sprintf()` or `glue()`). rawMessage will be added by default to json + log files (#60) * updated Readme diff --git a/R/LogEvent.R b/R/LogEvent.R index 069c7a00..e97bd7f3 100644 --- a/R/LogEvent.R +++ b/R/LogEvent.R @@ -108,11 +108,10 @@ LogEvent <- R6::R6Class( #' @field values `list`. All values stored in the `LogEvent`, including #' all *custom fields*, but not including `event$.logger`. values = function(){ - fixed_vals <- c("level", "timestamp", "logger", "caller", "msg") + fixed_vals <- c("level", "timestamp", "logger", "caller", "msg", "rawMsg") custom_vals <- setdiff( names(get(".__enclos_env__", self)[["self"]]), - c(".__enclos_env__", "level_name", "initialize", "clone", "values", "rawMsg", - ".logger") + c(".__enclos_env__", "level_name", "initialize", "clone", "values", ".logger") ) valnames <- union(fixed_vals, custom_vals) # to enforce order of fixed_vals mget(valnames, envir = self) @@ -335,6 +334,7 @@ as_tibble.LogEvent <- function( #' multiple threads.} #' \item{`%c`}{the calling function} #' \item{`%m`}{the log message} +#' \item{`%r`}{the raw log message (without string interpolation) #' \item{`%f`}{all custom fields of `x` in a pseudo-JSON like format that is #' optimized for human readability and console output} #' \item{`%j`}{all custom fields of `x` in proper JSON. This requires that you @@ -433,7 +433,7 @@ format.LogEvent <- function( fmt, valid_tokens = paste0( "%", - c("t", "p", "c", "m", "l", "L", "n", "f", "j", "k", "K", "g")) + c("t", "p", "c", "m", "r", "l", "L", "n", "f", "j", "k", "K", "g")) ) # format @@ -450,6 +450,7 @@ format.LogEvent <- function( "%K" = colorize_levels(lvls, colors, transform = function(.) toupper(strtrim(., 1))), "%t" = format(get("timestamp", envir = x), format = timestamp_fmt), "%m" = get("msg", envir = x), + "%r" = get("rawMsg", envir = x), "%c" = get("caller", envir = x), "%g" = get("logger", envir = x), "%p" = Sys.getpid(), @@ -597,4 +598,4 @@ tokenize_format <- function( # globals -------------------------------------------------------- -DEFAULT_FIELDS <- c("level", "timestamp", "logger", "caller", "msg") +DEFAULT_FIELDS <- c("level", "timestamp", "logger", "caller", "msg", "rawMsg") diff --git a/R/basic_config.R b/R/basic_config.R index d3421deb..2e190b62 100644 --- a/R/basic_config.R +++ b/R/basic_config.R @@ -97,17 +97,20 @@ basic_config <- function( if (!is.null(file)){ ext <- tools::file_ext(file) - if (identical(tolower(ext), "json")){ - stop( - "Please use `.jsonl` and not `.json` as file extension for JSON log", - "files. The reason is that that JSON files created", - "by lgr are not true JSON files but JSONlines files.", - "See https://jsonlines.org/ for more infos." - ) + if (tolower(ext) %in% c("jsonl", "json")){ + + if (identical(tolower(ext), "json")){ + warning( + "Please use `.jsonl` and not `.json` as file extension for JSON log ", + "files. The reason is that that JSON files created ", + "by lgr are not true JSON files but JSONlines files. ", + "See https://jsonlines.org/ for more infos." + ) + } - } else if (identical(tolower(ext), "jsonl")){ - if (!is.null(fmt) && !identical(fmt, default_fmt)) + if (!is.null(fmt) && !identical(fmt, default_fmt)){ warning("`fmt` is ignored if `file` is a '.jsonl' file") + } l$add_appender( name = "file", diff --git a/tests/testthat/test_Appender.R b/tests/testthat/test_Appender.R index 664d0738..98564375 100644 --- a/tests/testthat/test_Appender.R +++ b/tests/testthat/test_Appender.R @@ -6,7 +6,8 @@ event <- LogEvent$new( level = 200L, timestamp = structure(1541175573.9308, class = c("POSIXct", "POSIXt")), caller = NA_character_, - msg = "foo bar" + msg = "foo bar", + rawMsg = "foo raw" ) @@ -19,8 +20,6 @@ test_that("Appender: $append() works", { }) - - test_that("Appender: $set_threshold() works", { app <- Appender$new() @@ -50,7 +49,6 @@ test_that("AppenderFile: logging with LayoutFormat", { }) - test_that("AppenderFile: logging with LayoutJson", { tf <- tempfile() on.exit(unlink(tf)) @@ -68,7 +66,6 @@ test_that("AppenderFile: logging with LayoutJson", { }) - test_that("AppenderFile: creates empty log file on init", { tf <- tempfile() on.exit(unlink(tf)) @@ -82,7 +79,6 @@ test_that("AppenderFile: creates empty log file on init", { }) - test_that("AppenderFile: $show() works", { tf <- tempfile() on.exit(unlink(tf)) @@ -117,7 +113,6 @@ test_that("AppenderFile: $show() works", { }) - test_that("AppenderFile$data throws an error", { tf <- tempfile() on.exit(unlink(tf)) @@ -136,9 +131,6 @@ test_that("AppenderFile$data throws an error", { }) - - - test_that("AppenderFile: creates empty log file on init", { tf <- tempfile() on.exit(unlink(tf)) @@ -192,8 +184,6 @@ test_that("AppenderConsole: $append() works", { }) - - test_that("AppenderConsole: $filter() works", { app1 <- AppenderConsole$new() expect_true(app1$filter(event)) @@ -240,6 +230,17 @@ test_that("AppenderConsole: chooses stderr by default when in knitr", { }) +test_that("AppenderConsole: rawMessage visible when set in layout", { + + lo <- LayoutFormat$new("%m -- %r") + app <- AppenderConsole$new(layout = lo) + + expect_match( + capture.output(app$append(event)), + "foo bar -- foo raw") +}) + + # AppenderBuffer ---------------------------------------------------- # Tests must be executed in sequence # setup diff --git a/tests/testthat/test_read_json_log.R b/tests/testthat/test_read_json_log.R index 8d52e3ae..7147f1b0 100644 --- a/tests/testthat/test_read_json_log.R +++ b/tests/testthat/test_read_json_log.R @@ -20,7 +20,7 @@ test_that("read_json_lines() works as expected", { tres <- read_json_lines(tf) - expect_identical(names(tres), c("level", "timestamp", "logger", "caller", "msg")) + expect_identical(names(tres), c("level", "timestamp", "logger", "caller", "msg", "rawMsg")) expect_true(all(tres$level == seq(100, 600, by = 100))) file.remove(tf) })