Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Client timeout and async close exceptions when setting max duration on pool #7107

Closed
clardeur opened this issue Nov 12, 2021 · 7 comments · Fixed by #7146 or #7123
Closed

Client timeout and async close exceptions when setting max duration on pool #7107

clardeur opened this issue Nov 12, 2021 · 7 comments · Fixed by #7146 or #7123
Assignees
@lorban
Labels
Bug For general bugs on Jetty side

Comments

@clardeur
Copy link

Jetty version(s)

11.0.6

Java version/vendor (use: java -version)

openjdk version "11.0.11" 2021-04-20
OpenJDK Runtime Environment (build 11.0.11+9-Ubuntu-0ubuntu2.18.04)
OpenJDK 64-Bit Server VM (build 11.0.11+9-Ubuntu-0ubuntu2.18.04, mixed mode, sharing)

OS type/version

Linux 5.4.0-89-generic #100~18.04.1-Ubuntu SMP Wed Sep 29 10:59:42 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux

Description

We have been using Jetty in production for a while, client and server side, with a custom client RoundRobinConnectionPool that support TTL connection, like this proposal (#1893), after upgrading we have tested the max duration implementation (#5799) and we have encountered several issues by carrying out production load tests.

We have detected many AsynchronousCloseException after the connection was marked as removed due to expiration and after a certain time all our client requests fails with a TimeoutException. I don't know if this is two separated issues or the same root cause, but this is a blocking issue for us when all clients requests fails, the pool seems to be in a bad and is not able to recover.

How to reproduce?

I have reproduced the AsynchronousCloseException problem in the branch 11.0.x by running the concurrent load test and completing the HttpClientLoadTest.LoadTransportScenario.provideClientTransport() with this snippet :

                case H2:
                case H2C:
                {
                    ClientConnector clientConnector = new ClientConnector();
                    clientConnector.setSelectors(1);
                    clientConnector.setSslContextFactory(sslContextFactory);
                    HttpClientTransport clientTransport = new HttpClientTransportOverHTTP2(new HTTP2Client(clientConnector));
                    clientTransport.setConnectionPoolFactory(destination -> {
                        RoundRobinConnectionPool pool = new RoundRobinConnectionPool(destination, 4, destination);
                        pool.setMaxDuration(500);
                        return pool;
                    });
                    return clientTransport;
                }

The exception stacktrace :

java.nio.channels.AsynchronousCloseException
	at org.eclipse.jetty.http2.client.http.HttpConnectionOverHTTP2.close(HttpConnectionOverHTTP2.java:200)
	at org.eclipse.jetty.client.HttpDestination.release(HttpDestination.java:427)
	at org.eclipse.jetty.http2.client.http.HttpChannelOverHTTP2.release(HttpChannelOverHTTP2.java:110)
	at org.eclipse.jetty.http2.client.http.HttpChannelOverHTTP2.exchangeTerminated(HttpChannelOverHTTP2.java:119)
	at org.eclipse.jetty.client.HttpReceiver.terminateResponse(HttpReceiver.java:473)
	at org.eclipse.jetty.client.HttpReceiver.terminateResponse(HttpReceiver.java:458)
	at org.eclipse.jetty.client.HttpReceiver.responseSuccess(HttpReceiver.java:421)
	at org.eclipse.jetty.http2.client.http.HttpReceiverOverHTTP2.access$100(HttpReceiverOverHTTP2.java:52)
	at org.eclipse.jetty.http2.client.http.HttpReceiverOverHTTP2$ContentNotifier.process(HttpReceiverOverHTTP2.java:298)
	at org.eclipse.jetty.http2.client.http.HttpReceiverOverHTTP2$ContentNotifier.offer(HttpReceiverOverHTTP2.java:259)
	at org.eclipse.jetty.http2.client.http.HttpReceiverOverHTTP2.notifyContent(HttpReceiverOverHTTP2.java:235)
	at org.eclipse.jetty.http2.client.http.HttpReceiverOverHTTP2.onData(HttpReceiverOverHTTP2.java:204)
	at org.eclipse.jetty.http2.client.http.HttpChannelOverHTTP2$Listener.onData(HttpChannelOverHTTP2.java:187)
	at org.eclipse.jetty.http2.api.Stream$Listener.onDataDemanded(Stream.java:256)
	at org.eclipse.jetty.http2.HTTP2Stream.notifyDataDemanded(HTTP2Stream.java:807)
	at org.eclipse.jetty.http2.HTTP2Stream.processData(HTTP2Stream.java:522)
	at org.eclipse.jetty.http2.HTTP2Stream.onData(HTTP2Stream.java:480)
	at org.eclipse.jetty.http2.HTTP2Stream.process(HTTP2Stream.java:368)
	at org.eclipse.jetty.http2.HTTP2Session.onData(HTTP2Session.java:262)
	at org.eclipse.jetty.http2.HTTP2Connection$ParserListener.onData(HTTP2Connection.java:407)
	at org.eclipse.jetty.http2.parser.BodyParser.notifyData(BodyParser.java:103)
	at org.eclipse.jetty.http2.parser.DataBodyParser.onData(DataBodyParser.java:145)
	at org.eclipse.jetty.http2.parser.DataBodyParser.onData(DataBodyParser.java:140)
	at org.eclipse.jetty.http2.parser.DataBodyParser.parse(DataBodyParser.java:106)
	at org.eclipse.jetty.http2.parser.Parser.parseBody(Parser.java:193)
	at org.eclipse.jetty.http2.parser.Parser.parse(Parser.java:122)
	at org.eclipse.jetty.http2.HTTP2Connection$HTTP2Producer.produce(HTTP2Connection.java:278)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.produceTask(AdaptiveExecutionStrategy.java:446)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:239)
	at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.produce(AdaptiveExecutionStrategy.java:190)
	at org.eclipse.jetty.http2.HTTP2Connection.produce(HTTP2Connection.java:208)
	at org.eclipse.jetty.http2.HTTP2Connection.onFillable(HTTP2Connection.java:155)
	at org.eclipse.jetty.http2.HTTP2Connection$FillableCallback.succeeded(HTTP2Connection.java:378)
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:100)
	at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:548)
	at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:397)
	at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:164)
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:100)

For reproducibility reason, the max duration is very low (500ms) in this test but in our production load tests the max duration parameter was setted to 60s and the problem was the same.
@clardeur clardeur added the Bug For general bugs on Jetty side label Nov 12, 2021
@lorban lorban self-assigned this Nov 16, 2021
@lorban
Copy link
Contributor

lorban commented Nov 16, 2021 •
edited
Loading

Thanks for the detailed report, and thank you very much for the reproducing instructions as those are invaluable.

Indeed there is a problem when the connection expiration feature is enabled on a multiplexed connection pool.

I'm currently working on a fix and will keep you updated soon.

lorban added a commit that referenced this issue Nov 16, 2021
@lorban
#7107: candidate fix
100b3c7 
 the pool must be asked to know if a released connection can be closed
@lorban lorban modified the milestone: 10.0.x Nov 16, 2021
lorban added a commit that referenced this issue Nov 16, 2021
@lorban
#7107: candidate fix
2bf5247 
 the pool must be asked to know if a released connection can be closed
lorban added a commit that referenced this issue Nov 17, 2021
@lorban
#7107: fix too-eager closing of multiplexed connections marked as clo…
b57eb57 
…sed but still in use
@lorban
Copy link
Contributor

lorban commented Nov 17, 2021

I believe I nailed the problem and have a fix ready, hopefully it will get reviewed and merged soon: #7123

Please note that my PR is against 10.0.x because this bug impacts both 10.0.x and 11.0.x identically, and probably 9.4.x too.

lorban added a commit that referenced this issue Nov 17, 2021
@lorban
#7107: fix too-eager closing of multiplexed connections marked as clo…
79bed1d 
…sed but still in use
@lorban lorban modified the milestones: 10.0.x, 11.0.x Nov 17, 2021
lorban added a commit that referenced this issue Nov 18, 2021
@lorban
#7107: fix too-eager closing of multiplexed connections marked as clo…
9e0ee4b 
…sed but still in use
@clardeur
Copy link
Author

Here are some logs about our pool blocked in a bad state, all our client requests generate these logs :

2021/09/29 08:27:37.969 [qtp1217466562-1784] DEBUG o.e.j.client.AbstractConnectionPool - Acquiring create=true on RoundRobinConnectionPool@5932c3f9[c=0/4/4,a=0,i=0,q=1] 
2021/09/29 08:27:37.969 [qtp1217466562-1784] DEBUG o.e.j.client.AbstractConnectionPool - Try creating connection 4/4 with 0 pending 
2021/09/29 08:27:37.969 [qtp1217466562-1784] DEBUG o.e.j.client.AbstractConnectionPool - Try creating(true) connection, pending/demand/supply: 0/2/0, result=true 
2021/09/29 08:28:07.969 [HttpClient@82101952-48] DEBUG o.e.j.client.AbstractConnectionPool - Removed (true) Entry@461dfe57{CLOSED, usage=0, multiplex=0/128, pooled=HttpConnectionOverHTTP2@58ab568b(closed=true)[HTTP2ClientSession@7fecf0ad{
local:0.0.0.0/0.0.0.0:38326,remote:null,sendWindow=1048576,recvWindow=16777033,state=[streams=0,CLOSED,goAwayRecv=GoAwayFrame@3895aaaa{1/no_error/idle_timeout},goAwaySent=GoAwayFrame@38be7e11{0/no_error/close},failure=null]}]} Pool@1ddabc
e4[size=0 closed=false] 
2021/09/29 08:28:07.970 [HttpClient@34136bd1-scheduler-1] DEBUG o.eclipse.jetty.client.HttpExchange - Failed HttpExchange@7ef9c9c9{req=HttpRequest[GET /studies HTTP/1.1]@66245b3a[COMPLETED/java.util.concurrent.TimeoutException: Total time
out 30000 ms elapsed] res=HttpResponse[null 0 null]@b51a3f2[COMPLETED/java.util.concurrent.TimeoutException: Total timeout 30000 ms elapsed]}: req=true/rsp=true {} 
2021/09/29 08:28:07.970 [HttpClient@34136bd1-scheduler-1] DEBUG o.eclipse.jetty.client.HttpExchange - Aborting while queued HttpExchange@7ef9c9c9{req=HttpRequest[GET /studies HTTP/1.1]@66245b3a[COMPLETED/java.util.concurrent.TimeoutException: Total timeout 30000 ms elapsed] res=HttpResponse[null 0 null]@b51a3f2[COMPLETED/java.util.concurrent.TimeoutException: Total timeout 30000 ms elapsed]}: {} 
2021/09/29 08:28:07.971 [qtp1217466562-1784] ERROR c.y.h.s.e.ServerErrorExceptionMapper - server error <java.util.concurrent.ExecutionException: java.util.concurrent.TimeoutException: Total timeout 30000 ms elapsed> javax.ws.rs.ProcessingException: java.util.concurrent.ExecutionException: java.util.concurrent.TimeoutException: Total timeout 30000 ms elapsed

No sockets opened to the destination, verified with netstats. We have tried to remove the maxDuration param and use the maxUsage only, no more AsynchronousCloseException but a pool still in a bad state.

@lorban do you think this is an other issue, not related with this one ? Do you have any idea of what's happening ? We still have not been successful to reproduce the problem locally, this only happens in our production environment.

Thanks for your time.

@lorban
Copy link
Contributor

lorban commented Nov 18, 2021

maxDuration and maxUsage rely on the same buggy code path to figure out when to close connections. I'm not certain both features are impacted by the identified bug, especially since you report that the symptoms are slightly different, but it may be the case.

The logs you included are too brief to jump to any conclusion but since you suspect your connection pool being stuck, I would advise you to dump the server to try to get an idea of what the pool's state actually is and post the output on this issue. Have a look here to get an idea of how to get such dump.

What we're looking for looks like the following:

RoundRobinConnectionPool@6e83bfeb[c=0/10/1024,a=0,i=10,q=0] - STARTED
+- Pool@2d0979f2[size=10 closed=false]
|  +> entries size=10
|     +> Entry@32481bd{INUSE, usage=117665, multiplex=1/1, pooled=HttpConnectionOverHTTP@59302015::DecryptedEndPoint@3abc1b14{l=/127.0.0.1:54456,r=localhost/127.0.0.1:8443,OPEN,fill=FI,flush=-,to=0/15000}}
|     +> Entry@366ad57f{INUSE, usage=287, multiplex=1/1, pooled=HttpConnectionOverHTTP@11e49366::DecryptedEndPoint@498c39c7{l=/127.0.0.1:54462,r=localhost/127.0.0.1:8443,OPEN,fill=FI,flush=-,to=0/15000}}
...

Hopefully, the dump will tell us enough about the state of the pool to figure out how it ended up corrupted.

As a secondary step, I would advise you -if possible- to try using the HTTP/1.1 protocol instead of HTTP/2 to figure if the problem is still reproducible or if it's specific to HTTP/2.

lorban added a commit that referenced this issue Nov 19, 2021
@lorban
#7107: move new test into existing test class
4039360
lorban added a commit that referenced this issue Nov 19, 2021
@lorban
#7107: change quiche native dependency to released version
b2cfd16
lorban added a commit that referenced this issue Nov 19, 2021
@lorban
#7107: handle review comments
77f953f
lorban added a commit that referenced this issue Nov 22, 2021
@lorban
#7107: fix too-eager closing of multiplexed connections marked as clo…
3c019fa 
…sed but still in use
lorban added a commit that referenced this issue Nov 22, 2021
@lorban
#7107: move new test into existing test class
ad6434b
lorban added a commit that referenced this issue Nov 22, 2021
@lorban
#7107: handle review comments
f048f4d
lorban added a commit that referenced this issue Nov 22, 2021
@lorban
#7107: fix too-eager closing of multiplexed connections marked as clo…
259348d 
…sed but still in use
lorban added a commit that referenced this issue Nov 22, 2021
@lorban
#7107: fix too-eager closing of multiplexed connections marked as clo…
1c649c5 
…sed but still in use
@c-legrand
Copy link

Here a full dump of pools when the issue occurs :

HttpClient@38159384{STARTED} - STARTED
+= HttpClientTransportOverHTTP2@399291e6{STARTED} - STARTED
|  +~ ClientConnector@646ce4c5{STARTED} - STARTED
|  += HTTP2Client@4a19129a{STARTED} - STARTED
|     += ClientConnector@646ce4c5{STARTED} - STARTED
|        += QueuedThreadPool[HttpClient@38159384]@28b8f98a{STARTED,8<=8<=200,i=7,r=-1,q=0}[ReservedThreadExecutor@544e7941{s=0/1,p=0}] - STARTED
|        |  +- org.eclipse.jetty.util.thread.ThreadPoolBudget@79fedf8f
|        |  += ReservedThreadExecutor@544e7941{s=0/1,p=0} - STARTED
|        |  +> threads size=8
|        |     +> HttpClient@38159384-26 TIMED_WAITING tid=26 prio=5 IDLE
|        |     +> HttpClient@38159384-29 TIMED_WAITING tid=29 prio=5 IDLE
|        |     +> HttpClient@38159384-24 RUNNABLE tid=24 prio=5 SELECTING
|        |     +> HttpClient@38159384-28 TIMED_WAITING tid=28 prio=5 IDLE
|        |     +> HttpClient@38159384-31 TIMED_WAITING tid=31 prio=5 IDLE
|        |     +> HttpClient@38159384-27 TIMED_WAITING tid=27 prio=5 IDLE
|        |     +> HttpClient@38159384-30 TIMED_WAITING tid=30 prio=5 IDLE
|        |     +> HttpClient@38159384-25 TIMED_WAITING tid=25 prio=5 IDLE
|        +- org.eclipse.jetty.io.MappedByteBufferPool@7ab756b9
|        += ScheduledExecutorScheduler@783816b7{STARTED} - STARTED
|        |  +> java.base@11.0.7/jdk.internal.misc.Unsafe.park(Native Method)
|        |  +> java.base@11.0.7/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194)
|        |  +> java.base@11.0.7/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2081)
|        |  +> java.base@11.0.7/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1170)
|        |  +> java.base@11.0.7/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:899)
|        |  +> java.base@11.0.7/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1054)
|        |  +> java.base@11.0.7/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1114)
|        |  +> java.base@11.0.7/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
|        |  +> java.base@11.0.7/java.lang.Thread.run(Thread.java:834)
|        += Client@79247535[provider=null,keyStore=null,trustStore=null] - STARTED
|        |  +> trustAll=false
|        |  +> Protocol Selections
|        |  |  +> Enabled size=4
|        |  |  |  +> TLSv1
|        |  |  |  +> TLSv1.1
|        |  |  |  +> TLSv1.2
|        |  |  |  +> TLSv1.3
|        |  |  +> Disabled size=2
|        |  |     +> SSLv2Hello - ConfigExcluded:'SSLv2Hello' JVM:disabled
|        |  |     +> SSLv3 - ConfigExcluded:'SSLv3' JVM:disabled
|        |  +> Cipher Suite Selections
|        |     +> Enabled size=27
|        |     |  +> TLS_AES_128_GCM_SHA256
|        |     |  +> TLS_AES_256_GCM_SHA384
|        |     |  +> TLS_DHE_DSS_WITH_AES_128_CBC_SHA256
|        |     |  +> TLS_DHE_DSS_WITH_AES_128_GCM_SHA256
|        |     |  +> TLS_DHE_DSS_WITH_AES_256_CBC_SHA256
|        |     |  +> TLS_DHE_DSS_WITH_AES_256_GCM_SHA384
|        |     |  +> TLS_DHE_RSA_WITH_AES_128_CBC_SHA256
|        |     |  +> TLS_DHE_RSA_WITH_AES_128_GCM_SHA256
|        |     |  +> TLS_DHE_RSA_WITH_AES_256_CBC_SHA256
|        |     |  +> TLS_DHE_RSA_WITH_AES_256_GCM_SHA384
|        |     |  +> TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256
|        |     |  +> TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256
|        |     |  +> TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384
|        |     |  +> TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384
|        |     |  +> TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256
|        |     |  +> TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
|        |     |  +> TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384
|        |     |  +> TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384
|        |     |  +> TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA256
|        |     |  +> TLS_ECDH_ECDSA_WITH_AES_128_GCM_SHA256
|        |     |  +> TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA384
|        |     |  +> TLS_ECDH_ECDSA_WITH_AES_256_GCM_SHA384
|        |     |  +> TLS_ECDH_RSA_WITH_AES_128_CBC_SHA256
|        |     |  +> TLS_ECDH_RSA_WITH_AES_128_GCM_SHA256
|        |     |  +> TLS_ECDH_RSA_WITH_AES_256_CBC_SHA384
|        |     |  +> TLS_ECDH_RSA_WITH_AES_256_GCM_SHA384
|        |     |  +> TLS_EMPTY_RENEGOTIATION_INFO_SCSV
|        |     +> Disabled size=18
|        |        +> TLS_DHE_DSS_WITH_AES_128_CBC_SHA - ConfigExcluded:'^.*_(MD5|SHA|SHA1)$'
|        |        +> TLS_DHE_DSS_WITH_AES_256_CBC_SHA - ConfigExcluded:'^.*_(MD5|SHA|SHA1)$'
|        |        +> TLS_DHE_RSA_WITH_AES_128_CBC_SHA - ConfigExcluded:'^.*_(MD5|SHA|SHA1)$'
|        |        +> TLS_DHE_RSA_WITH_AES_256_CBC_SHA - ConfigExcluded:'^.*_(MD5|SHA|SHA1)$'
|        |        +> TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA - ConfigExcluded:'^.*_(MD5|SHA|SHA1)$'
|        |        +> TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA - ConfigExcluded:'^.*_(MD5|SHA|SHA1)$'
|        |        +> TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA - ConfigExcluded:'^.*_(MD5|SHA|SHA1)$'
|        |        +> TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA - ConfigExcluded:'^.*_(MD5|SHA|SHA1)$'
|        |        +> TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA - ConfigExcluded:'^.*_(MD5|SHA|SHA1)$'
|        |        +> TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA - ConfigExcluded:'^.*_(MD5|SHA|SHA1)$'
|        |        +> TLS_ECDH_RSA_WITH_AES_128_CBC_SHA - ConfigExcluded:'^.*_(MD5|SHA|SHA1)$'
|        |        +> TLS_ECDH_RSA_WITH_AES_256_CBC_SHA - ConfigExcluded:'^.*_(MD5|SHA|SHA1)$'
|        |        +> TLS_RSA_WITH_AES_128_CBC_SHA - ConfigExcluded:'^.*_(MD5|SHA|SHA1)$', ConfigExcluded:'^TLS_RSA_.*$'
|        |        +> TLS_RSA_WITH_AES_128_CBC_SHA256 - ConfigExcluded:'^TLS_RSA_.*$'
|        |        +> TLS_RSA_WITH_AES_128_GCM_SHA256 - ConfigExcluded:'^TLS_RSA_.*$'
|        |        +> TLS_RSA_WITH_AES_256_CBC_SHA - ConfigExcluded:'^.*_(MD5|SHA|SHA1)$', ConfigExcluded:'^TLS_RSA_.*$'
|        |        +> TLS_RSA_WITH_AES_256_CBC_SHA256 - ConfigExcluded:'^TLS_RSA_.*$'
|        |        +> TLS_RSA_WITH_AES_256_GCM_SHA384 - ConfigExcluded:'^TLS_RSA_.*$'
|        += ClientSelectorManager@39f9e4a3{STARTED} - STARTED
|           += ManagedSelector@5961c696{STARTED} id=0 keys=0 selected=0 updates=0 - STARTED
|              += AdaptiveExecutionStrategy@739c6cb2/SelectorProducer@2a3bf6a3/REPRODUCING/p=false/QueuedThreadPool[HttpClient@38159384]@28b8f98a{STARTED,8<=8<=200,i=7,r=-1,q=0}[ReservedThreadExecutor@544e7941{s=0/1,p=0}][pc=0,pic=234,pec=0,epc=1556449]@2021-11-22T11:48:54.853676Z - STARTED
|              |  +- SelectorProducer@2a3bf6a3
|              |  +~ QueuedThreadPool[HttpClient@38159384]@28b8f98a{STARTED,8<=8<=200,i=7,r=-1,q=0}[ReservedThreadExecutor@544e7941{s=0/1,p=0}] - STARTED
|              +> updates @ 2021-11-22T11:48:54.853015Z size=0
|              +> keys @ 2021-11-22T11:48:54.853189Z size=0
+- org.eclipse.jetty.client.ProtocolHandlers@3d574675
|  +> java.util.LinkedHashMap@8f6e91e1{size=5}
|     +@ continue = org.eclipse.jetty.client.ContinueProtocolHandler@c36d59b
|     +@ redirect = org.eclipse.jetty.client.RedirectProtocolHandler@15f6a18c
|     +@ www-authenticate = org.eclipse.jetty.client.WWWAuthenticationProtocolHandler@53744c3c
|     +@ proxy-authenticate = org.eclipse.jetty.client.ProxyAuthenticationProtocolHandler@5417ccc9
|     +@ upgrade = org.eclipse.jetty.client.UpgradeProtocolHandler@6e3751dd
+- org.eclipse.jetty.client.HttpClient$ContentDecoderFactorySet@4eed7756(size=1)
|  +: org.eclipse.jetty.client.GZIPContentDecoder$Factory@30a95a
+- org.eclipse.jetty.util.SocketAddressResolver$Async@3f09d71b
+= HttpDestination[Origin@60bf2298[http://10.240.12.240,tag=null,protocol=Protocol@301a9e[proto=[h2c],nego=false]]]@559225b7,queue=0,pool=RoundRobinConnectionPool@17f3f61[c=0/0/4,a=0,i=0,q=0] - STARTED
|  += RoundRobinConnectionPool@17f3f61[c=0/0/4,a=0,i=0,q=0] - STARTED
|  |  +- Pool@11b62dd9[size=0 closed=false]
|  |     +> entries size=0
|  +> exchanges size=0
+= HttpDestination[Origin@30817c56[http://10.240.14.240,tag=null,protocol=Protocol@301a9e[proto=[h2c],nego=false]]]@1d2a1389,queue=0,pool=RoundRobinConnectionPool@3d522d10[c=0/0/4,a=0,i=0,q=0] - STARTED
|  += RoundRobinConnectionPool@3d522d10[c=0/0/4,a=0,i=0,q=0] - STARTED
|  |  +- Pool@c0c157[size=0 closed=false]
|  |     +> entries size=0
|  +> exchanges size=0
+= HttpDestination[Origin@94884515[http://10.240.26.240,tag=null,protocol=Protocol@301a9e[proto=[h2c],nego=false]]]@44d01f72,queue=0,pool=RoundRobinConnectionPool@429ca4c6[c=0/4/4,a=0,i=0,q=0] - STARTED
|  += RoundRobinConnectionPool@429ca4c6[c=0/4/4,a=0,i=0,q=0] - STARTED
|  |  +- Pool@c0a984b[size=4 closed=false]
|  |     +> entries size=4
|  |        +> Entry@51c40b15{CLOSED, usage=0, multiplex=6/128, pooled=HttpConnectionOverHTTP2@768cdd78(closed=true)[HTTP2ClientSession@5b271c7e{local:null,remote:null,sendWindow=537769,recvWindow=12991803,state=[streams=0,CLOSED,goAwayRecv=GoAwayFrame@3eb44a1f{1755/no_error/idle_timeout},goAwaySent=GoAwayFrame@4f59627f{0/no_error/idle_timeout},failure=null]}]}
|  |        +> Entry@5f2e01f1{CLOSED, usage=0, multiplex=5/128, pooled=HttpConnectionOverHTTP2@3c893286(closed=true)[HTTP2ClientSession@207173ba{local:null,remote:null,sendWindow=649523,recvWindow=16477947,state=[streams=0,CLOSED,goAwayRecv=GoAwayFrame@243fb751{415/no_error/idle_timeout},goAwaySent=GoAwayFrame@bb10bae{0/no_error/idle_timeout},failure=null]}]}
|  |        +> Entry@7e59155c{CLOSED, usage=0, multiplex=1/128, pooled=HttpConnectionOverHTTP2@559e458e(closed=true)[HTTP2ClientSession@c42e553{local:null,remote:null,sendWindow=940773,recvWindow=15937821,state=[streams=0,CLOSED,goAwayRecv=GoAwayFrame@f2d630e{867/no_error/idle_timeout},goAwaySent=GoAwayFrame@39e86442{0/no_error/close},failure=null]}]}
|  |        +> Entry@1e7de4c4{CLOSED, usage=0, multiplex=6/128, pooled=HttpConnectionOverHTTP2@58ef225(closed=true)[HTTP2ClientSession@61dfc489{local:null,remote:null,sendWindow=1032449,recvWindow=14873660,state=[streams=0,CLOSED,goAwayRecv=GoAwayFrame@1b6f6684{13481/no_error/idle_timeout},goAwaySent=GoAwayFrame@6ac5eae9{0/no_error/idle_timeout},failure=null]}]}
|  +> exchanges size=0
+= HttpDestination[Origin@d0062fd2[http://10.240.18.240,tag=null,protocol=Protocol@301a9e[proto=[h2c],nego=false]]]@33ccde12,queue=0,pool=RoundRobinConnectionPool@6b5cc0e0[c=0/0/4,a=0,i=0,q=0] - STARTED
|  += RoundRobinConnectionPool@6b5cc0e0[c=0/0/4,a=0,i=0,q=0] - STARTED
|  |  +- Pool@49214ee7[size=0 closed=false]
|  |     +> entries size=0
|  +> exchanges size=0
+= HttpDestination[Origin@254137db[http://10.240.20.240,tag=null,protocol=Protocol@301a9e[proto=[h2c],nego=false]]]@ac2417a,queue=0,pool=RoundRobinConnectionPool@49d770b3[c=0/0/4,a=0,i=0,q=0] - STARTED
|  += RoundRobinConnectionPool@49d770b3[c=0/0/4,a=0,i=0,q=0] - STARTED
|  |  +- Pool@7680eb58[size=0 closed=false]
|  |     +> entries size=0
|  +> exchanges size=0
+= HttpDestination[Origin@43d614[http://10.240.16.240,tag=null,protocol=Protocol@301a9e[proto=[h2c],nego=false]]]@3d115f10,queue=0,pool=RoundRobinConnectionPool@4cbab9c1[c=0/0/4,a=0,i=0,q=0] - STARTED
|  += RoundRobinConnectionPool@4cbab9c1[c=0/0/4,a=0,i=0,q=0] - STARTED
|  |  +- Pool@1efd4b02[size=0 closed=false]
|  |     +> entries size=0
|  +> exchanges size=0
+= HttpDestination[Origin@644a9ed3[http://10.240.28.240,tag=null,protocol=Protocol@301a9e[proto=[h2c],nego=false]]]@13561a78,queue=0,pool=RoundRobinConnectionPool@30db1255[c=0/0/4,a=0,i=0,q=0] - STARTED
|  += RoundRobinConnectionPool@30db1255[c=0/0/4,a=0,i=0,q=0] - STARTED
|  |  +- Pool@1501bde8[size=0 closed=false]
|  |     +> entries size=0
|  +> exchanges size=0
+= HttpDestination[Origin@b985a6dc[http://10.240.30.240,tag=null,protocol=Protocol@301a9e[proto=[h2c],nego=false]]]@1ebb016c,queue=0,pool=RoundRobinConnectionPool@64d01ae[c=0/0/4,a=0,i=0,q=0] - STARTED
|  += RoundRobinConnectionPool@64d01ae[c=0/0/4,a=0,i=0,q=0] - STARTED
|  |  +- Pool@368b76b3[size=0 closed=false]
|  |     +> entries size=0
|  +> exchanges size=0
+> requestListeners size=0
key: +- bean, += managed, +~ unmanaged, +? auto, +: iterable, +] array, +@ map, +> undefined

Where the one in bad state is :

+= HttpDestination[Origin@94884515[http://10.240.26.240,tag=null,protocol=Protocol@301a9e[proto=[h2c],nego=false]]]@44d01f72,queue=0,pool=RoundRobinConnectionPool@429ca4c6[c=0/4/4,a=0,i=0,q=0] - STARTED
|  += RoundRobinConnectionPool@429ca4c6[c=0/4/4,a=0,i=0,q=0] - STARTED
|  |  +- Pool@c0a984b[size=4 closed=false]
|  |     +> entries size=4
|  |        +> Entry@51c40b15{CLOSED, usage=0, multiplex=6/128, pooled=HttpConnectionOverHTTP2@768cdd78(closed=true)[HTTP2ClientSession@5b271c7e{local:null,remote:null,sendWindow=537769,recvWindow=12991803,state=[streams=0,CLOSED,goAwayRecv=GoAwayFrame@3eb44a1f{1755/no_error/idle_timeout},goAwaySent=GoAwayFrame@4f59627f{0/no_error/idle_timeout},failure=null]}]}
|  |        +> Entry@5f2e01f1{CLOSED, usage=0, multiplex=5/128, pooled=HttpConnectionOverHTTP2@3c893286(closed=true)[HTTP2ClientSession@207173ba{local:null,remote:null,sendWindow=649523,recvWindow=16477947,state=[streams=0,CLOSED,goAwayRecv=GoAwayFrame@243fb751{415/no_error/idle_timeout},goAwaySent=GoAwayFrame@bb10bae{0/no_error/idle_timeout},failure=null]}]}
|  |        +> Entry@7e59155c{CLOSED, usage=0, multiplex=1/128, pooled=HttpConnectionOverHTTP2@559e458e(closed=true)[HTTP2ClientSession@c42e553{local:null,remote:null,sendWindow=940773,recvWindow=15937821,state=[streams=0,CLOSED,goAwayRecv=GoAwayFrame@f2d630e{867/no_error/idle_timeout},goAwaySent=GoAwayFrame@39e86442{0/no_error/close},failure=null]}]}
|  |        +> Entry@1e7de4c4{CLOSED, usage=0, multiplex=6/128, pooled=HttpConnectionOverHTTP2@58ef225(closed=true)[HTTP2ClientSession@61dfc489{local:null,remote:null,sendWindow=1032449,recvWindow=14873660,state=[streams=0,CLOSED,goAwayRecv=GoAwayFrame@1b6f6684{13481/no_error/idle_timeout},goAwaySent=GoAwayFrame@6ac5eae9{0/no_error/idle_timeout},failure=null]}]}
|  +> exchanges size=0

Hope it can help to fix the issue.

@lorban lorban mentioned this issue Nov 23, 2021
Closed
@lorban
Copy link
Contributor

lorban commented Nov 23, 2021 •
edited
Loading

Thank you for reporting the pool dump, it really helped figuring out what state the pool and its connections ended up in so I could reproduce the problem locally.

That is caused by second bug for which I opened a different issue: #7157.

This issue's fix has already been merged into the jetty-11.0.x branch, so you could check it out, apply the fix for #7157 (there's a PR out for 10.0.x but I think the patch should apply cleanly onto the 11.0.x branch) and test it out. I'd be glad if you could give it a try before the next release to make sure your problem got fixed for good. Do not hesitate to drop a note if you need help with this.

Thanks again for the report!

lorban added a commit that referenced this issue Nov 23, 2021
@lorban
#7107: fix too-eager closing of multiplexed connections marked as clo…
3ae63ef 
…sed but still in use
This was linked to pull requests Nov 23, 2021
#7107: (9.4.x) fix too-eager closing of multiplexed connections marked as closed but still in use #7146
Merged
#7107: (10.0.x) fix too-eager closing of multiplexed connections marked as closed but still in use #7123
Merged
@lorban lorban closed this as completed Nov 23, 2021
@c-legrand
Copy link

Thank you for fixing quickly these issues.

We would like to try the jetty-11.0.x version with the fix #7157 but the problem occurs only on our production environment and we prefer to wait for the release (11.0.x) for stability reason.

Thanks again for your help.

@clardeur clardeur mentioned this issue Sep 15, 2022
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@lorban lorban

Labels
Bug For general bugs on Jetty side
Projects
None yet
Milestone
No milestone
3 participants
@lorban @clardeur @c-legrand