Connection timeout the double of what is configured

[oleborup]

Introduced with Jersey 2.31 the client connection timeout is the double of the configured when posting an entity.

    client.property(ClientProperties.CONNECT_TIMEOUT, 2000);
    ...
    invocationBuilder.post(null); // correct connection timeout of 2 secs
    invocationBuilder.post(Entity.json(request)); // double connection timeout of 4 secs

Small Spring Boot example project here: https://github.com/oleborup/jersey-client-connection-timeout

To reproduce

mvn test

[jbescos]

Hello

I am running your example in last Jersey and I am getting 2 in both tests:

[INFO] Running org.glassfish.jersey.tests.e2e.client.Issue4742ExampleTest
java.net.SocketTimeoutException: connect timed out
Duration: 2
Jun 18, 2021 10:35:59 AM org.glassfish.jersey.message.internal.WriterInterceptorExecutor$TerminalWriterInterceptor aroundWriteTo
SEVERE: MessageBodyWriter not found for media type=application/json, type=class java.util.HashMap, genericType=class java.util.HashMap.
MessageBodyWriter not found for media type=application/json, type=class java.util.HashMap, genericType=class java.util.HashMap.
Duration: 2

I also tried my own test, and it behaves equal:

public class Issue4742Test extends JerseyTest {

    private static final String RESOURCE = "resource";
    private static final long TIMEOUT = 50;

    @Test
    public void readTimeout() {
        try {
            target()
            .property(ClientProperties.READ_TIMEOUT, TIMEOUT).path(RESOURCE).request().post(null);
            fail("It is expected to fail");
        } catch (ProcessingException e) {
        }
        try {
            target()
            .property(ClientProperties.READ_TIMEOUT, TIMEOUT).path(RESOURCE).request().post(Entity.text("example"));
            fail("It is expected to fail");
        } catch (ProcessingException e) {
        }
    }

    @Override
    protected Application configure() {
        return new ResourceConfig(Resource.class);
    }

    @Path(RESOURCE)
    public static class Resource {
        @POST
        public String test(String text) {
            try {
                Thread.sleep(TIMEOUT + 1);
            } catch (InterruptedException e) {}
            return "ok";
        }
    }
}

[oleborup]

Hi @jbescos

Have just reproduced on a fresh Ubuntu 20.04 cloud instance with both OpenJDK 8 and 11. Same issue as on my Mac with AdoptOpenJDK 8. In which environment are you trying to reproduce?

Java 8:

$ git clone https://github.com/oleborup/jersey-client-connection-timeout.git
$ cd jersey-client-connection-timeout/
$ java -version
openjdk version "1.8.0_292"
OpenJDK Runtime Environment (build 1.8.0_292-8u292-b10-0ubuntu1~20.04-b10)
OpenJDK 64-Bit Server VM (build 25.292-b10, mixed mode)
$ javac -version
javac 1.8.0_292
$ mvn test
-------------------------------------------------------
 T E S T S
-------------------------------------------------------
Running oleborup.jerseyconnectiontimeout.TimeoutTest
java.net.SocketTimeoutException: connect timed out
Duration: 2
java.net.SocketTimeoutException: connect timed out
Duration: 4
Tests run: 2, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 7.195 sec <<< FAILURE!
connectionTimeoutPostEntity(oleborup.jerseyconnectiontimeout.TimeoutTest)  Time elapsed: 4.133 sec  <<< FAILURE!
java.lang.AssertionError: expected:<2> but was:<4>

For Java 11:

$ git clone https://github.com/oleborup/jersey-client-connection-timeout.git
$ cd jersey-client-connection-timeout/
$ java -version
openjdk version "11.0.11" 2021-04-20
OpenJDK Runtime Environment (build 11.0.11+9-Ubuntu-0ubuntu2.20.04)
OpenJDK 64-Bit Server VM (build 11.0.11+9-Ubuntu-0ubuntu2.20.04, mixed mode, sharing)
$ javac -version
javac 11.0.11
$ mvn test
-------------------------------------------------------
 T E S T S
-------------------------------------------------------
Running oleborup.jerseyconnectiontimeout.TimeoutTest
java.net.SocketTimeoutException: connect timed out
Duration: 2
java.net.SocketTimeoutException: connect timed out
Duration: 4
Tests run: 2, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 7.389 sec <<< FAILURE!
connectionTimeoutPostEntity(oleborup.jerseyconnectiontimeout.TimeoutTest)  Time elapsed: 4.132 sec  <<< FAILURE!
java.lang.AssertionError: expected:<2> but was:<4>

[oleborup]

Jun 18, 2021 10:35:59 AM org.glassfish.jersey.message.internal.WriterInterceptorExecutor$TerminalWriterInterceptor aroundWriteTo
SEVERE: MessageBodyWriter not found for media type=application/json, type=class java.util.HashMap, genericType=class java.util.HashMap.
MessageBodyWriter not found for media type=application/json, type=class java.util.HashMap, genericType=class java.util.HashMap.
Duration: 2

Just noticed the MessageBodyWriter error. Your example does not seem to produce content to post, so probably not triggering the specific issue.

[jbescos]

Thank you, I have modified it by Entity.text("example") and I can reproduce it.

However the test is against http://stripe.reepay.com and we cannot see what is happening there. Maybe the server is spending some time.

I have modified your test to run in localhost. You can copy paste the next class and put it in jersey/tests/e2e-client:

public class Issue4742ExampleTest extends JerseyTest {

    private static final String RESOURCE = "resource";
    private static final int TIMEOUT = 1000;
    private final Invocation.Builder invocationBuilder;

    public Issue4742ExampleTest() {
        Client client = ClientBuilder.newClient();
        client.property(ClientProperties.CONNECT_TIMEOUT, TIMEOUT);
        client.property(ClientProperties.READ_TIMEOUT, TIMEOUT);
        invocationBuilder = client.target("http://localhost:9998/" + RESOURCE).request();
    }

    @Override
    protected Application configure() {
        return new ResourceConfig(Resource.class);
    }

    @Test
    public void connectionTimeoutPostNoEntity() {
        // Timeout should be approx 2 sec
        long start = System.currentTimeMillis();
        try {
            invocationBuilder.post(null);
        } catch (ProcessingException e) {
            System.out.println(e.getMessage());
        }
        long duration = (System.currentTimeMillis() - start) / 1000;
        System.out.println("Duration: " + duration);
    }

    @Test
    public void connectionTimeoutPostEntity() {
        // Timeout should be approx 2 sec - IS 4
        long start = System.currentTimeMillis();
        try {
            invocationBuilder.post(Entity.text("example"));
        } catch (ProcessingException e) {
            System.out.println(e.getMessage());
        }
        long duration = (System.currentTimeMillis() - start) / 1000;
        System.out.println("Duration: " + duration);
    }

    @Path(RESOURCE)
    public static class Resource {
        @POST
        public String test(String text) {
            try {
                Thread.sleep(TIMEOUT + 1);
            } catch (InterruptedException e) {}
            return "ok";
        }
    }
}

The output says that it takes 1 second (the specified timeout):

[INFO] Running org.glassfish.jersey.tests.e2e.client.Issue4742ExampleTest
Jun 18, 2021 12:02:22 PM org.glassfish.jersey.test.grizzly.GrizzlyTestContainerFactory$GrizzlyTestContainer <init>
INFO: Creating GrizzlyTestContainer configured at the base URI http://localhost:9998/
Jun 18, 2021 12:02:23 PM org.hibernate.validator.internal.util.Version <clinit>
INFO: HV000001: Hibernate Validator 6.2.0.Final
Jun 18, 2021 12:02:23 PM org.glassfish.grizzly.http.server.NetworkListener start
INFO: Started listener bound to [localhost:9998]
Jun 18, 2021 12:02:23 PM org.glassfish.grizzly.http.server.HttpServer start
INFO: [HttpServer] Started.
java.net.SocketTimeoutException: Read timed out
Duration: 1
Jun 18, 2021 12:02:24 PM org.glassfish.grizzly.http.server.NetworkListener shutdownNow
INFO: Stopped listener bound to [localhost:9998]
Jun 18, 2021 12:02:24 PM org.glassfish.jersey.test.grizzly.GrizzlyTestContainerFactory$GrizzlyTestContainer <init>
INFO: Creating GrizzlyTestContainer configured at the base URI http://localhost:9998/
Jun 18, 2021 12:02:24 PM org.glassfish.grizzly.http.server.NetworkListener start
INFO: Started listener bound to [localhost:9998]
Jun 18, 2021 12:02:24 PM org.glassfish.grizzly.http.server.HttpServer start
INFO: [HttpServer-1] Started.
java.net.SocketTimeoutException: Read timed out
Duration: 1
Jun 18, 2021 12:02:26 PM org.glassfish.grizzly.http.server.NetworkListener shutdownNow
INFO: Stopped listener bound to [localhost:9998]
[INFO] Tests run: 2, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 3.989 s - in org.glassfish.jersey.tests.e2e.client.Issue4742ExampleTest

[oleborup]

Hi jbescos

The modified test produces a read timeout, not a connection timeout. The issue is specifically regarding TCP connection timeout. stripe.reepay.com port 80 was used as there is no response on this port. It's a host we control.

[jbescos]

Thank you @oleborup, I have debugged this.

There are 2 requests actually when the entity is not null.

In org.glassfish.jersey.client.internal.HttpUrlConnector#_apply(368) there is one request that happens only if entity is not null.

And later in sun.net.www.protocol.http.HttpURLConnection#_apply(374) in the catch, there is a handleException method that invokes java.net.HttpURLConnection#getResponseCode. This triggers again another connection.

[jbescos]

I'm attaching 2 screenshots with null and not null entity. We can see in the not null entity there are 2 SYN.