One Logger per R6 object: is there any practical limit to number of Loggers?

[mmuurr]

While reviewing a few recently-closed issues, I came across #41. This dovetailed nicely with an idea I've had for more helpful logging in Shiny apps where much of the application logic exists within R6 objects. I had considered extending Logger to help identify which R6 class and instance (the former via class(obj)[1], the latter via rlang::env_label(obj)) from which the log msg originated in some cases. This quickly got messy (having to walk up the call stack via parent.frame() and such) and I abandoned the idea, but #41 has given me a simpler new idea.

I'm now considering creating a separate Logger instance for each R6 object instance. The Logger could be constructed via the object's constructor like so:

public = list(
  initialize = function(...) {
    private$lgr <- lgr::get_logger(sprintf("%s/%s", class(self)[1], rlang::env_label(self)))
  }

Now, if using a LayoutFormat, a format string like "%L [%t] [%g] [%c] %m %f" will include the classname and instance identifier (via the %g element) from which the message originated.

Still some thought to be put into this (e.g. needing to deal with cloning correctly/carefully (unless setting cloneable=FALSE)), but the looming largest question I have has to do with any performance impacts of having lots of Logger objects around in memory. I'm guessing hundreds (or thousands) of Logger instances wasn't part of the initial design strategy of {lgr}, so I'm curious about your initial thoughts around this idea, @s-fleck.

[s-fleck]

So I am not 100% sure about the performance implications of this, but I know instantiating a large number of R6 objects can be bad. In this case your just 2x-ing the number of objects, so I see no problem here. If you are not already experiencing problems because of the large number of R6 objects you are instantiating you should be fine.

Very deep inheritance trees of lgr objects could be bad for performance; e.g. my/very/deeply/deeply/............/deeply/nested/logger. This is because a Logger sometimes has to look up information on all its parents. I've never benchmarked this in detail though so take it with a grain of salt. Very broad lgr trees should be fine!

While I think performance should not be an issue, you should benchmark just to be safe. Another solution would be using active bindings and filters:

myClass <- R6::R6Class(
  "myClass",
  public = list(
    foo = function(){
      self$lg$info("bar")
    }
  ),

  active = list(
    lg = function(x){
      lg <- lgr::get_logger(class(self)[[1]])$
        add_filter(lgr::FilterInject$new(address = rlang::env_label(self)), "object_address")
    }
  )
)

a <- myClass$new()
b <- myClass$new()

a$foo()
b$foo()
a$foo()

This way whenever you call self$lg the logger's myclass gets a Filter that injects the object address. It is important to name the filter in the $add_filter call so that it gets replaced, and not just a new filter added every time. You could also just define this once in a base class that all your r6 objects inherit from.

The dissadvantage is if you use the "myclass" logger from a different context, i will still show the memory address of the last R6 object that used it.

[s-fleck]

i should add that i don't think my suggestion would do much performance wise, but is IMHO a bit cleaner.

[mmuurr]

So the first issue I've run into is that I'm not sure how to easily remove (or deregister) Loggers from the global index once created. It appears that dropping the references to the Logger isn't enough to trigger garbage collection and finalize() (since those global structures also hold their own references).

lg <- lgr::get_logger("root/foo")
lgr::logger_tree()  ## foo is there, under root
rm(lg)              ## drop program's reference to lg
gc()                ## force gc to run
lgr::logger_tree()  ## foo is still there

I couldn't find anything in the docs about explicitly deregistering Loggers ... is this currently (officially) supported?

I did find lgr:::remove_all_loggers() and it seems like an easy extension to replicate for specific Loggers: remove a Logger specified by name from the lgr:::loggers environment.

remove_logger <- function(name) {
  rm(name, pos = loggers)
}

(That'll warn if name isn't found in loggers, but can obviously try-catch it to swallow/alter that warning if desired.)

Now, what happens if one removes the Logger but still holds a reference and tries to use that reference to log? I feel like this falls squarely into the 'developers still need to do the right thing' category and that typically the order should be:

1. lose one's R6 reference to the Logger
2. then remove_logger (by name).

[mmuurr]

Minor change to deal with the sometimes-explicit-sometimes-implicit root logger:

## vectorized
remove_logger <- function(name = character(0)) {
  has_explicit_root <- grepl("^root/", name)  ## where is explicit root present?
  with_explicit_root <- ifelse(has_explicit_root, name, sprintf("root/%s", name))  ## adds "root/" prefix if not present.
  without_explicit_root <- sub("^root/", "", with_explicit_root)  ## strips "root/" prefix
  rm(  ## indented below for clarity
    list = intersect(
      ls(loggers),
      c(with_explicit_root, without_explicit_root)
    ),
    pos = loggers
  )
}

[s-fleck]

Currently it is not supported to really remove loggers, except all at once with remove_all_loggers(), which I mainly implemented for cleaning up the session when running tests.

I never really considered the problem of large amounts of loggers without children. For loggers with children it does not make much sense to really remove them, because sometimes they have to be explictely re-initialized by their children.

To get rid of a logger you would have to remove all references to it (e.g. the lg object), and then also remove the reference from the loggers environment. However, there can also be references to a logger hidden in other places, for example if you use one of the loggers that logs the memory or uses a logging cache, they internal LogEvent objects might also still have a reference to the logger.

So while cleanly removing loggers seems like basic future, this probelm is rather complex and I am not sure if I want to address that at this point as long as I don't see a usecase with obvious severe performance implications. I also haven't looked into the whole concept in a while and I'm sure I'm also missing some potential problems.

In short, thats a can of worms that I don't want to open now ;). In addition, I'm still not sure if your initilizing a logger for each R6 object approach is the best way to achieve what you are trying to achieve.