如何在Java中使用MDC记录日志

Question

我试图找到在Java的反应式/事件驱动异步编程中使用MDC的方法，但是我没有找到。

有人能够解释一下如何在回调事件/方法中传播MDC变量吗？

在这种情况下，如何跟踪请求直到响应被提供，就像传统的同步编程一样？

- mac

Answer 1

程序化地，你可以做到：

MDC.put("transId", transId);

变量transId保存了您想要跟踪的交易ID。

接下来是logback配置：

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

请注意，MDC使用threadLocal存储上下文，因此如果您跳转服务器或线程（例如使用worker模式），则必须在新线程中重置MDC上下文。我想这可能是您真正询问的内容，但没有捷径可以在线程更改时保持MDC上下文。这意味着您必须在两个调用和回调中将transId作为参数发送。

注释和AOP可以缓解在调用中传递transId的某些乏味。

- Jan Larsen

---

OP问了一下响应式编程怎么样？回调函数是由单独的线程调用的，对吧？如何跟踪请求流程？ - Saptarshi Basu

Answer 2

如我在本文中所解释的那样，您可以使用MDC日志记录将各种应用程序级变量打印到日志中。

因此，考虑将当前数据库事务ID放入MDC日志中：

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

我们可以使用以下日志记录器模式将txId日志变量打印到日志中：

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

%X{txId}模式用于引用txId日志变量。

因此，在执行以下测试用例时：

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

请注意，我们正在从MDC日志变量存储中删除txId，以便在退出当前数据访问方法后不会将其附加到日志中。

Hibernate将生成以下日志条目：

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"

在设置txId MDC日志变量后执行每个SQL语句时，将添加TxId条目。

正如我在this article中解释的那样，在PostgreSQL中使用SELECT CAST(txid_current() AS text)来获取底层数据库事务标识符。

- Vlad Mihalcea