如何使用Java进行MDC日志记录

Question

我试图在java中找到一种在基于反应/事件的异步编程中使用MDC的方法，但我找不到。

有人可以解释如何在回调事件/方法中传播MDC变量吗？

在这种情况下，如何在传统的同步编程中提供响应之前，如何跟踪请求？

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来存储上下文，因此如果您跳转服务器或线程（例如使用工作模式），则必须在新线程中重置MDC上下文。我想这可能是你真正要求的，但是没有捷径可以在线程更改中保持MDC上下文。这意味着您必须在调用和回叫中将transId作为参数发送。

注释和AOP可以减轻在调用中传输transId的一些苦差事。

Answer 2

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

因此，考虑到我们将当前数据库事务id放在MDC日志中：

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

我们可以使用以下log appender模式将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)来获取底层数据库事务标识符。