switching formatters

[r2evans]

I work with others, and we don't always have the same formatter set. We found recently that when my code (I tend to use formatter_json) is logging with their non-json formatter, the message is lost.

For instance,

log_formatter(formatter_glue)
log_info("hello: {nrow(mtcars)}")         # fashioned for formatter_glue
# INFO [2022-12-09 14:46:11] hello: 32
log_info(msg = "hello", n = nrow(mtcars)) # fashioned for formatter_json
# INFO [2022-12-09 14:46:11] 

Where the last message is empty. If all of our code bases were using the same assumptions, then either all or none would have (say) msg= as the main message. The issue is that it is a named argument, not that it's msg=.

(One of my colleagues likes formatter_glue, ergo my inclusion of {..} above.)

It's not a problem in the reverse, a non-json-assuming log is sent with formatter_json:

log_formatter(formatter_json)
log_info("hello: {nrow(mtcars)}")         # fashioned for formatter_glue
# INFO [2022-12-09 14:46:21] ["hello: {nrow(mtcars)}"]
log_info(msg = "hello", n = nrow(mtcars)) # fashioned for formatter_json
# INFO [2022-12-09 14:46:21] {"msg":"hello","n":32}

I suggest either updating the formatters or supplying alternative functions, such as

formatter_glue2 <- function (..., .logcall = sys.call(), .topcall = sys.call(-1),
                             .topenv = parent.frame(), collapse = "; ") {
  fail_on_missing_package("glue")
  paste(
    sapply(list(...), function(dot) {
      tryCatch(as.character(glue::glue(dot, .envir = .topenv)),
               error = function(e) {
                 stop(paste("`glue` failed in `formatter_glue` on:\n\n",
                            capture.output(str(dot)), "\n\nRaw error message:\n\n",
                            e$message, "\n\nPlease consider using another `log_formatter` or",
                            "`skip_formatter` on strings with curly braces."))
               })
    }),
    collapse = collapse)
}

log_formatter(formatter_glue2)
log_info("hello: {nrow(mtcars)}")
# INFO [2022-12-09 14:48:50] hello: 32
log_info(msg = "hello", n = nrow(mtcars))
# INFO [2022-12-09 14:48:50] hello; 32

(No missing messages.) Since one of my colleagues prefers formatter_glue, I focused on that formatter, but this could apply to others as well.

---

As one more step, it would be nice if my colleague were able to see all of the components send in my messages, where I often have one or more named components (in lieu of encoding within a string, where json makes it much easier to programmatically consume later). What about:

formatter_json_glue <- function(..., .logcall = sys.call(), .topcall = sys.call(-1),
                                .topenv = parent.frame()) {
  logger::fail_on_missing_package("jsonlite")
  dots <- list(...)
  if (is.null(nms <- names(dots))) nms <- rep("", length(dots))
  if (any(!nzchar(nms))) {
    nms[!nzchar(nms)] <- paste0("arg", seq_along(dots))[!nzchar(nms)]
  }
  names(dots) <- nms
  eval(as.character(jsonlite::toJSON(
    lapply(dots, function(dot) tryCatch(glue::glue(dot, .envir = .topenv), error = function(ign) dot)),
    auto_unbox = TRUE)),
    envir = .topenv)
}

logger::log_formatter(formatter_json_glue)
logger::log_info("hello")                 # fashioned for any formatter
# INFO [2022-12-09 14:52:55] {"arg1":"hello"}
logger::log_info("hello: {nrow(mtcars)}") # fashioned for formatter_glue
# INFO [2022-12-09 14:52:55] {"arg1":"hello: 32"}
logger::log_info(msg = "hello: {nrow(mtcars)}", n = nrow(mtcars))
# INFO [2022-12-09 14:52:55] {"msg":"hello: 32","n":"32"}

[r2evans]

I think this is distinct from #130, where that fixes a symptom and this one suggests a new formatter. What's your preference @daroczig ?

[daroczig]

Sorry for the long delay on this. I'd be happy to take a PR on adding formatter_json_glue and we can also suggest in places when it seems useful.

On the other hand, for your use case (preferring different formatters in a team), I wonder if using namespaces might be a better approach? e.g. you picking a namespace and setting up the JSON formatted for it in your internal R package (or scripts), and your colleague could use their own formatted and use that in their namespace.