Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
hagbard opened this issue Aug 22, 2023 · 5 comments
Assignees
Labels
P2 type=defect Bug, not working as expected

Comments

@hagbard
Copy link
Contributor

hagbard commented Aug 22, 2023

See:
5aa0649#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
Copy link
Contributor Author

hagbard commented Aug 22, 2023

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
Copy link
Contributor Author

hagbard commented Aug 22, 2023

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()) ...

@cgdecker
Copy link
Member

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 cgdecker added the P2 label Aug 28, 2023
@cgdecker
Copy link
Member

82362ff 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).

@chaoren chaoren added the type=defect Bug, not working as expected label Aug 28, 2023
@hagbard
Copy link
Contributor Author

hagbard commented Sep 8, 2023

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
P2 type=defect Bug, not working as expected
Projects
None yet
Development

No branches or pull requests

3 participants