logger integration

logging

As code shifts from prototype to production, logging becomes important. Given the ubiquity of the cli and logger packages, it would be helpful to have the option of routing cli output directly into the logs. More generally, any code that generates conditions–messages, warnings, and errors–should be easily loggable as well. To address this concern, metayer provides a with_logger function and uses it to wrap many of the cli functions.

## tl;dr

cli_alert("use cli methods to route output into the logs") %>%
  suppressMessages()

[INFO/global] > use cli methods to route output into the logs 

tryCatch(
  cli_abort("abort: an error"),
  error = function(m) {
    log_error("error: handled")
    invisible(NULL)
  }
)

[ERROR/global] abort: an error 
[ERROR/global] error: handled 

msg <- with_logger({
  message("a logged message")
}) %>%
  catch_cnd()

[INFO/global] a logged message 

with_logger

with_logger provides explicit logging. Internally, this uses withCallingHandlers, so conditions are processed with a log entry before being propagated to the next handler. This results in the visibility of both the log entry as well as the message.

# explicity logging
with_logger({
  message("a logged message")
})

[INFO/global] a logged message 

a logged message

cli wrappers

metayer uses some metadata magic to wrap cli functions. This imbues them with logging functionality.

metayer also utilizes the cli.default_handler option provided by the cli package. This upgrades glue semantics to generate visible NULL values and is useful when debugging.

We consider the available variants of cli_alert_warning, starting with cli’s default behavior.

# default behavior of cli_alert_warning
withr::with_options(
  list(cli.default_handler = NULL), 
  cli::cli_alert_warning("a message without a visible null: '{NULL}'")          
)

! a message without a visible null: ''

cli.default_handler - visible nulls

When using the default metayer handler–cli_nullity_handler–we see that NULL values are handled differently. We can also customize this behavior.

# visible null, default
cli::cli_alert_warning("a message with a default null: '{NULL}'") 

! a message with a default null: '<null>'

# visible null, customized
withr::with_options(
  list(mty.cli_null = "NULL"),
  cli::cli_alert_warning("a message with a custom null: '{NULL}'") 
)

! a message with a custom null: 'NULL'

explicitly logged cli functions

If we were willing to, we could apply wrap_logger to every cli call.

# logging
with_logger(
  cli::cli_alert_warning("a logged message from 'cli::cli_alert_warning'")
)

[INFO/global] ! a logged message from 'cli::cli_alert_warning' 

! a logged message from 'cli::cli_alert_warning'

It’s odd to see a function named cli_alert_warning producing a log with an INFO threshold. This is easily amended. To ensure that the logger level is aligned with the naming implications of the cli function, use the level parameter. Now cli_alert_warning is producing a WARN entry in the logs.

# logging with log level
with_logger(
  cli::cli_alert_warning("a logged warning with 'cli::cli_alert_warning'"),
  level = logger::WARN
)

[WARN/global] ! a logged warning with 'cli::cli_alert_warning' 

! a logged warning with 'cli::cli_alert_warning'

Finally, it’s worth mentioning the double output above. This is because cli::cli_alert_warning bubbles up a message condition, and with_logger processes it along the way. The second output above is that message, delivered to the user. We can deal with this using an even more verbose expression. Now we’ll only see what’s propagated to the logs.

# fix the double messaging
tryCatch(
  {
    with_logger(
      cli::cli_alert_warning("a logged warning with 'cli::cli_alert_warning'"),
      level = logger::WARN
    )
  },
  message = function(msg) invisible(NULL)
)

[WARN/global] ! a logged warning with 'cli::cli_alert_warning' 

wrapped cli functions

metayer provides wrapped versions of cli functions. This recovers the usual verbosity of the original cli package but without the pain previously demonstrated.

# implicit logging and log levels
cli_alert_warning("a logged warning with 'cli_alert_warning'")

[WARN/global] ! a logged warning with 'cli_alert_warning' 

! a logged warning with 'cli_alert_warning'

namespace context

So far, all of the logging has been to the global namespace. In an article context, this is as it should be. However, logs originating elsewhere should reflect the point of origin.

With log_info and friends, one can explicitly specify a namespace.

# explicit custom namespace
log_warn("a warning with 'log_warn' in a custom namespace", namespace = "custom")

[WARN/custom] a warning with 'log_warn' in a custom namespace 

To showcase implicit namespace behavior, we’ll create two functions in the global namespace. We’ll also put copies of these functions in a namespace anchored to metayer. This is intended to mimic the scenario where these functions would have been formally defined in the package.

# two functions in the global namespace
foo <- function() log_info("foo called `log_info`")
bar <- function() cli_alert("bar called `cli_alert`")

# global functions produce 'global' namespace
foo()

[INFO/global] foo called `log_info` 

bar()

[INFO/global] > bar called `cli_alert` 

> bar called `cli_alert`

In the previous output, note that foo–inherently, log_info–doesn’t generate a condition; it shows up only once.

bar, on the other hand, calls cli_alert which generates a condition. Hence that output shows up twice: once as a log entry, processed as it happens, and a second time, now as an unhandled condition that has bubbled up to the top level. This is the same behavior we observed previously.

Next, we’ll put foo and bar into the metayer namespace and observe that they now display a “metayer” namespace.

# two functions "above" the metayer namespace
ns <- new_environment(parent = getNamespace("metayer"))
ns[["foo"]] <- set_env(foo, ns)
ns[["bar"]] <- set_env(bar, ns)

# packaged functions produce 'metayer' namespace
ns$foo()

[INFO/metayer] foo called `log_info` 

ns$bar()

[INFO/metayer] > bar called `cli_alert` 

> bar called `cli_alert`

glue semantics

The wrapped functions are designed to replicate the usual glue semantics found in the cli and logger packages.

# glue semantics for `cli_alert_info` (with visible NULLs)
v1 = "foo"
v2 = NULL
v3 = "bar"

cli_alert_info("{v1} {v2} {v3}")

[INFO/global] i foo <null> bar 

i foo <null> bar

# glue semantics for log_info
log_info("a log: {v1} {v3}")

[INFO/global] a log: foo bar 

However, just like their analogues in the logger package, log_info and friends won’t handle NULL values.

# null values were never allowed here!
logger::log_info("a log: {v1} {v2} {v3}")

# and so we don't expect them to be available here, either.
log_info("a log: {v1} {v2} {v3}")