Add tags from thread context to log

[int64max]

I want to achieve something similar to fish tagging in log4j (https://logging.apache.org/log4j/2.x/manual/thread-context.html)

Basically, we have a multi-component system receiving requests from users. At entry point, I want to add the user's ID to the thread context, and then each log line output by any sub-component should automatically include the user ID in the log. Asking each component to add the ID explicitly is error prone.

From what I understand looking at Flogger, this is what "tags" and "metadata" are supposed to be for. Though I don't see how we can use these. I don't want to use LOG.atInfo().with(USER_ID, userId).log() everywhere.

I've seen #309 and #145 but they don't seem to have a conclusion, and seem overly complicated for this use case.

What are my options? Is this not supported by flogger? If so, which classes should I extend to achieve my goal?

Thanks.

[hagbard]

ScopedLoggingContext is the mechanism designed exactly for your use case.
You'll need to depend on the Flogger grpc artifact to enable this, but if you do that, you should be able to write something like:

ScopedLoggingContext.newContext().withTags(Tags.of(USER_ID, userId)).run(() -> myRequest());

In your case, a "tag" looks like it will probably suffice since you say you only want to see the output in logs (not trigger any special behaviour in the backend because of it).

See the full API in:
https://github.com/google/flogger/blob/master/api/src/main/java/com/google/common/flogger/context/ScopedLoggingContext.java

By using gRPC contexts, you can also propagate the context between threads (e.g. for tasks being handled in worker pools). See the docs in https://grpc.github.io/grpc-java/javadoc/io/grpc/Context.html for more about how to propagate gRPC contexts.

Note that you could (for extra debugging fun) conditionally add a LogLevelMap to the scope when it's built (e.g. based on a URL parameter or the type of request). This way you can increase logging for "0.1% of foo requests" or "requests with the dbg flag" without the pain of increasing logging everywhere (which in a shared server can really hurt performance). When logging is enabled like this it also bypasses rate-limiting, so you can be sure you get everything for a request at the requested log level.

One note of caution is that Flogger does not accept scoped data in the "implicit" context (e.g. code run without any context having been created). So if you "add tags" to the "current" context using the ScopedLoggingContexts (note the trailing 's') helper class API, it will have no effect in those cases (and it returns a boolean indicating this).

[int64max]

Thanks for the comment. ScopedLoggingContext looks like exactly what I need. Yes, "tag" should suffice. And thanks for the extra note on LogLevelMap. We definitely run into scenarios like you mentioned (more logging for requests with the dbg flag), so I'll be using it.

I tried to use ScopedLoggingContext, but couldn't get it to work. I have the following code:

public static void main(String[] argv) {
    ScopedLoggingContext
        .getInstance()
        .newContext()
        .withTags(
            Tags.of("USER_ID", "int64max"))
        .run(() -> {
          LOG.atInfo().log("Processing user request.");
        });
  }

Using pattern 0 %x 1 %x{USER_ID} 2 %X 3 %X{USER_ID} 4 %msg%n, I get:

0 [] 1 [] 2 {} 3  4 Processing user request.

Can you kindly comment what I'm doing wrong? Thanks.

[hagbard]

I'm not 100% sure how Log4J converts tags to the MDC contexts, so can't obviously say if what you're doing with formatting works. Can you try:

import static com.google.common.flogger.LogContext.Key.TAGS;

LOG.atInfo().with(TAGS, Tags.of("USER_ID", "int64max")).log("Processing user request.");

If you can get that working as expected, the switch to ScopedLoggingContext should give the same result.

Also, if scoped contexts cannot be enabled there should be an error message in stderr explaining things. Can you check for that please?

However the Log4J backend code is:
https://github.com/google/flogger/blob/master/log4j/src/main/java/com/google/common/flogger/backend/log4j/Log4jLoggingEventUtil.java#L53

And looking at it, I'm not sure I see where the metadata (including TAGS) is processed (other than be being formatted into the message string). I didn't contribute this code, so perhaps it needs adjusting?

[int64max]

That works fine:

LOG.atInfo().with(TAGS, Tags.of("USER_ID", "int64max")).log("Processing user request.");

Prints:

0 [] 1 [] 2 {tags=[USER_ID=int64max]} 3  4 Processing user request.

How can we scope the tags?

[hagbard]

The code you had should have done it. Was there a message in stderr about not being able to find the grpc context implementation?

[hagbard]

Actually it occurs to me you probably need to set a system property:
https://github.com/google/flogger/blob/master/api/src/main/java/com/google/common/flogger/backend/system/DefaultPlatform.java#L71

We are looking at making this automatic (since not everyone is in a position to set system properties) but perhaps that change hasn't happened yet.

If you print the Platform.getConfigInfo() string it should show what's configured for the context stuff.

[int64max]

I have the following to set system properties:

  private static final FluentLogger LOG;
  static {
    System.setProperty(
      "flogger.backend_factory",
      "com.google.common.flogger.backend.log4j2.Log4j2BackendFactory#getInstance");
    LOG = FluentLogger.forEnclosingClass();
  }

Then, printing gives me the following:

Platform: com.google.common.flogger.backend.system.DefaultPlatform
BackendFactory: Log4j2 backend
Clock: Default millisecond precision clock
ContextDataProvider: No-op Provider
LogCallerFinder: Default stack-based caller finder

What should I set the flogger.logging_context system property to?

The code you had should have done it. Was there a message in stderr about not being able to find the grpc context implementation?

No error message on stderr.

[int64max]

Any pointers? I'll appreciate help as we'd like to roll this out, and set up observability on the tags. Thanks.

[hagbard]

If you examine the code I linked, the context data provider is created by this call to loadService:
https://github.com/google/flogger/blob/master/api/src/main/java/com/google/common/flogger/backend/system/DefaultPlatform.java#L101
which calls:

flogger/api/src/main/java/com/google/common/flogger/util/StaticMethodCaller.java

Line 50 in d2f442d

/**

So what you're using looks fine.

I suspect the issue is that logging may have already occurred before the class you are adding your code to was statically initialized. What happens if you set the property on the command line before starting the JVM?

The line ContextDataProvider: No-op Provider should change to list the gRPC implementation when this is working.

[chaoren]

It seems the feature you requested already exists, so I'll just close this issue now.

[hagbard]

I don't think this should be closed. I want understand what's missing from the docs and/or code so users don't run into these road blocks in future.

[int64max]

Thanks for all the help and pointers. I was able to make this work. For future reference, the code and output is below. As you can see, there is a warning in the output now, but still, the log context is correctly being added:

Pattern: Pattern: "%X - %msg%n"

Code:

  public static void main(String[] argv) {
    System.setProperty("flogger.backend_factory",
        "com.google.common.flogger.backend.log4j2.Log4j2BackendFactory#getInstance");
    System.setProperty("flogger.logging_context",
        "com.google.common.flogger.grpc.GrpcContextDataProvider#getInstance");
    FluentLogger LOG = FluentLogger.forEnclosingClass();

    System.out.println("******* CONFIG *******\n" + Platform.getConfigInfo() + "**********************\n");

    ScopedLoggingContext
        .getInstance()
        .newContext()
        .withTags(
            Tags.of("USER_ID", "int64max"))
        .run(() -> {
            LOG.atInfo().log("Processing user request.");
        });
  }

Output:

class com.google.common.flogger.util.StaticMethodCaller: cannot call expected no-argument constructor or static method 'com.google.common.flogger.grpc.GrpcContextDataProvider#getInstance()': java.lang.reflect.InvocationTargetException

******* CONFIG *******
Platform: com.google.common.flogger.backend.system.DefaultPlatform
BackendFactory: Log4j2 backend
Clock: Default millisecond precision clock
ContextDataProvider: com.google.common.flogger.grpc.GrpcContextDataProvider@336f1079
LogCallerFinder: Default stack-based caller finder
**********************

{tags=[USER_ID=int64max]} - Processing user request.

Process finished with exit code 0

[hagbard]

If you look at the code, the warning means that it didn't find a getInstance() method, so used the constructor instead. I think you can just get rid of the #getInstance suffix for the GrpcContextDataProvider. This "plugin" mechanism has gone through a few iterations and tries to be flexible about whether there's a static factory method or not.

However, what you are doing currently will fail as soon as a class referenced by your main class uses logging in its static initialization. It's entirely possible for a lot of code to be run before your "main" method is executed. These values really need to be set on the JVM via flags, not set in code.

[int64max]

I had actually initially set flogger.logging_context without the #getInstance suffix, but received the same warning message. You are right that it should use the default no-arg constructor, but it was attempting to use #getInstance, hence the warning in either case.

However, what you are doing currently will fail as soon as a class referenced by your main class uses logging in its static initialization. It's entirely possible for a lot of code to be run before your "main" method is executed. These values really need to be set on the JVM via flags, not set in code.

Yes, I understand this and thanks for pointing out. I had just left it here as an example. In practice, we set it in a static block in the class to which main belongs. So all is fine.

[hagbard]

""In practice, we set it in a static block in the class to which main belongs. So all is fine.""

Interesting. If the static block is the first thing in the class (before static fields) then I think that could work (it's not an approach that had occurred to me before). I don't recall if the JVM loads certain dependencies for the "main" class before it begins static execution, or whether dependency loading is only done as a result of static initialization (which should happen in top-to-bottom order).

Note that, of course, you'll need to be sure that you don't accidentally call any other libraries which might do (flogger) logging before setting the properties, but that's not too hard.

Please let me know what sort of documentation changes you think would have helped you not need to ask this question (I am well aware that Flogger's docs need some care and improvement. If you wanted to send this as a PR, just to make clear what you mean, I'd be happy to incorporate it.

[int64max]

I think something as simple as the following will go a long way to direct users to the right path.

Logging Context

You can use tags and metadata to automatically add information to logged lines. This is akin to Fish Tagging or Thread Context in Log4j (not sure you want to refer to Log4j in flogger documentation). To use tags, you need to provide a logging context first. This can be done by setting the flogger.logging_context system property, e.g., to com.google.common.flogger.grpc.GrpcContextDataProvider. Any tags added to the context are then logged if the pattern includes %X.

Best practice: you can use scoped context to automatically unset the tags. For example:

try (var scope = ScopedLoggingContext
        .getInstance()
        .newContext()
        .withTags(
            Tags.of("USER_ID", "int64max"))
        .install() {
  logger.atInfo().log("Procesing request.");
}

[hagbard]

Thanks, I'll see about making improvements to the docs.
Also note that tags cannot be "unset", they are a cumulative bag of values.
Metadata values can be replaced though (but also not unset).
I'll make sure the docs are clear on this too.

It can be difficult for me to realize what's clear or not in the open-source docs because (a) I designed all the APIs, so don't need the docs and (b) we have additional docs for Flogger inside Google which are what I primarily use/maintain.

So thanks for helping out and giving me the perspective of someone from the "outside" :)