daroczig / logger

A lightweight, modern and flexible, log4j and futile.logger inspired logging utility for R
https://daroczig.github.io/logger
249 stars 38 forks source link

length > 1 warnings result in errors with `formatter_glue()` #119

Closed patrickvdb closed 11 months ago

patrickvdb commented 11 months ago

We ran into some warnings with length 2 that resulted in glue returning an error. The solution I found right now it is to use a custom formatter that unlists the input for glue.

I am unsure if this would be a drop+replace for the current formatter (formatter_glue()).

NB The same problem occured with formatter_glue_or_sprintf()

> library(logger)
> library(forcats) # this will generate the length 2 warning
> log_warnings()
> tryCatch(
+   forcats::fct_explicit_na(1:3),
+   warning = function(x){
+     a<<-x
+   }
+ )
> print(a$message) # length 2 message
                                                                                                            i 
"`fct_explicit_na()` was deprecated in forcats 1.0.0."        "Please use `fct_na_value_to_level()` instead." 
> log_warn(a$message)
Error in value[[3L]](cond) : `glue` failed in `formatter_glue` on:

  Named chr [1:2] "`fct_explicit_na()` was deprecated in forcats 1.0.0." "Please use `fct_na_value_to_level()` instead." 

Raw error message:

 All unnamed arguments must be length 1 

Please consider using another `log_formatter` or `skip_formatter` on strings with curly braces.`glue` failed in `formatter_glue` on:

  - attr(*, "names")= chr [1:2] "" "i" 

Raw error message:

 All unnamed arguments must be length 1 

Please consider using another `log_formatter` or `skip_formatter` on strings with curly braces.
> # solution, unlist+paste input of glue()
> formatter_glue2 <- structure(function(..., .logcall = sys.call(), .topcall = sys.call(-1), .topenv = parent.frame()) {
+   fail_on_missing_package('glue')
+   as.character(
+     tryCatch(
+       do.call(glue::glue, c(.envir = .topenv, paste(unlist(list(...))))),
+       error = function(e) {
+         stop(paste(
+           '`glue` failed in `formatter_glue` on:\n\n',
+           capture.output(str(...)),
+           '\n\nRaw error message:\n\n',
+           e$message,
+           '\n\nPlease consider using another `log_formatter` or',
+           '`skip_formatter` on strings with curly braces.'))
+       }))
+ }, generator = quote(formatter_glue2()))
> logger::log_formatter(formatter_glue2)
> log_warn(a$message) 
WARN [2023-08-10 15:57:08] `fct_explicit_na()` was deprecated in forcats 1.0.0.Please use `fct_na_value_to_level()` instead.
daroczig commented 11 months ago

I think the root of the above is this:

> glue(1:2)
Error: All unnamed arguments must be length 1

So although glue can take multiple arguments and will concat if needed, e.g.:

> glue('foo', 'bar')
foobar

Passing a character vector as per above will not work.

If you want to pass character vectors instead of strings (to be interpolated), then indeed a new/another formatted is needed, e.g.

> log_formatter(formatter_paste)
> log_info(1:2)
INFO [2023-08-19 12:23:55] 1
INFO [2023-08-19 12:23:55] 2

Or a custom one, like you suggested above making use of glue after concatenating internally.

Overall, I don't think it's a bug in formatter_glue as it works as intended -- passing log msg and variables for interpolation to glue. So thus I'm closing this ticket, but feel free to open a PR to add a new formatter.

patrickvdb commented 11 months ago

Perhaps it was not clear why this can be a problem. It's not a bug if it works as expected, I agree, but we don't fully control warning messages other packages print and with log_warnings() this results in code failing just because the log functions fails. See mwe example below.

Perhaps I'll make a pull request for formatter_glue_safe() that defaults to another formatter for the log instead of stopping.

library(logger)
library(forcats)
log_warnings()
fct_explicit_na(factor(c("a", NA)))
# anything after this is not run: glue+logger error stops the script entirely even though it was merely warning
patrickvdb commented 11 months ago

I noticed there already is a pull request for a formatter_glue_safe() that uses glue::glue_safe(). Maybe I'll figure out something different. Perhaps a fallback mechanic to the paste formatter?

I would also like to note that I was was mistaken before in that formatter_glue_or_sprintf() does not result in an error in the above case.