fabric8io / docker-maven-plugin

Maven plugin for running and creating Docker images
https://dmp.fabric8.io
Apache License 2.0
1.87k stars 641 forks source link

Hanging on stop, does not detect when a container exited... #1028

Open aaronjwhiteside opened 6 years ago

aaronjwhiteside commented 6 years ago

Description

On our jenkins server/slave about half the time the dmp fails to stop the containers it started.. on closer inspection it appears that the container did exit, but that dmp failed to detect this..

[INFO] --- docker-maven-plugin:0.25.2:stop (stop-containers) @ functional-tests ---
consul>     2018/05/18 18:34:41 [DEBUG] http: Request GET /v1/kv/config/application/?recurse&wait=55s&index=48 (55.579435756s) from=172.17.0.8:56272
homeaway> May 18, 2018 6:34:41 PM org.apache.coyote.AbstractProtocol pause
homeaway> INFO: Pausing ProtocolHandler ["http-bio-8080"]
kafka> [2018-05-18 18:34:41,749] INFO [GroupCoordinator 1]: Preparing to rebalance group HOMEAWAY with old generation 1 (__consumer_offsets-5) (kafka.coordinator.group.GroupCoordinator)
kafka> [2018-05-18 18:34:41,757] INFO [GroupCoordinator 1]: Group HOMEAWAY with generation 2 is now empty (__consumer_offsets-5) (kafka.coordinator.group.GroupCoordinator)
homeaway> May 18, 2018 6:34:41 PM org.apache.coyote.AbstractProtocol pause
homeaway> INFO: Pausing ProtocolHandler ["ajp-bio-8009"]
homeaway> May 18, 2018 6:34:41 PM org.apache.catalina.core.StandardService stopInternal
homeaway> INFO: Stopping service Catalina
homeaway> May 18, 2018 6:34:41 PM com.rentpayment.listener.AppServletContextListener contextDestroyed
homeaway> INFO: AppServletContextListener destroyed.
homeaway> May 18, 2018 6:34:41 PM com.rentpayment.listener.AppServletContextListener contextDestroyed
homeaway> INFO: AppServletContextListener shutdown.
homeaway> May 18, 2018 6:34:41 PM com.sun.xml.ws.transport.http.servlet.WSServletDelegate destroy
homeaway> INFO: WSSERVLET15: JAX-WS servlet destroyed
homeaway> May 18, 2018 6:34:41 PM com.sun.xml.ws.transport.http.servlet.WSServletContextListener contextDestroyed
homeaway> INFO: WSSERVLET13: JAX-WS context listener destroyed
homeaway> May 18, 2018 6:34:41 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesJdbc
homeaway> SEVERE: The web application [] registered the JDBC driver [com.microsoft.sqlserver.jdbc.SQLServerDriver] but failed to unregister it when the web application was stopped. To prevent a memory leak, the JDBC Driver has been forcibly unregistered.
homeaway> May 18, 2018 6:34:41 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
homeaway> SEVERE: The web application [] appears to have started a thread named [Timer-0] but has failed to stop it. This is very likely to create a memory leak.
homeaway> May 18, 2018 6:34:41 PM org.apache.catalina.loader.WebappClassLoaderBase clearReferencesThreads
homeaway> SEVERE: The web application [] appears to have started a thread named [ReportServiceExecutor1] but has failed to stop it. This is very likely to create a memory leak.
homeaway> May 18, 2018 6:34:41 PM org.apache.coyote.AbstractProtocol stop
homeaway> INFO: Stopping ProtocolHandler ["http-bio-8080"]
homeaway> May 18, 2018 6:34:41 PM org.apache.coyote.AbstractProtocol stop
homeaway> INFO: Stopping ProtocolHandler ["ajp-bio-8009"]
homeaway> May 18, 2018 6:34:41 PM org.apache.coyote.AbstractProtocol destroy
homeaway> INFO: Destroying ProtocolHandler ["http-bio-8080"]
homeaway> May 18, 2018 6:34:41 PM org.apache.coyote.AbstractProtocol destroy
homeaway> INFO: Destroying ProtocolHandler ["ajp-bio-8009"]
CONTAINER ID        IMAGE                                                   COMMAND                  CREATED             STATUS                       PORTS                                                        NAMES
22b84da977fe        yapstone/domestic:latest                                "catalina.sh run"        7 minutes ago       Exited (143) 6 minutes ago                
docker inspect 22b84da977fe
[
    {
        "Id": "22b84da977fe5d1f9aff090c231cd723f93d8c6734f3b162a5fe367988cc3e48",
        "Created": "2018-05-18T18:33:45.528591424Z",
        "Path": "catalina.sh",
        "Args": [
            "run"
        ],
        "State": {
            "Status": "exited",
            "Running": false,
            "Paused": false,
            "Restarting": false,
            "OOMKilled": false,
            "Dead": false,
            "Pid": 0,
            "ExitCode": 143,
            "Error": "",
            "StartedAt": "2018-05-18T18:33:45.868135081Z",
            "FinishedAt": "2018-05-18T18:34:42.04234177Z"
        },

jstack on the maven process

"main" #1 prio=5 os_prio=0 tid=0x00007fce1c00a800 nid=0x5b36 runnable [0x00007fce2488d000]
   java.lang.Thread.State: RUNNABLE
    at com.kenai.jffi.Foreign.invokeN3O1(Native Method)
    at com.kenai.jffi.Invoker.invokeN3(Invoker.java:1061)
    at jnr.enxio.channels.Native$LibC$jnr$ffi$1.read(Unknown Source)
    at jnr.enxio.channels.Native.read(Native.java:95)
    at jnr.enxio.channels.NativeSocketChannel.read(NativeSocketChannel.java:68)
    at sun.nio.ch.ChannelInputStream.read(ChannelInputStream.java:59)
    - locked <0x00000007835b5078> (a java.lang.Object)
    at sun.nio.ch.ChannelInputStream.read(ChannelInputStream.java:109)
    at sun.nio.ch.ChannelInputStream.read(ChannelInputStream.java:103)
    - locked <0x00000007835b54a8> (a sun.nio.ch.ChannelInputStream)
    at java.io.FilterInputStream.read(FilterInputStream.java:133)
    at org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:137)
    at org.apache.http.impl.io.SessionInputBufferImpl.fillBuffer(SessionInputBufferImpl.java:153)
    at org.apache.http.impl.io.SessionInputBufferImpl.readLine(SessionInputBufferImpl.java:282)
    at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:138)
    at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:56)
    at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:259)
    at org.apache.http.impl.DefaultBHttpClientConnection.receiveResponseHeader(DefaultBHttpClientConnection.java:163)
    at org.apache.http.impl.conn.CPoolProxy.receiveResponseHeader(CPoolProxy.java:165)
    at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:273)
    at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:125)
    at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:272)
    at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:185)
    at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89)
    at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:111)
    at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185)
    at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:72)
    at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:221)
    at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:165)
    at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:140)
    at io.fabric8.maven.docker.access.hc.ApacheHttpClientDelegate.post(ApacheHttpClientDelegate.java:102)
    at io.fabric8.maven.docker.access.hc.ApacheHttpClientDelegate.post(ApacheHttpClientDelegate.java:108)
    at io.fabric8.maven.docker.access.hc.DockerAccessWithHcClient.stopContainer(DockerAccessWithHcClient.java:208)
    at io.fabric8.maven.docker.service.RunService.shutdown(RunService.java:446)
    at io.fabric8.maven.docker.service.RunService.stopStartedContainers(RunService.java:179)
    at io.fabric8.maven.docker.StopMojo.executeInternal(StopMojo.java:68)
    at io.fabric8.maven.docker.AbstractDockerMojo.execute(AbstractDockerMojo.java:222)
    at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:137)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:208)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:154)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:146)
    at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:117)
    at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:81)
    at org.apache.maven.lifecycle.internal.builder.singlethreaded.SingleThreadedBuilder.build(SingleThreadedBuilder.java:56)
    at org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:128)
    at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:305)
    at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:192)
    at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:105)
    at org.apache.maven.cli.MavenCli.execute(MavenCli.java:956)
    at org.apache.maven.cli.MavenCli.doMain(MavenCli.java:290)
    at org.apache.maven.cli.MavenCli.main(MavenCli.java:194)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.codehaus.plexus.classworlds.launcher.Launcher.launchEnhanced(Launcher.java:289)
    at org.codehaus.plexus.classworlds.launcher.Launcher.launch(Launcher.java:229)
    at org.codehaus.plexus.classworlds.launcher.Launcher.mainWithExitCode(Launcher.java:415)
    at org.codehaus.plexus.classworlds.launcher.Launcher.main(Launcher.java:356)

Info

Server: Engine: Version: 17.12.1-ce API version: 1.35 (minimum version 1.12) Go version: go1.9.4 Git commit: 7390fc6/17.12.1-ce Built: Tue Apr 3 23:38:52 2018 OS/Arch: linux/amd64 Experimental: false

rhuss commented 6 years ago

It looks like that the Docker daemon is still not closing the HTTP request to containers/%s/stop. Its not really clear to me, why this should be the case.

Could you try to add a

<wait>
  <kill>2000</kill>
</wait>

to specify a timeout for the stop operation (2s in this example) ?

aaronjwhiteside commented 6 years ago

Setting

<wait>
  <kill>2000</kill>
</wait>

made no difference..

Shouldn't DMP have a read timeout? Jenkins killed the job after 2 hours (the integration test timeout value), but I feel like the DMP's read timeout should have kicked in long before that?

emmaLP commented 5 years ago

Getting the same issue when running a docker image for integration tests and the building a docker image with run skipped.

Setting ```

2000

`` worked the first time and then ran themvn clean deploy sonar:sonar` again and it hung again as usual.

Docker Version:

Client:
 Version:           18.09.2
 API version:       1.39
 Go version:        go1.10.6
 Git commit:        6247962
 Built:             Sun Feb 10 04:13:47 2019
 OS/Arch:           linux/amd64
 Experimental:      false

Server: Docker Engine - Community
 Engine:
  Version:          18.09.2
  API version:      1.39 (minimum version 1.12)
  Go version:       go1.10.6
  Git commit:       6247962
  Built:            Sun Feb 10 03:42:13 2019
  OS/Arch:          linux/amd64
  Experimental:     false

Fabric8 Plugin Version: 0.28.0 Maven version: 3.5.2

Please can this issue be prioritised as it's becoming more and more persistent.

rhuss commented 5 years ago

It's not possible to me to reproduce this behaviour. Do you have a trimmed down sample which exhibits this behaviour so that we can troubleshoot this hanging ?

emmaLP commented 5 years ago

Experienced the issue again with a different project.

Project is a maven multi module with the docker plugin configured in a child pom. The configuration of the plugin in the child pom is pretty much this:

<plugin>
<groupId>io.fabric8</groupId>
<artifactId>docker-maven-plugin</artifactId>
<configuration>
    <images>
        <image>
            <name>artifact</name>
            <alias>artifact</alias>
            <build>
                <dockerFileDir>${project.basedir}/src/main/docker</dockerFileDir>
                <assembly>
                    <inline>
                        <dependencySets>
                            <dependencySet>
                                <includes>
                                    <include>
                                        ${project.groupId}:${project.artifactId}
                                    </include>
                                </includes>
                                <outputDirectory>.</outputDirectory>
                                <outputFileNameMapping>application.jar
                                </outputFileNameMapping>
                            </dependencySet>
                        </dependencySets>
                    </inline>
                </assembly>
                <tags>
                    <tag>${project.parent.version}</tag>
                    <tag>${git.commit.id}</tag>
                </tags>
            </build>
            <run>
                <skip>true</skip>
            </run>
        </image>
        <image>
            <name>posgres:9.4-alpine
            </name>
            <alias>db</alias>
            <run>
                <ports>
                    <port>5432:5432</port>
                </ports>
                <wait>
                    <log>database system is ready to accept connections</log>
                    <time>10000</time>
                </wait>
                <log>
                    <file>${project.build.directory}/db.log</file>
                </log>
            </run>
        </image>
    </images>
</configuration>
<executions>
    <execution>
        <id>start</id>
        <phase>pre-integration-test</phase>
        <goals>
            <goal>start</goal>
        </goals>
    </execution>
    <execution>
        <id>stop</id>
        <phase>post-integration-test</phase>
        <goals>
            <goal>stop</goal>
        </goals>
    </execution>
    <execution>
        <id>docker-build</id>
        <goals>
            <goal>build</goal>
        </goals>
    </execution>
    <execution>
        <id>docker-push</id>
        <goals>
            <goal>push</goal>
        </goals>
    </execution>
</executions>
</plugin>
emmaLP commented 5 years ago

With the above configuration I downgraded to version 0.27.2 of the docker plugin and the issue occurs there to.

aaronjwhiteside commented 5 years ago

@rhuss any movement on this, given @emmaLP 's example?

rhuss commented 5 years ago

Sorry, no. Still stuck in work and not sure when I can pick this up again.

chonton commented 5 years ago

Same problem as #552?