Socket leak in client when server sends GoAway

[bbeaudreault]

Please answer these questions before submitting your issue.

What version of gRPC are you using?

1.5.0 (previously 1.0.2)

What JVM are you using (java -version)?

Various versions of 1.8, this one 1.8.0_66

What did you do?

If possible, provide a recipe for reproducing the error.

Golang gRPC server configured with MaxConnectionAge set to 30s. Simple java main client:

ManagedChannel chan = NettyChannelBuilder.forTarget("myhost:port").negotiationType(NegotiationType.PLAINTEXT).build();
RpcClient rpcClient = createStubFromChan(chan);
long start = System.currentTimeMillis();
    try {
      int lastCount = 0;
      while (true) {
        try {
            rpcClient.execute(ctx, Vtgate.ExecuteRequest
                .newBuilder()
                .setQuery(Query.BoundQuery.newBuilder().setSql("select 1").build())
                .setSession(Vtgate.Session
                    .newBuilder()
                    .setTargetString("vttest@master")
                    .setAutocommit(true))
                .build()).get();
          int count = 0;
          for (Thread t : Thread.getAllStackTraces().keySet()) {
            if (t.getName().contains("grpc-default-worker")) {
              count++;
            }
          }
          if (count != lastCount) {
            System.out.println("Threads: " + Long.toString(count));
            lastCount = count;
          }
        } catch (Exception e) {
          System.out.println("Caught exception: " + e.getMessage());
        }
      }
    } finally {
      System.out.println("Finished after: " + Long.toString(System.currentTimeMillis() - start));
    }

What did you expect to see?

Max age is set low to exacerbate the issue, but is also seen over a longer period of time when run in production with a larger value.

On GoAway, the streams should be drained and the connection closed once gracefully finished. I expect to see no growth in count of grpc-default-worker threads. On the server side I expect to see no growth in grpc http2_client goroutines.

What did you see instead?

Every time max age is triggered, sending a GoAway, streams seem to be drained and unary calls fail. On retry a new connection and thus grpc-default-worker thread is created. Those threads are never cleaned up, even over the course of many hours. When the loop restarts a new connection is created, which results in a new grpc-default-worker thread. Therefore we see growth over time.

On the server side, we see a growth in grpc http2_client goroutines. They are all stuck on readFrame, waiting to receive a ping or EOF from the client.

Setting the GRPCMaxConnectionAgeGrace mitigates this a little, in that the server will force close the connections. However, this is not acceptable because sometimes we do have long running streams which we want to allow to finish gracefully.

[ejona86]

How many grpc-default-workers did you see, and how many cores does the machine it's running on have? Netty eagerly creates new Threads, even when a thread could be reused, until it reaches the target number of threads, currently configured at 2*core count.

[bbeaudreault]

@ejona86 you beat me! Was just writing this up:

Closing this for now. After a bunch of testing and deciding to write this up, I finally got some data while writing it up to potentially disprove the leak. I think our problem may be that we are running our applications on mesos which slices up very large machines. With the thread multiplier each client ends up using up 80+ threads over time. On my local machine it tops out at just 16.

I think we may just need to limit that max number of threads.

[bbeaudreault]

@ejona86 sorry, reopening. You were right that changing to my own NioEventLoopGroup allows me to limit the number of threads. However, I think the thread count was a red herring. The real problem seems to be a leak of sockets. I've been trying to trace through the various layers of calls between grpc and netty, but am not having much luck.

Basically the problem is that with a simple java main class running against a server with MaxConnectionAge of 30s, I can quickly build up open sockets on the server side:

netstat -nap | grep 10.204.112.178
tcp        0      0 172.18.115.137:16101        10.204.112.178:53648        ESTABLISHED -
tcp        0      0 172.18.115.137:16101        10.204.112.178:53718        ESTABLISHED -
tcp        0      0 172.18.115.137:16101        10.204.112.178:53650        ESTABLISHED -
tcp        0      0 172.18.115.137:16101        10.204.112.178:53700        ESTABLISHED -
tcp        0    426 172.18.115.137:16101        10.204.112.178:53721        ESTABLISHED -
tcp        0      0 172.18.115.137:16101        10.204.112.178:53669        ESTABLISHED -
tcp        0      0 172.18.115.137:16101        10.204.112.178:53715        ESTABLISHED -

That is on the server side after only a few minutes. Similarly I can still see the ports open on the java/client side. If I let it run for a a long time they never go away until the MaxConnectionAgeGrace triggers a server-side kill. Looking at the active goroutine dump on the server side, they are all just hanging on IO waiting for a frame from the client. But the client will never send it, because the sockets are active but unused.

I would expect the sockets to be closed once they are drained, but it doesn't appear to.

Do you have any thoughts?

I tried updating to netty-handler 4.1.14.Final (leaving the rest handled by grpc 1.5.0), but that did not help.

[bbeaudreault]

Note: in the above I've limited the threads to 2, and verified that no more than 2 are being created. However, the sockets build well past 2.

[bbeaudreault]

Here is from the client side (my mac):

netstat -na | grep 172.18.115.137
tcp4       0     84  10.204.112.178.54004   172.18.115.137.16101   ESTABLISHED
tcp4       0      0  10.204.112.178.53989   172.18.115.137.16101   ESTABLISHED
tcp4       0      0  10.204.112.178.53985   172.18.115.137.16101   ESTABLISHED
tcp4       0      0  10.204.112.178.53982   172.18.115.137.16101   ESTABLISHED
tcp4       0      0  10.204.112.178.53980   172.18.115.137.16101   ESTABLISHED

Note only 1 of the sockets is being sent any traffic (or at least has any queued). Each time a new one is created, the "active" one changes -- makes sense I'm only actually using 1 of the open sockets.

[carl-mastrangelo]

@bbeaudreault unrelated, but you should also set an executor on your server. Executors.newFixedThreadPool(2) should work. (The default, which is different than the event loop group, spawns threads a lot.)

[bbeaudreault]

Thanks @carl-mastrangelo -- in this case I'm using a grpc-go based server, so not sure if that setting can affect the client?

Back to the issue, I've added breakpoints throughout AbstractChannelHandlerContext and can see plenty of calls to invokeConnect (i.e. on retry), but no calls to invokeClose, close, or deregister, disconnect.

Is it possible that the GoAway stuff is only partially implemented? I see a lot of code related to GoAway around shutting down of streams, avoiding new streams, setting to IDLE, etc. But I don't see the connection ever being closed. It instead seems to become orphaned.

I'm just getting my bearings here, but I see the following happen when a GoAway comes in:

• notifyShutdown is called
• this goes to InternalSubchannel.transportShutdown
• this:
  • sets subchannel state to IDLE
  • sets activeTransport to null
  • calls drain() on channelExecutor
• the IDLE change triggers PickFirstBalancerFactory, which picks the newly idle SubChannel

Later when a new request comes in, it calls InternalSubchannel.obtainActiveTransport(). Since the activeTransport was set to null above, this causes startNewTransport(). At this point the old socket is orphaned. It's never cleaned up as far as I can tell.

Shut there be a call to shutdown the activeTransport before setting it to null in InternalSubchannel.transportShutdown? Or should there be a executeLater call to clean it up once drain() has finished?

[carl-mastrangelo]

@bbeaudreault How many active RPCs do you have at the time? The connections will never die if there are active RPCs. Getting a Go away means that the other side would like to shut down once all the RPCs are complete, and also please don't start any more. All the threads stuck in read sounds like not all RPCs are done.

[bbeaudreault]

@carl-mastrangelo I was doing around 30 QPS -- unary requests, no streaming. But when I was doing the above attempt at stepping through, I had actually simplified to just a single call:

Context ctx = Context.getDefault();
    RpcClient rpcClient = factory.create(ctx, "hostname:16101");
    rpcClient.execute(ctx, Vtgate.ExecuteRequest
        .newBuilder()
        .setQuery(Query.BoundQuery.newBuilder().setSql("select 1").build())
        .setSession(Vtgate.Session
            .newBuilder()
            .setTargetString("vttest@master")
            .setAutocommit(true))
        .build()).get();
    long start = System.currentTimeMillis();
    try {
      int lastCount = 0;
      while (true) {
        Thread.sleep(1000);
         // commented out the execute call that used to be here
      }
    } finally {
      System.out.println("Finished after: " + Long.toString(System.currentTimeMillis() - start));
    }

With that running I could step through with the debugger and verify that close was never called and the socket remained open.

[bbeaudreault]

Also, just to clarify, the "threads stuck in read" were on the server side. On the client side I could find no pointer to them or thread, but the file descriptors were still open and I had never seen close happen.

[carl-mastrangelo]

Alas, I think I am going to need more detail before this can be debugged further. When you are stepping through, are you checking when these points are reached?

1. https://github.com/grpc/grpc-java/blob/master/netty/src/main/java/io/grpc/netty/NettyClientHandler.java#L175
2. https://github.com/grpc/grpc-java/blob/master/netty/src/main/java/io/grpc/netty/NettyClientHandler.java#L410
3. https://github.com/grpc/grpc-java/blob/master/netty/src/main/java/io/grpc/netty/NettyClientHandler.java#L451
4. https://github.com/grpc/grpc-java/blob/master/netty/src/main/java/io/grpc/netty/NettyClientHandler.java#L573

Are any of these points hit?

[bbeaudreault]

Thanks for the pointers @carl-mastrangelo -- i'll dig into those points tomorrow and report back.

[bbeaudreault]

@carl-mastrangelo: only the first and last link are hit (L175 & L573). In my slimmed down test case pasted above this makes sense I think:

I connect and kick off a single unary call. The connection stays open (which is good). 30s later the GOAWAY comes. There are no active streams at this time.

goingAway calls lifecycleManager.notifyShutdown(status)which calls listener.transportShutdown(s), implemented by InternalSubchannel. This sets activeChannel to null which effectively orphans it. We should call activeChannel.shutdown() or call it in the finally after drain() maybe?