Agent interfering with GCP Pub/Sub credentials?

[notgerry]

Describe the bug
I have a service that is running in GKE. It simply connects to Google Pub/Sub and spits out messages it receives from the topic subscription. When I deploy it normally all is well. I tried adding the OpenTel agent (awesome project, btw) and it seems like something is getting in the way of how the service is getting credentials.

Steps to reproduce
Thus far I've been unable to repro this locally as the error does not present when using the Pub/Sub emulator. To repro you need to be connected to the real thing running in GCP.

I have a minimal repo here here that has a sample project that exhibits this problem. I build an image with the bootBuildImage task and deploy to GKE. Like I mentioned earlier if I deploy without specifying the agent -javaagent:BOOT-INF/lib/opentelemetry-javaagent-1.1.0.jar then pubsub messages come through. If the agent is specified then the UNAUTHENTICATED errors start popping up.

What did you expect to see?
Expect to see messages from the subscription being logged.

What did you see instead?
com.google.api.gax.rpc.UnauthenticatedException: com.google.api.gax.rpc.UnauthenticatedException: io.grpc.StatusRuntimeException: UNAUTHENTICATED: Failed computing credential metadata
at com.google.api.gax.rpc.ApiExceptionFactory.createException(ApiExceptionFactory.java:73) ~[gax-1.60.0.jar:1.60.0]
at com.google.cloud.pubsub.v1.StreamingSubscriberConnection$1.onFailure(StreamingSubscriberConnection.java:260) ~[google-cloud-pubsub-1.108.6.jar:1.108.6]
at com.google.api.core.ApiFutures$1.onFailure(ApiFutures.java:68) ~[api-common-1.10.0.jar:na]
at com.google.common.util.concurrent.Futures$CallbackListener.run(Futures.java:1083) ~[guava-29.0-jre.jar:na]
at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30) ~[guava-29.0-jre.jar:na]
at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1174) ~[guava-29.0-jre.jar:na]
at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:969) ~[guava-29.0-jre.jar:na]
at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:760) ~[guava-29.0-jre.jar:na]
at com.google.api.core.AbstractApiFuture$InternalSettableFuture.setException(AbstractApiFuture.java:95) ~[api-common-1.10.0.jar:na]
at com.google.api.core.AbstractApiFuture.setException(AbstractApiFuture.java:77) ~[api-common-1.10.0.jar:na]
at com.google.api.core.SettableApiFuture.setException(SettableApiFuture.java:52) ~[api-common-1.10.0.jar:na]
at com.google.cloud.pubsub.v1.StreamingSubscriberConnection$StreamingPullResponseObserver.onError(StreamingSubscriberConnection.java:191) ~[google-cloud-pubsub-1.108.6.jar:1.108.6]
at com.google.api.gax.tracing.TracedResponseObserver.onError(TracedResponseObserver.java:103) ~[gax-1.60.0.jar:1.60.0]
at com.google.api.gax.grpc.ExceptionResponseObserver.onErrorImpl(ExceptionResponseObserver.java:84) ~[gax-grpc-1.60.0.jar:1.60.0]
at com.google.api.gax.rpc.StateCheckingResponseObserver.onError(StateCheckingResponseObserver.java:86) ~[gax-1.60.0.jar:1.60.0]
at com.google.api.gax.grpc.GrpcDirectStreamController$ResponseObserverAdapter.onClose(GrpcDirectStreamController.java:149) ~[gax-grpc-1.60.0.jar:1.60.0]
at io.opentelemetry.javaagent.shaded.instrumentation.grpc.v1_5.TracingClientInterceptor$TracingClientCallListener.onClose(TracingClientInterceptor.java:128) ~[na:na]
at io.grpc.internal.DelayedClientCall$DelayedListener$3.run(DelayedClientCall.java:463) ~[grpc-core-1.33.0.jar:1.33.0]
at io.grpc.internal.DelayedClientCall$DelayedListener.delayOrExecute(DelayedClientCall.java:427) ~[grpc-core-1.33.0.jar:1.33.0]
at io.grpc.internal.DelayedClientCall$DelayedListener.onClose(DelayedClientCall.java:460) ~[grpc-core-1.33.0.jar:1.33.0]
at io.grpc.internal.ClientCallImpl.closeObserver(ClientCallImpl.java:616) ~[grpc-core-1.33.0.jar:1.33.0]
at io.grpc.internal.ClientCallImpl.access$300(ClientCallImpl.java:69) ~[grpc-core-1.33.0.jar:1.33.0]
at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInternal(ClientCallImpl.java:802) ~[grpc-core-1.33.0.jar:1.33.0]
at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInContext(ClientCallImpl.java:781) ~[grpc-core-1.33.0.jar:1.33.0]
at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37) ~[grpc-core-1.33.0.jar:1.33.0]
at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:123) ~[grpc-core-1.33.0.jar:1.33.0]
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source) ~[na:na]
at java.base/java.util.concurrent.FutureTask.run(Unknown Source) ~[na:na]
at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source) ~[na:na]
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) ~[na:na]
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) ~[na:na]
at java.base/java.lang.Thread.run(Unknown Source) ~[na:na]
Caused by: com.google.api.gax.rpc.UnauthenticatedException: io.grpc.StatusRuntimeException: UNAUTHENTICATED: Failed computing credential metadata
at com.google.api.gax.rpc.ApiExceptionFactory.createException(ApiExceptionFactory.java:73) ~[gax-1.60.0.jar:1.60.0]
at com.google.api.gax.grpc.GrpcApiExceptionFactory.create(GrpcApiExceptionFactory.java:72) ~[gax-grpc-1.60.0.jar:1.60.0]
at com.google.api.gax.grpc.GrpcApiExceptionFactory.create(GrpcApiExceptionFactory.java:60) ~[gax-grpc-1.60.0.jar:1.60.0]
at com.google.api.gax.grpc.ExceptionResponseObserver.onErrorImpl(ExceptionResponseObserver.java:82) ~[gax-grpc-1.60.0.jar:1.60.0]
... 18 common frames omitted
Caused by: io.grpc.StatusRuntimeException: UNAUTHENTICATED: Failed computing credential metadata
at io.grpc.Status.asRuntimeException(Status.java:533) ~[grpc-api-1.33.0.jar:1.33.0]
... 17 common frames omitted
Caused by: java.lang.NullPointerException: null
at io.opentelemetry.javaagent.shaded.instrumentation.grpc.v1_5.internal.ContextStorageBridge.detach(ContextStorageBridge.java:90) ~[na:na]
at io.grpc.Context.detach(Context.java:463) ~[grpc-context-1.33.0.jar:1.33.0]
at io.opencensus.trace.CurrentSpanUtils$ScopeInSpan.close(CurrentSpanUtils.java:98) ~[opencensus-api-0.24.0.jar:0.24.0]
at com.google.api.client.http.HttpRequest.execute(HttpRequest.java:1043) ~[google-http-client-1.37.0.jar:1.37.0]
at com.google.auth.oauth2.ServiceAccountCredentials.refreshAccessToken(ServiceAccountCredentials.java:441) ~[google-auth-library-oauth2-http-0.22.0.jar:na]
at com.google.auth.oauth2.OAuth2Credentials.refresh(OAuth2Credentials.java:157) ~[google-auth-library-oauth2-http-0.22.0.jar:na]
at com.google.auth.oauth2.OAuth2Credentials.getRequestMetadata(OAuth2Credentials.java:145) ~[google-auth-library-oauth2-http-0.22.0.jar:na]
at com.google.auth.oauth2.ServiceAccountCredentials.getRequestMetadata(ServiceAccountCredentials.java:603) ~[google-auth-library-oauth2-http-0.22.0.jar:na]
at com.google.auth.Credentials.blockingGetToCallback(Credentials.java:112) ~[google-auth-library-credentials-0.22.0.jar:na]
at com.google.auth.Credentials$1.run(Credentials.java:98) ~[google-auth-library-credentials-0.22.0.jar:na]
... 6 common frames omitted

What version are you using?
1.1.0 of the agent.

Environment
Running in GKE, built with AdopOpenJdk 11.0.10

Additional context
I looked briefly through the OpenTelemetry repo but nothing obvious jumped out at me. I'm not familiar enough with the code yet to really understand where to go next. Any help much appreciated!

[trask]

hey @notgerry! this looks like the same issue as #2564 (comment), which we believe is fixed just recently by #2948

[trask]

oops didn't mean to hit close with comment

[anuraaga]

@notgerry A new snapshot with that fix was published, can you give it a try? https://oss.sonatype.org/content/repositories/snapshots/io/opentelemetry/javaagent/opentelemetry-javaagent/1.2.0-SNAPSHOT/

[anuraaga]

Another followup fix in #2970 to remove some incorrect log spam, hopefully this issue will be solved after that.

[notgerry]

Oh, nice! I'll give it a shot and report back.

[notgerry]

Looks like the 1.2.0-SNAPSHOT fix works :)

There are, however, still a couple of errors coming from OpenTel agent when we first start up:

[opentelemetry.auto.trace 2021-05-12 17:45:30:772 +0000] [Subscriber-SE-1-3] ERROR io.opentelemetry.javaagent.shaded.instrumentation.grpc.v1_6.internal.ContextStorageBridge - Context was not attached when detaching
java.lang.Throwable
at io.opentelemetry.javaagent.shaded.instrumentation.grpc.v1_6.internal.ContextStorageBridge.detach(ContextStorageBridge.java:71)
at io.grpc.Context.detach(Context.java:463)
at io.opencensus.trace.CurrentSpanUtils$ScopeInSpan.close(CurrentSpanUtils.java:98)
at com.google.api.client.http.HttpRequest.execute(HttpRequest.java:1043)
at com.google.auth.oauth2.ServiceAccountCredentials.refreshAccessToken(ServiceAccountCredentials.java:441)
at com.google.auth.oauth2.OAuth2Credentials.refresh(OAuth2Credentials.java:157)
at com.google.auth.oauth2.OAuth2Credentials.getRequestMetadata(OAuth2Credentials.java:145)
at com.google.auth.oauth2.ServiceAccountCredentials.getRequestMetadata(ServiceAccountCredentials.java:603)
at com.google.auth.Credentials.blockingGetToCallback(Credentials.java:112)
at com.google.auth.Credentials$1.run(Credentials.java:98)
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
at java.base/java.util.concurrent.FutureTask.run(Unknown Source)
at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.base/java.lang.Thread.run(Unknown Source)

I'm not sure if this is anything to be concerned about or not. Let me know if you need any more information.

[trask]

great to hear! that additional error message looks like what @anuraaga just fixed in #2970, so fix for that should be available in the next nightly snapshot

[notgerry]

Great, thanks for the help!