CODEWITHSUNDEEP
javasoap-clientspring-wsapache-commons-httpclient
Syed Ali
Syed Ali

Reputation: 1897

HttpClientConnectionManager connection not reusing tcp connection when connecting to https endpoint

I am connecting to a SOAP service using a client built with Spring WebServiceGatewaySupport. However, I noticed that the TCP connection is closed after every request/response cycle. Upon further investigation, I found that the connection closes as soon as another request is attempted. This behavior is causing performance issues due to frequent opening and closing of TCP connections.

To address this, I attempted to use a custom HttpClient with connection reuse enabled, but I could not achieve the desired result. Below is a summary of my setup and findings.

Dependencies

<parent>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-parent</artifactId>
    <version>2.7.18</version>
    <relativePath/> 
</parent>
    <dependency>
        <groupId>org.springframework.ws</groupId>
        <artifactId>spring-ws-core</artifactId>
    </dependency>
    <dependency>
        <groupId>org.springframework.ws</groupId>
        <artifactId>spring-ws-security</artifactId>
    </dependency>

    <dependency>
        <groupId>org.apache.wss4j</groupId>
        <artifactId>wss4j-ws-security-dom</artifactId>
        <version>2.4.0</version> 
    </dependency>

    <dependency>
        <groupId>org.apache.httpcomponents</groupId>
        <artifactId>httpclient</artifactId>
    </dependency>
    <dependency>
        <groupId>org.apache.httpcomponents</groupId>
        <artifactId>httpcore</artifactId>
    </dependency>

Additional information

Case 1

Use HTTP connection against plain http server running locally in a docker container.

Client code

Registry<ConnectionSocketFactory> socketFactoryRegistry = RegistryBuilder.<ConnectionSocketFactory>create()
        .register("http", PlainConnectionSocketFactory.getSocketFactory())
        .build();
        
PoolingHttpClientConnectionManager connectionManager = new PoolingHttpClientConnectionManager(socketFactoryRegistry);
connectionManager.setDefaultSocketConfig(SocketConfig.custom()
                 .setSoTimeout(2 * 60 * 1000)
                 .build());
                 
        CloseableHttpClient httpClient = HttpClients.custom()
                .setConnectionManager(connectionManager)
                .addInterceptorFirst((HttpRequestInterceptor) (request, context) -> {
                    // Remove Content-Length header to prevent conflict
                    request.removeHeaders("Content-Length");
                })
                .setConnectionReuseStrategy((response, context) -> true)
                .setDefaultRequestConfig(RequestConfig.custom()
                                                 .setExpectContinueEnabled(true)
                                                 .setConnectTimeout(2 * 60 * 1000)
                                                 .setSocketTimeout(2 * 60 * 1000)
                                                 .build())
                .setKeepAliveStrategy((response, context) -> 2 * 60 * 1000)
                .evictIdleConnections(2, TimeUnit.MINUTES)
                .build();
                
HttpComponentsMessageSender messageSender = new HttpComponentsMessageSender(httpClient);

Log for Request #1

2025-01-15 15:07:57.388 DEBUG 46686 --- [nio-8042-exec-1] org.apache.http.wire                     : http-outgoing-0 >> "Connection: Keep-Alive[\r][\n]"
2025-01-15 15:07:57.388 DEBUG 46686 --- [nio-8042-exec-1] org.apache.http.wire                     : http-outgoing-0 >> "User-Agent: Apache-HttpClient/4.5.14 (Java/17.0.13)[\r][\n]"
…
2025-01-15 15:07:57.421 DEBUG 46686 --- [nio-8042-exec-1] o.a.http.impl.execchain.MainClientExec   : Connection can be kept alive for 120000 MILLISECONDS
2025-01-15 15:07:57.424 DEBUG 46686 --- [nio-8042-exec-1] h.i.c.PoolingHttpClientConnectionManager : Connection [id: 0][route: {}->localhost:9090] can be kept alive for 120.0 seconds
2025-01-15 15:07:57.425 DEBUG 46686 --- [nio-8042-exec-1] h.i.c.DefaultManagedHttpClientConnection : http-outgoing-0: set socket timeout to 0
2025-01-15 15:07:57.425 DEBUG 46686 --- [nio-8042-exec-1] h.i.c.PoolingHttpClientConnectionManager : Connection released: [id: 0][route: {}->localhost:9090][total available: 1; route allocated: 1 of 2; total allocated: 1 of 20]
…
2025-01-15 15:07:57.480 DEBUG 46686 --- [nio-8042-exec-1] o.s.web.servlet.DispatcherServlet        : Completed 200 OK

Log for Request #2

2025-01-15 15:08:21.082 DEBUG 46686 --- [nio-8042-exec-4] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to com.syed...TestController#testSpringClient()
2025-01-15 15:08:21.084 DEBUG 46686 --- [nio-8042-exec-4] o.s.ws.client.core.WebServiceTemplate    : Opening [org.springframework.ws.transport.http.HttpComponentsConnection@596d45e8] to [localhost:9090/test/ch]
2025-01-15 15:08:21.088 DEBUG 46686 --- [nio-8042-exec-4] o.s.ws.client.MessageTracing.sent        : Sent request [SaajSoapMessage {urn://test.com/xmlmessaging/CH}testEP]
2025-01-15 15:08:21.092 DEBUG 46686 --- [nio-8042-exec-4] o.a.h.client.protocol.RequestAddCookies  : CookieSpec selected: default
2025-01-15 15:08:21.092 DEBUG 46686 --- [nio-8042-exec-4] o.a.h.client.protocol.RequestAuthCache   : Auth cache not set in the context
2025-01-15 15:08:21.092 DEBUG 46686 --- [nio-8042-exec-4] h.i.c.PoolingHttpClientConnectionManager : Connection request: [route: {}->localhost:9090][total available: 1; route allocated: 1 of 2; total allocated: 1 of 20]
2025-01-15 15:08:21.094 DEBUG 46686 --- [nio-8042-exec-4] org.apache.http.wire                     : http-outgoing-0 << "[read] I/O error: Read timed out"
2025-01-15 15:08:21.095 DEBUG 46686 --- [nio-8042-exec-4] h.i.c.PoolingHttpClientConnectionManager : Connection leased: [id: 0][route: {}->localhost:9090][total available: 0; route allocated: 1 of 2; total allocated: 1 of 20]
2025-01-15 15:08:21.095 DEBUG 46686 --- [nio-8042-exec-4] h.i.c.DefaultManagedHttpClientConnection : http-outgoing-0: set socket timeout to 120000
…
2025-01-15 15:08:21.096 DEBUG 46686 --- [nio-8042-exec-4] org.apache.http.wire                     : http-outgoing-0 >> "Host: localhost:9090[\r][\n]"
2025-01-15 15:08:21.096 DEBUG 46686 --- [nio-8042-exec-4] org.apache.http.wire                     : http-outgoing-0 >> "Connection: Keep-Alive[\r][\n]"
2025-01-15 15:08:21.096 DEBUG 46686 --- [nio-8042-exec-4] org.apache.http.wire                     : http-outgoing-0 >> "User-Agent: Apache-HttpClient/4.5.14 (Java/17.0.13)[\r][\n]"
2025-01-15 15:08:21.096 DEBUG 46686 --- [nio-8042-exec-4] org.apache.http.wire                     : http-outgoing-0 >> "Expect: 100-continue[\r][\n]"
2025-01-15 15:08:21.096 DEBUG 46686 --- [nio-8042-exec-4] org.apache.http.wire                     : http-outgoing-0 >> "[\r][\n]"
…
2025-01-15 15:08:21.119 DEBUG 46686 --- [nio-8042-exec-4] org.apache.http.headers                  : http-outgoing-0 << Date: Wed, 15 Jan 2025 21:08:21 GMT
2025-01-15 15:08:21.119 DEBUG 46686 --- [nio-8042-exec-4] o.a.http.impl.execchain.MainClientExec   : Connection can be kept alive for 120000 MILLISECONDS
2025-01-15 15:08:21.120 DEBUG 46686 --- [nio-8042-exec-4] h.i.c.PoolingHttpClientConnectionManager : Connection [id: 0][route: {}->http://localhost:9090] can be kept alive for 120.0 seconds
2025-01-15 15:08:21.120 DEBUG 46686 --- [nio-8042-exec-4] h.i.c.DefaultManagedHttpClientConnection : http-outgoing-0: set socket timeout to 0
2025-01-15 15:08:21.120 DEBUG 46686 --- [nio-8042-exec-4] h.i.c.PoolingHttpClientConnectionManager : Connection released: [id: 0][route: {}->http://localhost:9090][total available: 1; route allocated: 1 of 2; total allocated: 1 of 20]
...
2025-01-15 15:08:21.127 DEBUG 46686 --- [nio-8042-exec-4] o.s.web.servlet.DispatcherServlet        : Completed 200 OK
…
2025-01-15 15:09:46.704 DEBUG 46686 --- [nection evictor] h.i.c.PoolingHttpClientConnectionManager : Closing connections idle longer than 120000 MILLISECONDS
2025-01-15 15:11:46.697 DEBUG 46686 --- [nection evictor] h.i.c.PoolingHttpClientConnectionManager : Closing expired connections
2025-01-15 15:11:46.701 DEBUG 46686 --- [nection evictor] org.apache.http.impl.conn.CPool          : Connection [id:0][route:{}->http://localhost:9090][state:null] expired @ Wed Jan 15 15:10:21 CST 2025
2025-01-15 15:11:46.701 DEBUG 46686 --- [nection evictor] h.i.c.DefaultManagedHttpClientConnection : http-outgoing-0: Close connection

When the connection is made to plain HTTP/TCP endpoint, the same socket, http-outgoing-0, is reused. It gets closed after the set keep alive time out.

Case 2

Connecting to service using HTTPS/TLS connection.

Client code

Client code remains the same except for addition of SSL configuration.

// Load client certificate keystore from resources
KeyStore keyStore = KeyStore.getInstance("JKS");
try (InputStream keyStoreStream = new ClassPathResource("services.jks").getInputStream()) {
    keyStore.load(keyStoreStream, "YOUR-PASSWORD".toCharArray());
}

// Load server truststore from resources (if needed)
KeyStore trustStore = KeyStore.getInstance("JKS");
try (InputStream trustStoreStream = new ClassPathResource("services.jks").getInputStream()) {
    trustStore.load(trustStoreStream, "YOUR-PASSWORD".toCharArray());
}

SSLContext sslContext = SSLContexts.custom()
        .loadKeyMaterial(keyStore, "YOUR-PASSWORD".toCharArray(), (aliases, socket) -> "alias")
        .loadTrustMaterial(trustStore, new TrustSelfSignedStrategy()) // Trust strategy
        .build();

// Create SSLConnectionSocketFactory
SSLConnectionSocketFactory sslSocketFactory = new SSLConnectionSocketFactory(
        sslContext,
        new String[]{"TLSv1.2"}, // Protocols
        null, // Cipher suites (null for default)
        SSLConnectionSocketFactory.getDefaultHostnameVerifier()
);

// Create a connection manager with SSL support
Registry<ConnectionSocketFactory> socketFactoryRegistry = RegistryBuilder.<ConnectionSocketFactory>create()
        .register("http", PlainConnectionSocketFactory.getSocketFactory())
        .register("https", sslSocketFactory)
        .build();

Log for Request #1

2025-01-15 15:53:03.509 DEBUG 48661 --- [nio-8042-exec-1] .i.c.DefaultHttpClientConnectionOperator : Connection established xxx:53882<->xxx:443
2025-01-15 15:53:03.509 DEBUG 48661 --- [nio-8042-exec-1] h.i.c.DefaultManagedHttpClientConnection : http-outgoing-0: set socket timeout to 120000
2025-01-15 15:53:03.509 DEBUG 48661 --- [nio-8042-exec-1] o.a.http.impl.execchain.MainClientExec   : Executing request POST /xxx/xxx HTTP/1.1
…
2025-01-15 15:53:03.511 DEBUG 48661 --- [nio-8042-exec-1] org.apache.http.wire                     : http-outgoing-0 >> "Host: xxx[\r][\n]"
2025-01-15 15:53:03.511 DEBUG 48661 --- [nio-8042-exec-1] org.apache.http.wire                     : http-outgoing-0 >> "Connection: Keep-Alive[\r][\n]"
2025-01-15 15:53:03.511 DEBUG 48661 --- [nio-8042-exec-1] org.apache.http.wire                     : http-outgoing-0 >> "User-Agent: Apache-HttpClient/4.5.14 (Java/17.0.13)[\r][\n]"
…
2025-01-15 15:53:03.723 DEBUG 48661 --- [nio-8042-exec-1] o.a.http.impl.execchain.MainClientExec   : Connection can be kept alive for 120000 MILLISECONDS
…
2025-01-15 15:53:03.731 DEBUG 48661 --- [nio-8042-exec-1] h.i.c.DefaultManagedHttpClientConnection : http-outgoing-0: set socket timeout to 0
2025-01-15 15:53:03.732 DEBUG 48661 --- [nio-8042-exec-1] h.i.c.PoolingHttpClientConnectionManager : Connection released: [id: 0][route: {s}->https://xxx:443][state: CN=*.xxx][total available: 1; route allocated: 1 of 2; total allocated: 1 of 1]
…
2025-01-15 15:53:03.761 DEBUG 48661 --- [nio-8042-exec-1] o.s.web.servlet.DispatcherServlet        : Completed 200 OK

Log for Request #2

2025-01-15 15:53:10.827 DEBUG 48661 --- [nio-8042-exec-4] h.i.c.PoolingHttpClientConnectionManager : Connection request: [route: {s}->https://xxx:443][total available: 1; route allocated: 1 of 2; total allocated: 1 of 1]
2025-01-15 15:53:10.827 DEBUG 48661 --- [nio-8042-exec-4] h.i.c.DefaultManagedHttpClientConnection : http-outgoing-0: Close connection
2025-01-15 15:53:10.830 DEBUG 48661 --- [nio-8042-exec-4] h.i.c.PoolingHttpClientConnectionManager : Connection leased: [id: 1][route: {s}->https://xxx:443][total available: 0; route allocated: 1 of 2; total allocated: 1 of 1]
2025-01-15 15:53:10.830 DEBUG 48661 --- [nio-8042-exec-4] o.a.http.impl.execchain.MainClientExec   : Opening connection {s}->https://xxx:443
2025-01-15 15:53:10.830 DEBUG 48661 --- [nio-8042-exec-4] .i.c.DefaultHttpClientConnectionOperator : Connecting to xxx:443
...
2025-01-15 15:53:10.976 DEBUG 48661 --- [nio-8042-exec-4] .i.c.DefaultHttpClientConnectionOperator : Connection established xxx:53923<->xxx:443
2025-01-15 15:53:10.976 DEBUG 48661 --- [nio-8042-exec-4] h.i.c.DefaultManagedHttpClientConnection : http-outgoing-1: set socket timeout to 120000

We can see that http-outgoing-0 is closed and http-outgoing-1 is created. No error is thrown. I don't understand why DefaultManagedHttpClientConnection : http-outgoing-0: Close connection happened?

2025-01-15 15:56:54.783 DEBUG 48661 --- [nection evictor] h.i.c.PoolingHttpClientConnectionManager : Closing connections idle longer than 120000 MILLISECONDS
2025-01-15 15:56:54.784 DEBUG 48661 --- [nection evictor] org.apache.http.impl.conn.CPool          : Connection [id:1][route:{s}->https://xxx:443][state:CN=*.cert] expired @ Wed Jan 15 15:55:11 CST 2025
2025-01-15 15:56:54.785 DEBUG 48661 --- [nection evictor] h.i.c.DefaultManagedHttpClientConnection : http-outgoing-1: Close connection
2025-01-15 15:56:54.790 DEBUG 48661 --- [nection evictor] h.i.c.PoolingHttpClientConnectionManager : Closing connections idle longer than 120000 MILLISECONDS

Subsequently, the connection gets closed after the set time out if no more requests come in.

Question

Any insights or suggestions are appreciated. Let me know if additional details are required.

Upvotes: 0

Views: 30

Answers (0)

Related Questions