Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

GrpcExceptionListener handle exceptions outside of observation scope #1088

Open
hnvas opened this issue Apr 9, 2024 · 2 comments
Open

GrpcExceptionListener handle exceptions outside of observation scope #1088

hnvas opened this issue Apr 9, 2024 · 2 comments
Labels
bug Something does not work as expected

Comments

@hnvas
Copy link

hnvas commented Apr 9, 2024

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

@hnvas hnvas added the bug Something does not work as expected label Apr 9, 2024
@nikita-rogovyi
Copy link

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
Copy link

rafal-dudek commented Jun 6, 2024

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something does not work as expected
Projects
None yet
Development

No branches or pull requests

3 participants