Skip to content

Commit d800d91

Browse files
thomasp85thomasp85
committed
Add .timestamp argument to overwrite log time
1 parent e3de03f commit d800d91

File tree

6 files changed

+63
-38
lines changed

6 files changed

+63
-38
lines changed

‎NEWS.md‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -5,7 +5,8 @@
55
* `log_errors()` gains a `traceback` argument that toggles whether the error traceback should be logged along with the message (fix #86 via #223, @thomasp85)
66
* File and line location of the log call is now available to the layouts (fix #110 via #224, @thomasp85)
77
* New `formatter_cli()` allows you to use the syntax from the cli package to create log messages (fix #210 via #225, @thomasp85)
8-
* New `log_chunk_time()` helper function to automatically log the execution time of knitr code chunks (fix #222 via ##227, @thomasp85)
8+
* New `log_chunk_time()` helper function to automatically log the execution time of knitr code chunks (fix #222 via #227, @thomasp85)
9+
* Allow user to overwrite the timestamp during logging if needed (fix #230, @thomasp85)
910

1011
# logger 0.4.0 (2024-10-19)
1112

‎R/helpers.R‎

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -102,7 +102,8 @@ log_separator <- function(level = INFO,
102102
width = 80,
103103
.logcall = sys.call(),
104104
.topcall = sys.call(-1),
105-
.topenv = parent.frame()) {
105+
.topenv = parent.frame(),
106+
.timestamp = Sys.time()) {
106107
stopifnot(length(separator) == 1, nchar(separator) == 1)
107108

108109
base_info_chars <- nchar(catch_base_log(level, namespace, .topcall = .topcall, .topenv = .topenv))
@@ -113,7 +114,8 @@ log_separator <- function(level = INFO,
113114
namespace = namespace,
114115
.logcall = .logcall,
115116
.topcall = .topcall,
116-
.topenv = .topenv
117+
.topenv = .topenv,
118+
.timestamp = .timestamp
117119
)
118120
}
119121

‎R/layouts.R‎

Lines changed: 26 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -37,9 +37,9 @@ get_logger_meta_variables <- function(log_level = NULL,
3737
namespace = NA_character_,
3838
.logcall = sys.call(),
3939
.topcall = sys.call(-1),
40-
.topenv = parent.frame()) {
40+
.topenv = parent.frame(),
41+
.timestamp = Sys.time()) {
4142
sysinfo <- Sys.info()
42-
timestamp <- Sys.time()
4343

4444
list(
4545
ns = namespace,
@@ -48,7 +48,7 @@ get_logger_meta_variables <- function(log_level = NULL,
4848
fn = deparse_to_one_line(.topcall[[1]]),
4949
call = deparse_to_one_line(.topcall),
5050
location = log_call_location(.logcall),
51-
time = timestamp,
51+
time = .timestamp,
5252
levelr = log_level,
5353
level = attr(log_level, "level"),
5454
pid = Sys.getpid(),
@@ -104,7 +104,8 @@ layout_glue_generator <- function(format = '{level} [{format(time, "%Y-%m-%d %H:
104104
namespace = NA_character_,
105105
.logcall = sys.call(),
106106
.topcall = sys.call(-1),
107-
.topenv = parent.frame()) {
107+
.topenv = parent.frame(),
108+
.timestamp = Sys.time()) {
108109
fail_on_missing_package("glue")
109110
if (!inherits(level, "loglevel")) {
110111
stop("Invalid log level, see ?log_levels")
@@ -116,6 +117,7 @@ layout_glue_generator <- function(format = '{level} [{format(time, "%Y-%m-%d %H:
116117
.logcall = .logcall,
117118
.topcall = .topcall,
118119
.topenv = .topenv,
120+
.timestamp = .timestamp,
119121
parent = environment()
120122
)
121123
glue::glue(format, .envir = meta)
@@ -135,7 +137,8 @@ layout_blank <- function(level,
135137
namespace = NA_character_,
136138
.logcall = sys.call(),
137139
.topcall = sys.call(-1),
138-
.topenv = parent.frame()) {
140+
.topenv = parent.frame(),
141+
.timestamp = Sys.time()) {
139142
msg
140143
}
141144
attr(layout_blank, "generator") <- quote(layout_blank())
@@ -152,8 +155,9 @@ layout_simple <- function(level,
152155
namespace = NA_character_,
153156
.logcall = sys.call(),
154157
.topcall = sys.call(-1),
155-
.topenv = parent.frame()) {
156-
paste0(attr(level, "level"), " [", format(Sys.time(), "%Y-%m-%d %H:%M:%S"), "] ", msg)
158+
.topenv = parent.frame(),
159+
.timestamp = Sys.time()) {
160+
paste0(attr(level, "level"), " [", format(.timestamp, "%Y-%m-%d %H:%M:%S"), "] ", msg)
157161
}
158162
attr(layout_simple, "generator") <- quote(layout_simple())
159163

@@ -179,16 +183,18 @@ layout_logging <- function(level,
179183
namespace = NA_character_,
180184
.logcall = sys.call(),
181185
.topcall = sys.call(-1),
182-
.topenv = parent.frame()) {
186+
.topenv = parent.frame(),
187+
.timestamp = Sys.time()) {
183188
meta <- logger_meta_env(
184189
log_level = level,
185190
namespace = namespace,
186191
.logcall = .logcall,
187192
.topcall = .topcall,
188-
.topenv = .topenv
193+
.topenv = .topenv,
194+
.timestamp = .timestamp
189195
)
190196
paste0(
191-
format(Sys.time(), "%Y-%m-%d %H:%M:%S"), " ",
197+
format(meta$time, "%Y-%m-%d %H:%M:%S"), " ",
192198
attr(level, "level"), ":",
193199
ifelse(meta$ns == "global", "", meta$ns), ":",
194200
msg
@@ -267,15 +273,17 @@ layout_json <- function(fields = default_fields()) {
267273
namespace = NA_character_,
268274
.logcall = sys.call(),
269275
.topcall = sys.call(-1),
270-
.topenv = parent.frame()) {
276+
.topenv = parent.frame(),
277+
.timestamp = Sys.time()) {
271278
fail_on_missing_package("jsonlite")
272279

273280
meta <- logger_meta_env(
274281
log_level = level,
275282
namespace = namespace,
276283
.logcall = .logcall,
277284
.topcall = .topcall,
278-
.topenv = .topenv
285+
.topenv = .topenv,
286+
.timestamp = .timestamp
279287
)
280288
json <- mget(fields, meta)
281289
sapply(msg, function(msg) jsonlite::toJSON(c(json, list(msg = msg)), auto_unbox = TRUE))
@@ -317,15 +325,17 @@ layout_json_parser <- function(fields = default_fields()) {
317325
namespace = NA_character_,
318326
.logcall = sys.call(),
319327
.topcall = sys.call(-1),
320-
.topenv = parent.frame()) {
328+
.topenv = parent.frame(),
329+
.timestamp = Sys.time()) {
321330
fail_on_missing_package("jsonlite")
322331

323332
meta <- logger_meta_env(
324333
log_level = level,
325334
namespace = namespace,
326335
.logcall = .logcall,
327336
.topcall = .topcall,
328-
.topenv = .topenv
337+
.topenv = .topenv,
338+
.timestamp = .timestamp
329339
)
330340
meta <- mget(fields, meta)
331341
field_names <- names(fields)
@@ -363,7 +373,8 @@ layout_syslognet <- structure(
363373
namespace = NA_character_,
364374
.logcall = sys.call(),
365375
.topcall = sys.call(-1),
366-
.topenv = parent.frame()) {
376+
.topenv = parent.frame(),
377+
.timestamp = Sys.time()) {
367378
ret <- paste(attr(level, "level"), msg)
368379
attr(ret, "severity") <- switch(
369380
attr(level, "level", exact = TRUE),

‎R/logger-meta.R‎

Lines changed: 2 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -3,9 +3,8 @@ logger_meta_env <- function(log_level = NULL,
33
.logcall = sys.call(),
44
.topcall = sys.call(-1),
55
.topenv = parent.frame(),
6+
.timestamp = Sys.time(),
67
parent = emptyenv()) {
7-
timestamp <- Sys.time()
8-
98
env <- new.env(parent = parent)
109
env$ns <- namespace
1110
env$ans <- fallback_namespace(namespace)
@@ -17,7 +16,7 @@ logger_meta_env <- function(log_level = NULL,
1716
delayedAssign("topenv", top_env_name(.topenv), assign.env = env)
1817
delayedAssign("location", log_call_location(.logcall), assign.env = env)
1918

20-
env$time <- timestamp
19+
env$time <- .timestamp
2120
env$levelr <- log_level
2221
env$level <- attr(log_level, "level")
2322

‎R/logger.R‎

Lines changed: 25 additions & 17 deletions
Original file line numberDiff line numberDiff line change
@@ -51,7 +51,8 @@ logger <- function(threshold, formatter, layout, appender) {
5151
force(appender)
5252

5353
function(level, ..., namespace = NA_character_,
54-
.logcall = sys.call(), .topcall = sys.call(-1), .topenv = parent.frame()) {
54+
.logcall = sys.call(), .topcall = sys.call(-1),
55+
.topenv = parent.frame(), .timestamp = Sys.time()) {
5556
res <- list(
5657
level = level,
5758
namespace = namespace,
@@ -83,7 +84,10 @@ logger <- function(threshold, formatter, layout, appender) {
8384
res$record <- layout(
8485
level, res$message,
8586
namespace = namespace,
86-
.logcall = substitute(.logcall), .topcall = substitute(.topcall), .topenv = .topenv
87+
.logcall = substitute(.logcall),
88+
.topcall = substitute(.topcall),
89+
.topenv = .topenv,
90+
.timestamp = .timestamp
8791
)
8892

8993
appender(res$record)
@@ -307,6 +311,8 @@ log_indices <- function(namespace = "global") {
307311
#' @param .topenv original frame of the `.topcall` calling function
308312
#' where the formatter function will be evaluated and that is used
309313
#' to look up the `namespace` as well via `logger:::top_env_name`
314+
#' @param .timestamp The time the logging occured. Defaults to the current time
315+
#' but may be overwritten if the logging is delayed from the time it happend
310316
#' @export
311317
#' @examples
312318
#' \dontshow{old <- logger:::namespaces_set()}
@@ -329,7 +335,8 @@ log_indices <- function(namespace = "global") {
329335
#' \dontshow{logger:::namespaces_set(old)}
330336
#' @return Invisible `list` of `logger` objects. See [logger()] for more details on the format.
331337
log_level <- function(level, ..., namespace = NA_character_,
332-
.logcall = sys.call(), .topcall = sys.call(-1), .topenv = parent.frame()) {
338+
.logcall = sys.call(), .topcall = sys.call(-1),
339+
.topenv = parent.frame(), .timestamp = Sys.time()) {
333340
## guess namespace
334341
if (is.na(namespace)) {
335342
topenv <- top_env_name(.topenv)
@@ -354,6 +361,7 @@ log_level <- function(level, ..., namespace = NA_character_,
354361
NA
355362
}
356363
log_arg$.topenv <- .topenv
364+
log_arg$.timestamp <- .timestamp
357365
log_arg$namespace <- namespace
358366

359367
invisible(lapply(definitions, function(definition) {
@@ -385,44 +393,44 @@ validate_log_level <- function(level) {
385393
#' @export
386394
#' @rdname log_level
387395
log_fatal <- function(..., namespace = NA_character_,
388-
.logcall = sys.call(), .topcall = sys.call(-1), .topenv = parent.frame()) {
389-
log_level(FATAL, ..., namespace = namespace, .logcall = .logcall, .topcall = .topcall, .topenv = .topenv)
396+
.logcall = sys.call(), .topcall = sys.call(-1), .topenv = parent.frame(), .timestamp = Sys.time()) {
397+
log_level(FATAL, ..., namespace = namespace, .logcall = .logcall, .topcall = .topcall, .topenv = .topenv, .timestamp = .timestamp)
390398
}
391399
#' @export
392400
#' @rdname log_level
393401
log_error <- function(..., namespace = NA_character_,
394-
.logcall = sys.call(), .topcall = sys.call(-1), .topenv = parent.frame()) {
395-
log_level(ERROR, ..., namespace = namespace, .logcall = .logcall, .topcall = .topcall, .topenv = .topenv)
402+
.logcall = sys.call(), .topcall = sys.call(-1), .topenv = parent.frame(), .timestamp = Sys.time()) {
403+
log_level(ERROR, ..., namespace = namespace, .logcall = .logcall, .topcall = .topcall, .topenv = .topenv, .timestamp = .timestamp)
396404
}
397405
#' @export
398406
#' @rdname log_level
399407
log_warn <- function(..., namespace = NA_character_,
400-
.logcall = sys.call(), .topcall = sys.call(-1), .topenv = parent.frame()) {
401-
log_level(WARN, ..., namespace = namespace, .logcall = .logcall, .topcall = .topcall, .topenv = .topenv)
408+
.logcall = sys.call(), .topcall = sys.call(-1), .topenv = parent.frame(), .timestamp = Sys.time()) {
409+
log_level(WARN, ..., namespace = namespace, .logcall = .logcall, .topcall = .topcall, .topenv = .topenv, .timestamp = .timestamp)
402410
}
403411
#' @export
404412
#' @rdname log_level
405413
log_success <- function(..., namespace = NA_character_,
406-
.logcall = sys.call(), .topcall = sys.call(-1), .topenv = parent.frame()) {
407-
log_level(SUCCESS, ..., namespace = namespace, .logcall = .logcall, .topcall = .topcall, .topenv = .topenv)
414+
.logcall = sys.call(), .topcall = sys.call(-1), .topenv = parent.frame(), .timestamp = Sys.time()) {
415+
log_level(SUCCESS, ..., namespace = namespace, .logcall = .logcall, .topcall = .topcall, .topenv = .topenv, .timestamp = .timestamp)
408416
}
409417
#' @export
410418
#' @rdname log_level
411419
log_info <- function(..., namespace = NA_character_,
412-
.logcall = sys.call(), .topcall = sys.call(-1), .topenv = parent.frame()) {
413-
log_level(INFO, ..., namespace = namespace, .logcall = .logcall, .topcall = .topcall, .topenv = .topenv)
420+
.logcall = sys.call(), .topcall = sys.call(-1), .topenv = parent.frame(), .timestamp = Sys.time()) {
421+
log_level(INFO, ..., namespace = namespace, .logcall = .logcall, .topcall = .topcall, .topenv = .topenv, .timestamp = .timestamp)
414422
}
415423
#' @export
416424
#' @rdname log_level
417425
log_debug <- function(..., namespace = NA_character_,
418-
.logcall = sys.call(), .topcall = sys.call(-1), .topenv = parent.frame()) {
419-
log_level(DEBUG, ..., namespace = namespace, .logcall = .logcall, .topcall = .topcall, .topenv = .topenv)
426+
.logcall = sys.call(), .topcall = sys.call(-1), .topenv = parent.frame(), .timestamp = Sys.time()) {
427+
log_level(DEBUG, ..., namespace = namespace, .logcall = .logcall, .topcall = .topcall, .topenv = .topenv, .timestamp = .timestamp)
420428
}
421429
#' @export
422430
#' @rdname log_level
423431
log_trace <- function(..., namespace = NA_character_,
424-
.logcall = sys.call(), .topcall = sys.call(-1), .topenv = parent.frame()) {
425-
log_level(TRACE, ..., namespace = namespace, .logcall = .logcall, .topcall = .topcall, .topenv = .topenv)
432+
.logcall = sys.call(), .topcall = sys.call(-1), .topenv = parent.frame(), .timestamp = Sys.time()) {
433+
log_level(TRACE, ..., namespace = namespace, .logcall = .logcall, .topcall = .topcall, .topenv = .topenv, .timestamp = .timestamp)
426434
}
427435

428436

‎tests/testthat/test-layouts.R‎

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -20,6 +20,10 @@ test_that("metavars", {
2020

2121
f_warn <- function() log_warn()
2222
expect_output(f_warn(), "WARN global f_warn()")
23+
24+
local_test_logger(layout = layout_glue_generator("{time}"))
25+
time <- as.POSIXct("2025-04-04 10:31:57 CEST")
26+
expect_output(log_info("test", .timestamp = time), "2025-04-04 10:31:57")
2327
})
2428

2529
test_that("JSON layout", {

0 commit comments

Comments
 (0)