HttpClient idleTimeout configuration being ignored/overridden

[cotej]

Jetty version(s)

jetty-client 10.0.9

Java version/vendor

java version "11.0.11" 2021-04-20 LTS
Java(TM) SE Runtime Environment 18.9 (build 11.0.11+9-LTS-194)
Java HotSpot(TM) 64-Bit Server VM 18.9 (build 11.0.11+9-LTS-194, mixed mode)

OS type/version

macOS Monterey 12.3.1

Description

The idleTimeout configuration that's set on an HttpClient is ignored when making a request to an HTTPS destination via a proxy.

How to reproduce?

Consider this example:

var client = new HttpClient();
client.setIdleTimeout(30000);
client.getProxyConfiguration().getProxies().add(
    new HttpProxy(new Origin.Address("127.0.0.1", 3128), false)
);
client.start();

log("Client is configured with idleTimeout = %s", client.getIdleTimeout());

var req = client.newRequest("https://example.webaddress.com:3000");
//req.idleTimeout(30, TimeUnit.SECONDS);

log("Sending the request with URI = %s, idleTimeout = %s", req.getURI(), req.getIdleTimeout());
req.send(new BufferingResponseListener() {
    @Override
    public void onComplete(Result result) {
        if (result.isFailed()) {
            log("Request has failed: %s", result.getFailure().getMessage());
            result.getFailure().printStackTrace();
        } else {
            log("Got a response with status = %d%n%s", result.getResponse().getStatus(), getContentAsString());
        }
    }
});

Result:

[2022-05-14 17:29.37:084] Client is configured with idleTimeout = 30000
[2022-05-14 17:29.37:137] Sending the request with URI = https://example.webaddress.com:3000, idleTimeout = -1
[2022-05-14 17:29.47:347] Request has failed: Idle timeout 10000 ms
java.util.concurrent.TimeoutException: Idle timeout 10000 ms
	at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.onIdleExpired(HttpConnectionOverHTTP.java:181)
	at org.eclipse.jetty.io.ssl.SslConnection.onIdleExpired(SslConnection.java:360)
	at org.eclipse.jetty.io.AbstractEndPoint.onIdleExpired(AbstractEndPoint.java:407)
	at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:166)
	at org.eclipse.jetty.io.IdleTimeout.idleCheck(IdleTimeout.java:108)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:834)

In this example, the server that's running at https://example.webaddress.com:3000 is configured to wait 20 seconds before sending its response, in order to exercise idling the connection.

The HttpClient has been configured to have an idle timeout of 30 seconds and there is no idle timeout being configured directly on the request itself, however a TimeoutException ends up occuring and clearly shows Idle timeout 10000 ms.

It's worth pointing out that this only happens for these specific set of conditions (going through a proxy, to an HTTPS endpoint). i.e.

• When a proxy is not set on the client this works as expected and the request succeeds.
• If a proxy is set on the client but the request is to a plain HTTP endpoint, it works as expected and the request succeeds.
• Additionally, if I set an explicit idleTimeout on the request itself (commented line in the example), it works as expected and the request succeeds.
• This also did not seem to be an issue on jetty-client 9.4.x

So, where is this 10000 ms timeout coming from? Seems to be this:
https://github.com/eclipse/jetty.project/blob/b47d9c41d7b9ecc90844be545f2aee618447419e/jetty-client/src/main/java/org/eclipse/jetty/client/http/HttpConnectionOverHTTP.java#L305

It seems rather intentional, so I'm not certain this is necessarily a bug, but at the very least it seems that this behaviour is very non-obvious and non-documented.

[sbordet]

#8635 is related, but for the SOCKS proxy.

[sbordet]

@cotej I have a fix in branch jetty-10.0.x-7993-httpclient-proxy-timeout.
Can you build it and test it out?

[cotej]

Hi @sbordet - I built the branch and did some quick testing... It seems to fix the client's idleTimeout being ignored, but causes a new problem where the request's idleTimeout now gets ignored.

Using the same test setup with a server that responds after 20s, here's a quick summary of what I'm seeing:

---

1. Client idleTimeout = 30000, with no idleTimeout on the request - this is the case that you've fixed. ✅

[2022-10-01 15:24.09:751] Client is configured with idleTimeout = 30000
[2022-10-01 15:24.09:796] Sending the request with URI = https://example.webaddress.com:3000?t=1664652249777, idleTimeout = -1
[2022-10-01 15:24.29:996] Got a response with status = 200

2. Client idleTimeout = 30000, Request idleTimeout = 5000 - this should timeout due to the request timeout right? ❌

[2022-10-01 15:21.24:264] Client is configured with idleTimeout = 30000
[2022-10-01 15:21.24:308] Sending the request with URI = https://example.webaddress.com:3000?t=1664652084289, idleTimeout = 5000
[2022-10-01 15:21.44:518] Got a response with status = 200

3. Client idleTimeout = 5000, Request idleTimeout = 30000 - would expect this should work based on the request timeout ? ❌

[2022-10-01 15:23.11:027] Client is configured with idleTimeout = 5000
[2022-10-01 15:23.11:073] Sending the request with URI = https://example.webaddress.com:3000?t=1664652191053, idleTimeout = 30000
[2022-10-01 15:23.16:342] Request has failed: Idle timeout 5000 ms

[sbordet]

@cotej I pushed updated code on the same branch, can you please try again?

[cotej]

@sbordet It seems much better now with the latest changes 👍

Here's the scenarios I checked, and I'm now getting the expected results in all cases.

Idle timeouts	HTTP (direct)	HTTP (via proxy)	HTTPS (direct)	HTTPS (via proxy)
client = 10s, request = -1	t/o @ 10s	t/o @ 10s	t/o @ 10s	t/o @ 10s
client = 10s, request = 30s	200 ok @ 20s	200 ok @ 20s	200 ok @ 20s	200 ok @ 20s
client = 30s, request = -1	200 ok @ 20s	200 ok @ 20s	200 ok @ 20s	200 ok @ 20s
client = 30s, request = 10s	t/o @ 10s	t/o @ 10s	t/o @ 10s	t/o @ 10s

[sbordet]

@cotej thanks for confirming! 👍🏼

[xiongtx]

Just a note--the issue says that:

This also did not seem to be an issue on jetty-client 9.4.x

But I'm able to replicate in 9.4.48.v20220622. The offending line seems to be here in HttpProxy.java.

[sbordet]

@xiongtx this issue is fixed in Jetty 10+, so consider upgrading.