2296 improve reuse connection strategy #2487

f-delahaye · 2024-01-24T19:41:06Z

Description

Improves the brutal no reuse connection strategy initially implemented in #2471.

The default reuse connection strategy was causing ProxyServerTest to fail and I think the reason is:
when a proxy is used, ProxyRemoteHandler is called, but it closes the channel when the response is set (See last line in ProxyRemoteHandler.channelRead0).
But the apache http client is not notified and tries to re-use the connection, hence the error on subsequent calls.

The new proposed strategy therefore closes the connection when a proxy is used, and delegates to the default strategy in all other cases. It might be possibly to be even smarter and take nonProxyHosts and a few other parameters into account too, but this implementation should be good enough, I believe.

Logs from this PR, using hc5 version 5.4.alpha1 because version 5.3 has an annoying bug causing NPEs in DEBUG:

mvn test -Dtest=ProxyServerTest

Connection is closed after each call. This is on purpose whenever a proxy is used, as ProxyRemoteHandler closes the channel, hence causing SocketException if the connection is re-used.

19:26:08.733 [main] DEBUG o.a.h.c.h.impl.classic.ConnectExec - ex-0000000001 acquiring connection with route {}->http://localhost:55214->http://localhost:55215
19:26:08.764 [main] DEBUG o.a.h.c.h.impl.classic.ConnectExec - ex-0000000001 opening connection {}->http://localhost:55214->http://localhost:55215
19:26:08.795 [main] DEBUG o.a.h.c.h.i.i.PoolingHttpClientConnectionManager - ep-0000000001 connected http-outgoing-0
19:26:08.842 [main] DEBUG com.intuit.karate - request:
1 > GET http://localhost:55215/v1/cats/0
1 > Accept-Encoding: gzip, x-gzip, deflate
1 > Host: localhost:55215
1 > User-Agent: Apache-HttpClient/5.4-alpha1 (Java/17.0.9)
19:26:08.842 [main] DEBUG o.a.h.c.h.i.i.PoolingHttpClientConnectionManager - ep-0000000001 executing exchange ex-0000000001 over http-outgoing-0
19:26:09.545 [main] DEBUG o.a.h.c.h.i.i.DefaultManagedHttpClientConnection - http-outgoing-0 close connection IMMEDIATE
19:26:09.545 [main] DEBUG o.a.h.c.h.i.i.PoolingHttpClientConnectionManager - ep-0000000001 connection released [route: {}->http://localhost:55214->http://localhost:55215][total available: 0; route allocated: 0 of 5; total allocated: 0 of 25]


19:26:09.561 [main] DEBUG o.a.h.c.h.impl.classic.ConnectExec - ex-0000000002 acquiring connection with route {}->http://localhost:55214->http://localhost:55215
19:26:09.561 [main] DEBUG o.a.h.c.h.impl.classic.ConnectExec - ex-0000000002 opening connection {}->http://localhost:55214->http://localhost:55215
19:26:09.561 [main] DEBUG o.a.h.c.h.i.i.PoolingHttpClientConnectionManager - ep-0000000002 connected http-outgoing-1
19:26:09.561 [main] DEBUG com.intuit.karate - request:
2 > POST http://localhost:55215/v1/cats
2 > Content-Type: application/json; charset=UTF-8
2 > Accept-Encoding: gzip, x-gzip, deflate
2 > Content-Length: 17
2 > Host: localhost:55215
2 > User-Agent: Apache-HttpClient/5.4-alpha1 (Java/17.0.9)
{"name":"Billie"}
19:26:09.561 [main] DEBUG o.a.h.c.h.i.i.PoolingHttpClientConnectionManager - ep-0000000002 executing exchange ex-0000000002 over http-outgoing-1
19:26:09.698 [main] DEBUG o.a.h.c.h.i.i.DefaultManagedHttpClientConnection - http-outgoing-1 close connection IMMEDIATE
19:26:09.698 [main] DEBUG o.a.h.c.h.i.i.PoolingHttpClientConnectionManager - ep-0000000002 connection released [route: {}->http://localhost:55214->http://localhost:55215][total available: 0; route allocated: 0 of 5; total allocated: 0 of 25]
...

mvn test -Dtest=FeatureServerTest

the first 6 calls, all within the same Scenario, use the same http-outgoing-0 connection.
The connection is released after the call, but not closed.
Calls #7 and #8, which belong to different Scenarios, will create one connection per Scenario.

19:08:21.605 [main] DEBUG o.a.h.c.h.impl.classic.ConnectExec - ex-0000000001 acquiring connection with route {}->http://localhost:55045
19:08:21.636 [main] DEBUG o.a.h.c.h.impl.classic.ConnectExec - ex-0000000001 opening connection {}->http://localhost:55045
19:08:21.658 [main] DEBUG com.intuit.karate - request:
1 > GET http://localhost:55045/v1/cats/0
1 > Accept-Encoding: gzip, x-gzip, deflate
1 > Host: localhost:55045
1 > Connection: keep-alive
1 > User-Agent: Apache-HttpClient/5.4-alpha1 (Java/17.0.9)
19:08:21.658 [main] DEBUG o.a.h.c.h.i.i.PoolingHttpClientConnectionManager - ep-0000000001 executing exchange ex-0000000001 over http-outgoing-0
19:08:22.112 [main] DEBUG o.a.h.c.h.i.i.PoolingHttpClientConnectionManager - ep-0000000001 connection http-outgoing-0 can be kept alive for 3 MINUTES
19:08:22.112 [main] DEBUG o.a.h.c.h.i.i.PoolingHttpClientConnectionManager - ep-0000000001 connection released [route: {}->http://localhost:55045][total available: 1; route allocated: 1 of 5; total allocated: 1 of 25]


19:08:22.127 [main] DEBUG o.a.h.c.h.impl.classic.ConnectExec - ex-0000000002 acquiring connection with route {}->http://localhost:55045
19:08:22.127 [main] DEBUG com.intuit.karate - request:
2 > POST http://localhost:55045/v1/cats
2 > Content-Type: application/json; charset=UTF-8
2 > Accept-Encoding: gzip, x-gzip, deflate
2 > Content-Length: 17
2 > Host: localhost:55045
2 > Connection: keep-alive
2 > User-Agent: Apache-HttpClient/5.4-alpha1 (Java/17.0.9)
{"name":"Billie"}
19:08:22.127 [main] DEBUG o.a.h.c.h.i.i.PoolingHttpClientConnectionManager - ep-0000000002 executing exchange ex-0000000002 over http-outgoing-0
19:08:22.271 [main] DEBUG o.a.h.c.h.i.i.PoolingHttpClientConnectionManager - ep-0000000002 connection http-outgoing-0 can be kept alive for 3 MINUTES
19:08:22.271 [main] DEBUG o.a.h.c.h.i.i.PoolingHttpClientConnectionManager - ep-0000000002 connection released [route: {}->http://localhost:55045][total available: 1; route allocated: 1 of 5; total allocated: 1 of 25]
19:08:22.286 [main] DEBUG com.intuit.karate - response time in milliseconds: -1706119702127


19:08:22.318 [main] DEBUG o.a.h.c.h.impl.classic.ConnectExec - ex-0000000003 acquiring connection with route {}->http://localhost:55045
19:08:22.318 [main] DEBUG com.intuit.karate - request:
3 > GET http://localhost:55045/v1/cats/1
3 > Accept-Encoding: gzip, x-gzip, deflate
3 > Host: localhost:55045
3 > Connection: keep-alive
3 > User-Agent: Apache-HttpClient/5.4-alpha1 (Java/17.0.9)
19:08:22.318 [main] DEBUG o.a.h.c.h.i.i.PoolingHttpClientConnectionManager - ep-0000000003 executing exchange ex-0000000003 over http-outgoing-0
19:08:22.349 [main] DEBUG o.a.h.c.h.i.i.PoolingHttpClientConnectionManager - ep-0000000003 connection http-outgoing-0 can be kept alive for 3 MINUTES
19:08:22.349 [main] DEBUG o.a.h.c.h.i.i.PoolingHttpClientConnectionManager - ep-0000000003 connection released [route: {}->http://localhost:55045][total available: 1; route allocated: 1 of 5; total allocated: 1 of 25]


19:08:22.380 [main] DEBUG o.a.h.c.h.impl.classic.ConnectExec - ex-0000000004 acquiring connection with route {}->http://localhost:55045
19:08:22.380 [main] DEBUG com.intuit.karate - request:
4 > POST http://localhost:55045/v1/cats
4 > Content-Type: application/json; charset=UTF-8
4 > Accept-Encoding: gzip, x-gzip, deflate
4 > Content-Length: 15
4 > Host: localhost:55045
4 > Connection: keep-alive
4 > User-Agent: Apache-HttpClient/5.4-alpha1 (Java/17.0.9)
{"name":"Wild"}
19:08:22.380 [main] DEBUG o.a.h.c.h.i.i.PoolingHttpClientConnectionManager - ep-0000000004 executing exchange ex-0000000004 over http-outgoing-0
19:08:22.416 [main] DEBUG o.a.h.c.h.i.i.PoolingHttpClientConnectionManager - ep-0000000004 connection http-outgoing-0 can be kept alive for 3 MINUTES
19:08:22.416 [main] DEBUG o.a.h.c.h.i.i.PoolingHttpClientConnectionManager - ep-0000000004 connection released [route: {}->http://localhost:55045][total available: 1; route allocated: 1 of 5; total allocated: 1 of 25]


19:08:22.432 [main] DEBUG o.a.h.c.h.impl.classic.ConnectExec - ex-0000000005 acquiring connection with route {}->http://localhost:55045
19:08:22.432 [main] DEBUG com.intuit.karate - request:
5 > GET http://localhost:55045/v1/cats/2
5 > Accept-Encoding: gzip, x-gzip, deflate
5 > Host: localhost:55045
5 > Connection: keep-alive
5 > User-Agent: Apache-HttpClient/5.4-alpha1 (Java/17.0.9)
19:08:22.447 [main] DEBUG o.a.h.c.h.i.i.PoolingHttpClientConnectionManager - ep-0000000005 executing exchange ex-0000000005 over http-outgoing-0
19:08:22.479 [main] DEBUG o.a.h.c.h.i.i.PoolingHttpClientConnectionManager - ep-0000000005 connection http-outgoing-0 can be kept alive for 3 MINUTES
19:08:22.479 [main] DEBUG o.a.h.c.h.i.i.PoolingHttpClientConnectionManager - ep-0000000005 connection released [route: {}->http://localhost:55045][total available: 1; route allocated: 1 of 5; total allocated: 1 of 25]


19:08:22.479 [main] DEBUG o.a.h.c.h.impl.classic.ConnectExec - ex-0000000006 acquiring connection with route {}->http://localhost:55045
19:08:22.494 [main] DEBUG com.intuit.karate - request:
6 > GET http://localhost:55045/v1/cats
6 > Accept-Encoding: gzip, x-gzip, deflate
6 > Host: localhost:55045
6 > Connection: keep-alive
6 > User-Agent: Apache-HttpClient/5.4-alpha1 (Java/17.0.9)
19:08:22.494 [main] DEBUG o.a.h.c.h.i.i.PoolingHttpClientConnectionManager - ep-0000000006 executing exchange ex-0000000006 over http-outgoing-0
19:08:22.512 [main] DEBUG o.a.h.c.h.i.i.PoolingHttpClientConnectionManager - ep-0000000006 connection http-outgoing-0 can be kept alive for 3 MINUTES
19:08:22.512 [main] DEBUG o.a.h.c.h.i.i.PoolingHttpClientConnectionManager - ep-0000000006 connection released [route: {}->http://localhost:55045][total available: 1; route allocated: 1 of 5; total allocated: 1 of 25]


19:08:22.574 [main] DEBUG o.a.h.c.h.impl.classic.ConnectExec - ex-0000000007 acquiring connection with route {}->http://localhost:55045
19:08:22.574 [main] DEBUG o.a.h.c.h.impl.classic.ConnectExec - ex-0000000007 opening connection {}->http://localhost:55045
19:08:22.574 [main] DEBUG com.intuit.karate - request:
1 > POST http://localhost:55045/v1/body/json
1 > Content-Type: application/json; charset=UTF-8
1 > Accept-Encoding: gzip, x-gzip, deflate
1 > Content-Length: 17
1 > Host: localhost:55045
1 > Connection: keep-alive
1 > User-Agent: Apache-HttpClient/5.4-alpha1 (Java/17.0.9)
{"name":"Scooby"}
19:08:22.574 [main] DEBUG o.a.h.c.h.i.i.PoolingHttpClientConnectionManager - ep-0000000007 executing exchange ex-0000000007 over http-outgoing-1
...

For reference, mvn test -Dtest=FeatureServerTest against current master:

Connection is closed after each call. So is the connection manager, by the way.

19:45:39.035 [main] DEBUG com.intuit.karate - request:
1 > GET http://localhost:55314/v1/cats/0
1 > Host: localhost:55314
1 > Connection: Keep-Alive
1 > User-Agent: Apache-HttpClient/4.5.14 (Java/17.0.9)
1 > Accept-Encoding: gzip,deflate
19:45:39.035 [main] DEBUG o.a.h.i.c.PoolingHttpClientConnectionManager - Connection request: [route: {}->http://localhost:55314][total available: 0; route allocated: 0 of 5; total allocated: 0 of 10]
19:45:39.098 [main] DEBUG o.a.h.i.c.DefaultHttpClientConnectionOperator - Connection established 127.0.0.1:55315<->127.0.0.1:55314
19:45:39.098 [main] DEBUG o.a.h.i.c.DefaultManagedHttpClientConnection - http-outgoing-0: set socket timeout to 30000
19:45:39.785 [main] DEBUG o.a.h.i.c.PoolingHttpClientConnectionManager - Connection released: [id: 0][route: {}->http://localhost:55314][total available: 1; route allocated: 1 of 5; total allocated: 1 of 10]
19:45:39.785 [main] DEBUG o.a.h.i.c.DefaultManagedHttpClientConnection - http-outgoing-0: Close connection
19:45:39.785 [main] DEBUG o.a.h.i.c.PoolingHttpClientConnectionManager - Connection manager shut down

19:45:39.801 [main] DEBUG com.intuit.karate - request:
2 > POST http://localhost:55314/v1/cats
2 > Content-Type: application/json; charset=UTF-8
2 > Content-Length: 17
2 > Host: localhost:55314
2 > Connection: Keep-Alive
2 > User-Agent: Apache-HttpClient/4.5.14 (Java/17.0.9)
2 > Accept-Encoding: gzip,deflate
{"name":"Billie"}
19:45:39.801 [main] DEBUG o.a.h.i.c.PoolingHttpClientConnectionManager - Connection request: [route: {}->http://localhost:55314][total available: 0; route allocated: 0 of 5; total allocated: 0 of 10]
19:45:39.801 [main] DEBUG o.a.h.i.c.DefaultHttpClientConnectionOperator - Connection established 127.0.0.1:55316<->127.0.0.1:55314
19:45:39.801 [main] DEBUG o.a.h.i.c.DefaultManagedHttpClientConnection - http-outgoing-1: set socket timeout to 30000
19:45:39.942 [main] DEBUG o.a.h.i.c.PoolingHttpClientConnectionManager - Connection released: [id: 1][route: {}->http://localhost:55314][total available: 1; route allocated: 1 of 5; total allocated: 1 of 10]
19:45:39.942 [main] DEBUG o.a.h.i.c.DefaultManagedHttpClientConnection - http-outgoing-1: Close connection
19:45:39.942 [main] DEBUG o.a.h.i.c.PoolingHttpClientConnectionManager - Connection manager shut down


19:45:39.957 [main] DEBUG com.intuit.karate - request:
3 > GET http://localhost:55314/v1/cats/1
3 > Host: localhost:55314
3 > Connection: Keep-Alive
3 > User-Agent: Apache-HttpClient/4.5.14 (Java/17.0.9)
3 > Accept-Encoding: gzip,deflate
19:45:39.957 [main] DEBUG o.a.h.i.c.PoolingHttpClientConnectionManager - Connection request: [route: {}->http://localhost:55314][total available: 0; route allocated: 0 of 5; total allocated: 0 of 10]
19:45:39.957 [main] DEBUG o.a.h.i.c.DefaultHttpClientConnectionOperator - Connection established 127.0.0.1:55317<->127.0.0.1:55314
19:45:39.957 [main] DEBUG o.a.h.i.c.DefaultManagedHttpClientConnection - http-outgoing-2: set socket timeout to 30000
19:45:40.067 [main] DEBUG o.a.h.i.c.PoolingHttpClientConnectionManager - Connection released: [id: 2][route: {}->http://localhost:55314][total available: 1; route allocated: 1 of 5; total allocated: 1 of 10]
19:45:40.067 [main] DEBUG o.a.h.i.c.DefaultManagedHttpClientConnection - http-outgoing-2: Close connection
19:45:40.067 [main] DEBUG o.a.h.i.c.PoolingHttpClientConnectionManager - Connection manager shut down

Relevant Issues : (2296)
Relevant PRs : (optional)
Type of change :
- [X ] Code quality improvement

…d support of ntlm

…ctionManager in Apache client which is now shared

…/noproxy ones

f-delahaye · 2024-01-24T19:45:54Z

Sorry, @ptrthomas I was hoping to have this PR target the branch used in #2471 to show only the changes relevant for the new reuse connection strategy (one line) but I could not.
So, this PR includes all the changes.

Sorry for the confusion.

You can merge directly this PR and disregard 2471 , or merge 2471 first and then this one, whatever is more convenient for you.

ptrthomas · 2024-01-25T15:07:20Z

@f-delahaye I don't mind closing 2471 and just focus on this one, good to target a new version of hc, does that sound ok, anyway I will park this for 2-3 weeks while I release 1.5.0 final

f-delahaye added 13 commits November 5, 2023 20:42

karatelabs#2296

a0b30bf

karatelabs#2296 - disable keepalive strategy to fix SocketException

b143b25

karatelabs#2296 - code clean up

b470148

Merge branch 'develop' into 2296-upgrade-to-apache-httpclient-5

5f33d92

Merge branch 'develop' into 2296-upgrade-to-apache-httpclient-5

4544a15

remove references to http client 4

abc38b4

karatelabs#2296 Upgraded to latest apache httpclient (5.3) and droppe…

683ce85

…d support of ntlm

2296 Cosmetic change

d9d58e9

Upgrade karate-demo to same version of httpclient5 as karate-core

715ed4a

Introduced close() method in HttpClient and use it to close the conne…

7246fa5

…ctionManager in Apache client which is now shared

Redesigned RoutePlanner - Separate ProxySelector use cases from proxy…

f9a530b

…/noproxy ones

cosmetic changes

b9507de

Improved reuse connection strategy

9ebd88b

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

2296 improve reuse connection strategy #2487

2296 improve reuse connection strategy #2487

f-delahaye commented Jan 24, 2024

f-delahaye commented Jan 24, 2024

ptrthomas commented Jan 25, 2024

2296 improve reuse connection strategy #2487

Are you sure you want to change the base?

2296 improve reuse connection strategy #2487

Conversation

f-delahaye commented Jan 24, 2024

Description

f-delahaye commented Jan 24, 2024

ptrthomas commented Jan 25, 2024