diff --git a/NEWS.md b/NEWS.md index 4ffcb6f8..67e79efe 100644 --- a/NEWS.md +++ b/NEWS.md @@ -1,5 +1,7 @@ # logger (development version) +* `log_appender()`, `log_layout()` and `log_formatter()` now check that you are calling them with a function, and return the previously set value. + # logger 0.3.0 (2024-03-03) Many unrelated small features, fixes and documentation updates collected over 2+ years. diff --git a/R/logger.R b/R/logger.R index 49a1704d..894494cf 100644 --- a/R/logger.R +++ b/R/logger.R @@ -105,9 +105,11 @@ fallback_namespace <- function(namespace) { #' @param namespace logger namespace #' @param index index of the logger within the namespace -#' @return currently set or return log function property +#' @return If `value` is `NULL`, will return the currently set value. +#' If `value` is not `NULL`, will return the previously set value. #' @noRd log_config_setter <- function(name, value, namespace = "global", index = 1) { + if (length(namespace) > 1) { for (ns in namespace) { log_config_setter(name, value, ns, index) @@ -117,6 +119,7 @@ log_config_setter <- function(name, value, namespace = "global", index = 1) { configs <- get(fallback_namespace(namespace), envir = namespaces) config <- configs[[min(index, length(configs))]] + old <- config[[name]] if (name == "threshold") { if (is.null(value)) { @@ -137,6 +140,8 @@ log_config_setter <- function(name, value, namespace = "global", index = 1) { configs[[min(index, length(config) + 1)]] <- config assign(namespace, configs, envir = namespaces) + invisible(old) + } @@ -195,6 +200,9 @@ log_threshold <- function(level = NULL, namespace = "global", index = 1) { #' } #' @seealso [logger()], [log_threshold()], [log_appender()] and [log_formatter()] log_layout <- function(layout = NULL, namespace = "global", index = 1) { + if (!is.null(layout) && !is.function(layout)) { + stop("`layout` must be a function") + } log_config_setter("layout", layout, namespace = namespace, index = index) } @@ -209,6 +217,9 @@ log_layout <- function(layout = NULL, namespace = "global", index = 1) { #' @seealso [logger()], [log_threshold()], [log_appender()] and #' [log_layout()] log_formatter <- function(formatter = NULL, namespace = "global", index = 1) { + if (!is.null(formatter) && !is.function(formatter)) { + stop("`formatter` must be a function") + } log_config_setter("formatter", formatter, namespace = namespace, index = index) } @@ -236,6 +247,9 @@ log_formatter <- function(formatter = NULL, namespace = "global", index = 1) { #' } #' @seealso [logger()], [log_threshold()], [log_layout()] and [log_formatter()] log_appender <- function(appender = NULL, namespace = "global", index = 1) { + if (!is.null(appender) && !is.function(appender)) { + stop("`appender` must be a function") + } log_config_setter("appender", appender, namespace = namespace, index = index) } @@ -425,10 +439,7 @@ log_trace <- function(..., namespace = NA_character_, #' log_trace("DONE") #' } with_log_threshold <- function(expression, threshold = ERROR, namespace = "global", index = 1) { - old <- log_threshold(namespace = namespace, index = index) - on.exit({ - log_threshold(old, namespace = namespace, index = index) - }) - log_threshold(threshold, namespace = namespace, index = index) + old <- log_threshold(threshold, namespace = namespace, index = index) + on.exit(log_threshold(old, namespace = namespace, index = index)) expression } diff --git a/R/utils.R b/R/utils.R index 2738de42..8f6944ef 100644 --- a/R/utils.R +++ b/R/utils.R @@ -78,16 +78,14 @@ deparse_to_one_line <- function(x) { #' fun() #' catch_base_log(INFO, NA_character_, .topcall = call("funLONG")) #' } -catch_base_log <- function( - level, - namespace, - .topcall = sys.call(-1), - .topenv = parent.frame()) { +catch_base_log <- function(level, namespace, .topcall = sys.call(-1), .topenv = parent.frame()) { namespace <- fallback_namespace(namespace) - orginal_appender <- log_appender(namespace = namespace) - log_appender(appender_console, namespace = namespace) + + old <- log_appender(appender_console, namespace = namespace) + on.exit(log_appender(old, namespace = namespace)) + # catch error, warning or message - res <- capture.output( + capture.output( log_level( level = level, "", @@ -97,8 +95,7 @@ catch_base_log <- function( ), type = "message" ) - log_appender(orginal_appender, namespace = namespace) - res + } in_pkgdown <- function() { diff --git a/tests/testthat/_snaps/logger.md b/tests/testthat/_snaps/logger.md new file mode 100644 index 00000000..4607194d --- /dev/null +++ b/tests/testthat/_snaps/logger.md @@ -0,0 +1,23 @@ +# setters check inputs + + Code + log_appender(1) + Condition + Error in `log_appender()`: + ! `appender` must be a function + Code + log_formatter(1) + Condition + Error in `log_formatter()`: + ! `formatter` must be a function + Code + log_layout(1) + Condition + Error in `log_layout()`: + ! `layout` must be a function + Code + log_threshold("x") + Condition + Error in `validate_log_level()`: + ! Invalid log level + diff --git a/tests/testthat/test-logger.R b/tests/testthat/test-logger.R index 5714136c..5e3a8a7e 100644 --- a/tests/testthat/test-logger.R +++ b/tests/testthat/test-logger.R @@ -147,3 +147,12 @@ test_that("providing log_level() args to wrappers diretly is OK", { local_test_logger(WARN) expect_silent(log_info("{Sepal.Length}", .topenv = iris)) }) + +test_that("setters check inputs", { + expect_snapshot(error = TRUE, { + log_appender(1) + log_formatter(1) + log_layout(1) + log_threshold("x") + }) +}) diff --git a/vignettes/migration.html b/vignettes/migration.html new file mode 100644 index 00000000..de52b543 --- /dev/null +++ b/vignettes/migration.html @@ -0,0 +1,914 @@ + + + + +
+ + + + + + + + +In this vignette I suppose that you are already familiar with at
+least one of the similar
+logging R packages and you are looking for suggestions on how to
+switch to logger
. Before moving forward, please make sure
+that you have read the Introduction
+to logger, The
+Anatomy of a Log Request and Customizing
+the Format and the Destination of a Log Record vignettes for a
+decent background on logger
, and use this vignette as a
+quick-reference sheet to help you migrate from another package.
The logger
package has been very heavily inspired by futile.logger
+and have been using it for many years, also opened multiple pull
+requests to extend futile.logger
before I decided to revamp
+my ideas into a new R package – but there are still many common things
+between futile.logger
and logger
.
Both packages comes with a default log engine / config, so it’s +enough to load the packages and those are ready to be used right +away:
+library(futile.logger)
+#>
+#> Attaching package: 'futile.logger'
+#> The following objects are masked from 'package:logger':
+#>
+#> DEBUG, ERROR, FATAL, INFO, TRACE, WARN
+library(logger)
+The most important change is that function names are by snake_case in
+logger
, while futile.logger
uses dot.separated
+expressions, and futile.logger
prefixes function names by
+flog
while logger
uses log
for
+that:
flog.info('hi there')
+#> INFO [2024-08-06 14:28:37] hi there
+flog.warn('watch out')
+#> WARN [2024-08-06 14:28:37] watch out
+log_info('hi there')
+#> INFO [2024-08-06 14:28:37] hi there
+log_warn('watch out')
+#> WARN [2024-08-06 14:28:37] watch out
+As you can see above, the default layout of the messages is exactly +the same.
+Regarding log levels, futile.logger
bundles the default
+log4j
levels (TRACE
, DEBUG
,
+INFO
, WARN
, ERROR
and
+FATAL
) that is extended by SUCCESS
in
+logger
as sometimes it’s worth logging with a higher than
+INFO
level that something succeeded.
Changing layouts is easy in both package, as you simply pass a layout +function:
+flog.layout(layout.json)
+#> NULL
+flog.info('hi again')
+#> {"level":"INFO","timestamp":"2024-08-06 14:28:37 -0500","message":"hi again","func":"rmarkdown::render"}
+log_layout(layout_json())
+
+log_info('hi again')
+#> {"time":"2024-08-06 14:28:37","level":"INFO","ns":"global","ans":"global","topenv":"R_GlobalEnv","fn":"eval","node":"Hadleys-MBP.attlocal.net","arch":"arm64","os_name":"Darwin","os_release":"23.5.0","os_version":"Darwin Kernel Version 23.5.0: Wed May 1 20:12:58 PDT 2024; root:xnu-10063.121.3~5/RELEASE_ARM64_T6000","pid":86631,"user":"hadleywickham","msg":"hi again"}
+As you can see, logger
provided a bit more information
+about the log request compared to futile.logger
, but it’s
+easy to change the list of fields to be used in the JSON – see
+?get_logger_meta_variables
for a complete list of variable
+names to be passed to ?layout_json
. logger
+also ships a lot more layouts, eg ?layout_glue_colors
or
+roll out your own via the ?layout_glue_generator
factory
+function.
By default, futile.logger
uses an sprintf
+formatter, while logger
passes the objects to be logged to
+glue
:
flog.info('hi')
+#> INFO [2024-08-06 14:28:37] hi
+flog.info('hi %s', 84/2)
+#> INFO [2024-08-06 14:28:37] hi 42
+flog.info(paste('hi', 84/2))
+#> INFO [2024-08-06 14:28:37] hi 42
+flog.info(glue::glue('hi {84/2}'))
+#> INFO [2024-08-06 14:28:37] hi 42
+log_info('hi')
+#> INFO [2024-08-06 14:28:37] hi
+log_info('hi {84/2}')
+#> INFO [2024-08-06 14:28:37] hi 42
+log_formatter(formatter_sprintf)
+log_info('hi %s', 84/2)
+#> INFO [2024-08-06 14:28:37] hi 42
+log_formatter(formatter_paste)
+log_info('hi', 84/2)
+#> INFO [2024-08-06 14:28:37] hi 42
+It’s easy to change this default formatter in both packages: use
+flog.layout
handles this as well in
+futile.logger
, while the formatter is separated from the
+layout function in logger
, so check
+?log_formatter
instead. logger
ships with a
+bit more formatter functions, eg the default
+?formatter_glue
and ?formatter_glue_or_sprintf
+that tries to combine the best from both words.
Setting the destination of the log records works similarly in both
+packages, although he logger
packages bundles a lot more
+options:
t <- tempfile()
+flog.appender(appender.file(t))
+#> NULL
+flog.appender(appender.tee(t))
+#> NULL
+t <- tempfile()
+log_appender(appender_file(t))
+log_appender(appender_tee(t))
+Both packages support using different logging namespaces and stacking
+loggers within the same namespace. Performance-wise, there’s
+logger
seems to be faster than futile.logger
,
+but for more details, check the Simple
+Benchmarks on Performance vignette.
logger
as a drop-in-replacement of
+futile.logger
logger
has no hard requirements, so it’s a very
+lightweight alternative of futile.logger
. Although the
+function names are a bit different, and the message formatter also
+differs, but with some simple tweaks, logger
can become an
+almost perfect drop-in-replacement of futile.logger
:
library(logger)
+log_formatter(formatter_sprintf)
+flog.trace <- log_trace
+flog.debug <- log_debug
+flog.info <- log_info
+flog.warn <- log_warn
+flog.error <- log_error
+
+flog.info('Hello from logger in a futile.logger theme ...')
+flog.warn('... where the default log message formatter is %s', 'sprintf')
+The logging
+package behaves very similarly to the Python logging module and so thus
+being pretty Pythonic, while logger
tries to accommodate
+native R users’ expectations – so there are some minor nuances between
+the usage of the two packages.
In logging
, you have to initialize a logger first via
+addHandler
or simply by calling basicConfig
,
+which is not required in logger
as it already comes with a
+default log config:
library(logging)
+basicConfig()
+library(logger)
+After initializing the logging engine, actual logging works similarly +in the two packages – with a bit different function names:
+logging
uses mostly camelCase function names
+(eg basicConfig
), but the logging functions are all
+lowercase without any separator, such as loginfo
or
+logwarn
logger
uses snake_case for the function names, such as
+log_info
and log_warn
loginfo('hi there')
+#> 2024-08-06 14:28:37.693914 INFO::hi there
+logwarn('watch out')
+#> 2024-08-06 14:28:37.698499 WARNING::watch out
+log_info('hi there')
+log_warn('watch out')
+As you can see above, the default layout of the log messages is +somewhat different:
+logging
starts with the timestamp that is followed by
+the log level, optional namespace and the message separated by
+colonslogger
starts with the log level, followed by the
+timestamp between brackets and then the messageFor the available log levels in logging
, check
+?loglevels
, and ?log_levels
for the same in
+logger
:
str(as.list(loglevels))
+#> List of 11
+#> $ NOTSET : num 0
+#> $ FINEST : num 1
+#> $ FINER : num 4
+#> $ FINE : num 7
+#> $ DEBUG : num 10
+#> $ INFO : num 20
+#> $ WARNING : num 30
+#> $ WARN : num 30
+#> $ ERROR : num 40
+#> $ CRITICAL: num 50
+#> $ FATAL : num 50
+levels <- mget(ls(
+ envir = environment(logger), pattern = '^[A-Z]'),
+ envir = environment(logger))
+str(levels[order(-as.numeric(levels))], give.attr = FALSE)
+#> List of 8
+#> $ TRACE : 'loglevel' int 600
+#> $ DEBUG : 'loglevel' int 500
+#> $ INFO : 'loglevel' int 400
+#> $ SUCCESS: 'loglevel' int 350
+#> $ WARN : 'loglevel' int 300
+#> $ ERROR : 'loglevel' int 200
+#> $ FATAL : 'loglevel' int 100
+#> $ OFF : 'loglevel' int 0
+Performance-wise, there’s no big difference between the two packages, +but for more details, check the Simple +Benchmarks on Performance vignette.
+Getting and setting the layout of the log record should happen +up-front in both packages:
+getLogger()[['handlers']]$basic.stdout$formatter
+#> function (record)
+#> {
+#> msg <- trimws(record$msg)
+#> text <- paste(record$timestamp, paste(record$levelname, record$logger,
+#> msg, sep = ":"))
+#> return(text)
+#> }
+#> <bytecode: 0x1375de6b8>
+#> <environment: namespace:logging>
+log_layout()
+#> layout_simple
+logger
provides multiple configurable layouts to fit the
+user’s need, eg easily show the calling function of the lof request, the
+pid
of the R process, name of the machine etc. or colorized
+outputs. See Customizing
+the Format and the Destination of a Log Record vignette for more
+details.
If you want to pass dynamic log messages to the log engines, you can
+do that via the hard-coded sprintf
in the
+logging
package, while you can set that on a namespaces
+basis in logger
, which is by default using
+glue
:
loginfo('hi')
+#> 2024-08-06 14:28:37.726038 INFO::hi
+loginfo('hi %s', 84/2)
+#> 2024-08-06 14:28:37.726619 INFO::hi 42
+loginfo(paste('hi', 84/2))
+#> 2024-08-06 14:28:37.727083 INFO::hi 42
+loginfo(glue::glue('hi {84/2}'))
+#> 2024-08-06 14:28:37.727625 INFO::hi 42
+log_info('hi')
+log_info('hi {84/2}')
+log_formatter(formatter_sprintf)
+log_info('hi %s', 84/2)
+log_formatter(formatter_paste)
+log_info('hi', 84/2)
+For even better compatibility, there’s also
+?formatter_logging
that not only relies on
+sprintf
when the first argument is a string, but will log
+the call and the result as well when the log object is an R
+expression:
log_formatter(formatter_logging)
+log_info('42')
+log_info(42)
+log_info(4+2)
+log_info('foo %s', 'bar')
+log_info(12, 1+1, 2 * 2)
+Setting the destination of the log records works similarly in both
+packages, although he logger
packages bundles a lot more
+options:
?addHandler
+?writeToConsole
+?writeToFile
+?log_appender
+?appender_console
+?appender_file
+?appender_tee
+?appender_slack
+?appender_pushbullet
+Both packages support using different logging namespaces and stacking +loggers within the same namespace.
+logger
as a drop-in-replacement of
+logging
logger
has no hard requirements, so it’s an adequate
+alternative of logging
. Although the function names are a
+bit different, and the message formatter also differs, but with some
+simple tweaks, logger
can become an almost perfect
+drop-in-replacement of logging
– although not all log
+levels (eg and ) are supported:
library(logger)
+log_formatter(formatter_logging)
+log_layout(layout_logging)
+logdebug <- log_debug
+loginfo <- log_info
+logwarn <- log_warn
+logerror <- log_error
+
+loginfo('Hello from logger in a logging theme ...')
+logwarn('... where the default log message formatter is %s', 'sprintf', namespace = 'foobar')
+The log4r
+package provides an object-oriented approach for logging in R, so the
+logger object is to be passed to the log calls – unlike in the
+logger
package.
So thus it’s important to create a logging object in
+log4r
before being able to log messages, while that’s
+automatically done in `logger:
library(log4r)
+#>
+#> Attaching package: 'log4r'
+#> The following object is masked from 'package:logging':
+#>
+#> levellog
+#> The following objects are masked from 'package:logger':
+#>
+#> as.loglevel, logger
+#> The following object is masked from 'package:base':
+#>
+#> debug
+logger <- create.logger(logfile = stdout(), level = "INFO")
+library(logger)
+Please note that in the background, logger
does have a
+concept of logger objects, but that’s behind the scene and the user does
+not have to specify / reference it. On the other hand, if you wish, you
+can do that via the namespace
concept of
+logger
– more on that later.
While logger
has a log_
prefix for all
+logging functions, log4r
has lowercase functions names
+referring to the log level, which takes a logging object and the log
+message:
info(logger, 'hi there')
+#> INFO [2024-08-06 14:28:37] hi there
+warn(logger, 'watch out')
+#> WARN [2024-08-06 14:28:37] watch out
+log_info('hi there')
+log_warn('watch out')
+As you can see the default layout of the messages is a bit different +in the two packages.
+Both packages are based on log4j
, and log4r
+provides DEBUG
, INFO
, WARN
,
+ERROR
and FATAL
, while logger
+also adds TRACE
and SUCCESS
on the top of
+these.
To change the log level threshold, use the level
+function on the logging object in log4r
, while it’s
+log_level
in logger
.
The log4r
provides a logformat
argument in
+create.logger
that can be used to override the default
+formatting, while logger
provides formatter and layout
+functions for a flexible log record design.
By default, log4r
logs to a file that can be set to
+stoud
to write to the console, while logger
+writes to the console by default, but logging to files via the
+appender_file
functions is also possible – besides a number
+of other log record destinations as well.
Creating objects is the log4r
way of handling multiple
+log environments, while logger
handles that via
+namespace
s.