Как использовать перехватчик gRPC для присоединения / обновления MDC журналирования в приложении Spring-Boot

Проблема

У меня есть приложение Spring-Boot, в котором я также запускаю сервер / службу gRPC. И сервлет, и код gRPC отправляют запросы к общему объекту для обработки запроса. Когда приходит запрос, я хочу обновить журнал, чтобы отобразить уникальный «ID», чтобы я мог отслеживать запрос через систему.

На стороне Spring я установил «Фильтр», который обновляет MDC ведения журнала, чтобы добавить некоторые данные в запрос журнала (см. этот пример). это нормально работает

На стороне gRPC я создал ServerInterceptor и добавил его в службу, в то время как перехватчик вызывается, код для обновления MDC не придерживается, поэтому, когда запрос приходит через службу gRPC, я не печатайте идентификатор в журнале. Я понимаю, что это связано с тем фактом, что я перехватываю вызов в одном потоке, а он отправляется gRPC в другом, я не могу понять, как перехватить вызовите поток, выполняющий работу, или добавьте информацию MDC, чтобы она должным образом распространялась на поток, выполняющий работу.

Что я пробовал

Я провел много поисков и был очень удивлен, не обнаружив этого вопроса / ответа, я могу только предположить, что мне не хватает навыков запроса :(

Я новичок в gRPC, и это первый перехватчик, который я пишу. Я пробовал добавить перехватчик несколькими способами (через ServerInterceptors.intercept, BindableService instance.intercept).

Я просмотрел Spring Boot gRPC Starter от LogNet, но не уверен это решило бы проблему.

Вот код, который я добавил в свой класс перехватчика

@Override
public <ReqT, RespT> ServerCall.Listener<ReqT> interceptCall(final ServerCall<ReqT, RespT> call, final Metadata headers, final ServerCallHandler<ReqT, RespT> next) {
    try {
        final String mdcData = String.format("[requestID=%s]",
            UUID.randomUUID().toString());
    MDC.put(MDC_DATA_KEY, mdcData);
    return next.startCall(call, headers);
    } finally {
        MDC.clear();
    }
}

ожидаемый результат

Когда запрос поступает через RESTful API, я вижу такой вывод журнала

2019-04-09 10:19:16.331 [requestID=380e28db-c8da-4e35-a097-4b8c90c006f4] INFO 87100 --- [nio-8080-exec-1] c.c.es.xxx: processing request step 1
2019-04-09 10:19:16.800 [requestID=380e28db-c8da-4e35-a097-4b8c90c006f4] INFO 87100 --- [nio-8080-exec-1] c.c.es.xxx: processing request step 2
2019-04-09 10:19:16.803 [requestID=380e28db-c8da-4e35-a097-4b8c90c006f4] INFO 87100 --- [nio-8080-exec-1] c.c.es.xxx: Processing request step 3
...

Я надеюсь получить аналогичный результат, когда запрос поступит через службу gRPC.

Спасибо


spring-boot grpc grpc-java slf4j mdc
person Jim M.    schedule 09.04.2019    source источник

Ответы (1)


arrow_upward
7
arrow_downward

Поскольку никто не ответил, я продолжал попытки и придумал следующее решение для моей функции interceptCall. Я не уверен на 100%, почему это работает, но в моем случае это работает.

    private class LogInterceptor implements ServerInterceptor {
        @Override
        public <ReqT, RespT> ServerCall.Listener<ReqT> interceptCall(final ServerCall<ReqT, RespT> call,
                                                                     final Metadata headers,
                                                                     final ServerCallHandler<ReqT, RespT> next) {
            Context context = Context.current();
            final String requestId = UUID.randomUUID().toString();
            return Contexts.interceptCall(context, call, headers, new ServerCallHandler<ReqT, RespT>() {
                @Override
                public ServerCall.Listener<ReqT> startCall(ServerCall<ReqT, RespT> call, Metadata headers) {

                    return new ForwardingServerCallListener.SimpleForwardingServerCallListener<ReqT>(next.startCall(call, headers)) {
                        /**
                         * The actual service call happens during onHalfClose().
                         */
                        @Override
                        public void onHalfClose() {
                            try (final CloseableThreadContext.Instance ctc = CloseableThreadContext.put("requestID",
                                    UUID.randomUUID().toString())) {
                                super.onHalfClose();
                            }
                        }
                    };
                }
            });
        }
    }

В моем application.properties я добавил следующее (которое у меня уже было)

logging.pattern.level = [% X]% -5level

"% X" указывает системе ведения журнала распечатать все пары "ключ-значение" CloseableThreadContext.

Надеюсь, это поможет кому-то другому.

person Jim M.    schedule 10.04.2019
comment
Немного не по теме. Но dd ваше приложение grpc поддерживает журнал доступа, как в http1? - person Key_coder; 18.05.2020