How to use MDC logging with Java

Question

I have tried to find out a way of using MDC in reactive/event based async programming in java but I could not find one.

Could someone explain how to propagate MDC variables in call back events/methods?

In this case, how a request can be traced until a response is served like in traditional Synchronous programming?

Answer 1

As I explained in this article, you can use MDC logging to print various application-level variables into the log.

Therefore, considering we put the current database transaction id in the MDC log:

MDC.put("txId", String.format(" TxId: [%s]", transactionId(entityManager)));

We can print the txId log variable to the log using the following log appender pattern:

<appender name="console" class="ch.qos.logback.core.ConsoleAppender">
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
        <level>TRACE</level>
    </filter>
    <encoder>
        <Pattern>%-5p [%t]:%X{txId} %c{1} - %m%n</Pattern>
        <charset>UTF-8</charset>
    </encoder>
</appender>

The %X{txId} pattern is used to reference the txId log variable.

So, when executing the following test case:

try {
    doInJPA(entityManager -> {
        MDC.put(
            "txId",
            String.format(
                " TxId: [%s]",
                transactionId(entityManager)
            )
        );

        Post post = entityManager.createQuery(
            "select p " +
            "from Post p " +
            "where p.id = :id", Post.class)
        .setParameter("id", 1L)
        .setLockMode(LockModeType.PESSIMISTIC_WRITE)
        .getSingleResult();

        try {
            executeSync(() -> {
                try {
                    doInJPA(_entityManager -> {
                        MDC.put(
                            "txId",
                            String.format(
                                " TxId: [%s]",
                                transactionId(_entityManager)
                            )
                        );

                        Post _post = (Post) _entityManager.createQuery(
                            "select p " +
                            "from Post p " +
                            "where p.id = :id", Post.class)
                        .setParameter("id", 1L)
                        .unwrap(org.hibernate.query.Query.class)
                        .setLockOptions(
                            new LockOptions()
                            .setLockMode(LockMode.PESSIMISTIC_WRITE)
                            .setTimeOut(LockOptions.NO_WAIT)
                        )
                        .getSingleResult();
                    });
                } finally {
                    MDC.remove("txId");
                }
            });
        } catch (Exception expected) {
            assertTrue(
                ExceptionUtil
                .rootCause(expected)
                .getMessage()
                .contains(
                    "could not obtain lock on row in relation"
                )
            );
        }
    });
} finally {
    MDC.remove("txId");
}

Notice that we are removing the txId from the MDC log variable storage so that it will not be appended to the log after exiting the current data access method.

Hibernate is going to generate the following log entries:

DEBUG [Alice]: n.t.d.l.SLF4JQueryLoggingListener -
    Time:1,
    Success:True,
    Type:Prepared,
    Batch:False,
    QuerySize:1,
    BatchSize:0,
    Query:["
        SELECT CAST(txid_current() AS text)
    "],
    Params:[()]

DEBUG [Alice]: TxId: [796989] n.t.d.l.SLF4JQueryLoggingListener -
    Name:DATA_SOURCE_PROXY,
    Time:3,
    Success:True,
    Type:Prepared,
    Batch:False,
    QuerySize:1,
    BatchSize:0,
    Query:["
        SELECT p.id AS id1_0_,
               p.title AS title2_0_,
               p.version AS version3_0_
        FROM   post p
        WHERE  p.id = ?
        FOR UPDATE OF p "],
    Params:[(
        1
    )]

DEBUG [Bob]: n.t.d.l.SLF4JQueryLoggingListener -
    Time:1,
    Success:True,
    Type:Prepared,
    Batch:False,
    QuerySize:1,
    BatchSize:0,
    Query:["
        SELECT CAST(txid_current() AS text)
    "],
    Params:[()]

DEBUG [Bob]: TxId: [796990] n.t.d.l.SLF4JQueryLoggingListener -
    Time:0,
    Success:False,
    Type:Prepared,
    Batch:False,
    QuerySize:1,
    BatchSize:0,
    Query:["
        SELECT p.id AS id1_0_,
               p.title AS title2_0_,
               p.version AS version3_0_
        FROM   post p
        WHERE  p.id = ?
        FOR UPDATE OF p NOWAIT  "],
    Params:[(
        1
    )]

WARN  [Bob]: TxId: [796990] o.h.e.j.s.SqlExceptionHelper -
    SQL Error: 0, SQLState: 55P03

ERROR [Bob]: TxId: [796990] o.h.e.j.s.SqlExceptionHelper -
    ERROR: could not obtain lock on row in relation "post"

The TxId entry is added for each SQL statement executed after setting the txId MDC log variable.

As I explained in this article, the SELECT CAST(txid_current() AS text) is used in PostgreSQL to get the underlying database transaction identifier.

Answer 2

Programmatically you can do

MDC.put("transId", transId);

Where the transId variable holds the transaction ID you want to be able to track.

followed by this logback config:

<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
        <pattern>[%date] %level [%mdc{transId}] %m%n</pattern>
    </encoder>
</appender>

Be aware that MDC uses threadLocal to store context, so if you jump server or thread (using worker pattern for instance) you will have to reset the MDC context in the new thread. I suppose that might be what you are really asking, but there is no shortcut to keep MDC context across a thread change. This means that you will have to send your transId as a parameter in both calls and call-backs.

Annotations and AOP can alleviate some of the drudgery of transferring the transId in calls.