Skip to content

issues with apache httpclient 5.1.x #1789

Closed

Description

@dimovelev

When I switch the httpclient version from 5.0.x to 5.1.x, docker-java has problems communicating with docker - the process hangs with such a stack trace:

"main" #1 prio=5 os_prio=0 cpu=4140.63ms elapsed=64.25s tid=0x0000021b0a61af20 nid=0x544c waiting on condition  [0x000000a03dff8000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park([email protected]/Native Method)
	- parking to wait for  <0x00000006070433f8> (a java.util.concurrent.CompletableFuture$Signaller)
	at java.util.concurrent.locks.LockSupport.park([email protected]/LockSupport.java:211)
	at java.util.concurrent.CompletableFuture$Signaller.block([email protected]/CompletableFuture.java:1864)
	at java.util.concurrent.ForkJoinPool.unmanagedBlock([email protected]/ForkJoinPool.java:3463)
	at java.util.concurrent.ForkJoinPool.managedBlock([email protected]/ForkJoinPool.java:3434)
	at java.util.concurrent.CompletableFuture.waitingGet([email protected]/CompletableFuture.java:1898)
	at java.util.concurrent.CompletableFuture.get([email protected]/CompletableFuture.java:2072)
	at java.nio.channels.Channels$2.read([email protected]/Channels.java:238)
	- locked <0x000000060371f9f8> (a java.nio.channels.Channels$2)
	at org.apache.hc.core5.http.impl.io.SessionInputBufferImpl.fillBuffer(SessionInputBufferImpl.java:149)
	at org.apache.hc.core5.http.impl.io.BHttpConnectionBase.fillInputBuffer(BHttpConnectionBase.java:265)
	at org.apache.hc.core5.http.impl.io.BHttpConnectionBase.isStale(BHttpConnectionBase.java:295)
	at org.apache.hc.core5.http.impl.io.DefaultBHttpClientConnection.isStale(DefaultBHttpClientConnection.java:67)
	at org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager$1.get(PoolingHttpClientConnectionManager.java:287)
	- locked <0x0000000607043268> (a org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager$1)
	at org.apache.hc.client5.http.impl.classic.InternalExecRuntime.acquireEndpoint(InternalExecRuntime.java:109)
	at org.apache.hc.client5.http.impl.classic.ConnectExec.execute(ConnectExec.java:119)
	at org.apache.hc.client5.http.impl.classic.ExecChainElement.execute(ExecChainElement.java:51)
	at org.apache.hc.client5.http.impl.classic.ExecChainElement$1.proceed(ExecChainElement.java:57)
	at org.apache.hc.client5.http.impl.classic.ProtocolExec.execute(ProtocolExec.java:175)
	at org.apache.hc.client5.http.impl.classic.ExecChainElement.execute(ExecChainElement.java:51)
	at org.apache.hc.client5.http.impl.classic.ExecChainElement$1.proceed(ExecChainElement.java:57)
	at org.apache.hc.client5.http.impl.classic.HttpRequestRetryExec.execute(HttpRequestRetryExec.java:96)
	at org.apache.hc.client5.http.impl.classic.ExecChainElement.execute(ExecChainElement.java:51)
	at org.apache.hc.client5.http.impl.classic.ExecChainElement$1.proceed(ExecChainElement.java:57)
	at org.apache.hc.client5.http.impl.classic.ContentCompressionExec.execute(ContentCompressionExec.java:133)
	at org.apache.hc.client5.http.impl.classic.ExecChainElement.execute(ExecChainElement.java:51)
	at org.apache.hc.client5.http.impl.classic.ExecChainElement$1.proceed(ExecChainElement.java:57)
	at org.apache.hc.client5.http.impl.classic.RedirectExec.execute(RedirectExec.java:115)
	at org.apache.hc.client5.http.impl.classic.ExecChainElement.execute(ExecChainElement.java:51)
	at org.apache.hc.client5.http.impl.classic.InternalHttpClient.doExecute(InternalHttpClient.java:170)
	at org.apache.hc.client5.http.impl.classic.CloseableHttpClient.execute(CloseableHttpClient.java:67)
	at com.github.dockerjava.httpclient5.ApacheDockerHttpClientImpl.execute(ApacheDockerHttpClientImpl.java:175)
	at com.github.dockerjava.httpclient5.ApacheDockerHttpClient.execute(ApacheDockerHttpClient.java:9)
	at com.github.dockerjava.core.DefaultInvocationBuilder.execute(DefaultInvocationBuilder.java:228)
	at com.github.dockerjava.core.DefaultInvocationBuilder.get(DefaultInvocationBuilder.java:202)
	at com.github.dockerjava.core.DefaultInvocationBuilder.get(DefaultInvocationBuilder.java:74)
	at com.github.dockerjava.core.exec.ListImagesCmdExec.execute(ListImagesCmdExec.java:41)
	at com.github.dockerjava.core.exec.ListImagesCmdExec.execute(ListImagesCmdExec.java:16)
	at com.github.dockerjava.core.exec.AbstrSyncDockerCmdExec.exec(AbstrSyncDockerCmdExec.java:21)
	at com.github.dockerjava.core.command.AbstrDockerCmd.exec(AbstrDockerCmd.java:35)

OS: Windows 10 with Docker Desktop
Docker-Java: 3.2.11 and 3.2.12
JDK: Corretto 17.0.1

Some commands seem to succeed but sooner or later one hangs forever. So far I have not been able to create a small reproducer - executing e.g. listImages in a loop did not produce the issue.

Activity

  1. peterdnight commented on Jan 21, 2022

    @peterdnight

    Same issue - thanks for taking time to report (although i still burned many hours isolating JVM crashes)

    	<!-- 
    		- DockerJava integration
    		-  5.1.2 hangs,  5.0.4 is the workaround pending next release 3.2.13 ?
    	 -->
    	<dependency>
    		<groupId>org.apache.httpcomponents.client5</groupId>
    		<artifactId>httpclient5</artifactId>
    		<version>5.0.4</version> 
    	</dependency>
    	
    	<dependency>
    		<groupId>com.github.docker-java</groupId>
    		<artifactId>docker-java-transport-httpclient5</artifactId>
    		<version>3.2.12</version>
    		<exclusions>
    			<exclusion>
    				<groupId>org.apache.httpcomponents.client5</groupId>
    				<artifactId>httpclient5</artifactId>
    			</exclusion>
    		</exclusions>
    	</dependency>
    
    
    	<dependency>
    		<groupId>com.github.docker-java</groupId>
    		<artifactId>docker-java</artifactId>
    		<version>3.2.12</version>
    		<exclusions>
    			<exclusion>
    				<groupId>com.github.docker-java</groupId>
    				<artifactId>
    					docker-java-transport-jersey
    				</artifactId>
    			</exclusion>
    			<exclusion>
    				<groupId>com.github.docker-java</groupId>
    				<artifactId>docker-java-transport-netty</artifactId>
    			</exclusion>
    		</exclusions>
    	</dependency>
    
  2. dimovelev commented on Jan 21, 2022

    @dimovelev
    Author

    @peterdnight i switched to the zerodep client - it seems to be a shaded httpclient5 so it does not clash with the version i have in the remaining part of my application. I guess that is the safer bet for future updates and i will stick to it.

  3. dimovelev commented on Jan 21, 2022

    @dimovelev
    Author

    After reading through the other issue I have a short reproducer:

    package com.example;
    
    import java.io.IOException;
    import java.util.List;
    
    import com.github.dockerjava.api.DockerClient;
    import com.github.dockerjava.api.model.Image;
    import com.github.dockerjava.core.DefaultDockerClientConfig;
    import com.github.dockerjava.core.DockerClientImpl;
    import com.github.dockerjava.httpclient5.ApacheDockerHttpClient;
    import com.github.dockerjava.transport.DockerHttpClient;
    import org.slf4j.Logger;
    
    import static org.slf4j.LoggerFactory.getLogger;
    
    public class Issue {
        private static final Logger LOGGER = getLogger(Issue.class);
    
        public static void main(String[] args) throws IOException, InterruptedException {
            final var config = DefaultDockerClientConfig.createDefaultConfigBuilder() //
                .withDockerHost("npipe:////./pipe/docker_engine") //
                .build();
            final DockerHttpClient httpClient = new ApacheDockerHttpClient.Builder() //
                .dockerHost(config.getDockerHost()) //
                .build();
            final DockerClient client = DockerClientImpl.getInstance(config, httpClient);
            try {
                LOGGER.info("Listing images");
                final List<Image> result1 = client.listImagesCmd().exec();
                LOGGER.info("Found {} images", result1.size());
                Thread.sleep(2_000);
                LOGGER.info("Listing images");
                final List<Image> result2 = client.listImagesCmd().exec();
                LOGGER.info("Found {} images", result2.size());
            } finally {
                client.close();
                httpClient.close();
            }
        }
    }
    

    The second list images hangs forever.
    The crucial part is sleeping for at least 2 seconds (1 second is fine). With that and going through the apache httpclient commits I would guess that the issue is this one - apache/httpcomponents-client@10e2deb

  4. dimovelev commented on Jan 21, 2022

    @dimovelev
    Author

    So the connection staleness check in org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager seems to block forever. It is triggered (with default configuration) after 2 seconds of inactivity. If you change that to -1 the check is disabled and the code above does not block. you can call this method after creating the client to change the value:

        private static void changeValidateAfterInactivity(final DockerHttpClient httpClient) throws NoSuchFieldException,
            IllegalAccessException {
            final Field httpClientField = httpClient.getClass().getSuperclass().getDeclaredField("httpClient");
            httpClientField.setAccessible(true);
            final Object apacheClient = httpClientField.get(httpClient);
            final Field connManagerField = apacheClient.getClass().getDeclaredField("connManager");
            connManagerField.setAccessible(true);
            final PoolingHttpClientConnectionManager connManager =
                (PoolingHttpClientConnectionManager) connManagerField.get(apacheClient);
            connManager.setValidateAfterInactivity(TimeValue.NEG_ONE_MILLISECOND);
        }
    

    So I guess a change in com.github.dockerjava.httpclient5.ApacheDockerHttpClientImpl will be required to set this value.

  5. dimovelev commented on Jan 21, 2022

    @dimovelev
    Author

    The connection staleness check in apache httpclient seems to rely on modifying the socket timeout to 1 ms then trying to read something and resetting the timeout back to the original value. I guess that this fails in our case - the timeout is not reset and thus the read blocks forever (as the original timeout was 0).

  6. dimovelev commented on Jan 21, 2022

    @dimovelev
    Author

    that was a big waste of time. the issue has been fixed (well the timeout set to -1 as i figured out above) in November 2021 - see #1727 . The latest release of docker-java does not include the fix.

    @bsideup when is the next released planned?

  7. peterdnight commented on Jan 24, 2022

    @peterdnight

    @dimovelev - i feel your pain. fyi - if you are curious regarding my use case, check out my docker tutorial:
    https://www.youtube.com/playlist?list=PLETtnz3MXNMUBFq_kSSXrXm1lnp10rt0I

  8. bsideup commented on Feb 15, 2022

    @bsideup
    Member

    Should be fixed in 3.2.13

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions