Issues with TransportChannel not getting closed in gax-java library usage

[gabriel-sada]

Environment details

1. Google Cloud Logging Client for Java
2. OS type and version: macOS Big Sur
3. Java version: AdoptOpenJDK 15.0.2
4. logging version(s): 2.3.1

Steps to reproduce

On instantiating instances of the Logging service multiple times in a row, a RuntimeException is thrown in the gRPC library

Code example

 try (Logging logging = LoggingOptions.getDefaultInstance().getService()) {
    LogEntry entry = LogEntry
                .newBuilder( ... ).build()
    // build `entry`
    logging.write(Collections.singleton(entry));
    logging.flush();
}

Run this code multiple times in a row and it will eventually throw the error, in my experience.

Stack trace

java.lang.RuntimeException: ManagedChannel allocation site at io.grpc.internal.ManagedChannelOrphanWrapper$ManagedChannelReference.<init>(ManagedChannelOrphanWrapper.java:93) 
~[grpc-core-1.38.0.jar!/:1.38.0] at io.grpc.internal.ManagedChannelOrphanWrapper.<init>(ManagedChannelOrphanWrapper.java:53) 
~[grpc-core-1.38.0.jar!/:1.38.0] at io.grpc.internal.ManagedChannelOrphanWrapper.<init>(ManagedChannelOrphanWrapper.java:44) 
~[grpc-core-1.38.0.jar!/:1.38.0] at io.grpc.internal.ManagedChannelImplBuilder.build(ManagedChannelImplBuilder.java:615) 
~[grpc-core-1.38.0.jar!/:1.38.0] at io.grpc.internal.AbstractManagedChannelImplBuilder.build(AbstractManagedChannelImplBuilder.java:261) 
~[grpc-core-1.38.0.jar!/:1.38.0] at com.google.api.gax.grpc.InstantiatingGrpcChannelProvider.createSingleChannel(InstantiatingGrpcChannelProvider.java:360) 
~[gax-grpc-1.65.0.jar!/:1.65.0] at com.google.api.gax.grpc.InstantiatingGrpcChannelProvider.access$1800(InstantiatingGrpcChannelProvider.java:81) 
~[gax-grpc-1.65.0.jar!/:1.65.0] at com.google.api.gax.grpc.InstantiatingGrpcChannelProvider$1.createSingleChannel(InstantiatingGrpcChannelProvider.java:231) 
~[gax-grpc-1.65.0.jar!/:1.65.0] at com.google.api.gax.grpc.ChannelPool.create(ChannelPool.java:72) 
~[gax-grpc-1.65.0.jar!/:1.65.0] at com.google.api.gax.grpc.InstantiatingGrpcChannelProvider.createChannel(InstantiatingGrpcChannelProvider.java:241) 
~[gax-grpc-1.65.0.jar!/:1.65.0] at com.google.api.gax.grpc.InstantiatingGrpcChannelProvider.getTransportChannel(InstantiatingGrpcChannelProvider.java:219) 
~[gax-grpc-1.65.0.jar!/:1.65.0] at com.google.api.gax.rpc.ClientContext.create(ClientContext.java:199) 
~[gax-1.65.0.jar!/:1.65.0] at com.google.api.gax.rpc.ClientContext.create(ClientContext.java:133) 
~[gax-1.65.0.jar!/:1.65.0] at com.google.cloud.logging.spi.v2.GrpcLoggingRpc.<init>(GrpcLoggingRpc.java:142) 
~[google-cloud-logging-2.3.1.jar!/:2.3.1] at com.google.cloud.logging.LoggingOptions$DefaultLoggingRpcFactory.create(LoggingOptions.java:61) 
~[google-cloud-logging-2.3.1.jar!/:2.3.1] at com.google.cloud.logging.LoggingOptions$DefaultLoggingRpcFactory.create(LoggingOptions.java:55) 
~[google-cloud-logging-2.3.1.jar!/:2.3.1] at com.google.cloud.ServiceOptions.getRpc(ServiceOptions.java:560) 
~[google-cloud-core-1.95.0.jar!/:1.95.0] at com.google.cloud.logging.LoggingOptions.getLoggingRpcV2(LoggingOptions.java:129) 
~[google-cloud-logging-2.3.1.jar!/:2.3.1] at com.google.cloud.logging.LoggingImpl.<init>(LoggingImpl.java:120) 
~[google-cloud-logging-2.3.1.jar!/:2.3.1] at com.google.cloud.logging.LoggingOptions$DefaultLoggingFactory.create(LoggingOptions.java:46) 
~[google-cloud-logging-2.3.1.jar!/:2.3.1] at com.google.cloud.logging.LoggingOptions$DefaultLoggingFactory.create(LoggingOptions.java:41) 
~[google-cloud-logging-2.3.1.jar!/:2.3.1] at com.google.cloud.ServiceOptions.getService(ServiceOptions.java:540) 
~[google-cloud-core-1.95.0.jar!/:1.95.0] at [ redacted internal calls ]
~[na:na] at java.base/java.lang.Thread.run(Thread.java:832) 
~[na:na]

Any additional information below

There was a previous error very similar to this that was resolved in #212, but I think there is still some similar code with a TransportChannel that is not getting closed. The previous fix made sure that the TransportChannel here (https://github.com/googleapis/java-logging/blob/master/google-cloud-logging/src/main/java/com/google/cloud/logging/spi/v2/GrpcLoggingRpc.java#L110) was getting closed, but there is another code path where a ClientContext is getting created here: https://github.com/googleapis/java-logging/blob/master/google-cloud-logging/src/main/java/com/google/cloud/logging/spi/v2/GrpcLoggingRpc.java#L142

In the creation of the ClientContext, it creates its own TransportChannel that I think is not being closed in our usage here in java-logging. See the code in the gax-java codebase here: https://github.com/googleapis/gax-java/blob/master/gax/src/main/java/com/google/api/gax/rpc/ClientContext.java#L199

Hope this helps, thanks!

[minherz]

Thank you, Gabriel. The behavior that you were observing is probably related to the limit of grpc channels that can be simultaneously opened from the same client.
However, the code snippet that you referenced is intended to demonstrate one of the functional aspects of the library. It is not intended for stress using. If you need to write multiple log entries you should reuse the same Logging instance instead of recreate it.
Can you please explain the nature of the problem that you are trying to solve?

[gabriel-sada]

@minherz the snippet I put on this issue is taken directly from the documentation here.

I wouldn't consider our use case to be stress testing, but we are sending a large number of logging requests, and it appears that the grpc channels do not get cleaned up properly even after the Logging instance is closed at the end of the try-with-resources block in Java. Regardless of how we are using the library, this seems like it's an unexpected behavior.

At the very least, it would be good to update the documentation to indicate that the usage of the library in that code snippet is not for production use.

[minherz]

hi Gabriel, thank you for your feedback. The samples show how to perform different Logging operations using Java client library or logback logging framework. However, it is still a subject to constraints on the client side (such as a number of RPC channels) and on the server side such as API quota.

If you can post the full code of the sample application that demonstrates this problem here or in https://gist.github.com/ we will try to help you in resolving the problem.

[minherz]

hi Gabriel,
I am closing this issue for now. Feel free to re-open this issue when you have a working example that is reproducing the described behavior.