Improve logging context integration

[rocketraman]

Using log4j2 context seems a bit limited for non-thread use cases. The assumption that context will always be set at the Thread or coroutine level is IMO false, and sometimes we just want to set context for a particular block of code, or for a particular logger.

We should have a way to do something like this outside of a coroutine / suspending context:

withContextMap(...) {
  // log something
}

Possible implementations (only map shown here, but similar for stack)?

fun <T> withContextMap(
  map: Map<String, String>,
  block: () -> T,
): T {
  val oldMap = ContextMap.view
  return try {
    ContextMap += map
    block()
  } finally {
    ContextMap.clear()
    ContextMap += oldMap
  }
}

Could also be related to #36. We may want to do something like:

val log = parentLog.withContext(...)

...

log.debug { ... }

[vy]

I think this is related to apache/logging-log4j2#2213.

[rocketraman]

I think this is related to [apache/logging-log4j2#2213].

@vy It seems so, but I'm unsatisfied by the answers in the discussion.

Let me see if I can illustrate my use case with a generic example.

Assume we have this setup:

class T {
  val log = logger()

  val r: R

  fun doSomethingInThread() {
    r.doSomethingOnResource()
    log.info { "bar" }
  }
}

class R {
  val log = logger()

  fun doSomethingOnResource() {
    log.info { "foo" }
  }
}

T represents some kind of thread. It could be an HTTP request thread for example. So we have some diagnostic context related to that thread, say a request id.

R represents some kind of resource used by T. It could be a state machine or a physical resource or whatever. There is some diagnostic context related to this resource, say a resource name or id.

Inside doSomethingOnResource when logging "foo", both the thread and resource diagnostic contexts are relevant.

However, inside doSomethingInThread i.e. the "bar" log, only the thread context is relevant.

If doSomethingOnResource were to set the context for the resource in the ThreadContext before the foo log, then the bar log would also show the resource context, which would be incorrect.

The thread or coroutine attached context works well for T but doesn't work well at all for R, which is used within the thread of T.

[vy]

@rocketraman, AFAIC, the problem is the lack of a dynamically scoped variable (you might be familiar with this concept if you have ever used a Lisp dialect), and hence, we use the one closest to that: a thread-local one. Imagine ThreadContext is a ScopedValue. Your withContextMap(map: Map<String, String>, block: () -> T) could simply be represented as ThreadContext.runWhere("mdcKey", "mdcVal", doStuff()). Am I missing something?

[rocketraman]

Am I missing something?

@vy Yes, I think so. Or I am :-)

If you look back at my example, logging in R is not (only) thread-scoped, it is both thread-scoped AND class-scoped. In other words, I want all logging in R to show the specific context of R in addition to the thread-scoped context that is executing the code.

[rocketraman]

I think the ideal solution for this would look something like this, and could leverage the solution we come up with for #36:

class R {
  val log = logger().withContext(...)

  fun doSomethingOnResource() {
    log.info { "foo" }
  }
}

[rgoers]

Please see #2385 as this should do what you want - for Java. I am not sure how to incorporate this into Kotlin.

You can now do:

ScopedContext.newInstance().where("key1", "value1").where("key2", "value2").run(() -> {
    logger.debug("This will include key1 and key2 in the ThreadContextMap of the LogEvent");
 });

or you can do

boolean result = ScopedContext.newInstance().where("key1", "value1").where("key2", "value2").call(() -> {
    logger.debug("This will include key1 and key2 in the ThreadContextMap of the LogEvent");
    return true;
 });

In addition, nesting is supported as are arbitrary objects. To include the key/value pairs of the parent you would do:

ScopedContext.newInstance().where("user", userObject).run(() -> {
   ScopedContext.newInstance(true).where("key1", "value1").run() -> {
          logger.debug("This will include the String representation of the user and key1");
    });
});

If the object implements the Renderable interface then it can control the formatting of the object. Otherwise, toString() is used.

[ppkarwasz]

If you look back at my example, logging in R is not (only) thread-scoped, it is both thread-scoped AND class-scoped. In other words, I want all logging in R to show the specific context of R in addition to the thread-scoped context that is executing the code.

There are already two sources for context data:

• the contents of the thread-bound context map,
• the contents of the <Property> elements bound the logger in the configuration:

<Logger name="resource">
    <Property name="resourceId" value="abcd"/>
</Logger>

Is this what you are missing?

[rocketraman]

@rgoers I think you missed the class-scoped (not thread-scoped) context in my example.

@ppkarwasz Ah interesting -- if I could bind Property dynamically then yes, that would work. For example, lets say I have 3 instances of class R, all with different values of resourceId. They all use the same logger name, but each have a different resourceId. I haven't looked deeply but it doesn't seem there is any API for this.

[rgoers]

@rocketraman I guess I am not grasping at all what you want. With my PR you can now do:

class T {
  private static final Logger log = LogManger.getLogger(T.class);

  R r = new R();

  doSomethingInThread() {
   ScopedContext.newInstance().where("context", "thread").run(() -> {
          r.doSomethingOnResource();
          log.info{ "bar");
      });
  }
}

class R {
 private static final Logger log = LogManger.getLogger(R.class);

  fun doSomethingOnResource() {
    log.info("context will be 'thread' here);
    ScooedContext.newInstance().where("context", "resource").run(() -> {
        log.info { "foo" };
    )};
  }
}

In this example the value of "context" when bar is logged would be "thread" and would be "resource" when foo is logged.

so everything inside the run method, and only inside the run method contains the data. In the example above the value of context will vary depending on which ScopedContext you are executing in. Isn't this what you wanted?

Note, that while the PR uses a ThreadLocal it has to do that to make it thread-safe. Each Thread has its own stack of contexts.

Now it would be great if instead you could annotate the class or method with the scope but due to their limitations I am not sure how you could actually populate the context since properties associated with annotations have to be known at compile time.

[rocketraman]

@rgoers Yes, in my original post I proposed a method withContextMap that would be used in Kotlin the same way as ScopedContext (though its a bit nicer in Kotlin).

Now it would be great if instead you could annotate the class or method with the scope but due to their limitations I am not sure how you could actually populate the context since properties

I think with some kind of LogBuilder-type API this could be possible.

[rgoers]

@rocketraman Again, I don't understand. ScopedContext IS a builder. Each where method adds a new key/value pair to the context. The run and call methods are, in essence, the builders. Of course, that isn't strictly true since newInstance creates the object, but the ScopedContext cannot reallly be used for anything until run or call are called.

I also don't see how a builder could be leveraged from an Java annotation.

Note: I very loosely used Java 21 ScopedValues for the API for this, although ScopedContext is quite a bit simpler IMO. The where method in scoped variables creates a new immutable ScopedValue.Carrier - I believe the JDK has gone a bit overboard in making things immutable.

[ppkarwasz]

I think we should discuss it in dev@logging. I started a thread dedicated to this subject.

[rocketraman]

Again, I don't understand. ScopedContext IS a builder.

@rgoers ScopedContext is a builder for the context. I was talking about a builder for the logger. The thread that @ppkarwasz started is conceptually the same as what I was talking about:

Regarding problem 1, I don't know what the best approach would be. Maybe we can add withContextData to LogBuilder and create a BoundLogger interface with methods to create LogBuilder instance pre-filled with some context data.

[rgoers]

OK. Personally, I see little value in adding context data to a logger. That simply wouldn't fit with any use cases I work with. However, it might if Logger names were more generic instead of using class names as is done now by convention.