return value?

[r2evans]

Have you considered invisibly returning the log message?

I find myself periodically doing something like:

if (x < badcondition) {
  logger::log_fatal("message of badness {x}")
  stop("message of badness ", x)
}

I can form the message once and use it in both logger::log_fatal and stop, but (1) I might like to take advantage of logger's formatting methodologies (e.g., glue or json); and (2) I think a more straight-forward approach is something like:

if (x < badcondition) {
  stop(logger::log_fatal("message of badness {x}"))
}

(This if course applies to other loggers, not just log_fatal.)

I'd think there are two good options for exactly what to return:

• "message of badness 42", before some of the final formatting ... or
• "[2019-07-12 17:04:42] FATAL message of badness 42", the literal full log entry

Thoughts?

[daroczig]

Yeah, this is a great idea, thanks 👍

I'm towards returning the formatted message before running through the layout function, so "message of badness 42" in this case, but might be indeed cleaner to return the actual log record ...

Let me do some research on how others are doing this and please let me know meanwhile if you have any further thoughts.

[r2evans]

One beneficial side-effect for returning the entire formatted string is that testing becomes a little more literal. I recognize you already have tests set up so you don't need new ones, but perhaps:

testthat::expect_true(grepl(ptn, logger::log_info(...)))

where ptn checks for a post-formatting feature (perhaps including timestamp stuff).

[daroczig]

Yeah, that's a great point Actually, now I have a (I think) great idea of invisibly returning an object instead of a string -- that includes the formatted message + full log record with the layout and a bunch of other things

…

-- Sent from a mobile phone with an annoying input interface, pls excuse my brevity/spelling issues.

On Fri, Jul 26, 2019, 18:37 r2evans ***@***.***> wrote: One beneficial side-effect for returning the entire formatted string is that testing becomes a little more literal. I recognize you already have tests set up so you don't need new ones, but perhaps: testthat::expect_true(grepl(ptn, logger::log_info(...))) where ptn checks for a post-formatting feature (perhaps including timestamp stuff). — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#26?email_source=notifications&email_token=AADZA6BW4C4EMOFL5NAKCITQBMR57A5CNFSM4ICTRRSKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD25DQFQ#issuecomment-515520534>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AADZA6GLVPXZON5ZNCX5BL3QBMR57ANCNFSM4ICTRRSA> .

[r2evans]

Returning a non-character object will preclude the ability to do the nested stop(log_fatal(...)), so the above situation would be

# logger package code
log_level <- function(level, ...) {
  # normal stuff here
  ret <- list(..., ..., ...)
  class(ret) <- c("logger", "list")
  return(ret)
}
as.character.logger <- function(x, ...) {
  # abuses the fact that R looks anyway, even though base::as.character is not S3
  # something here
}
print.logger <- function(x, ...) {
  # something here
}

# code using this package
if (x < badcondition) {
  msg <- logger::log_fatal("message of badness {x}")
  stop(as.character(msg))
}

Or were you thinking of something like:

log_level <- function(level, ...) {
  # normal stuff here
  ret <- as.character(...)
  class(ret) <- c("logger", "character")
  attr(ret, "logger_obj") <- myobj
  return(ret)
}

print.logger <- function(x, ...) {
  obj <- attr(x, "logger_obj")
  # print something meaningful from that ...
  # then perhaps do a normal-print of the original string
  print.default(`attr<-`(x, "logger_obj", NULL))`
}

[daroczig]

Because this object would be returned invisibly, the print would not be called on that anyway ... as we don't want something like:

> log_info(42)
INFO [timestamp] 42
[1] "42"

I'm not sure if anyone would actually call print on the object ... but of course we can provide some helpers for that S3 object, eg what you can use with stop, eg:

as.character.logger <- function(x, ...) { x$$formatted_message }
stop(as.character(logger::log_fatal("message of badness {x}")))

or even without a helper:

stop(logger::log_fatal("message of badness {x}")$formatted_message)

[r2evans]

I don't disagree that it won't normally be called with print (that would seem weird given what you're intending to do with it).

As I was generating suggested code for this comment, I realized that this is complicated by the nature of iterating over definitions, so as always it's not as easy or direct as I thought. I haven't dived into what is in the nuances of each definition (I know it's a list with threshold, layout, formatter, appender), do you anticipate including definitions somehow in the return from log_fatal (and friends)?

• If yes, then I'm still thinking.
• If no, then the remaining "meaningful" component is log_arg.
• Regardless, the question arises: if multiple, which formatted log message from definitions would be returned? First? All?

(BTW: am I wrong, or does log_arg in log_level() get rebuilt identically on each iteration of definitions? I'd think it can be moved outside of the loop for a speed improvement in the case of multiple definitions.)

[daroczig]

The returned object can be as complex as needed I think, I don't see any issues there -- but will do some benchmarks. as.character.logger can get some extra params, like namespace and index with sane defaults (namespace="global" and index=1) to decide which definition to use.

[r2evans]

I think your use of index=1 resolves my third bullet perfectly. With that, I think requiring the use of as.character is reasonable, good thinking. I'm not familiar enough with multiple logging layouts/formats/destinations to speak that portion fluently ... would index= always be numeric (in which case order of assignment/definition always matters) or can they be named as well?

[r2evans]

@daroczig, I see you've been merging PRs recently. Is our above discussion enough or do you need it to be formalized into a PR? (Assuming of course that you still see value in this FR.) Thanks!

[daroczig]

Yeah, I tried to dedicate some time to this project again, but no promises 🤐

Thanks for the bump here, though! This is a really cool FR, so I'd like to get this done - but definitely larger task than all the other minor things I got done recently in this package.

In short, any help is appreciated, otherwise I'll try to get a PR together for review in the Dec holiday season.

[r2evans]

I hope the PR makes sense.

[daroczig]

I hope the PR makes sense.

Very much, thank you! I'm going through this today or tomorrow with the goal of merging by the end of the week and also making this part of a CRAN release planned by EOW.

[FMKerckhof]

Hi, sorry for posting on this older issue, it just seemed more relevant than making a new one. I am working with a docker container on AWS lambda, and was using logger for structured logging to AWS CloudWatch (basically only the log_info, log_debug and log_error functions for their consistent output formatting in the logs, I have set-up some CloudWatch alarms on log_error output for example).

Now that I updated to 0.3.0 in my docker image I am getting errors that jsonlite::toJSON cannot work with the output of my function. So my question is, is there a flag (e.g. in options) to disable the invisible object from being returned? If not, would you be open to introducing such a flag? (I could make a PR)

Reprex:

logger 0.2.2

library(jsonlite) # 1.8.8
library(logger) # 0.2.2

toJSON(log_info("test"))
# INFO [2024-04-09 09:24:53] test
# {} 

logger 0.3.0

library(jsonlite) # 1.8.8
library(logger) # 0.3.0

toJSON(log_info("test"))
# INFO [2024-04-09 09:24:30] test
# Error: No method asJSON S3 class: logger

[r2evans]

Up front,

library(logger)
jsonlite::toJSON(log_info("test")[[1]]$record)
# INFO [2024-04-09 09:16:45] test
# ["INFO [2024-04-09 09:16:45] test"] 
log_layout(layout_json())
jsonlite::toJSON(log_info("test")[[1]]$record)
# {"time":"2024-04-09 09:17:00","level":"INFO","ns":"global","ans":"global","topenv":"R_GlobalEnv","fn":"force","node":"d2xps","arch":"x86_64","os_name":"Linux","os_release":"6.5.0-27-generic","os_version":"#28-Ubuntu SMP PREEMPT_DYNAMIC Thu Mar  7 18:21:00 UTC 2024","pid":29118,"user":"r2","msg":"test"}
# ["{\"time\":\"2024-04-09 09:17:00\",\"level\":\"INFO\",\"ns\":\"global\",\"ans\":\"global\",\"topenv\":\"R_GlobalEnv\",\"fn\":\"force\",\"node\":\"d2xps\",\"arch\":\"x86_64\",\"os_name\":\"Linux\",\"os_release\":\"6.5.0-27-generic\",\"os_version\":\"#28-Ubuntu SMP PREEMPT_DYNAMIC Thu Mar  7 18:21:00 UTC 2024\",\"pid\":29118,\"user\":\"r2\",\"msg\":\"test\"}"] 

If you look at the return value from log_*, you'll see that it is a list that contains (among other things) environments and functions.

str(log_info("test"))
# {"time":"2024-04-09 09:17:29","level":"INFO","ns":"global","ans":"global","topenv":"R_GlobalEnv","fn":"str","node":"d2xps","arch":"x86_64","os_name":"Linux","os_release":"6.5.0-27-generic","os_version":"#28-Ubuntu SMP PREEMPT_DYNAMIC Thu Mar  7 18:21:00 UTC 2024","pid":29118,"user":"r2","msg":"test"}
# List of 1
#  $ default:List of 6
#   ..$ level    : 'loglevel' int 400
#   .. ..- attr(*, "level")= chr "INFO"
#   ..$ namespace: chr "global"
#   ..$ params   :List of 1
#   .. ..$ : chr "test"
#   ..$ handlers :List of 3
#   .. ..$ formatter:function (..., .logcall = sys.call(), .topcall = sys.call(-1), .topenv = parent.frame())  
#   .. .. ..- attr(*, "generator")= language formatter_glue()
#   .. ..$ layout   :function (level, msg, namespace = NA_character_, .logcall = sys.call(), .topcall = sys.call(-1), .topenv = parent.frame())  
#   .. .. ..- attr(*, "generator")= chr "layout_json()"
#   .. ..$ appender :function (lines)  
#   .. .. ..- attr(*, "generator")= language appender_console()
#   ..$ message  : chr "test"
#   ..$ record   : Named chr "{\"time\":\"2024-04-09 09:17:29\",\"level\":\"INFO\",\"ns\":\"global\",\"ans\":\"global\",\"topenv\":\"R_Global"| __truncated__
#   .. ..- attr(*, "names")= chr "test"
#   ..- attr(*, "class")= chr "logger"

The list is because logger supports multiple sinks/layouts (or something like that ... @daroczig ?), so we reference [[1]]. Within that, the multiple components are for other various reasons, and we can target the $record to get what we need.

[FMKerckhof]

Thanks @r2evans , that already clarifies a lot - I should have been a bit more clear in my problem description as well. I am actually getting the problem because to interface with AWS lambda I am calling the lambda API using httr::POST with encode set to json (https://httr.r-lib.org/) - which under the hood calls httr:::body_config that in turn executes the code below for the json encode argument:

if (encode == "json") {
        body_raw(jsonlite::toJSON(body, auto_unbox = TRUE, digits = 22), 
            "application/json")
}

I have no option to pass along arguments to jsonlite::toJSON from the encompassing httr::POSTcall, hence my question above. hhtr2's req_body_json appears to have a bit more flexibility, but would require a very thorough rewrite of my runtime code. I'll monitor #152 to see how you proceed with this and for now try to stick to logger 0.2.2.