beam export job leaks grpc connections

[igorbernstein2]

Dataflow logs are filled with:

Channel ManagedChannelImpl{logId=3217, target=bigtableadmin.googleapis.com:443} was not shutdown properly!!! *~ Make sure to call shutdown()/shutdownNow() and wait until awaitTermination() returns true.

I'm guessing this is an issue with channel pool caching where the dataflow job reuses the same channel pool for data channels, but opens new ones for admin channels.

[dmitry-fa]

The same message appears in the log from running tests:

[INFO] Running com.google.cloud.bigtable.grpc.TestBigtableTableAdminGCJClient
Aug 18, 2020 11:47:27 AM com.google.cloud.bigtable.config.CredentialOptions info
INFO: Enabling the use of null credentials. This should not be used in production.
Aug 18, 2020 11:47:27 AM com.google.cloud.bigtable.config.BigtableVeneerSettingsFactory info
INFO: Enabling the use of null credentials. This should not be used in production.
Aug 18, 2020 11:47:27 AM io.grpc.internal.ManagedChannelOrphanWrapper$ManagedChannelReference cleanQueue
SEVERE: *~*~*~ Channel ManagedChannelImpl{logId=166, target=bigtableadmin.googleapis.com:443} was not shutdown properly!!! ~*~*~*
    Make sure to call shutdown()/shutdownNow() and wait until awaitTermination() returns true.
java.lang.RuntimeException: ManagedChannel allocation site
        at io.grpc.internal.ManagedChannelOrphanWrapper$ManagedChannelReference.<init>(ManagedChannelOrphanWrapper.java:93)
        at io.grpc.internal.ManagedChannelOrphanWrapper.<init>(ManagedChannelOrphanWrapper.java:53)
        at io.grpc.internal.ManagedChannelOrphanWrapper.<init>(ManagedChannelOrphanWrapper.java:44)
        at io.grpc.internal.AbstractManagedChannelImplBuilder.build(AbstractManagedChannelImplBuilder.java:518)
        at com.google.cloud.bigtable.grpc.BigtableSession.createNettyChannel(BigtableSession.java:630)
        at com.google.cloud.bigtable.grpc.BigtableSession.createInstanceClient(BigtableSession.java:778)
        at com.google.cloud.bigtable.grpc.TestBigtableSession.testCreateInstanceClient(TestBigtableSession.java:83)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        ...

I think that confusing message is due to the bug in the logger: googleapis/java-logging#211 caused by not closing a channel in the GrpcLoggingRpc

[dmitry-fa]

@igorbernstein2 This message no longer appears in the test logs, so I closing this issue. Please reopen it if you meet this message somewhere else.

[dmitry-fa]

The same message appears in the tests for BigTable Hello World snippet.

Nov 09, 2020 11:51:08 AM io.grpc.internal.ManagedChannelOrphanWrapper$ManagedChannelReference cleanQueue
SEVERE: *~*~*~ Channel ManagedChannelImpl{logId=39, target=bigtable.googleapis.com:443} was not shutdown properly!!! ~*~*~*
    Make sure to call shutdown()/shutdownNow() and wait until awaitTermination() returns true.
java.lang.RuntimeException: ManagedChannel allocation site
	at io.grpc.internal.ManagedChannelOrphanWrapper$ManagedChannelReference.<init>(ManagedChannelOrphanWrapper.java:93)
	at io.grpc.internal.ManagedChannelOrphanWrapper.<init>(ManagedChannelOrphanWrapper.java:53)
	at io.grpc.internal.ManagedChannelOrphanWrapper.<init>(ManagedChannelOrphanWrapper.java:44)
	at io.grpc.internal.ManagedChannelImplBuilder.build(ManagedChannelImplBuilder.java:596)
	at io.grpc.internal.AbstractManagedChannelImplBuilder.build(AbstractManagedChannelImplBuilder.java:261)
	at com.google.api.gax.grpc.InstantiatingGrpcChannelProvider.createSingleChannel(InstantiatingGrpcChannelProvider.java:340)
	at com.google.api.gax.grpc.InstantiatingGrpcChannelProvider.access$1600(InstantiatingGrpcChannelProvider.java:71)
	at com.google.api.gax.grpc.InstantiatingGrpcChannelProvider$1.createSingleChannel(InstantiatingGrpcChannelProvider.java:236)
	at com.google.api.gax.grpc.ChannelPool.create(ChannelPool.java:72)
	at com.google.api.gax.grpc.InstantiatingGrpcChannelProvider.createChannel(InstantiatingGrpcChannelProvider.java:243)
	at com.google.api.gax.grpc.InstantiatingGrpcChannelProvider.getTransportChannel(InstantiatingGrpcChannelProvider.java:226)
	at com.google.api.gax.rpc.ClientContext.create(ClientContext.java:169)
	at com.google.cloud.bigtable.data.v2.stub.EnhancedBigtableStub.create(EnhancedBigtableStub.java:128)
	at com.google.cloud.bigtable.data.v2.BigtableDataClient.create(BigtableDataClient.java:161)
	at com.m.examples.bigtable.HelloWorld.<init>(HelloWorld.java:79)
	at com.m.examples.bigtable.HelloWorldTest.testCreateAndDeleteTable(HelloWorldTest.java:99)

[dmitry-fa]

This might happen if a data or admin client is not closing properly.
In the Hello World snippet, the client created at:

78    // Creates a bigtable data client.
79    dataClient = BigtableDataClient.create(settings);

is never closed, quoting stack trace:

at com.m.examples.bigtable.HelloWorld.<init>(HelloWorld.java:79)

Note that the printed stack trace corresponds not the moment when cleanQueue method is invoked, but the instance when the client is created.

[kolea2]

@dmitry-fa going to close this here as this will be resolved by googleapis/java-bigtable#516. If we see it elsewhere, let's raise a new issue in the java-bigtable repo for the samples. Thanks!