Grpc-java: Make sure to call shutdown()/shutdownNow() and wait until awaitTermination() returns true

[runzhiwang]

gRPC-java version: 1.28.1

What's the problem ?

1. The exception java.lang.RuntimeException: ManagedChannel allocation site threw too many times, the detail as the following stack shows. I do not want the exception happens.

 May 07, 2020 3:15:12 PM org.apache.ratis.thirdparty.io.grpc.internal.ManagedChannelOrphanWrapper$ManagedChannelReference cleanQueue
 SEVERE: *~*~*~ Channel ManagedChannelImpl{logId=91, target=0.0.0.0:35791} was not shutdown properly!!! ~*~*~*
     Make sure to call shutdown()/shutdownNow() and wait until awaitTermination() returns true.
 java.lang.RuntimeException: ManagedChannel allocation site
    at org.apache.ratis.thirdparty.io.grpc.internal.ManagedChannelOrphanWrapper$ManagedChannelReference.<init>(ManagedChannelOrphanWrapper.java:94)
    at org.apache.ratis.thirdparty.io.grpc.internal.ManagedChannelOrphanWrapper.<init>(ManagedChannelOrphanWrapper.java:52)
    at org.apache.ratis.thirdparty.io.grpc.internal.ManagedChannelOrphanWrapper.<init>(ManagedChannelOrphanWrapper.java:43)
    at org.apache.ratis.thirdparty.io.grpc.internal.AbstractManagedChannelImplBuilder.build(AbstractManagedChannelImplBuilder.java:518)
    at org.apache.ratis.grpc.client.GrpcClientProtocolClient.<init>(GrpcClientProtocolClient.java:129)
    at org.apache.ratis.grpc.client.GrpcClientRpc.lambda$new$0(GrpcClientRpc.java:55)
    at org.apache.ratis.util.PeerProxyMap$PeerAndProxy.lambda$getProxy$0(PeerProxyMap.java:62)
    at org.apache.ratis.util.LifeCycle.startAndTransition(LifeCycle.java:257)
    at org.apache.ratis.util.PeerProxyMap$PeerAndProxy.getProxy(PeerProxyMap.java:61)
    at org.apache.ratis.util.PeerProxyMap.getProxy(PeerProxyMap.java:109)
    at org.apache.ratis.grpc.client.GrpcClientRpc.sendRequestAsync(GrpcClientRpc.java:66)
    at org.apache.ratis.client.impl.OrderedAsync.sendRequest(OrderedAsync.java:233)
    at org.apache.ratis.client.impl.OrderedAsync.sendRequestWithRetry(OrderedAsync.java:187)
    at org.apache.ratis.util.SlidingWindow$Client.sendOrDelayRequest(SlidingWindow.java:278)
    at org.apache.ratis.util.SlidingWindow$Client.retry(SlidingWindow.java:294)
    at org.apache.ratis.client.impl.OrderedAsync.lambda$scheduleWithTimeout$7(OrderedAsync.java:220)
    at org.apache.ratis.util.TimeoutScheduler.lambda$onTimeout$0(TimeoutScheduler.java:141)
    at org.apache.ratis.util.TimeoutScheduler.lambda$onTimeout$1(TimeoutScheduler.java:155)
    at org.apache.ratis.util.LogUtils.runAndLog(LogUtils.java:38)
    at org.apache.ratis.util.LogUtils$1.run(LogUtils.java:79)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

1. build ManagedChannel code, you can also find it here :

    channel = channelBuilder.flowControlWindow(flowControlWindow.getSizeInt())
        .maxInboundMessageSize(maxMessageSize.getSizeInt())
        .build();

1. close ManagedChannel code, you can also find it at shutdownManagedChannel:

  static void shutdownManagedChannel(ManagedChannel managedChannel, Logger LOG) {
    // Close the gRPC managed-channel if not shut down already.
    if (!managedChannel.isShutdown()) {
      try {
        managedChannel.shutdown();
        if (!managedChannel.awaitTermination(45, TimeUnit.SECONDS)) {
          LOG.warn("Timed out gracefully shutting down connection: {}. ", managedChannel);
        }
      } catch (Exception e) {
        LOG.error("Unexpected exception while waiting for channel termination", e);
      }
    }

    // Forceful shut down if still not terminated.
    if (!managedChannel.isTerminated()) {
      try {
        managedChannel.shutdownNow();
        if (!managedChannel.awaitTermination(15, TimeUnit.SECONDS)) {
          LOG.warn("Timed out forcefully shutting down connection: {}. ", managedChannel);
        }
      } catch (Exception e) {
        LOG.error("Unexpected exception while waiting for channel termination", e);
      }
    }
  }

[ericgribkoff]

Could you clarify what you're asking for here? I think the question is why you're seeing the warning posted in section (1). This is intended to let you know that your channels are going out of scope without properly being shutdown, which can leak resources. You posted your channel shutdown code (shutdownManagedChannel); my guess would be that this method is not being called for all channels. If you could provide more details I may be able to provide more help. Thanks.

[runzhiwang]

@ericgribkoff Thank you for your explanation very much.

I think the question is why you're seeing the warning posted in section (1)

Yes, it's the question.

my guess would be that this method is not being called for all channels.

shutdownManagedChannel has been called, actually.

More details:

1. There are two variables of ManagedChannel, one is in client, the other is in server.

2. This problem happen when I run the CI of ratis, I add more log to show how many ManagedChannel exist before/after create/close client and server.

3. you can find it print grpc close client this:1665219149 addr:0.0.0.0:33377 shutdown:true terminated:true client channel count:3 in the following log, and this log message was printed after GrpcUtil::shutdownManagedChannel. So GrpcUtil::shutdownManagedChannel was executed.

4. You can also find ManagedChannel.isShutdown() and ManagedChannel.isTerminated() both become true after GrpcUtil::shutdownManagedChannel from the following log. The log of the CI can be found here

 grpc create client this:1665219149 addr:0.0.0.0:33377 client channel count:3
 grpc close client this:1665219149 addr:0.0.0.0:33377 shutdown:true terminated:true client channel count:3
 grpc create client this:194830930 addr:0.0.0.0:43189 client channel count:3
 grpc create server this:151619692 addr:0.0.0.0:33015 server channel count:4
 grpc create server this:1892865681 addr:0.0.0.0:32825 server channel count:4
 May 09, 2020 1:09:40 AM org.apache.ratis.thirdparty.io.grpc.internal.ManagedChannelOrphanWrapper$ManagedChannelReference cleanQueue
 SEVERE: *~*~*~ Channel ManagedChannelImpl{logId=20, target=0.0.0.0:38551} was not shutdown properly!!! ~*~*~*
     Make sure to call shutdown()/shutdownNow() and wait until awaitTermination() returns true.
 java.lang.RuntimeException: ManagedChannel allocation site
    at org.apache.ratis.thirdparty.io.grpc.internal.ManagedChannelOrphanWrapper$ManagedChannelReference.<init>(ManagedChannelOrphanWrapper.java:94)
    at org.apache.ratis.thirdparty.io.grpc.internal.ManagedChannelOrphanWrapper.<init>(ManagedChannelOrphanWrapper.java:52)
    at org.apache.ratis.thirdparty.io.grpc.internal.ManagedChannelOrphanWrapper.<init>(ManagedChannelOrphanWrapper.java:43)
    at org.apache.ratis.thirdparty.io.grpc.internal.AbstractManagedChannelImplBuilder.build(AbstractManagedChannelImplBuilder.java:518)
    at org.apache.ratis.grpc.client.GrpcClientProtocolClient.<init>(GrpcClientProtocolClient.java:132)
    at org.apache.ratis.grpc.client.GrpcClientRpc.lambda$new$0(GrpcClientRpc.java:55)
    at org.apache.ratis.util.PeerProxyMap$PeerAndProxy.lambda$getProxy$0(PeerProxyMap.java:62)
    at org.apache.ratis.util.LifeCycle.startAndTransition(LifeCycle.java:213)
    at org.apache.ratis.util.PeerProxyMap$PeerAndProxy.getProxy(PeerProxyMap.java:61)
    at org.apache.ratis.util.PeerProxyMap.getProxy(PeerProxyMap.java:109)
    at org.apache.ratis.grpc.client.GrpcClientRpc.sendRequest(GrpcClientRpc.java:91)
    at org.apache.ratis.client.impl.RaftClientImpl.sendRequest(RaftClientImpl.java:337)
    at org.apache.ratis.client.impl.RaftClientImpl.groupAdd(RaftClientImpl.java:249)
    at org.apache.ratis.server.impl.GroupManagementBaseTest.testSingleGroupRestart(GroupManagementBaseTest.java:90)
    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.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
    at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
    at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
    at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
    at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
    at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:298)
    at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:292)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.lang.Thread.run(Thread.java:748)

[ericgribkoff]

Thanks for the details. I don't see, or am unable to parse out, a "smoking gun" from the unit test logs that shows definitively that the code is not leaking channels but still seeing the logged warning. Can you isolate this occurrence down to a single unit test that shows the problem? Or a separate stand-alone reproduction? The current logs have lots and lots of channels so it looks entirely possible that some are being leaked, so it would be very helpful to have a much smaller reproduction case to investigate. If so, it would also be helpful to turn on channel logging via setting io.grpc.ChannelLogger.level=FINEST in logging.properties (configured as in https://stackoverflow.com/questions/50243717/grpc-logger-level).

[runzhiwang]

@ericgribkoff Thank you very much. With you help, I have found the root cause: a lot of clients were not closed after use, in src and test.

[ericgribkoff]

@runzhiwang That's great :) It sounds like I can mark this issue closed then. If it turns out there's anything else involved feel free to comment here and I can reopen. Thanks!