如何在Spring-Boot应用程序中使用gRPC拦截器附加/更新日志MDC

Question

问题

我有一个Spring-Boot应用程序，在其中还启动了一个gRPC服务器/服务。servlet和gRPC代码都会向一个共同的对象发送请求来处理请求。当请求到达时，我希望更新日志以显示唯一的“ID”，以便可以通过系统跟踪请求。

在Spring方面，我设置了一个“过滤器”，该过滤器更新日志MDC以添加一些数据到日志请求（请参阅此示例）。 这很好用

在gRPC方面，我创建了一个“ServerInterceptor”并将其添加到服务中，尽管拦截器被调用了，但更新MDC的代码却不能够保留，所以当一个请求通过gRPC服务时，我不能在日志中打印出ID。我意识到这与我在一个线程中拦截调用，而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服务时获得类似的输出。

谢谢

- Jim M.

Answer 1

由于没有人回复，我继续尝试并为我的interceptCall函数提出了以下解决方案。 我不太确定为什么这个方案有效，但它适用于我的使用情况。

    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键/值对。

希望这可以帮助其他人。

- Jim M.

---

有点离题。但是你的grpc应用程序是否支持像http1中的访问日志？ - Key_coder

Answer 2

MDC 将数据存储在 ThreadLocal 变量中，你的想法是对的 - "我意识到这与我在一个线程中拦截调用，而 gRPC 在另一个线程中分派调用有关"。请查看 @Eric Anderson 关于正确使用 ThradLocal 的答案 - https://dev59.com/LbTna4cB1Zd3GeqPAtSg#56842315

这里有一个可行的示例 -

public class GrpcMDCInterceptor implements ServerInterceptor {
  private static final String MDC_DATA_KEY = "Key";

  @Override
  public <R, S> ServerCall.Listener<R> interceptCall(
      ServerCall<R, S> serverCall,
      Metadata metadata,
      ServerCallHandler<R, S> next
  ) {

    log.info("Setting user context, metadata {}", metadata);

    final String mdcData = String.format("[requestID=%s]", UUID.randomUUID().toString());

    MDC.put(MDC_DATA_KEY, mdcData);

    try {
      return new WrappingListener<>(next.startCall(serverCall, metadata), mdcData);
    } finally {
      MDC.clear();
    }
  }

  private static class WrappingListener<R>
      extends ForwardingServerCallListener.SimpleForwardingServerCallListener<R> {
    private final String mdcData;

    public WrappingListener(ServerCall.Listener<R> delegate, String mdcData) {
      super(delegate);
      this.mdcData = mdcData;
    }

    @Override
    public void onMessage(R message) {
      MDC.put(MDC_DATA_KEY, mdcData);
      try {
        super.onMessage(message);
      } finally {
        MDC.clear();
      }
    }

    @Override
    public void onHalfClose() {
      MDC.put(MDC_DATA_KEY, mdcData);
      try {
        super.onHalfClose();
      } finally {
        MDC.clear();
      }
    }

    @Override
    public void onCancel() {
      MDC.put(MDC_DATA_KEY, mdcData);
      try {
        super.onCancel();
      } finally {
        MDC.clear();
      }
    }

    @Override
    public void onComplete() {
      MDC.put(MDC_DATA_KEY, mdcData);
      try {
        super.onComplete();
      } finally {
        MDC.clear();
      }
    }

    @Override
    public void onReady() {
      MDC.put(MDC_DATA_KEY, mdcData);
      try {
        super.onReady();
      } finally {
        MDC.clear();
      }
    }
  }
}

- Pankaj