truncate anonymous functions with {fn} formatting

[r2evans]

The use of {fn} in a custom formatter goes a little crazy when the calling function name is not easily determined.

logger::log_layout(logger::layout_glue_generator(format = '[{time}] {level} {fn}: {msg}'))
log_info("hello")
# [2019-04-01 15:50:31] INFO NA: hello
func <- function(...) { log_info('hello'); }
func()
# [2019-04-01 15:50:39] INFO func: hello

But when done from an anonymous function (or similar), the log includes the entire function definition.

(function(...) { log_info('hello'); })()
# [2019-04-01 15:50:47] INFO (function(...) {: hello
# [2019-04-01 15:50:47] INFO     log_info("hello"): hello
# [2019-04-01 15:50:47] INFO }): hello

You can imagine how this gets crazy when the anon-function is more than "hello world".

Actually, it's a little more than just an anonymous function. In the code below, the function is perfectly named but not well-named within Map.

Map(func, 1, 2)
# [2019-04-01 15:54:02] INFO function (...) : hello
# [2019-04-01 15:54:02] INFO {: hello
# [2019-04-01 15:54:02] INFO     log_info("hello"): hello
# [2019-04-01 15:54:02] INFO }: hello
# [[1]]
# NULL

I wonder if the solution is to catch when {fn} will expand to something ridiculous and either head it or replace it with something much less unreasonable (such as "omg_im_lost" :-).

[r2evans]

Perhaps something like

fn = gsub("\\).*", ")", deparse(.topcall[[1]])[[1]])

returns function (...) in this example, an improvement over the whole function. Functions with long argument lists will still be a bit bulky, but at least will not be a cartesian join of "function-size and messages".

[daroczig]

Sorry for the late reply, missed this idea somehow.

So actually I wanted to log the full body of anonymous functions on purpose ... keeping in mind that if it's that important to log the fn name / body in a case, then the author would properly name the fn before writing a logger call in that fn I think.

But your Map example is indeed bad ... because we are missing capturing the calling fn name, which is a bug I think.

Just rephrasing your example:

> greet <- function(x) { log_info(paste('hello', x)) }
> lapply(1:3, function(i) greet(i))
[2019-07-26 17:03:31] INFO greet: hello 1
[2019-07-26 17:03:31] INFO greet: hello 2
[2019-07-26 17:03:31] INFO greet: hello 3
[[1]]
NULL

[[2]]
NULL

[[3]]
NULL

> Map(greet, 1:3)
[2019-07-26 17:03:51] INFO function (x) : hello 1
[2019-07-26 17:03:51] INFO {: hello 1
[2019-07-26 17:03:51] INFO     log_info(paste("hello", x)): hello 1
[2019-07-26 17:03:51] INFO }: hello 1
[2019-07-26 17:03:51] INFO function (x) : hello 2
[2019-07-26 17:03:51] INFO {: hello 2
[2019-07-26 17:03:51] INFO     log_info(paste("hello", x)): hello 2
[2019-07-26 17:03:51] INFO }: hello 2
[2019-07-26 17:03:51] INFO function (x) : hello 3
[2019-07-26 17:03:51] INFO {: hello 3
[2019-07-26 17:03:51] INFO     log_info(paste("hello", x)): hello 3
[2019-07-26 17:03:51] INFO }: hello 3
[[1]]
NULL

[[2]]
NULL

[[3]]
NULL

[daroczig]

Sorry for the long delay with this -- I'm just about to push a new release to CRAN, so doing some cleanup.

Regarding Map, I have not found any workarounds as it explicitly gets the body of the provided function, so there's no way to look up the function name (without modifying Map or mapply) as per my related knowledge, so it will log the provided function as an anonymous function :(

But regarding the original issue of too chatty logging of anonymous functions, I've just pushed a fix which should at least solve the Cartesian join problem ... I hope that helps. I short, after deparse, we will now merge all the returning lines and apply some regular expressions to prettify (eg merge excessive whitespace outside of quotes), which is not perfect, but probably fine for the purpose of logging.

If you don't like the whole fn to be logged, you could truncate fn inside of your layout_glue_generator call, so I hope that works.

Please let me know what you think or if you have any better ideas.

Thanks, Gergely

[r2evans]

I don't disagree with your simpler approach and assumption that the user gets what they (implicitly) request.

(The only other option I could think of is a simple fixed if (substr(fn, 1, 9) == "function(") fn <- "anon" or at worst if (grepl("^function\\s*\\(", fn[[1]])). But again, your simpler approach is probably best.)

Thanks!