diff --git a/NEWS.md b/NEWS.md index e773e311..1457af56 100644 --- a/NEWS.md +++ b/NEWS.md @@ -5,7 +5,8 @@ * `log_errors()` gains a `traceback` argument that toggles whether the error traceback should be logged along with the message (fix #86 via #223, @thomasp85) * File and line location of the log call is now available to the layouts (fix #110 via #224, @thomasp85) * New `formatter_cli()` allows you to use the syntax from the cli package to create log messages (fix #210 via #225, @thomasp85) -* New `log_chunk_time()` helper function to automatically log the execution time of knitr code chunks (fix #222 via ##227, @thomasp85) +* New `log_chunk_time()` helper function to automatically log the execution time of knitr code chunks (fix #222 via #227, @thomasp85) +* Allow user to overwrite the timestamp during logging if needed (fix #230, @thomasp85) # logger 0.4.0 (2024-10-19) diff --git a/R/helpers.R b/R/helpers.R index 226a76a7..e2793503 100644 --- a/R/helpers.R +++ b/R/helpers.R @@ -102,7 +102,8 @@ log_separator <- function(level = INFO, width = 80, .logcall = sys.call(), .topcall = sys.call(-1), - .topenv = parent.frame()) { + .topenv = parent.frame(), + .timestamp = Sys.time()) { stopifnot(length(separator) == 1, nchar(separator) == 1) base_info_chars <- nchar(catch_base_log(level, namespace, .topcall = .topcall, .topenv = .topenv)) @@ -113,7 +114,8 @@ log_separator <- function(level = INFO, namespace = namespace, .logcall = .logcall, .topcall = .topcall, - .topenv = .topenv + .topenv = .topenv, + .timestamp = .timestamp ) } diff --git a/R/layouts.R b/R/layouts.R index 7799560d..3356a329 100644 --- a/R/layouts.R +++ b/R/layouts.R @@ -37,9 +37,9 @@ get_logger_meta_variables <- function(log_level = NULL, namespace = NA_character_, .logcall = sys.call(), .topcall = sys.call(-1), - .topenv = parent.frame()) { + .topenv = parent.frame(), + .timestamp = Sys.time()) { sysinfo <- Sys.info() - timestamp <- Sys.time() list( ns = namespace, @@ -48,7 +48,7 @@ get_logger_meta_variables <- function(log_level = NULL, fn = deparse_to_one_line(.topcall[[1]]), call = deparse_to_one_line(.topcall), location = log_call_location(.logcall), - time = timestamp, + time = .timestamp, levelr = log_level, level = attr(log_level, "level"), pid = Sys.getpid(), @@ -104,7 +104,8 @@ layout_glue_generator <- function(format = '{level} [{format(time, "%Y-%m-%d %H: namespace = NA_character_, .logcall = sys.call(), .topcall = sys.call(-1), - .topenv = parent.frame()) { + .topenv = parent.frame(), + .timestamp = Sys.time()) { fail_on_missing_package("glue") if (!inherits(level, "loglevel")) { stop("Invalid log level, see ?log_levels") @@ -116,6 +117,7 @@ layout_glue_generator <- function(format = '{level} [{format(time, "%Y-%m-%d %H: .logcall = .logcall, .topcall = .topcall, .topenv = .topenv, + .timestamp = .timestamp, parent = environment() ) glue::glue(format, .envir = meta) @@ -135,7 +137,8 @@ layout_blank <- function(level, namespace = NA_character_, .logcall = sys.call(), .topcall = sys.call(-1), - .topenv = parent.frame()) { + .topenv = parent.frame(), + .timestamp = Sys.time()) { msg } attr(layout_blank, "generator") <- quote(layout_blank()) @@ -152,8 +155,9 @@ layout_simple <- function(level, namespace = NA_character_, .logcall = sys.call(), .topcall = sys.call(-1), - .topenv = parent.frame()) { - paste0(attr(level, "level"), " [", format(Sys.time(), "%Y-%m-%d %H:%M:%S"), "] ", msg) + .topenv = parent.frame(), + .timestamp = Sys.time()) { + paste0(attr(level, "level"), " [", format(.timestamp, "%Y-%m-%d %H:%M:%S"), "] ", msg) } attr(layout_simple, "generator") <- quote(layout_simple()) @@ -179,16 +183,18 @@ layout_logging <- function(level, namespace = NA_character_, .logcall = sys.call(), .topcall = sys.call(-1), - .topenv = parent.frame()) { + .topenv = parent.frame(), + .timestamp = Sys.time()) { meta <- logger_meta_env( log_level = level, namespace = namespace, .logcall = .logcall, .topcall = .topcall, - .topenv = .topenv + .topenv = .topenv, + .timestamp = .timestamp ) paste0( - format(Sys.time(), "%Y-%m-%d %H:%M:%S"), " ", + format(meta$time, "%Y-%m-%d %H:%M:%S"), " ", attr(level, "level"), ":", ifelse(meta$ns == "global", "", meta$ns), ":", msg @@ -267,7 +273,8 @@ layout_json <- function(fields = default_fields()) { namespace = NA_character_, .logcall = sys.call(), .topcall = sys.call(-1), - .topenv = parent.frame()) { + .topenv = parent.frame(), + .timestamp = Sys.time()) { fail_on_missing_package("jsonlite") meta <- logger_meta_env( @@ -275,7 +282,8 @@ layout_json <- function(fields = default_fields()) { namespace = namespace, .logcall = .logcall, .topcall = .topcall, - .topenv = .topenv + .topenv = .topenv, + .timestamp = .timestamp ) json <- mget(fields, meta) sapply(msg, function(msg) jsonlite::toJSON(c(json, list(msg = msg)), auto_unbox = TRUE)) @@ -317,7 +325,8 @@ layout_json_parser <- function(fields = default_fields()) { namespace = NA_character_, .logcall = sys.call(), .topcall = sys.call(-1), - .topenv = parent.frame()) { + .topenv = parent.frame(), + .timestamp = Sys.time()) { fail_on_missing_package("jsonlite") meta <- logger_meta_env( @@ -325,7 +334,8 @@ layout_json_parser <- function(fields = default_fields()) { namespace = namespace, .logcall = .logcall, .topcall = .topcall, - .topenv = .topenv + .topenv = .topenv, + .timestamp = .timestamp ) meta <- mget(fields, meta) field_names <- names(fields) @@ -363,7 +373,8 @@ layout_syslognet <- structure( namespace = NA_character_, .logcall = sys.call(), .topcall = sys.call(-1), - .topenv = parent.frame()) { + .topenv = parent.frame(), + .timestamp = Sys.time()) { ret <- paste(attr(level, "level"), msg) attr(ret, "severity") <- switch( attr(level, "level", exact = TRUE), diff --git a/R/logger-meta.R b/R/logger-meta.R index b34aacf1..1e26e0dc 100644 --- a/R/logger-meta.R +++ b/R/logger-meta.R @@ -3,9 +3,8 @@ logger_meta_env <- function(log_level = NULL, .logcall = sys.call(), .topcall = sys.call(-1), .topenv = parent.frame(), + .timestamp = Sys.time(), parent = emptyenv()) { - timestamp <- Sys.time() - env <- new.env(parent = parent) env$ns <- namespace env$ans <- fallback_namespace(namespace) @@ -17,7 +16,7 @@ logger_meta_env <- function(log_level = NULL, delayedAssign("topenv", top_env_name(.topenv), assign.env = env) delayedAssign("location", log_call_location(.logcall), assign.env = env) - env$time <- timestamp + env$time <- .timestamp env$levelr <- log_level env$level <- attr(log_level, "level") diff --git a/R/logger.R b/R/logger.R index c76de447..88179a37 100644 --- a/R/logger.R +++ b/R/logger.R @@ -51,7 +51,8 @@ logger <- function(threshold, formatter, layout, appender) { force(appender) function(level, ..., namespace = NA_character_, - .logcall = sys.call(), .topcall = sys.call(-1), .topenv = parent.frame()) { + .logcall = sys.call(), .topcall = sys.call(-1), + .topenv = parent.frame(), .timestamp = Sys.time()) { res <- list( level = level, namespace = namespace, @@ -83,7 +84,10 @@ logger <- function(threshold, formatter, layout, appender) { res$record <- layout( level, res$message, namespace = namespace, - .logcall = substitute(.logcall), .topcall = substitute(.topcall), .topenv = .topenv + .logcall = substitute(.logcall), + .topcall = substitute(.topcall), + .topenv = .topenv, + .timestamp = .timestamp ) appender(res$record) @@ -307,6 +311,8 @@ log_indices <- function(namespace = "global") { #' @param .topenv original frame of the `.topcall` calling function #' where the formatter function will be evaluated and that is used #' to look up the `namespace` as well via `logger:::top_env_name` +#' @param .timestamp The time the logging occured. Defaults to the current time +#' but may be overwritten if the logging is delayed from the time it happend #' @export #' @examples #' \dontshow{old <- logger:::namespaces_set()} @@ -329,7 +335,8 @@ log_indices <- function(namespace = "global") { #' \dontshow{logger:::namespaces_set(old)} #' @return Invisible `list` of `logger` objects. See [logger()] for more details on the format. log_level <- function(level, ..., namespace = NA_character_, - .logcall = sys.call(), .topcall = sys.call(-1), .topenv = parent.frame()) { + .logcall = sys.call(), .topcall = sys.call(-1), + .topenv = parent.frame(), .timestamp = Sys.time()) { ## guess namespace if (is.na(namespace)) { topenv <- top_env_name(.topenv) @@ -354,6 +361,7 @@ log_level <- function(level, ..., namespace = NA_character_, NA } log_arg$.topenv <- .topenv + log_arg$.timestamp <- .timestamp log_arg$namespace <- namespace invisible(lapply(definitions, function(definition) { @@ -385,44 +393,58 @@ validate_log_level <- function(level) { #' @export #' @rdname log_level log_fatal <- function(..., namespace = NA_character_, - .logcall = sys.call(), .topcall = sys.call(-1), .topenv = parent.frame()) { - log_level(FATAL, ..., namespace = namespace, .logcall = .logcall, .topcall = .topcall, .topenv = .topenv) + .logcall = sys.call(), .topcall = sys.call(-1), + .topenv = parent.frame(), .timestamp = Sys.time()) { + log_level(FATAL, ..., namespace = namespace, .logcall = .logcall, + .topcall = .topcall, .topenv = .topenv, .timestamp = .timestamp) } #' @export #' @rdname log_level log_error <- function(..., namespace = NA_character_, - .logcall = sys.call(), .topcall = sys.call(-1), .topenv = parent.frame()) { - log_level(ERROR, ..., namespace = namespace, .logcall = .logcall, .topcall = .topcall, .topenv = .topenv) + .logcall = sys.call(), .topcall = sys.call(-1), + .topenv = parent.frame(), .timestamp = Sys.time()) { + log_level(ERROR, ..., namespace = namespace, .logcall = .logcall, + .topcall = .topcall, .topenv = .topenv, .timestamp = .timestamp) } #' @export #' @rdname log_level log_warn <- function(..., namespace = NA_character_, - .logcall = sys.call(), .topcall = sys.call(-1), .topenv = parent.frame()) { - log_level(WARN, ..., namespace = namespace, .logcall = .logcall, .topcall = .topcall, .topenv = .topenv) + .logcall = sys.call(), .topcall = sys.call(-1), + .topenv = parent.frame(), .timestamp = Sys.time()) { + log_level(WARN, ..., namespace = namespace, .logcall = .logcall, + .topcall = .topcall, .topenv = .topenv, .timestamp = .timestamp) } #' @export #' @rdname log_level log_success <- function(..., namespace = NA_character_, - .logcall = sys.call(), .topcall = sys.call(-1), .topenv = parent.frame()) { - log_level(SUCCESS, ..., namespace = namespace, .logcall = .logcall, .topcall = .topcall, .topenv = .topenv) + .logcall = sys.call(), .topcall = sys.call(-1), + .topenv = parent.frame(), .timestamp = Sys.time()) { + log_level(SUCCESS, ..., namespace = namespace, .logcall = .logcall, + .topcall = .topcall, .topenv = .topenv, .timestamp = .timestamp) } #' @export #' @rdname log_level log_info <- function(..., namespace = NA_character_, - .logcall = sys.call(), .topcall = sys.call(-1), .topenv = parent.frame()) { - log_level(INFO, ..., namespace = namespace, .logcall = .logcall, .topcall = .topcall, .topenv = .topenv) + .logcall = sys.call(), .topcall = sys.call(-1), + .topenv = parent.frame(), .timestamp = Sys.time()) { + log_level(INFO, ..., namespace = namespace, .logcall = .logcall, + .topcall = .topcall, .topenv = .topenv, .timestamp = .timestamp) } #' @export #' @rdname log_level log_debug <- function(..., namespace = NA_character_, - .logcall = sys.call(), .topcall = sys.call(-1), .topenv = parent.frame()) { - log_level(DEBUG, ..., namespace = namespace, .logcall = .logcall, .topcall = .topcall, .topenv = .topenv) + .logcall = sys.call(), .topcall = sys.call(-1), + .topenv = parent.frame(), .timestamp = Sys.time()) { + log_level(DEBUG, ..., namespace = namespace, .logcall = .logcall, + .topcall = .topcall, .topenv = .topenv, .timestamp = .timestamp) } #' @export #' @rdname log_level log_trace <- function(..., namespace = NA_character_, - .logcall = sys.call(), .topcall = sys.call(-1), .topenv = parent.frame()) { - log_level(TRACE, ..., namespace = namespace, .logcall = .logcall, .topcall = .topcall, .topenv = .topenv) + .logcall = sys.call(), .topcall = sys.call(-1), + .topenv = parent.frame(), .timestamp = Sys.time()) { + log_level(TRACE, ..., namespace = namespace, .logcall = .logcall, + .topcall = .topcall, .topenv = .topenv, .timestamp = .timestamp) } diff --git a/man/get_logger_meta_variables.Rd b/man/get_logger_meta_variables.Rd index 8819cfaf..07224d70 100644 --- a/man/get_logger_meta_variables.Rd +++ b/man/get_logger_meta_variables.Rd @@ -9,7 +9,8 @@ get_logger_meta_variables( namespace = NA_character_, .logcall = sys.call(), .topcall = sys.call(-1), - .topenv = parent.frame() + .topenv = parent.frame(), + .timestamp = Sys.time() ) } \arguments{ @@ -32,6 +33,9 @@ function's name or arguments)} \item{.topenv}{original frame of the \code{.topcall} calling function where the formatter function will be evaluated and that is used to look up the \code{namespace} as well via \code{logger:::top_env_name}} + +\item{.timestamp}{The time the logging occured. Defaults to the current time +but may be overwritten if the logging is delayed from the time it happend} } \value{ list diff --git a/man/layout_blank.Rd b/man/layout_blank.Rd index ca9fd996..d9250b83 100644 --- a/man/layout_blank.Rd +++ b/man/layout_blank.Rd @@ -11,7 +11,8 @@ layout_blank( namespace = NA_character_, .logcall = sys.call(), .topcall = sys.call(-1), - .topenv = parent.frame() + .topenv = parent.frame(), + .timestamp = Sys.time() ) } \arguments{ @@ -36,6 +37,9 @@ function's name or arguments)} \item{.topenv}{original frame of the \code{.topcall} calling function where the formatter function will be evaluated and that is used to look up the \code{namespace} as well via \code{logger:::top_env_name}} + +\item{.timestamp}{The time the logging occured. Defaults to the current time +but may be overwritten if the logging is delayed from the time it happend} } \value{ character vector diff --git a/man/layout_glue.Rd b/man/layout_glue.Rd index addbfa12..e9a0ddf8 100644 --- a/man/layout_glue.Rd +++ b/man/layout_glue.Rd @@ -10,7 +10,8 @@ layout_glue( namespace = NA_character_, .logcall = sys.call(), .topcall = sys.call(-1), - .topenv = parent.frame() + .topenv = parent.frame(), + .timestamp = Sys.time() ) } \arguments{ @@ -35,6 +36,9 @@ function's name or arguments)} \item{.topenv}{original frame of the \code{.topcall} calling function where the formatter function will be evaluated and that is used to look up the \code{namespace} as well via \code{logger:::top_env_name}} + +\item{.timestamp}{The time the logging occured. Defaults to the current time +but may be overwritten if the logging is delayed from the time it happend} } \value{ character vector diff --git a/man/layout_glue_colors.Rd b/man/layout_glue_colors.Rd index 4fb4f18e..cdaaa4be 100644 --- a/man/layout_glue_colors.Rd +++ b/man/layout_glue_colors.Rd @@ -10,7 +10,8 @@ layout_glue_colors( namespace = NA_character_, .logcall = sys.call(), .topcall = sys.call(-1), - .topenv = parent.frame() + .topenv = parent.frame(), + .timestamp = Sys.time() ) } \arguments{ @@ -35,6 +36,9 @@ function's name or arguments)} \item{.topenv}{original frame of the \code{.topcall} calling function where the formatter function will be evaluated and that is used to look up the \code{namespace} as well via \code{logger:::top_env_name}} + +\item{.timestamp}{The time the logging occured. Defaults to the current time +but may be overwritten if the logging is delayed from the time it happend} } \value{ character vector diff --git a/man/layout_logging.Rd b/man/layout_logging.Rd index 0790077f..d6da9f6b 100644 --- a/man/layout_logging.Rd +++ b/man/layout_logging.Rd @@ -10,7 +10,8 @@ layout_logging( namespace = NA_character_, .logcall = sys.call(), .topcall = sys.call(-1), - .topenv = parent.frame() + .topenv = parent.frame(), + .timestamp = Sys.time() ) } \arguments{ @@ -35,6 +36,9 @@ function's name or arguments)} \item{.topenv}{original frame of the \code{.topcall} calling function where the formatter function will be evaluated and that is used to look up the \code{namespace} as well via \code{logger:::top_env_name}} + +\item{.timestamp}{The time the logging occured. Defaults to the current time +but may be overwritten if the logging is delayed from the time it happend} } \value{ character vector diff --git a/man/layout_simple.Rd b/man/layout_simple.Rd index 7df88771..d31ce01d 100644 --- a/man/layout_simple.Rd +++ b/man/layout_simple.Rd @@ -11,7 +11,8 @@ layout_simple( namespace = NA_character_, .logcall = sys.call(), .topcall = sys.call(-1), - .topenv = parent.frame() + .topenv = parent.frame(), + .timestamp = Sys.time() ) } \arguments{ @@ -36,6 +37,9 @@ function's name or arguments)} \item{.topenv}{original frame of the \code{.topcall} calling function where the formatter function will be evaluated and that is used to look up the \code{namespace} as well via \code{logger:::top_env_name}} + +\item{.timestamp}{The time the logging occured. Defaults to the current time +but may be overwritten if the logging is delayed from the time it happend} } \value{ character vector diff --git a/man/layout_syslognet.Rd b/man/layout_syslognet.Rd index a8c940a8..44606fa5 100644 --- a/man/layout_syslognet.Rd +++ b/man/layout_syslognet.Rd @@ -10,7 +10,8 @@ layout_syslognet( namespace = NA_character_, .logcall = sys.call(), .topcall = sys.call(-1), - .topenv = parent.frame() + .topenv = parent.frame(), + .timestamp = Sys.time() ) } \arguments{ @@ -35,6 +36,9 @@ function's name or arguments)} \item{.topenv}{original frame of the \code{.topcall} calling function where the formatter function will be evaluated and that is used to look up the \code{namespace} as well via \code{logger:::top_env_name}} + +\item{.timestamp}{The time the logging occured. Defaults to the current time +but may be overwritten if the logging is delayed from the time it happend} } \value{ A character vector with a severity attribute. diff --git a/man/log_level.Rd b/man/log_level.Rd index 2f557672..3eab425f 100644 --- a/man/log_level.Rd +++ b/man/log_level.Rd @@ -17,7 +17,8 @@ log_level( namespace = NA_character_, .logcall = sys.call(), .topcall = sys.call(-1), - .topenv = parent.frame() + .topenv = parent.frame(), + .timestamp = Sys.time() ) log_fatal( @@ -25,7 +26,8 @@ log_fatal( namespace = NA_character_, .logcall = sys.call(), .topcall = sys.call(-1), - .topenv = parent.frame() + .topenv = parent.frame(), + .timestamp = Sys.time() ) log_error( @@ -33,7 +35,8 @@ log_error( namespace = NA_character_, .logcall = sys.call(), .topcall = sys.call(-1), - .topenv = parent.frame() + .topenv = parent.frame(), + .timestamp = Sys.time() ) log_warn( @@ -41,7 +44,8 @@ log_warn( namespace = NA_character_, .logcall = sys.call(), .topcall = sys.call(-1), - .topenv = parent.frame() + .topenv = parent.frame(), + .timestamp = Sys.time() ) log_success( @@ -49,7 +53,8 @@ log_success( namespace = NA_character_, .logcall = sys.call(), .topcall = sys.call(-1), - .topenv = parent.frame() + .topenv = parent.frame(), + .timestamp = Sys.time() ) log_info( @@ -57,7 +62,8 @@ log_info( namespace = NA_character_, .logcall = sys.call(), .topcall = sys.call(-1), - .topenv = parent.frame() + .topenv = parent.frame(), + .timestamp = Sys.time() ) log_debug( @@ -65,7 +71,8 @@ log_debug( namespace = NA_character_, .logcall = sys.call(), .topcall = sys.call(-1), - .topenv = parent.frame() + .topenv = parent.frame(), + .timestamp = Sys.time() ) log_trace( @@ -73,7 +80,8 @@ log_trace( namespace = NA_character_, .logcall = sys.call(), .topcall = sys.call(-1), - .topenv = parent.frame() + .topenv = parent.frame(), + .timestamp = Sys.time() ) } \arguments{ @@ -99,6 +107,9 @@ function's name or arguments)} \item{.topenv}{original frame of the \code{.topcall} calling function where the formatter function will be evaluated and that is used to look up the \code{namespace} as well via \code{logger:::top_env_name}} + +\item{.timestamp}{The time the logging occured. Defaults to the current time +but may be overwritten if the logging is delayed from the time it happend} } \value{ Invisible \code{list} of \code{logger} objects. See \code{\link[=logger]{logger()}} for more details on the format. diff --git a/man/log_separator.Rd b/man/log_separator.Rd index ff174c65..36c080d4 100644 --- a/man/log_separator.Rd +++ b/man/log_separator.Rd @@ -11,7 +11,8 @@ log_separator( width = 80, .logcall = sys.call(), .topcall = sys.call(-1), - .topenv = parent.frame() + .topenv = parent.frame(), + .timestamp = Sys.time() ) } \arguments{ @@ -38,6 +39,9 @@ function's name or arguments)} \item{.topenv}{original frame of the \code{.topcall} calling function where the formatter function will be evaluated and that is used to look up the \code{namespace} as well via \code{logger:::top_env_name}} + +\item{.timestamp}{The time the logging occured. Defaults to the current time +but may be overwritten if the logging is delayed from the time it happend} } \description{ Logs a long line to stand out from the console diff --git a/tests/testthat/test-layouts.R b/tests/testthat/test-layouts.R index e8d6e1d0..633ebf40 100644 --- a/tests/testthat/test-layouts.R +++ b/tests/testthat/test-layouts.R @@ -20,6 +20,10 @@ test_that("metavars", { f_warn <- function() log_warn() expect_output(f_warn(), "WARN global f_warn()") + + local_test_logger(layout = layout_glue_generator("{time}")) + time <- as.POSIXct("2025-04-04 10:31:57 CEST") + expect_output(log_info("test", .timestamp = time), "2025-04-04 10:31:57") }) test_that("JSON layout", {