Ability to add metadata to all log event created by logger

[kertzi]

Some use cases it would be very beneficial to be able to attach metadata to logger created in some class.
There is MDC and NDC but those are global for thread and are not very good option in async application where some code maybe shared by same thread, for example application which uses workers and each job what workers does have own context and in that context there is logger which is used to log event specific for that job/context. In that case it would be way more better to attach needed metadata directly to logger.

Some example by pseudo code:

class App {

  void startWorkAtWorker() {
    Context context;
  
    context.logger = LogManager.getLogger("whatever");
    context.logger.addMetadata("key", "value");
    
    Worker WorkerInstance;   
    WorkerInstance.queue(context)
  }
}

class Worker {
 void runTask() {
  // pick context from queue....

  // run task
   context.logger.info("starting work, this event has metadata, pushed when context created");
 }
}

[vy]

I certainly recognize the problem. It is pretty common in reactive applications. The arrival of Loom and scoped values adds extra dimensions to it. Delivering a solution that only fixes the issue for one might jeopardize delivering a good fix for the others. I doubt if there is any one-size-fits-all answer to this. I personally expect MDC/NDC to be populated from scoped values in the future.

Coming back to your proposal of enriching the Logger with an extra field... Let's say we have implemented that. How will the downstream use it? We need to adapt all layouts to take this new field into account too. Hence, "a new field to Logger" has far reaching implications.

Using MapMessage

An approach you can carry yourself out is to use MapMessages instead:

context.addMetadata("githubUserId", "vy");
logger.info(new MapMessage(Map.of(
    "message", "comment submitted",
    "metadata", context.getMetadata())));

This is an area where Log4j shines compared to other logging solutions in the market: You can log anything that implements the Message interface, you are not limited to Strings.

Injecting a dynamic MDC entry

You can try injecting into MDC an Object whose toString() will return (or StringBuilderFormattable#formatTo(StringBuilder) will render) the metadata stored in the TaskContext. Something like this might work:

private volatile TaskContext taskContext;

private void initMdc() {
    ObjectThreadContextMap map = (ObjectThreadContextMap) ThreadContext.getThreadContextMap();
    map.put("taskMetadata", (StringBuilderFormattable) (buffer -> buffer.append(taskContext.getMetadata())));
}

private void performTask() {
    taskContext.addMetadata("foo", "bar");
    logger.info("buzz");
}

[kertzi]

Thanks for your prompt input!
I think I understand your alternative approach, still it requires that you need to add metadata before each log event write that's not as convenient as metadata is already stored in logger context.

My current solution is (I'm using slf4j as for logging api) to create custom implementation (based on implementation you guys has done) for slf4j which adds my metadata to MDC in each log call:

public class MetadataLog4jLogger implements LocationAwareLogger, Serializable {
....
    protected void addMetadata() {
        if (!this.metadata.isEmpty()) {
            for( Map.Entry<String, String> entry : this.metadata.entrySet()) {
                MDC.put(entry.getKey(), entry.getValue());
            }
        }
    }
    @Override
    public void debug(final String format, final Object o) {
        addMetadata();
        logger.logIfEnabled(FQCN, Level.DEBUG, null, format, o);
        clearMetadata();
    }
....
}

Then in app code I just push metadata to logger:

        org.slf4j.Logger log = LoggerFactory.getLogger(MyClass.class);

        MetadataLog4jLogger logRef = (MetadataLog4jLogger) log;
        logRef.getMetadata().put("SomeKey", "Somevalue");
        logRef.getMetadata().put("OtherKey", "OtherValue");

It would be convinient to has this kind of thing possible directly from log4j2 framework but I understand it has far reaching implications.

[vy]

your alternative approach, still it requires that you need to add metadata before each log event write

@kertzi, no. You just call initMdc() once while creating the worker threads. taskMetadata, dynamically populated from the reactive (or, say, Kotlin coroutine) context, will pass the appropriate value to the layout during MDC serialization. Let me demonstrate this with an example:

Given the following log4j2.xml

<?xml version="1.0" encoding="UTF-8"?>
<Configuration>
  <Appenders>
    <Console name="CONSOLE">
      <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %m %X%n"/>
    </Console>
  </Appenders>
  <Loggers>
    <Root level="INFO">
      <AppenderRef ref="CONSOLE"/>
    </Root>
  </Loggers>
</Configuration>

running below Log4j2Discussion2214 class

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.ThreadContext;
import org.apache.logging.log4j.spi.ObjectThreadContextMap;
import org.apache.logging.log4j.util.StringBuilderFormattable;

import java.time.Duration;
import java.util.Random;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import java.util.concurrent.atomic.AtomicInteger;
import java.util.concurrent.locks.LockSupport;
import java.util.function.Supplier;

public final class Log4j2Discussion2214 {

    static {
        System.setProperty("log4j.configurationFile", "target/classes/Log4j2Discussion2214.xml");
    }

    private static final Logger LOGGER = LogManager.getLogger();

    private static final class Task implements Runnable {

        @Override
        public void run() {
            long pauseNanos = Duration.ofMillis(200).toNanos();
            while (!Thread.currentThread().isInterrupted()) {
                LOGGER.info("task run");
                LockSupport.parkNanos(pauseNanos);
            }
        }

    }

    private static final class TaskContextGenerator implements Runnable, Supplier<Integer> {

        private final AtomicInteger context = new AtomicInteger();

        @Override
        public void run() {
            Random random = new Random(0);
            long pauseNanos = Duration.ofMillis(90).toNanos();
            while (!Thread.currentThread().isInterrupted()) {
                int nextContext = random.nextInt();
                LOGGER.info("context change: {}", nextContext);
                context.set(nextContext);
                LockSupport.parkNanos(pauseNanos);
            }
        }

        @Override
        public Integer get() {
            return context.get();
        }

    }

    public static void main(String[] args) {
        TaskContextGenerator taskContextGenerator = new TaskContextGenerator();
        int maxTaskCount = 10;
        ExecutorService executorService = Executors.newFixedThreadPool(maxTaskCount, runnable -> new Thread(() -> {
            ObjectThreadContextMap map = (ObjectThreadContextMap) ThreadContext.getThreadContextMap();
            map.putValue(
                    "taskMetadata",
                    (StringBuilderFormattable) (buffer -> buffer.append(taskContextGenerator.get())));
            runnable.run();
        }));
        executorService.submit(taskContextGenerator);
        for (int taskId = 0; taskId < (maxTaskCount - /* dedicated context generator: */ 1); taskId++) {
            LockSupport.parkNanos(Duration.ofMillis(50).toNanos()); // adding some jitter
            executorService.submit(new Task());
        }
        LockSupport.parkNanos(Duration.ofMillis(500).toNanos());
        executorService.shutdownNow();
    }

}

produces the following output

09:53:57.526 [Thread-0] context change: -1155484576 {taskMetadata=0}
09:53:57.566 [Thread-1] task run {taskMetadata=-1155484576}
09:53:57.616 [Thread-2] task run {taskMetadata=-1155484576}
09:53:57.618 [Thread-0] context change: -723955400 {taskMetadata=-1155484576}
09:53:57.666 [Thread-3] task run {taskMetadata=-723955400}
09:53:57.709 [Thread-0] context change: 1033096058 {taskMetadata=-723955400}
09:53:57.717 [Thread-4] task run {taskMetadata=1033096058}
09:53:57.766 [Thread-1] task run {taskMetadata=1033096058}
09:53:57.767 [Thread-5] task run {taskMetadata=1033096058}
09:53:57.799 [Thread-0] context change: -1690734402 {taskMetadata=1033096058}
09:53:57.816 [Thread-2] task run {taskMetadata=-1690734402}
09:53:57.817 [Thread-6] task run {taskMetadata=-1690734402}
09:53:57.867 [Thread-3] task run {taskMetadata=-1690734402}
09:53:57.868 [Thread-7] task run {taskMetadata=-1690734402}
09:53:57.889 [Thread-0] context change: -1557280266 {taskMetadata=-1690734402}
09:53:57.917 [Thread-4] task run {taskMetadata=-1557280266}
09:53:57.918 [Thread-8] task run {taskMetadata=-1557280266}
09:53:57.967 [Thread-1] task run {taskMetadata=-1557280266}
09:53:57.967 [Thread-5] task run {taskMetadata=-1557280266}
09:53:57.968 [Thread-9] task run {taskMetadata=-1557280266}
09:53:57.980 [Thread-0] context change: 1327362106 {taskMetadata=-1557280266}
09:53:58.017 [Thread-2] task run {taskMetadata=1327362106}
09:53:58.018 [Thread-6] task run {taskMetadata=1327362106}
09:53:58.067 [Thread-3] task run {taskMetadata=1327362106}
09:53:58.068 [Thread-7] task run {taskMetadata=1327362106}
09:53:58.070 [Thread-0] context change: -1930858313 {taskMetadata=1327362106}
09:53:58.117 [Thread-4] task run {taskMetadata=-1930858313}
09:53:58.118 [Thread-8] task run {taskMetadata=-1930858313}
09:53:58.160 [Thread-0] context change: 502539523 {taskMetadata=-1930858313}
09:53:58.167 [Thread-1] task run {taskMetadata=502539523}
09:53:58.168 [Thread-5] task run {taskMetadata=502539523}
09:53:58.169 [Thread-9] task run {taskMetadata=502539523}
09:53:58.217 [Thread-2] task run {taskMetadata=502539523}
09:53:58.218 [Thread-6] task run {taskMetadata=502539523}
09:53:58.251 [Thread-0] context change: -1728529858 {taskMetadata=502539523}
09:53:58.268 [Thread-3] task run {taskMetadata=-1728529858}
09:53:58.268 [Thread-7] task run {taskMetadata=-1728529858}
09:53:58.318 [Thread-4] task run {taskMetadata=-1728529858}
09:53:58.319 [Thread-8] task run {taskMetadata=-1728529858}
09:53:58.341 [Thread-0] context change: -938301587 {taskMetadata=-1728529858}
09:53:58.367 [Thread-1] task run {taskMetadata=-938301587}
09:53:58.368 [Thread-5] task run {taskMetadata=-938301587}
09:53:58.369 [Thread-9] task run {taskMetadata=-938301587}
09:53:58.417 [Thread-2] task run {taskMetadata=-938301587}
09:53:58.418 [Thread-6] task run {taskMetadata=-938301587}
09:53:58.431 [Thread-0] context change: 1431162155 {taskMetadata=-938301587}
09:53:58.468 [Thread-3] task run {taskMetadata=1431162155}

This example demonstrates that

1. You initialize MDC once for the scheduler threads.
2. taskMetadata is dynamically populated from the task context.

[kertzi]

Thank you for example code!
I'm now trying that but for some reason threadcontext is null in my initMdc()

    private void initMdc() {
        ObjectThreadContextMap map = (ObjectThreadContextMap) ThreadContext.getThreadContextMap();
        map.put("taskMetadata", this.getLogMetadata());
    }
    private String getLogMetadata() {
        Map<String, String> meta = new HashMap<>();
        meta.put("Key", "Value");
        return meta.toString();
    }

[kertzi]

Got it. I just changed my initMdc() to:

private void initMdc() {
        ThreadContext.put("taskMetadata", this.getLogMetadata());
    }

[rgoers]

Actually, you can create a ContextDataProvider to deal with this. Just store the data in the ContextDataProvider when you create it. However, the ContextDataProvider is NOT specific to a Logger. But this is similar to your approach of adding data to the MDC before each logging call except that this does NOT add it to the MDC but to the ThreadContextMap in the LogEvent.

[rgoers]

Please see #2385 as this should do what you want.

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]

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