GRPC Instrumentation doesn't work post 1.17.0

[anuragagarwal561994]

Describe the bug
This happens with grpc instrumentation post 1.17.0 version, I tried different versions and 1.17.0 was the last working version.

java.lang.NullPointerException
	at io.grpc.PartialForwardingClientCall.getAttributes(PartialForwardingClientCall.java:59)
	at io.grpc.ForwardingClientCall.getAttributes(ForwardingClientCall.java:22)
	at io.opentelemetry.javaagent.shaded.instrumentation.grpc.v1_6.TracingClientInterceptor.interceptCall(TracingClientInterceptor.java:62)
	at io.grpc.ClientInterceptors$InterceptorChannel.newCall(ClientInterceptors.java:156)
	at io.grpc.internal.ManagedChannelImpl.newCall(ManagedChannelImpl.java:920)
	at io.grpc.internal.ForwardingManagedChannel.newCall(ForwardingManagedChannel.java:63)
	at net.media.ipservice.IPServiceGrpc$IPServiceFutureStub.getIPInfo(IPServiceGrpc.java:181)
	at org.example.client.IPServiceGrpcClient.getIpInfo(IPServiceGrpcClient.java:33)
	at org.example.client.IPServiceGrpcServlet.doGet(IPServiceGrpcServlet.java:29)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:670)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:779)
	at com.google.inject.servlet.ServletDefinition.doServiceImpl(ServletDefinition.java:290)
	at com.google.inject.servlet.ServletDefinition.doService(ServletDefinition.java:280)
	at com.google.inject.servlet.ServletDefinition.service(ServletDefinition.java:184)
	at com.google.inject.servlet.ManagedServletPipeline.service(ManagedServletPipeline.java:89)
	at com.google.inject.servlet.ManagedFilterPipeline.dispatch(ManagedFilterPipeline.java:121)
	at com.google.inject.servlet.GuiceFilter.doFilter(GuiceFilter.java:133)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:177)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:541)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:135)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:360)
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:399)
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:891)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1784)
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
	at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
	at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.base/java.lang.Thread.run(Unknown Source)

Steps to reproduce
This is the simplest test code being used.

class IPServiceGrpcClient {
    private final IPServiceGrpc.IPServiceFutureStub futureStub;

    public IPServiceGrpcClient(String grpcTarget) {
        var channelCredentials = InsecureChannelCredentials.create();
        var xdsCredentials = XdsChannelCredentials.create(channelCredentials);
        var channel = Grpc.newChannelBuilder(grpcTarget, xdsCredentials).build();
        this.futureStub = IPServiceGrpc.newFutureStub(channel);
    }

    public static IPServiceGrpcClient create() {
        var config = ConfigCache.getOrCreate(GatewayConfig.class);
        var grpcTarget = config.grpcTarget();
        return new IPServiceGrpcClient(grpcTarget);
    }

    public ListenableFuture<Ipservice.IPResponse> getIpInfo() {
        return futureStub.getIPInfo(Ipservice.Empty.getDefaultInstance());
    }
}

client.getIpInfo().get(waitMs, TimeUnit.MILLISECONDS);

What did you expect to see?
Instrumentation should not give an error.

What did you see instead?
An exception and the grpc call resulted in an error.

What version are you using?
v1.21.0

Environment
openjdk version "17.0.5" 2022-10-18 LTS
OpenJDK Runtime Environment Zulu17.38+21-CA (build 17.0.5+8-LTS)
OpenJDK 64-Bit Server VM Zulu17.38+21-CA (build 17.0.5+8-LTS, mixed mode, sharing)

[mateuszrzeszutek]

Hey @anuragagarwal561994 ,

What version of grpc are you using?
Can you provide an executable repro scenario? Our grpc instrumentation tests contain somewhat similar invocations to what you posted, and they don't exhibit this issue. It'd be very helpful if we could debug this.

[anuragagarwal561994]

So I tried last 4 versions of grpc from 1.51 to 1.48 and none of them work with > 1.17.0 versions of otel instrumentation, while all of them works for <= 1.17.0.

Sure let me try and make an executable scenario where this might be taking place.

[anuragagarwal561994]

So as I was making a test setup for the same, I realised that this issue happens only in grpc-xds kind of setup and not in regular grpc client server. I am trying to make a test setup for the same, but since I am not able to bring up a xds kind of setup locally I have to use istio for the same, will that be debuggable?

[anuragagarwal561994]

https://github.com/anuragagarwal561994/otel-grpc-poc

Let me know if there are any issues you encounter, I have just setup this repo.

[anuragagarwal561994]

@mateuszrzeszutek I have debugged the issue on my own and identified why this is happening.

It is happening because of line https://github.com/open-telemetry/opentelemetry-java-instrumentation/blob/main/instrumentation/grpc-1.6/library/src/main/java/io/opentelemetry/instrumentation/grpc/v1_6/TracingClientInterceptor.java#L62

This was introduced in 1.18.0

Here after getting the call we are fetching the attributes.

https://github.com/grpc/grpc-java/blob/43bc578f20ffe54ba45a43f282a7e87757179bf1/core/src/main/java/io/grpc/internal/ManagedChannelImpl.java#L1114-L1131

If we check the above code snippet, when there is a simple RPC, which means configSelector.get() == null then we get the delegate() assigned before the start of the rpc and hence we are able to fetch the results.

But in case when we are using grpc-xds in that case, we will be doing new ConfigSelectingClientCall and if you observe the implementation.

https://github.com/grpc/grpc-java/blob/43bc578f20ffe54ba45a43f282a7e87757179bf1/core/src/main/java/io/grpc/internal/ManagedChannelImpl.java#L1168-L1190

The delegate is assigned when the rpc is starting.

Now the getAttributes() is using the delegate() method when the attributes are fetched. Since this is done before the RPC has started, hence we are getting NPE.

I guess we should ideally make the getAttributes() call when the instrumentation ends?