Как использовать ведение журнала MDC с Java

Question

Я пытался найти способ использования MDC в реактивном / основанном на событиях асинхронном программировании в Java, но я не смог его найти.

Может ли кто-нибудь объяснить, как распространять переменные MDC в событиях / методах обратного вызова?

В таком случае, как можно отслеживать запрос до тех пор, пока ответ не будет обработан, как в традиционном синхронном программировании?

Answer 1

Как я объяснил в этой статье , вы можете использовать ведение журнала MDC для печати различных переменных уровня приложения в журнале.

Поэтому, учитывая, что мы помещаем текущий идентификатор транзакции базы данных вЖурнал 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");
}

Обратите внимание, что мы удаляем txId из хранилища переменных журнала MDC, чтобы онне добавляется в журнал после выхода из текущего метода доступа к данным.

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 добавлена ​​длякаждый оператор SQL выполняется после установки переменной журнала txId MDC.

Как я объяснил в этой статье , SELECT CAST(txid_current() AS text) используется в PostgreSQL для получения идентификатора базовой транзакции базы данных.т.

Answer 2

Программно вы можете сделать

MDC.put("transId", transId);

Где переменная transId содержит идентификатор транзакции, который вы хотите отслеживать.

, за которым следует конфигурация обратного входа:

<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 в вызовах.