add hidden .rawMsg property to LogEvent for storing msg without string interpolation

Author: s-fleck

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

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 <Logger> 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

R/Logger.R

@@ -226,14 +226,16 @@ Logger <- R6::R6Class(
         }
 
         force(caller)
+        rawMsg <- msg
 
         if (missing(...)){
           vals <- list(
             logger = self,
             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

man/LogEvent.Rd

@@ -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}")
+})
+