How to use a gRPC interceptor to attach/update logging MDC in a Spring-Boot app

Question

Problem

I have a Spring-Boot application in which I am also starting a gRPC server/service. Both the servlet and gRPC code send requests to a common object to process the request. When the request comes in I want to update the logging to display a unique 'ID' so I can track the request through the system.

On the Spring side I have setup a 'Filter' which updates the logging MDC to add some data to the log request (see this example). this works fine

On the gRPC side I have created an 'ServerInterceptor' and added it to the service, while the interceptor gets called the code to update the MDC does not stick, so when a request comes through the gRPC service I do not get the ID printed in the log. I realize this has to do with the fact that I'm intercepting the call in one thread and it's being dispatched by gRPC in another, what I can't seem to figure out is how to either intercept the call in the thread doing the work or add the MDC information so it is properly propagated to the thread doing the work.

What I've tried

I have done a lot of searches and was quite surprised to not find this asked/answered, I can only assume my query skills are lacking :(

I'm fairly new to gRPC and this is the first Interceptor I'm writing. I've tried adding the interceptor several different ways (via ServerInterceptors.intercept, BindableService instance.intercept).

I've looked at LogNet's Spring Boot gRPC Starter, but I'm not sure this would solve the issue.

Here is the code I have added in my interceptor class

@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();
    }
}

Expected Result

When a request comes in via the RESTful API I see log output like this

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

I'm hoping to get similar output when the request comes through the gRPC service.

Thanks

Answer 1

Since no one replied, I kept trying and came up with the following solution for my interceptCall function. I'm not 100% sure why this works, but it works for my use case.

    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();
                            }
                        }
                    };
                }
            });
        }
    }

In my application.properties I added the following (which I already had)

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

The '%X' tells the logging system to print all of the CloseableThreadContext key/values.

Hopefully this may help someone else.

Answer 2

MDC stores data in ThreadLocal variable and you are right about - "I realize this has to do with the fact that I'm intercepting the call in one thread and it's being dispatched by gRPC in another". Check @Eric Anderson answer about the right way to use ThradLocal in the post - https://stackoverflow.com/a/56842315/2478531

Here is a working example -

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();
      }
    }
  }
}