Jetty.project: "Jetty 9.4.12" with "Conscrypt 1.2" provokes file descriptors leak

[tk-l2002]

_Originally posted by @tk-l2002 in https://github.com/eclipse/jetty.project/issues/2342#issuecomment-438718275_

[sbordet]

So if SSLEngine.isOutboundDone() returns true even though it has not produced the close_notify bytes, SslConnection.DecryptedEndPoint should still try to shutdown the output on the raw EndPoint, and possibly close.

[radifalco]

I also see this with Conscrypt 1.4.1 when using HTTP/2.

[sbordet]

I tried the latest Jetty (9.4.14 and 9.4.15) and latest Conscrypt (1.4.2 and 2.0.0), and I cannot see this issue with or without HTTP/2.

If you have a reproducible case, we would love to hear the details so that we can figure this out.

[sunng87]

I can reproduce this issue with Jetty 9.4.15 and Conscrypt 2.0.0, with wrk tool. SslConnections created by wrk were never recycled, which causes heap/off-heap/fd leak.

[sunng87]

Switched to jdk11 based alpn-java-server, there is no more leak. I believe this is an issue with Conscrypt.

[olamy]

@sunng87 current jetty-9.4.x branch has been upgraded to use Conscrypt 2.0.0 maybe this will fix your problem?
if not can you please provide a reproducible case.
thanks

[sunng87]

@olamy sorry for late response. I tested with latest 9.4.x branch and it's still the case. Simply start an https server using conscrypt, and test it with wrk -t 8 -c 500 -d 10 https://localhost:8443/ several times. You will see the memory usage of Jetty process goes up and never recycled. Also by acquiring a server dump using eclipse-mat, I can see almost as many SslConnections as I created stays in memory.

If you like to see the server, it's a Clojure one (I changed Jetty version locally): https://github.com/sunng87/ring-jetty9-adapter/blob/master/examples/rj9a/http2.clj

[mattnelson]

Was able to reproduce as well, providing some more information. I am using conscrypt-2.1.0 and jetty-9.4.15.v20190215. As shown below and commented on conscrypt this appears to be competing issue between GC and the file descriptor limit. With a small heap the objects will be reclaimed/closed before reaching the FD limit. With a large heap the opposite will happen.

# before test
# no SslConnection objects
jcmd 1 GC.class_histogram | grep SslConnection
1250:             2            176  org.eclipse.jetty.server.SslConnectionFactory
1982:             3             72  org.eclipse.jetty.io.ssl.SslConnection$FillState
1983:             3             72  org.eclipse.jetty.io.ssl.SslConnection$FlushState
1984:             3             72  org.eclipse.jetty.io.ssl.SslConnection$Handshake
2850:             1             32  [Lorg.eclipse.jetty.io.ssl.SslConnection$FillState;
2851:             1             32  [Lorg.eclipse.jetty.io.ssl.SslConnection$FlushState;
2852:             1             32  [Lorg.eclipse.jetty.io.ssl.SslConnection$Handshake;
# file descriptor count
ls /proc/1/fd | wc -l
61

I used vegeta to simulate the load

echo "HEAD https://localhost:8443" | vegeta attack -duration=60s -rate=200 | vegeta report -every 10s

Confirming object count and file descriptor usage

# Must supply "-all" flag to avoid a GC
jcmd 1 GC.class_histogram -all | grep SslConnection
  46:          3274         340496  org.eclipse.jetty.io.ssl.SslConnection
  72:          3274         235728  org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint
 174:          3274          78576  org.eclipse.jetty.io.ssl.SslConnection$1
 218:          3274          52384  org.eclipse.jetty.io.ssl.SslConnection$2
 219:          3274          52384  org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint$IncompleteWriteCallback
1652:             2            176  org.eclipse.jetty.server.SslConnectionFactory
2456:             3             72  org.eclipse.jetty.io.ssl.SslConnection$FillState
2457:             3             72  org.eclipse.jetty.io.ssl.SslConnection$FlushState
2458:             3             72  org.eclipse.jetty.io.ssl.SslConnection$Handshake
3392:             1             32  [Lorg.eclipse.jetty.io.ssl.SslConnection$FillState;
3393:             1             32  [Lorg.eclipse.jetty.io.ssl.SslConnection$FlushState;
3394:             1             32  [Lorg.eclipse.jetty.io.ssl.SslConnection$Handshake;
ls /proc/1/fd | wc -l
641

Trigger a GC

# repeat without all flag to GC the connection
jcmd 1 GC.class_histogram | grep SslConnection
1268:             2            176  org.eclipse.jetty.server.SslConnectionFactory
1622:             1            104  org.eclipse.jetty.io.ssl.SslConnection
2012:             1             72  org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint
2013:             3             72  org.eclipse.jetty.io.ssl.SslConnection$FillState
2014:             3             72  org.eclipse.jetty.io.ssl.SslConnection$FlushState
2015:             3             72  org.eclipse.jetty.io.ssl.SslConnection$Handshake
2897:             1             32  [Lorg.eclipse.jetty.io.ssl.SslConnection$FillState;
2898:             1             32  [Lorg.eclipse.jetty.io.ssl.SslConnection$FlushState;
2899:             1             32  [Lorg.eclipse.jetty.io.ssl.SslConnection$Handshake;
3909:             1             24  org.eclipse.jetty.io.ssl.SslConnection$1
5333:             1             16  org.eclipse.jetty.io.ssl.SslConnection$2
5334:             1             16  org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint$IncompleteWriteCallback
ls /proc/1/fd | wc -l
63

[sunng87]

In my case, SslConnections were not recycled even with jcmd pid GC.run

$ jcmd 25726 GC.class_histogram | grep SslConnection                                          [22:06:28]
  20:          3006         312624  org.eclipse.jetty.io.ssl.SslConnection
  37:          3006         216432  org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint
  95:          3006          72144  org.eclipse.jetty.io.ssl.SslConnection$1
 110:          3006          48096  org.eclipse.jetty.io.ssl.SslConnection$2
 111:          3006          48096  org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint$IncompleteWriteCallback
 626:             1             88  org.eclipse.jetty.server.SslConnectionFactory
 676:             3             72  org.eclipse.jetty.io.ssl.SslConnection$FillState
 677:             3             72  org.eclipse.jetty.io.ssl.SslConnection$FlushState
 678:             3             72  org.eclipse.jetty.io.ssl.SslConnection$Handshake
 859:             1             32  [Lorg.eclipse.jetty.io.ssl.SslConnection$FillState;
 860:             1             32  [Lorg.eclipse.jetty.io.ssl.SslConnection$FlushState;
 861:             1             32  [Lorg.eclipse.jetty.io.ssl.SslConnection$Handshake;

[j-razeed]

Any fix available for this issue?

[sbordet]

@j-razeed the fix seemed all the times a Conscrypt issue, so be sure to be updated to the latest release of Conscrypt. We don't have evidence it is a Jetty issue so far.

[sunng87]

Tried latest conscrypt 2.2.1 with no luck.

[sunng87]

Not quite sure if it's related. By analysing class diagram, I saw a bunch of ALPNCallbacks hold in memory, with it's number equals to connections I created. However, ALPN should have finished right after connection established.

[kruton]

@sunng87 the ALPNCallback adds itself as a HandshakeListener so it won't go away until the connection is GC'd.

You might be on to something, though. The ALPNCallback is added as a NewGlobalRef in the native code. That was added in Conscrypt 1.1.0 release. Perhaps a refactor to hold the reference via Java instead of in native's AppData structure would allow the GC to run on this.

[kruton]

It might work to separate the ALPNSelector and the SSLHandshakeCallback into two classes for now if anyone has the time to try that.

[sbordet]

@kruton @sunng87 one thing we can do is to remove the ALPNCallback when the ALPN negotiation is finished, via SslConnection.removeHandshakeListener().

If I create a branch for that, would you be able to test it?

[sunng87]

@sbordet sure, I can help test.

[kruton]

I posted a pull request at https://github.com/google/conscrypt/pull/735 which I think fixes the issue.

[sunng87]

Tested from my build, there is no more SslConnection leak with google/conscrypt#735

Class histogram after wrk test with 6000 SSL connections:

[joakime]

When that PR is merged, and a new release of conscrypt is released, we can upgrade Jetty to use it.

[prateekkohli2112]

I am also facing this issue with Jetty - 9.4.24.v20191120 and Conscrypt - 2.1.0 .

Will it be fixed if I upgrade my Jetty to 9.4.31.v20200723 and Conscrypt to 2.5.0?

[sunng87]

Unfortunately we are still experiencing memory leak with latest conscrypt. The issue is now tracked in https://github.com/google/conscrypt/issues/835

[prateekkohli2112]

Is there any workaround for this?

Or do we need to go with JDK8 ALPN.

[sunng87]

Yes JDK 8u252 has built-in ALPN support. Not sure about its real performance though