flogger icon indicating copy to clipboard operation
flogger copied to clipboard

I don't believe ScopedLoggingContexts should obviously accept null "no-op" arguments.

Open hagbard opened this issue 2 years ago • 5 comments

See: https://github.com/google/flogger/commit/5aa06498bacb2790dde73fd4c30c9ac796b58047#commitcomment-124981853

The problem with the commit which added this is that now you can pass in null (perhaps via a variable) and get unexpected runtime failures when building a logging context.

ScopedLoggingContext.newContext().withTags(tags1).withTags(tags2)...

Will fail at runtime if both tags1 and tags2 are non zero (the API only lets you see one tags instance). However if tags1 is null, the code will not throw an exception.

When I designed this API I had explicitly made it so that only one call withTags/withLogLevel was allowed (this encourages people to pull together they data they want to add before making the call). With the new change, this breaks that behaviour.

  1. withTags() doesn't need to cope with a null parameter as a "no-op", since Tags.empty() exists.
  2. withLogLevel() also has a valid "no-op" instance (via create(Level.OFF) which could be pulled out into a static field).

Having these methods accept null (and having that create different behaviour to passing the non-null no-op instance) is potentially confusing to users.

Only withMetadata() (which is defined to be able to be called more than once) arguably needs to handle null input, and that should just behave in exactly the same way as with() in the logging API.

hagbard avatar Aug 22 '23 15:08 hagbard

At the very least, passing "null" to withTags() / withLogLevelMap() should be a synonym for passing Tags.empty() / LogLevelMap.create(OFF) to avoid accidentally allowing methods to (sometimes) be callable twice.

And someone would need to check that passing LogLevelMap.create(OFF) is properly short-circuited when contexts are merged.

EDIT: I just checked and it looks like it is NOT handled well. Having the no-op log level map pushes you into a non-optimal code path for every log statement.

I had always envisaged code which want to add a log level map would look something like:

  DebugLevel dbgLevel = getDebugLevelFrom(request);
  if (dbgLevel != null) {
    LogLevelMap levelMap = getLevelMap(dbg);
    Tags tags = Tags.of("request_id", getRequestIdFrom(request));
    try (var context = ScopedLoggingContexts.newContext().withLogLevelMap(levelMap).withTags(tags).install()) {
      logger.atFine().log("Enabling targeted debug logging (level=%s)", dbgLevel);
      filterChain.doFilter(request, response);
    }    
  } else {
    // No debug level given, so no additional logging and no context created.
    filterChain.doFilter(request, response);
  }

hagbard avatar Aug 22 '23 15:08 hagbard

My recommendation is:

  1. Revert the change to withTags() and document that Tags.empty() exists.
  2. Add a LogLevelMap.noOp() singleton getter method and document that in withLogLevelMap()
  3. Add a isNoOp() method in LogLevelMap and test that when merging maps and (importantly) when deciding whether to flip the static flag which makes every log statement slower.

https://github.com/google/flogger/blob/master/grpc/src/main/java/com/google/common/flogger/grpc/GrpcContextDataProvider.java#L74C30-L74C30

I.e. change: https://github.com/google/flogger/blob/master/grpc/src/main/java/com/google/common/flogger/grpc/GrpcContextData.java#L139 to:

if (logLevelMap != null && !logLevelMap.isNoOp()) ...

hagbard avatar Aug 22 '23 15:08 hagbard

Thanks for catching this. I was initially dubious about allowing null like this until I saw that there were in fact other methods in the same class doing that, but I hadn't thought about Tags.empty() etc. as an alternative. I'll check with the person who sent the change about whether there's some particular reason that wouldn't work for them, but I imagine we can roll this back and make the changes you describe.

cgdecker avatar Aug 22 '23 15:08 cgdecker

82362ffc9cc726d69791d0d0257b50c2d4de88f3 changes withTags back to requiring a non-null argument and makes withLogLevelMap once again not callable twice.

null is currently still allowed for the LogLevelMap, in part because as you point out it's important to avoid using a LogLevelMap at all when it isn't needed, even if it's a no-op instance, and those code paths are already handled by null. Having to check for both null and isNoOp() feels a bit awkward and error-prone (though we could mitigate that some with a helper method).

I could also potentially see doing something like adding a no-op LogLevelMap, but only checking it in withLogLevelMap and translating it to null immediately (while still disallowing a null argument and not allowing it to be called twice).

cgdecker avatar Aug 28 '23 15:08 cgdecker

I'd still be interested to know where someone has a dynamically set level map which might be "no level map". I don't disbelieve it's possible but I did think about that use case and it always seemed better to just not create a context at all in those cases.

hagbard avatar Sep 08 '23 20:09 hagbard