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" :)

from flogger.

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

from flogger.

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.

from flogger.

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?

from flogger.

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?

from flogger.

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

from flogger.

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.

from flogger.

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.

from flogger.

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

from flogger.

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:

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.

from flogger.

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

from flogger.

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.

from flogger.

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

from flogger.

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.

from flogger.

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.

from flogger.

""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.

from flogger.

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.");
}

from flogger.