Opentelemetry-java: JaegerRemoteSamplerTest is flaky. (Fail 5x)

[arminru]

see https://circleci.com/gh/open-telemetry/opentelemetry-java/4241 or
https://circleci.com/gh/open-telemetry/opentelemetry-java/4259 for example

> Task :opentelemetry-sdk-contrib-jaeger-remote-sampler:test
Picked up _JAVA_OPTIONS: -Xmx3g

io.opentelemetry.sdk.contrib.trace.jaeger.sampler.JaegerRemoteSamplerTest > description FAILED
    java.lang.AssertionError: Resource ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=9, target=directaddress:///my-service}} can not be released in time at the end of test
        at io.grpc.testing.GrpcCleanupRule.teardown(GrpcCleanupRule.java:169)
        at io.grpc.testing.GrpcCleanupRule.access$100(GrpcCleanupRule.java:48)
        at io.grpc.testing.GrpcCleanupRule$1.evaluate(GrpcCleanupRule.java:138)

Re-running the build usually helps but this should be fixed.

Tracking instances:
https://app.circleci.com/pipelines/github/open-telemetry/opentelemetry-java/2325/workflows/8072b109-a9cd-4313-adcc-7304d4d51d49/jobs/4731/steps

https://app.circleci.com/pipelines/github/open-telemetry/opentelemetry-java/2335/workflows/c823a3cc-0c48-45db-ae87-646be91f033a/jobs/4754

[pavolloffay]

I will have a look at this

[arminru]

Thanks, Pavol! It's nice to have someone available in my timezone 😄

[pavolloffay]

@arminru could you please review? https://github.com/open-telemetry/opentelemetry-java/pull/1276

[jkwatson]

This is still breaking occasionally. reopening.

io.opentelemetry.sdk.contrib.trace.jaeger.sampler.JaegerRemoteSamplerTest > description FAILED
    java.lang.AssertionError: Resource ManagedChannelOrphanWrapper{delegate=ManagedChannelImpl{logId=9, target=directaddress:///9419dc37-9307-4d07-9428-f252a1befd87}} can not be released in time at the end of test
        at io.grpc.testing.GrpcCleanupRule.teardown(GrpcCleanupRule.java:169)
        at io.grpc.testing.GrpcCleanupRule.access$100(GrpcCleanupRule.java:48)
        at io.grpc.testing.GrpcCleanupRule$1.evaluate(GrpcCleanupRule.java:138)
        at org.junit.rules.RunRules.evaluate(RunRules.java:20)
        at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
        at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
        at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
        at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
        at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
        at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
        at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
        at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
        at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecutor.runTestClass(JUnitTestClassExecutor.java:110)
        at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecutor.execute(JUnitTestClassExecutor.java:58)
        at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecutor.execute(JUnitTestClassExecutor.java:38)
        at org.gradle.api.internal.tasks.testing.junit.AbstractJUnitTestClassProcessor.processTestClass(AbstractJUnitTestClassProcessor.java:62)
        at org.gradle.api.internal.tasks.testing.SuiteTestClassProcessor.processTestClass(SuiteTestClassProcessor.java:51)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:36)
        at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
        at org.gradle.internal.dispatch.ContextClassLoaderDispatch.dispatch(ContextClassLoaderDispatch.java:33)
        at org.gradle.internal.dispatch.ProxyDispatchAdapter$DispatchingInvocationHandler.invoke(ProxyDispatchAdapter.java:94)
        at com.sun.proxy.$Proxy2.processTestClass(Unknown Source)
        at org.gradle.api.internal.tasks.testing.worker.TestWorker.processTestClass(TestWorker.java:118)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:36)
        at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
        at org.gradle.internal.remote.internal.hub.MessageHubBackedObjectConnection$DispatchWrapper.dispatch(MessageHubBackedObjectConnection.java:182)
        at org.gradle.internal.remote.internal.hub.MessageHubBackedObjectConnection$DispatchWrapper.dispatch(MessageHubBackedObjectConnection.java:164)
        at org.gradle.internal.remote.internal.hub.MessageHub$Handler.run(MessageHub.java:412)
        at org.gradle.internal.concurrent.ExecutorPolicy$CatchAndRecordFailures.onExecute(ExecutorPolicy.java:64)
        at org.gradle.internal.concurrent.ManagedExecutorImpl$1.run(ManagedExecutorImpl.java:48)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at org.gradle.internal.concurrent.ThreadFactoryImpl$ManagedThreadRunnable.run(ThreadFactoryImpl.java:56)
        at java.lang.Thread.run(Thread.java:748)

[jarebudev]

i can take a look if noone is already

[jarebudev]

I had a look into this. It looks like there's a potential race condition in this test, although I couldn't recreate locally so have no proof :)

The JaegerRemoteSamplerTest.description test builds a JaegerRemoteSampler, and checks that the description of the sampler is the expected default sampling strategy before exiting the test method. The GrpcCleanupRule will then run and shutdown the gRPC resources.

The JaegerRemoteSampler constructor starts a separate thread to periodically retrieve the sampling strategy. I expect in most cases the GrpcCleanupRule happens before the thread to fetch sampling strategy starts, and you see the following stderr

Jun 21, 2020 11:51:39 AM io.opentelemetry.sdk.extensions.trace.jaeger.sampler.JaegerRemoteSampler$1 run
WARNING: Failed to update sampler
io.grpc.StatusRuntimeException: UNAVAILABLE: Channel shutdown invoked
    at io.grpc.stub.ClientCalls.toStatusRuntimeException(ClientCalls.java:240)
    at io.grpc.stub.ClientCalls.getUnchecked(ClientCalls.java:221)
    at io.grpc.stub.ClientCalls.blockingUnaryCall(ClientCalls.java:140)
    at io.opentelemetry.exporters.jaeger.proto.api_v2.SamplingManagerGrpc$SamplingManagerBlockingStub.getSamplingStrategy(SamplingManagerGrpc.java:169)
    at io.opentelemetry.sdk.extensions.trace.jaeger.sampler.JaegerRemoteSampler.getAndUpdateSampler(JaegerRemoteSampler.java:96)
    at io.opentelemetry.sdk.extensions.trace.jaeger.sampler.JaegerRemoteSampler.access$000(JaegerRemoteSampler.java:43)
    at io.opentelemetry.sdk.extensions.trace.jaeger.sampler.JaegerRemoteSampler$1.run(JaegerRemoteSampler.java:73)
    at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
    at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)
    at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base/java.lang.Thread.run(Thread.java:834)

However there is a chance that the GrpcCleanupRule may be attempting to clean up the registered server and channel at the same time the separate executing thread is trying to use the channel. I'm not an authority on gRPC so I don't know if there's potential for problems here, but it doesn't seem desirable to me.

I've got a PR which will prevent the test method from exiting until the sampling strategy is retrieved #1364

Suggest we try this fix and see if it resolves this?

[thisthat]

Closing the issue since it looks like #1364 did its job! I don't see the build fail for quite some time :wink:

[pavolloffay]

thanks @jarebudev for fixing this!