3

The value of io.micrometer.tracing.Tracer.currentSpan() becomes null for random calls at the server end.

This happens when hitting the server with multiple parallel calls, and not if calls are made sequentially.

This is the stack trace at server side:

java.lang.NullPointerException: Cannot invoke "io.micrometer.tracing.Span.context()" because the return value of "io.micrometer.tracing.Tracer.currentSpan()" is null
    at com.example.micrometer.GrpcServerApplication$EchoService.unaryRpc(GrpcServerApplication.java:85) ~[main/:na]
    at io.grpc.testing.protobuf.SimpleServiceGrpc$MethodHandlers.invoke(SimpleServiceGrpc.java:410) ~[grpc-testing-proto-1.54.1.jar:1.54.1]
    at io.grpc.stub.ServerCalls$UnaryServerCallHandler$UnaryServerCallListener.onHalfClose(ServerCalls.java:182) ~[grpc-stub-1.54.1.jar:1.54.1]
    at io.grpc.PartialForwardingServerCallListener.onHalfClose(PartialForwardingServerCallListener.java:35) ~[grpc-api-1.54.1.jar:1.54.1]
    at io.grpc.ForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:23) ~[grpc-api-1.54.1.jar:1.54.1]
    at io.grpc.ForwardingServerCallListener$SimpleForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:40) ~[grpc-api-1.54.1.jar:1.54.1]
    at io.micrometer.core.instrument.binder.grpc.ObservationGrpcServerCallListener.onHalfClose(ObservationGrpcServerCallListener.java:47) ~[micrometer-core-1.10.6.jar:1.10.6]
    at io.grpc.internal.ServerCallImpl$ServerStreamListenerImpl.halfClosed(ServerCallImpl.java:355) ~[grpc-core-1.54.1.jar:1.54.1]
    at io.grpc.internal.ServerImpl$JumpToApplicationThreadServerStreamListener$1HalfClosed.runInContext(ServerImpl.java:867) ~[grpc-core-1.54.1.jar:1.54.1]
    at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37) ~[grpc-core-1.54.1.jar:1.54.1]
    at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:133) ~[grpc-core-1.54.1.jar:1.54.1]
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[na:na]
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[na:na]
    at java.base/java.lang.Thread.run(Thread.java:833) ~[na:na]

Here is a minimal sample server and sample client reproducing the issue. What could I be missing?

Brian Clozel
  • 56,583
  • 15
  • 167
  • 176
daltonfury42
  • 3,103
  • 2
  • 30
  • 47

1 Answers1

0

This is a bug in micrometer as of 1.0.4 and is tracked here.

A temporary workaround till the issue is fixed is to write your own version of ObservationGrpcServerCallListener and then add extra line this.scope.makeCurrent(); on ObservationGrpcServerCallListener#[onMessage|onHalfClose].

daltonfury42
  • 3,103
  • 2
  • 30
  • 47