Various small updates to rawMsg handling

Author: s-fleck

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
 

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")

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",

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

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)
 })