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

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

3 голосов
/ 09 апреля 2019

Задача

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

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

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

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

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

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

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

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

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

Спасибо

1 Ответ

2 голосов
/ 10 апреля 2019

Поскольку никто не ответил, я продолжал пробовать и придумал следующее решение для моей функции 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 ключ / значения.

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

...