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 diff --git a/NEWS.md b/NEWS.md index 3ae441be..0465b507 100644 --- a/NEWS.md +++ b/NEWS.md @@ -4,6 +4,14 @@ `{knitr}` rendering process, log messages are now output to `stderr` instead of `stdout` by default, to avoid polluting markdown documents (#62, thx @gadenbuie). +* BREAKING: added `rawMsg` property to LogEvents to store message without + string interpolation (e.g. that still contains the placeholders from + `sprintf()` or `glue()`). rawMessage will be added by default to json + log files (#60) + +* updated Readme + + # 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..e97bd7f3 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,7 +96,11 @@ 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( @@ -102,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", - ".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) @@ -329,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 @@ -427,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 @@ -444,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(), @@ -591,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/Logger.R b/R/Logger.R index 3ec723d3..a4f1384e 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/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/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/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_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_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_Logger.R b/tests/testthat/test_Logger.R index fbc9dfa3..1f5739cf 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}") +}) + 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){ 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, 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) })