GrpcExceptionListener handle exceptions outside of observation scope

[hnvas]

The bug

The GrpcAdviceAutoConfiguration class initialises the global exception handler with higher precedence than the GrpcServerMicrometerTraceAutoConfiguration class, causing the GrpcExceptionListener to handle exceptions outside of observation scope and making it impossible for the exception handlers declared in @GrpcAdvice annotated classes to access the current tracing context.

Stacktrace and logs

[2024-04-09 14:31:42.548] - [grpc-default-executor-0] - [INFO] - [com.hnvas.grpctracingdemo.ExampleApiImpl->sayHelloError:26] - [traceId=66157b7e32dfc6c022c9a26f05d49218, spanId=22c9a26f05d49218]: Received a request on sayHelloError
[2024-04-09 14:31:42.549] - [grpc-default-executor-0] - [ERROR] - [com.hnvas.grpctracingdemo.GrpcExceptionAdvice->handleIllegalStateException:15] - [traceId=, spanId=]: This should not happen: null
java.lang.IllegalStateException: This should not happen
    at com.hnvas.grpctracingdemo.ExampleApiImpl.sayHelloError(ExampleApiImpl.java:27)
    at com.hnvas.grpctracingdemo.grpc.ExampleApiGrpc$MethodHandlers.invoke(ExampleApiGrpc.java:276)
    at io.grpc.stub.ServerCalls$UnaryServerCallHandler$UnaryServerCallListener.onHalfClose(ServerCalls.java:182)
    at io.grpc.PartialForwardingServerCallListener.onHalfClose(PartialForwardingServerCallListener.java:35)
    at io.grpc.ForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:23)
    at io.grpc.ForwardingServerCallListener$SimpleForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:40)
    at io.micrometer.core.instrument.binder.grpc.ObservationGrpcServerCallListener.lambda$onHalfClose$1(ObservationGrpcServerCallListener.java:47)
    at io.micrometer.observation.Observation.scoped(Observation.java:709)
    at io.micrometer.core.instrument.binder.grpc.ObservationGrpcServerCallListener.onHalfClose(ObservationGrpcServerCallListener.java:47)
    at io.grpc.PartialForwardingServerCallListener.onHalfClose(PartialForwardingServerCallListener.java:35)
    at io.grpc.ForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:23)
    at io.grpc.ForwardingServerCallListener$SimpleForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:40)
    at io.grpc.PartialForwardingServerCallListener.onHalfClose(PartialForwardingServerCallListener.java:35)
    at io.grpc.ForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:23)
    at io.grpc.ForwardingServerCallListener$SimpleForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:40)
    at net.devh.boot.grpc.server.error.GrpcExceptionListener.onHalfClose(GrpcExceptionListener.java:67)
    at io.grpc.PartialForwardingServerCallListener.onHalfClose(PartialForwardingServerCallListener.java:35)
    at io.grpc.ForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:23)
    at io.grpc.ForwardingServerCallListener$SimpleForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:40)
    at io.grpc.Contexts$ContextualizedServerCallListener.onHalfClose(Contexts.java:86)
    at io.grpc.internal.ServerCallImpl$ServerStreamListenerImpl.halfClosed(ServerCallImpl.java:351)
    at io.grpc.internal.ServerImpl$JumpToApplicationThreadServerStreamListener$1HalfClosed.runInContext(ServerImpl.java:861)
    at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
    at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:133)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
    at java.base/java.lang.Thread.run(Thread.java:1583)

The application's environment

Which versions do you use?

• Spring (boot): 3.2.4
• grpc-java: 1.62.2
• grpc-spring-boot-starter: 3.0.0
• java: 21 64bit

Additional context

• Do you have a demo?

[nikita-rogovyi]

I had the same issue with previous lib version: sleuth context was closed before I could log traceId in exception handler. And had to implement own GlobalServerInterceptorRegistry and switch TracingServerInterceptor and GrpcExceptionInterceptor. It's not what I'd like to do manually, so I will upvote and follow the thread.

[rafal-dudek]

We have similar problem in our applications. Logs in @GrpcService are inside observation context but logs in GrpcExceptionHandler are not. This prevents us from correlating error to specific transaction. Example:

@GrpcService
public class GreeterService extends GreeterGrpc.GreeterImplBase {
    Logger log = LoggerFactory.getLogger(GreeterService.class);

    @Override
    public void hello(Hello.HelloRequest request, StreamObserver<Hello.HelloReply> responseObserver) {
        Hello.HelloReply.Builder replyBuilder = Hello.HelloReply.newBuilder().setMessage("OK");
        responseObserver.onNext(replyBuilder.build());
        log.info("@GrpcService MDC " + MDC.getCopyOfContextMap());
        throw new RuntimeException();
    }
}

    @GrpcExceptionHandler
    public StatusRuntimeException handleCompletionException(RuntimeException exception) {
        com.google.rpc.Status status =
                com.google.rpc.Status.newBuilder()
                        .setCode(Code.INTERNAL.getNumber())
                        .setMessage(INTERNAL_SERVER_ERROR.toString())
                        .build();
        log.info("@GrpcExceptionHandler MDC " + MDC.getCopyOfContextMap());
        return StatusProto.toStatusRuntimeException(status);
    }

2024-06-06T16:24:53.408+02:00 INFO 21320 --- [demo] [ault-executor-0] [6661c6b5a565d0976496dafd60a17f77-f7d18210ee565ee4] com.example.demo.GreeterService : @GrpcService MDC {traceId=6661c6b5a565d0976496dafd60a17f77, spanId=f7d18210ee565ee4} 2024-06-06T16:24:53.411+02:00 INFO 21320 --- [demo] [ault-executor-0] [ ] c.example.demo.CustomExceptionHandler : @GrpcExceptionHandler MDC {}

I am also uploading a sample application: grpc-exception-handler.zip