search

fabric8io / docker-maven-plugin

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

Docker:stop hangs, gets reply on the wrong connection? #804

Open koscejev opened 7 years ago

koscejev commented 7 years ago

Description

We're using this plugin on multiple machines, including Windows, Ubuntu, CentOS. On our CentOS builder running Bamboo this plugin fails to stop the postgres container properly, instead hanging indefinitely (auto-killed after 10 minutes).

After enabling the debug log I can see that both the stop and the subsequent remove commands work properly, except one tiny thing: the reply for the remove command comes in on a different connection, but doesn't come in on the correct one!

On the troublesome environment this happens in majority of the cases, but not always. This happens with both overlay and devicemapper storage. (The storage seems to be one of the key differences, but I don't have the knowledge to understand how this could possibly be related.) On Ubuntu dev box we were somehow able to reproduce this with overlay storage. Java version 8u74 didn't seem to affect this in any way - couldn't reproduce by just downgrading Java on a box where this doesn't occur.

Info

Docker info on the failing box:

Info ``` Containers: 3 Running: 0 Paused: 0 Stopped: 3 Images: 65 Server Version: 17.05.0-ce Storage Driver: devicemapper Pool Name: docker-253:0-931755-pool Pool Blocksize: 65.54kB Base Device Size: 10.74GB Backing Filesystem: xfs Data file: /dev/loop0 Metadata file: /dev/loop1 Data Space Used: 35.11GB Data Space Total: 107.4GB Data Space Available: 14.96GB Metadata Space Used: 64.57MB Metadata Space Total: 2.147GB Metadata Space Available: 2.083GB Thin Pool Minimum Free Space: 10.74GB Udev Sync Supported: true Deferred Removal Enabled: false Deferred Deletion Enabled: false Deferred Deleted Device Count: 0 Data loop file: /var/lib/docker/devicemapper/devicemapper/data Metadata loop file: /var/lib/docker/devicemapper/devicemapper/metadata Library Version: 1.02.107-RHEL7 (2016-06-09) Logging Driver: json-file Cgroup Driver: cgroupfs Plugins: Volume: local Network: bridge host macvlan null overlay Swarm: inactive Runtimes: runc Default Runtime: runc Init Binary: docker-init containerd version: 9048e5e50717ea4497b757314bad98ea3763c145 runc version: 9c2d8d184e5da67c95d601382adf14862e4f2228 init version: 949e6fa Security Options: seccomp Profile: default Kernel Version: 3.10.0-514.10.2.el7.x86_64 Operating System: CentOS Linux 7 (Core) OSType: linux Architecture: x86_64 CPUs: 8 Total Memory: 7.639GiB Name: build7-64-01.ci.here.com ID: OVFO:BW2O:QRVA:EC56:SA5Y:PHA3:2NK4:JWM7:K2XX:YMWV:Z6OU:FHNL Docker Root Dir: /var/lib/docker Debug Mode (client): false Debug Mode (server): false Registry: https://index.docker.io/v1/ Experimental: false Insecure Registries: 127.0.0.0/8 Live Restore Enabled: false WARNING: devicemapper: usage of loopback devices is strongly discouraged for production use. Use `--storage-opt dm.thinpooldev` to specify a custom block storage device. WARNING: bridge-nf-call-iptables is disabled WARNING: bridge-nf-call-ip6tables is disabled ```

Debug logs

Debug logs on failing box:

Debug ``` [INFO] --- docker-maven-plugin:0.21.0:stop (docker-postgres-stop) @ my-project --- [DEBUG] Configuring mojo io.fabric8:docker-maven-plugin:0.21.0:stop from plugin realm ClassRealm[plugin>io.fabric8:docker-maven-plugin:0.21.0, parent: sun.misc.Launcher$AppClassLoader@5c647e05] [DEBUG] Configuring mojo 'io.fabric8:docker-maven-plugin:0.21.0:stop' with basic configurator --> [DEBUG] (f) allContainers = false [DEBUG] (f) autoCreateCustomNetworks = false [DEBUG] (f) autoPull = on [DEBUG] (f) execution = io.fabric8:docker-maven-plugin:0.21.0:stop {execution: docker-postgres-stop} [DEBUG] (f) alias = postgres [DEBUG] (s) name = comp/dep-dbpostgres:6.2.0-SNAPSHOT [DEBUG] (f) dockerFileDir = postgres [DEBUG] (f) filter = @ [DEBUG] (s) id = dbpostgres [DEBUG] (s) outputDirectory = / [DEBUG] (s) unpack = true [DEBUG] (s) useProjectArtifact = false [DEBUG] (s) includes = [comp.dep:dep-dbpostgres] [DEBUG] (s) scope = provided [DEBUG] (s) dependencySets = [org.apache.maven.plugin.assembly.model.DependencySet@75e9ccfe] [DEBUG] (f) inline = org.apache.maven.plugin.assembly.model.Assembly@2911f7a [DEBUG] (f) assembly = io.fabric8.maven.docker.config.AssemblyConfiguration@3e217bf7 [DEBUG] (f) build = io.fabric8.maven.docker.config.BuildImageConfiguration@b5e9abb [DEBUG] (f) ports = [+postgres.host:postgres.port:5432] [DEBUG] (f) log = PostgreSQL init process complete; ready for start up. [DEBUG] (f) time = 60000 [DEBUG] (f) kill = 0 [DEBUG] (f) wait = io.fabric8.maven.docker.config.WaitConfiguration@306b2912 [DEBUG] (f) run = io.fabric8.maven.docker.config.RunImageConfiguration@3a8b9aaa [DEBUG] (f) images = [ImageConfiguration {name='comp/dep-dbpostgres:6.2.0-SNAPSHOT', alias='postgres'}] [DEBUG] (f) keepContainer = false [DEBUG] (f) keepRunning = false [DEBUG] (f) logStdout = false [DEBUG] (f) maxConnections = 100 [DEBUG] (f) project = MavenProject: my.project:my-project:6.2.0-SNAPSHOT @ /home/bamboo/agent1-home/xml-data/build-dir/SIX-IC623-PSQL/dep/dep-stuff/pom.xml [DEBUG] (f) removeVolumes = false [DEBUG] (f) session = org.apache.maven.execution.MavenSession@41e1455d [DEBUG] (f) settings = org.apache.maven.execution.SettingsAdapter@51e3d37e [DEBUG] (f) skip = false [DEBUG] (f) skipExtendedAuth = false [DEBUG] (f) skipMachine = false [DEBUG] (f) sledgeHammer = false [DEBUG] (f) useColor = true [DEBUG] (f) verbose = true [DEBUG] -- end configuration -- [DEBUG] CookieSpec selected: default [DEBUG] Auth cache not set in the context [DEBUG] Connection request: [route: {}->unix://127.0.0.1:1][total kept alive: 0; route allocated: 0 of 100; total allocated: 0 of 20] [DEBUG] Connection leased: [id: 2][route: {}->unix://127.0.0.1:1][total kept alive: 0; route allocated: 1 of 100; total allocated: 1 of 20] [DEBUG] Opening connection {}->unix://127.0.0.1:1 [DEBUG] Connecting to 0.0.0.0/0.0.0.0:1 [DEBUG] Connection established [family=PF_UNIX path=/var/run/docker.sock]<->[family=PF_UNIX path=/var/run/docker.sock] [DEBUG] Executing request GET /version HTTP/1.1 [DEBUG] Target auth state: UNCHALLENGED [DEBUG] Proxy auth state: UNCHALLENGED [DEBUG] http-outgoing-4 >> GET /version HTTP/1.1 [DEBUG] http-outgoing-4 >> Accept: */* [DEBUG] http-outgoing-4 >> Content-Type: application/json; charset=utf-8 [DEBUG] http-outgoing-4 >> Host: 127.0.0.1:1 [DEBUG] http-outgoing-4 >> Connection: Keep-Alive [DEBUG] http-outgoing-4 >> User-Agent: Apache-HttpClient/4.5.2 (Java/1.8.0_74) [DEBUG] http-outgoing-4 >> Accept-Encoding: gzip,deflate [DEBUG] http-outgoing-4 >> "GET /version HTTP/1.1[\r][\n]" [DEBUG] http-outgoing-4 >> "Accept: */*[\r][\n]" [DEBUG] http-outgoing-4 >> "Content-Type: application/json; charset=utf-8[\r][\n]" [DEBUG] http-outgoing-4 >> "Host: 127.0.0.1:1[\r][\n]" [DEBUG] http-outgoing-4 >> "Connection: Keep-Alive[\r][\n]" [DEBUG] http-outgoing-4 >> "User-Agent: Apache-HttpClient/4.5.2 (Java/1.8.0_74)[\r][\n]" [DEBUG] http-outgoing-4 >> "Accept-Encoding: gzip,deflate[\r][\n]" [DEBUG] http-outgoing-4 >> "[\r][\n]" [DEBUG] http-outgoing-4 << "HTTP/1.1 200 OK[\r][\n]" [DEBUG] http-outgoing-4 << "Api-Version: 1.29[\r][\n]" [DEBUG] http-outgoing-4 << "Content-Type: application/json[\r][\n]" [DEBUG] http-outgoing-4 << "Docker-Experimental: false[\r][\n]" [DEBUG] http-outgoing-4 << "Ostype: linux[\r][\n]" [DEBUG] http-outgoing-4 << "Server: Docker/17.05.0-ce (linux)[\r][\n]" [DEBUG] http-outgoing-4 << "Date: Tue, 27 Jun 2017 16:04:59 GMT[\r][\n]" [DEBUG] http-outgoing-4 << "Content-Length: 235[\r][\n]" [DEBUG] http-outgoing-4 << "[\r][\n]" [DEBUG] http-outgoing-4 << "{"Version":"17.05.0-ce","ApiVersion":"1.29","MinAPIVersion":"1.12","GitCommit":"89658be","GoVersion":"go1.7.5","Os":"linux","Arch":"amd64","KernelVersion":"3.10.0-514.21.1.el7.x86_64","BuildTime":"2017-05-04T22:06:25.279181930+00:00"}[\n]" [DEBUG] http-outgoing-4 << HTTP/1.1 200 OK [DEBUG] http-outgoing-4 << Api-Version: 1.29 [DEBUG] http-outgoing-4 << Content-Type: application/json [DEBUG] http-outgoing-4 << Docker-Experimental: false [DEBUG] http-outgoing-4 << Ostype: linux [DEBUG] http-outgoing-4 << Server: Docker/17.05.0-ce (linux) [DEBUG] http-outgoing-4 << Date: Tue, 27 Jun 2017 16:04:59 GMT [DEBUG] http-outgoing-4 << Content-Length: 235 [DEBUG] Connection can be kept alive indefinitely [DEBUG] Connection [id: 2][route: {}->unix://127.0.0.1:1] can be kept alive indefinitely [DEBUG] Connection released: [id: 2][route: {}->unix://127.0.0.1:1][total kept alive: 1; route allocated: 1 of 100; total allocated: 1 of 20] [DEBUG] DOCKER> shutdown will wait max of 0 seconds before removing container [DEBUG] CookieSpec selected: default [DEBUG] Auth cache not set in the context [DEBUG] Connection request: [route: {}->unix://127.0.0.1:1][total kept alive: 1; route allocated: 1 of 100; total allocated: 1 of 20] [DEBUG] Connection leased: [id: 2][route: {}->unix://127.0.0.1:1][total kept alive: 0; route allocated: 1 of 100; total allocated: 1 of 20] [DEBUG] Executing request POST /v1.18/containers/74832870f151/stop HTTP/1.1 [DEBUG] Target auth state: UNCHALLENGED [DEBUG] Proxy auth state: UNCHALLENGED [DEBUG] http-outgoing-4 >> POST /v1.18/containers/74832870f151/stop HTTP/1.1 [DEBUG] http-outgoing-4 >> Accept: */* [DEBUG] http-outgoing-4 >> Content-Type: application/json; charset=utf-8 [DEBUG] http-outgoing-4 >> Content-Length: 0 [DEBUG] http-outgoing-4 >> Host: 127.0.0.1:1 [DEBUG] http-outgoing-4 >> Connection: Keep-Alive [DEBUG] http-outgoing-4 >> User-Agent: Apache-HttpClient/4.5.2 (Java/1.8.0_74) [DEBUG] http-outgoing-4 >> Accept-Encoding: gzip,deflate [DEBUG] http-outgoing-4 >> "POST /v1.18/containers/74832870f151/stop HTTP/1.1[\r][\n]" [DEBUG] http-outgoing-4 >> "Accept: */*[\r][\n]" [DEBUG] http-outgoing-4 >> "Content-Type: application/json; charset=utf-8[\r][\n]" [DEBUG] http-outgoing-4 >> "Content-Length: 0[\r][\n]" [DEBUG] http-outgoing-4 >> "Host: 127.0.0.1:1[\r][\n]" [DEBUG] http-outgoing-4 >> "Connection: Keep-Alive[\r][\n]" [DEBUG] http-outgoing-4 >> "User-Agent: Apache-HttpClient/4.5.2 (Java/1.8.0_74)[\r][\n]" [DEBUG] http-outgoing-4 >> "Accept-Encoding: gzip,deflate[\r][\n]" [DEBUG] http-outgoing-4 >> "[\r][\n]" [DEBUG] http-outgoing-2 << "4d[\r][\n]" [DEBUG] http-outgoing-2 << "[0x2][0x0][0x0][0x0][0x0][0x0][0x0]E2017-06-27T16:04:59.925281391Z LOG: received smart shutdown request[\n]" [DEBUG] http-outgoing-2 << "[\r][\n]" [DEBUG] http-outgoing-2 << "4f[\r][\n]" [DEBUG] http-outgoing-2 << "[0x2][0x0][0x0][0x0][0x0][0x0][0x0]G2017-06-27T16:04:59.925319136Z LOG: autovacuum launcher shutting down[\n]" [DEBUG] http-outgoing-2 << "[\r][\n]" [DEBUG] http-outgoing-3 << "4d[\r][\n]" postgres> LOG: received smart shutdown request [DEBUG] http-outgoing-3 << "[0x2][0x0][0x0][0x0][0x0][0x0][0x0]E2017-06-27T16:04:59.925281391Z LOG: received smart shutdown request[\n]" [DEBUG] http-outgoing-3 << "[\r][\n]" [DEBUG] http-outgoing-3 << "4f[\r][\n]" [DEBUG] http-outgoing-3 << "[0x2][0x0][0x0][0x0][0x0][0x0][0x0]G2017-06-27T16:04:59.925319136Z LOG: autovacuum launcher shutting down[\n]" [DEBUG] http-outgoing-3 << "[\r][\n]" postgres> LOG: autovacuum launcher shutting down [DEBUG] http-outgoing-2 << "3b[\r][\n]" [DEBUG] http-outgoing-2 << "[0x2][0x0][0x0][0x0][0x0][0x0][0x0]32017-06-27T16:04:59.925574572Z LOG: shutting down[\n]" [DEBUG] http-outgoing-2 << "[\r][\n]" postgres> LOG: shutting down [DEBUG] http-outgoing-2 << "4a[\r][\n]" [DEBUG] http-outgoing-2 << "[0x2][0x0][0x0][0x0][0x0][0x0][0x0]B2017-06-27T16:04:59.958370153Z LOG: database system is shut down[\n]" [DEBUG] http-outgoing-2 << "[\r][\n]" postgres> LOG: database system is shut down [DEBUG] http-outgoing-2 << "0[\r][\n]" [DEBUG] http-outgoing-2 << "[\r][\n]" [DEBUG] Releasing connection [family=PF_UNIX path=/var/run/docker.sock]<->[family=PF_UNIX path=/var/run/docker.sock] [DEBUG] Connection can be kept alive indefinitely [DEBUG] Shutting down connection [DEBUG] http-outgoing-2: Shutdown connection [DEBUG] http-outgoing-4 << "HTTP/1.1 204 No Content[\r][\n]" [DEBUG] http-outgoing-4 << "Api-Version: 1.29[\r][\n]" [DEBUG] http-outgoing-4 << "Docker-Experimental: false[\r][\n]" [DEBUG] http-outgoing-4 << "Ostype: linux[\r][\n]" [DEBUG] http-outgoing-4 << "Server: Docker/17.05.0-ce (linux)[\r][\n]" [DEBUG] http-outgoing-4 << "Date: Tue, 27 Jun 2017 16:05:00 GMT[\r][\n]" [DEBUG] http-outgoing-4 << "[\r][\n]" [DEBUG] http-outgoing-4 << HTTP/1.1 204 No Content [DEBUG] http-outgoing-4 << Api-Version: 1.29 [DEBUG] http-outgoing-4 << Docker-Experimental: false [DEBUG] http-outgoing-4 << Ostype: linux [DEBUG] http-outgoing-4 << Server: Docker/17.05.0-ce (linux) [DEBUG] http-outgoing-4 << Date: Tue, 27 Jun 2017 16:05:00 GMT [DEBUG] Connection can be kept alive indefinitely [DEBUG] Connection [id: 2][route: {}->unix://127.0.0.1:1] can be kept alive indefinitely [DEBUG] Connection released: [id: 2][route: {}->unix://127.0.0.1:1][total kept alive: 1; route allocated: 1 of 100; total allocated: 1 of 20] [DEBUG] CookieSpec selected: default [DEBUG] Auth cache not set in the context [DEBUG] Connection request: [route: {}->unix://127.0.0.1:1][total kept alive: 1; route allocated: 1 of 100; total allocated: 1 of 20] [DEBUG] Connection leased: [id: 2][route: {}->unix://127.0.0.1:1][total kept alive: 0; route allocated: 1 of 100; total allocated: 1 of 20] [DEBUG] Executing request DELETE /v1.18/containers/74832870f151?v=0 HTTP/1.1 [DEBUG] Target auth state: UNCHALLENGED [DEBUG] Proxy auth state: UNCHALLENGED [DEBUG] http-outgoing-4 >> DELETE /v1.18/containers/74832870f151?v=0 HTTP/1.1 [DEBUG] http-outgoing-4 >> Accept: */* [DEBUG] http-outgoing-4 >> Content-Type: application/json; charset=utf-8 [DEBUG] http-outgoing-4 >> Host: 127.0.0.1:1 [DEBUG] http-outgoing-4 >> Connection: Keep-Alive [DEBUG] http-outgoing-4 >> User-Agent: Apache-HttpClient/4.5.2 (Java/1.8.0_74) [DEBUG] http-outgoing-4 >> Accept-Encoding: gzip,deflate [DEBUG] http-outgoing-4 >> "DELETE /v1.18/containers/74832870f151?v=0 HTTP/1.1[\r][\n]" [DEBUG] http-outgoing-4 >> "Accept: */*[\r][\n]" [DEBUG] http-outgoing-4 >> "Content-Type: application/json; charset=utf-8[\r][\n]" [DEBUG] http-outgoing-4 >> "Host: 127.0.0.1:1[\r][\n]" [DEBUG] http-outgoing-4 >> "Connection: Keep-Alive[\r][\n]" [DEBUG] http-outgoing-4 >> "User-Agent: Apache-HttpClient/4.5.2 (Java/1.8.0_74)[\r][\n]" [DEBUG] http-outgoing-4 >> "Accept-Encoding: gzip,deflate[\r][\n]" [DEBUG] http-outgoing-4 >> "[\r][\n]" [DEBUG] http-outgoing-3 << "HTTP/1.1 204 No Content[\r][\n]" [DEBUG] http-outgoing-3 << "Api-Version: 1.29[\r][\n]" [DEBUG] http-outgoing-3 << "Docker-Experimental: false[\r][\n]" [DEBUG] http-outgoing-3 << "Ostype: linux[\r][\n]" [DEBUG] http-outgoing-3 << "Server: Docker/17.05.0-ce (linux)[\r][\n]" [DEBUG] http-outgoing-3 << "Date: Tue, 27 Jun 2017 16:05:00 GMT[\r][\n]" [DEBUG] http-outgoing-3 << "[\r][\n]" [DEBUG] DOCKER> Closing LogWaitChecker callback ```

^ And at this point the plugin just hangs there. It seems it's waiting to receive reply on http-outgoing-4, when the reply strangely already came in on http-outgoing-3. In fact, http-outgoing-3 is also receiving duplicate response that http-outgoing-2 is receiving.

koscejev commented 7 years ago

In the log above the http-outgoing-3 connection is the one that is doing GET /v1.18/containers/74832870f151/logs?follow=1&stderr=1&stdout=1&timestamps=1 right from the start.

rhuss commented 7 years ago

Thanks for the details bug report. In fact we had issues with concurrent access to the Docker Unix soket in the past. As this is something we do not have much influence on (except than updating the unix socket library we are using jnr-unixsocket. If you like you can try version 0.21-SNAPSHOT which contains an upgrade of jnr-unixsocket (but may have some other issues).

I really need to set some time aside for rigorously testing this concurrency issues (which we have for parallel log stream in general), but unfortunately i'm quite busy these days ;-(

It's a big dragon. Any help here is highly appreciated. And you can become a dragon slayer ;)

koscejev commented 7 years ago

We're continuing investigating this and we've also noticed that this might be related to unix sockets. In fact, I had different but similar persistent problems with Windows npipe too and switched to http a long time ago. It seems that Java version might be related after all - we now can reproduce this issue on Ubuntu regardless of storage if we use Java 8u74 and unix pipes.

I've checked out the code (master branch) and I noticed that you're using jnr-unixsocket version 0.12 - it was reverted back from 0.15 at some point. So does that mean that 0.21-SNAPSHOT actually won't have updated jnr-unixsocket? Or should I use some specific build that has a newer one? If so, where should I get it?

rhuss commented 7 years ago

The snapshot is from PR https://github.com/fabric8io/docker-maven-plugin/pull/770 which introduces jnr-unixsocket 0.18 but I can rebuild it again on top of master. I need to rebase the PR anyway.

rhuss commented 7 years ago

Just rebased and pushed out a new snapshot version 0.21-SNAPSHOT. Don't forget to add the Maven central snapshot repo to your pom to get it picked up.

koscejev commented 7 years ago

We've tried the snapshot (built locally), but we're getting the same issue that caused the revert initially: #660

rhuss commented 7 years ago

arrggh. sorry, so we have two issues to investigate ;|

koscejev commented 7 years ago

I've tried looking at the code and the issue at hand and there's clearly something I don't understand. You're starting up /logs?follow=1 command, which continuously returns chunked response, so the pipe is busy reporting logs from the container. So how can you reliably use the same pipe to issue other commands, knowing that at any point some log from container can be received instead of the expected output? Isn't the unix pipe shared? Or is this behavior somehow different based on kernel and such?

koscejev commented 7 years ago

Although reading this, it seems it should work perfectly for PF_UNIX of type SOCK_STREAM. And that's exactly what's used by default when opening jnr UnixSocketChannel. So if a different connection is receiving the reply, it's really not clear how it could happen (provided sockets work as described).

rhuss commented 7 years ago

Afaik its not a unix named pipe on Linux, but a unix socket. I'm not 100% sure but I suppose that Unix sockets behave like TCP sockets which allow for parallel connections (e.g. handing it off to some other thread).

Said that, I don't know how it works for Windows as Windows is supposed to use NamedPipe for it.

rhuss commented 7 years ago

ah, ok, I just answered your first comment before reading the second ;-)

albers commented 7 years ago

I'm also facing this. When shutting down the last of two containers after the integration tests, the plugin hangs. This does not happen all the time, occasionally a shutdown is successful. One difference to @koscejev's report: The connection is not autokilled after 10 minutes, it seems to hang forever.

The problem only occurs when I connect via a unix socket. There were no problems when I used a remote http connection.

The root cause seems the same as for @koscejev: The response for the stop request arrives on the wrong connection, intermixed with log messages from the first container. The connection that is used here was already actively shut down, see comments in the attached log file.

My setup is: docker-maven-plugin 0.21.0 against local Docker 17.06.0-ce on Ubuntu 16.04.2 LTS with Maven 3.5.0 and Java 1.8u131.

Maven debug output Two containers are started, integration tests are performed, the containers are shut down. During shutdown of the second container, Maven hangs. 
[INFO] --- docker-maven-plugin:0.21.0:start (start) @ de.hs.kis.server.systemtest ---
[...]
[DEBUG] Connection request: [route: {}->unix://127.0.0.1:1][total kept alive: 0; route allocated: 0 of 100; total allocated: 0 of 20]
[DEBUG] Connection leased: [id: 0][route: {}->unix://127.0.0.1:1][total kept alive: 0; route allocated: 1 of 100; total allocated: 1 of 20]
[DEBUG] Opening connection {}->unix://127.0.0.1:1
[DEBUG] Connecting to 0.0.0.0/0.0.0.0:1
[DEBUG] Connection established [family=PF_UNIX path=??o]<->[family=PF_UNIX path=/var/run/docker.sock]
#
# container A (IBM DB2 based) is created and started on http-outgoing-0
#
[DEBUG] Executing request GET /version HTTP/1.1
[DEBUG] Target auth state: UNCHALLENGED
[DEBUG] Proxy auth state: UNCHALLENGED
[DEBUG] http-outgoing-0 >> GET /version HTTP/1.1
[...]
[DEBUG] Connection can be kept alive indefinitely
[DEBUG] Connection [id: 0][route: {}->unix://127.0.0.1:1] can be kept alive indefinitely
[DEBUG] Connection released: [id: 0][route: {}->unix://127.0.0.1:1][total kept alive: 1; route allocated: 1 of 100; total allocated: 1 of 20]
[...]
[DEBUG] http-outgoing-0 >> GET /v1.18/images/hsgmbh%2Fdb2%3Alatest/json HTTP/1.1
[...]
[DEBUG] http-outgoing-0 >> POST /v1.18/containers/create HTTP/1.1
[...]
[DEBUG] http-outgoing-0 >> POST /v1.18/containers/226d222c62c9/start HTTP/1.1
[...]
[DEBUG] Connection can be kept alive indefinitely
[DEBUG] Connection [id: 0][route: {}->unix://127.0.0.1:1] can be kept alive indefinitely
[DEBUG] Connection released: [id: 0][route: {}->unix://127.0.0.1:1][total kept alive: 1; route allocated: 1 of 100; total allocated: 1 of 20]
[DEBUG] DOCKER> LogWaitChecker: Waiting on DB2 successfully started
[...]
[DEBUG] http-outgoing-0 >> GET /v1.18/containers/226d222c62c9/json HTTP/1.1
[...]
[DEBUG] Connection can be kept alive indefinitely
[DEBUG] Connection [id: 0][route: {}->unix://127.0.0.1:1] can be kept alive indefinitely
[DEBUG] Connection released: [id: 0][route: {}->unix://127.0.0.1:1][total kept alive: 1; route allocated: 1 of 100; total allocated: 1 of 20]
#
# Logs are inspected on http-outgoing-1
#
[DEBUG] DOCKER> LogWaitChecker: Pattern to match 'DB2 successfully started'
[DEBUG] CookieSpec selected: default
[DEBUG] Auth cache not set in the context
[DEBUG] Get connection for route {}->unix://127.0.0.1:1
[DEBUG] Opening connection {}->unix://127.0.0.1:1
[DEBUG] Connecting to 0.0.0.0/0.0.0.0:1
[DEBUG] Connection established [family=PF_UNIX path=??o]<->[family=PF_UNIX path=/var/run/docker.sock]
[DEBUG] Executing request GET /v1.18/containers/226d222c62c9/logs?follow=1&stderr=1&stdout=1×tamps=1 HTTP/1.1
[DEBUG] Target auth state: UNCHALLENGED
[DEBUG] Proxy auth state: UNCHALLENGED
[DEBUG] http-outgoing-1 >> GET /v1.18/containers/226d222c62c9/logs?follow=1&stderr=1&stdout=1×tamps=1 HTTP/1.1
[...]
[DEBUG] Connection can be kept alive indefinitely
[DEBUG] http-outgoing-1 << "34[\r][\n]"
[DEBUG] http-outgoing-1 << "[0x1][0x0][0x0][0x0][0x0][0x0][0x0],2017-07-24T12:43:21.032255675Z starting DB2[\n]"
[DEBUG] http-outgoing-1 << "[\r][\n]"
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'starting DB2' [Pattern: DB2 successfully started] [thread: 10]
[...]
[DEBUG] http-outgoing-1 << "40[\r][\n]"
[DEBUG] http-outgoing-1 << "[0x1][0x0][0x0][0x0][0x0][0x0][0x0]82017-07-24T12:43:33.156357266Z DB2 successfully started[\n]"
[DEBUG] http-outgoing-1 << "[\r][\n]"
[DEBUG] DOCKER> LogWaitChecker: Tying to match 'DB2 successfully started' [Pattern: DB2 successfully started] [thread: 10]
[...]
#
# After detecting the startup message of A, http-outgoing-1 is shutdown
#
[DEBUG] http-outgoing-1: Shutdown connection
[DEBUG] Connection discarded
[DEBUG] Releasing connection [Not bound]
[...]
#
# container B (Wildfly based) is created and started on http-outgoing-0
#
[DEBUG] http-outgoing-0 >> POST /v1.18/containers/create HTTP/1.1
[...]
[DEBUG] http-outgoing-0 >> POST /v1.18/containers/80d9ceaa4f3b/start HTTP/1.1
[...]
#
# Logs are inspected on http-outgoing-2
#
[DEBUG] http-outgoing-2 >> GET /v1.18/containers/80d9ceaa4f3b/logs?follow=1&stderr=1&stdout=1×tamps=1 HTTP/1.1
[...]
[DEBUG] http-outgoing-2 << "[0x1][0x0][0x0][0x0][0x0][0x0][0x1][0xc]2017-07-24T12:43:40.878460952Z [0x1b][0m[0x1b][0m2017-07-24 14:43:40,878 INFO  [org.jboss.as] (Controller Boot Thread) WFLYSRV0025: WildFly Full 9.0.2.Final (WildFly Core 1.0.2.Final) started in 7228ms - Started 517 of 707 services (245 services are lazy, passive or on-demand)[\n]"
[DEBUG] http-outgoing-2 << "[\r][\n]"
[DEBUG] DOCKER> LogWaitChecker: Tying to match '2017-07-24 14:43:40,878 INFO  [org.jboss.as] (Controller Boot Thread) WFLYSRV0025: WildFly Full 9.0.2.Final (WildFly Core 1.0.2.Final) started in 7228ms - Started 517 of 707 services (245 services are lazy, passive or on-demand)' [Pattern: WildFly Full .* \(WildFly Core .*\) started] [thread: 11]
[...]
#
# After detecting the startup message of B, http-outgoing-2 is shutdown
#
[DEBUG] http-outgoing-2: Shutdown connection
[DEBUG] Connection discarded
[DEBUG] Releasing connection [Not bound]
[...]
[DEBUG] Connection manager is shutting down
[DEBUG] http-outgoing-0: Close connection
[DEBUG] Connection manager shut down
[INFO] 
[INFO] --- maven-failsafe-plugin:2.20:integration-test (default) @ de.hs.kis.server.systemtest ---
#
# some integration tests
#
[...]
[INFO] --- docker-maven-plugin:0.21.0:stop (stop) @ de.hs.kis.server.systemtest ---
[DEBUG] Configuring mojo io.fabric8:docker-maven-plugin:0.21.0:stop from plugin realm ClassRealm[plugin>io.fabric8:docker-maven-plugin:0.21.0, parent: sun.misc.Launcher$AppClassLoader@74a14482]
[DEBUG] Configuring mojo 'io.fabric8:docker-maven-plugin:0.21.0:stop' with basic configurator -->
[DEBUG]   (f) allContainers = false
[DEBUG]   (f) autoCreateCustomNetworks = false
[DEBUG]   (f) autoPull = true
[DEBUG]   (f) execution = io.fabric8:docker-maven-plugin:0.21.0:stop {execution: stop}
[DEBUG]   (f) alias = db2
[DEBUG]   (s) name = hsgmbh/db2:latest
[DEBUG]   (f) ports = [50000]
[DEBUG]   (f) log = DB2 successfully started
[DEBUG]   (f) time = 180000
[DEBUG]   (f) wait = io.fabric8.maven.docker.config.WaitConfiguration@58fd1214
[DEBUG]   (f) run = io.fabric8.maven.docker.config.RunImageConfiguration@7d8cf9ac
[DEBUG]   (f) alias = kisserver
[DEBUG]   (s) name = hsgmbh/kisserver2:latest
[DEBUG]   (f) links = [db2]
[DEBUG]   (f) ports = [kisserver.port:8080]
[DEBUG]   (f) log = WildFly Full .* \(WildFly Core .*\) started
[DEBUG]   (f) time = 40000
[DEBUG]   (f) wait = io.fabric8.maven.docker.config.WaitConfiguration@5f0bab7e
[DEBUG]   (f) run = io.fabric8.maven.docker.config.RunImageConfiguration@3a7b2e2
[DEBUG]   (f) images = [ImageConfiguration {name='hsgmbh/db2:latest', alias='db2'}, ImageConfiguration {name='hsgmbh/kisserver2:latest', alias='kisserver'}]
[DEBUG]   (f) keepContainer = false
[DEBUG]   (f) keepRunning = false
[DEBUG]   (f) logDate = none
[DEBUG]   (f) logStdout = false
[DEBUG]   (f) maxConnections = 100
[DEBUG]   (f) removeVolumes = false
[DEBUG]   (f) session = org.apache.maven.execution.MavenSession@3a4b0e5d
[DEBUG]   (f) settings = org.apache.maven.execution.SettingsAdapter@40e37b06
[DEBUG]   (f) skip = false
[DEBUG]   (f) skipExtendedAuth = false
[DEBUG]   (f) skipMachine = false
[DEBUG]   (f) sledgeHammer = false
[DEBUG]   (f) useColor = true
[DEBUG]   (f) verbose = false
[DEBUG] -- end configuration --
[DEBUG] CookieSpec selected: default
[DEBUG] Auth cache not set in the context
[DEBUG] Connection request: [route: {}->unix://127.0.0.1:1][total kept alive: 0; route allocated: 0 of 100; total allocated: 0 of 20]
[DEBUG] Connection leased: [id: 1][route: {}->unix://127.0.0.1:1][total kept alive: 0; route allocated: 1 of 100; total allocated: 1 of 20]
[DEBUG] Opening connection {}->unix://127.0.0.1:1
[DEBUG] Connecting to 0.0.0.0/0.0.0.0:1
[DEBUG] Connection established [family=PF_UNIX path=??o]<->[family=PF_UNIX path=/var/run/docker.sock]
[DEBUG] Executing request GET /version HTTP/1.1
[DEBUG] Target auth state: UNCHALLENGED
[DEBUG] Proxy auth state: UNCHALLENGED
[DEBUG] http-outgoing-3 >> GET /version HTTP/1.1
[DEBUG] http-outgoing-3 >> Accept: */*
[DEBUG] http-outgoing-3 >> Content-Type: application/json; charset=utf-8
[DEBUG] http-outgoing-3 >> Host: 127.0.0.1:1
[DEBUG] http-outgoing-3 >> Connection: Keep-Alive
[DEBUG] http-outgoing-3 >> User-Agent: Apache-HttpClient/4.5.2 (Java/1.8.0_131)
[DEBUG] http-outgoing-3 >> Accept-Encoding: gzip,deflate
[DEBUG] http-outgoing-3 >> "GET /version HTTP/1.1[\r][\n]"
[DEBUG] http-outgoing-3 >> "Accept: */*[\r][\n]"
[DEBUG] http-outgoing-3 >> "Content-Type: application/json; charset=utf-8[\r][\n]"
[DEBUG] http-outgoing-3 >> "Host: 127.0.0.1:1[\r][\n]"
[DEBUG] http-outgoing-3 >> "Connection: Keep-Alive[\r][\n]"
[DEBUG] http-outgoing-3 >> "User-Agent: Apache-HttpClient/4.5.2 (Java/1.8.0_131)[\r][\n]"
[DEBUG] http-outgoing-3 >> "Accept-Encoding: gzip,deflate[\r][\n]"
[DEBUG] http-outgoing-3 >> "[\r][\n]"
[DEBUG] http-outgoing-3 << "HTTP/1.1 200 OK[\r][\n]"
[DEBUG] http-outgoing-3 << "Api-Version: 1.30[\r][\n]"
[DEBUG] http-outgoing-3 << "Content-Type: application/json[\r][\n]"
[DEBUG] http-outgoing-3 << "Docker-Experimental: false[\r][\n]"
[DEBUG] http-outgoing-3 << "Ostype: linux[\r][\n]"
[DEBUG] http-outgoing-3 << "Server: Docker/17.06.0-ce (linux)[\r][\n]"
[DEBUG] http-outgoing-3 << "Date: Mon, 24 Jul 2017 12:43:45 GMT[\r][\n]"
[DEBUG] http-outgoing-3 << "Content-Length: 225[\r][\n]"
[DEBUG] http-outgoing-3 << "[\r][\n]"
[DEBUG] http-outgoing-3 << "{"Version":"17.06.0-ce","ApiVersion":"1.30","MinAPIVersion":"1.12","GitCommit":"02c1d87","GoVersion":"go1.8.3","Os":"linux","Arch":"amd64","KernelVersion":"4.4.0-83-generic","BuildTime":"2017-06-23T21:19:04.990631145+00:00"}[\n]"
[DEBUG] http-outgoing-3 << HTTP/1.1 200 OK
[DEBUG] http-outgoing-3 << Api-Version: 1.30
[DEBUG] http-outgoing-3 << Content-Type: application/json
[DEBUG] http-outgoing-3 << Docker-Experimental: false
[DEBUG] http-outgoing-3 << Ostype: linux
[DEBUG] http-outgoing-3 << Server: Docker/17.06.0-ce (linux)
[DEBUG] http-outgoing-3 << Date: Mon, 24 Jul 2017 12:43:45 GMT
[DEBUG] http-outgoing-3 << Content-Length: 225
[DEBUG] Connection can be kept alive indefinitely
[DEBUG] Connection [id: 1][route: {}->unix://127.0.0.1:1] can be kept alive indefinitely
[DEBUG] Connection released: [id: 1][route: {}->unix://127.0.0.1:1][total kept alive: 1; route allocated: 1 of 100; total allocated: 1 of 20]
[DEBUG] DOCKER> shutdown will wait max of 0 seconds before removing container
[DEBUG] CookieSpec selected: default
[DEBUG] Auth cache not set in the context
[DEBUG] Connection request: [route: {}->unix://127.0.0.1:1][total kept alive: 1; route allocated: 1 of 100; total allocated: 1 of 20]
[DEBUG] Connection leased: [id: 1][route: {}->unix://127.0.0.1:1][total kept alive: 0; route allocated: 1 of 100; total allocated: 1 of 20]
[DEBUG] Executing request POST /v1.18/containers/80d9ceaa4f3b/stop HTTP/1.1
[DEBUG] Target auth state: UNCHALLENGED
[DEBUG] Proxy auth state: UNCHALLENGED
#
# container B is stopped
#
[DEBUG] http-outgoing-3 >> POST /v1.18/containers/80d9ceaa4f3b/stop HTTP/1.1
[DEBUG] http-outgoing-3 >> Accept: */*
[DEBUG] http-outgoing-3 >> Content-Type: application/json; charset=utf-8
[DEBUG] http-outgoing-3 >> Content-Length: 0
[DEBUG] http-outgoing-3 >> Host: 127.0.0.1:1
[DEBUG] http-outgoing-3 >> Connection: Keep-Alive
[DEBUG] http-outgoing-3 >> User-Agent: Apache-HttpClient/4.5.2 (Java/1.8.0_131)
[DEBUG] http-outgoing-3 >> Accept-Encoding: gzip,deflate
[DEBUG] http-outgoing-3 >> "POST /v1.18/containers/80d9ceaa4f3b/stop HTTP/1.1[\r][\n]"
[DEBUG] http-outgoing-3 >> "Accept: */*[\r][\n]"
[DEBUG] http-outgoing-3 >> "Content-Type: application/json; charset=utf-8[\r][\n]"
[DEBUG] http-outgoing-3 >> "Content-Length: 0[\r][\n]"
[DEBUG] http-outgoing-3 >> "Host: 127.0.0.1:1[\r][\n]"
[DEBUG] http-outgoing-3 >> "Connection: Keep-Alive[\r][\n]"
[DEBUG] http-outgoing-3 >> "User-Agent: Apache-HttpClient/4.5.2 (Java/1.8.0_131)[\r][\n]"
[DEBUG] http-outgoing-3 >> "Accept-Encoding: gzip,deflate[\r][\n]"
[DEBUG] http-outgoing-3 >> "[\r][\n]"
[DEBUG] http-outgoing-3 << "HTTP/1.1 204 No Content[\r][\n]"
[DEBUG] http-outgoing-3 << "Api-Version: 1.30[\r][\n]"
[DEBUG] http-outgoing-3 << "Docker-Experimental: false[\r][\n]"
[DEBUG] http-outgoing-3 << "Ostype: linux[\r][\n]"
[DEBUG] http-outgoing-3 << "Server: Docker/17.06.0-ce (linux)[\r][\n]"
[DEBUG] http-outgoing-3 << "Date: Mon, 24 Jul 2017 12:43:45 GMT[\r][\n]"
[DEBUG] http-outgoing-3 << "[\r][\n]"
#
# the response for the stop request arrives on the expected connection.
#
[DEBUG] http-outgoing-3 << HTTP/1.1 204 No Content
[DEBUG] http-outgoing-3 << Api-Version: 1.30
[DEBUG] http-outgoing-3 << Docker-Experimental: false
[DEBUG] http-outgoing-3 << Ostype: linux
[DEBUG] http-outgoing-3 << Server: Docker/17.06.0-ce (linux)
[DEBUG] http-outgoing-3 << Date: Mon, 24 Jul 2017 12:43:45 GMT
[DEBUG] Connection can be kept alive indefinitely
[DEBUG] Connection [id: 1][route: {}->unix://127.0.0.1:1] can be kept alive indefinitely
[DEBUG] Connection released: [id: 1][route: {}->unix://127.0.0.1:1][total kept alive: 1; route allocated: 1 of 100; total allocated: 1 of 20]
[DEBUG] CookieSpec selected: default
[DEBUG] Auth cache not set in the context
[DEBUG] Connection request: [route: {}->unix://127.0.0.1:1][total kept alive: 1; route allocated: 1 of 100; total allocated: 1 of 20]
[DEBUG] Connection leased: [id: 1][route: {}->unix://127.0.0.1:1][total kept alive: 0; route allocated: 1 of 100; total allocated: 1 of 20]
[DEBUG] Executing request DELETE /v1.18/containers/80d9ceaa4f3b?v=0 HTTP/1.1
[DEBUG] Target auth state: UNCHALLENGED
[DEBUG] Proxy auth state: UNCHALLENGED
#
# A delete request for B is sent, as expected.
#
[DEBUG] http-outgoing-3 >> DELETE /v1.18/containers/80d9ceaa4f3b?v=0 HTTP/1.1
[DEBUG] http-outgoing-3 >> Accept: */*
[DEBUG] http-outgoing-3 >> Content-Type: application/json; charset=utf-8
[DEBUG] http-outgoing-3 >> Host: 127.0.0.1:1
[DEBUG] http-outgoing-3 >> Connection: Keep-Alive
[DEBUG] http-outgoing-3 >> User-Agent: Apache-HttpClient/4.5.2 (Java/1.8.0_131)
[DEBUG] http-outgoing-3 >> Accept-Encoding: gzip,deflate
[DEBUG] http-outgoing-3 >> "DELETE /v1.18/containers/80d9ceaa4f3b?v=0 HTTP/1.1[\r][\n]"
[DEBUG] http-outgoing-3 >> "Accept: */*[\r][\n]"
[DEBUG] http-outgoing-3 >> "Content-Type: application/json; charset=utf-8[\r][\n]"
[DEBUG] http-outgoing-3 >> "Host: 127.0.0.1:1[\r][\n]"
[DEBUG] http-outgoing-3 >> "Connection: Keep-Alive[\r][\n]"
[DEBUG] http-outgoing-3 >> "User-Agent: Apache-HttpClient/4.5.2 (Java/1.8.0_131)[\r][\n]"
[DEBUG] http-outgoing-3 >> "Accept-Encoding: gzip,deflate[\r][\n]"
[DEBUG] http-outgoing-3 >> "[\r][\n]"
[DEBUG] http-outgoing-3 << "HTTP/1.1 204 No Content[\r][\n]"
[DEBUG] http-outgoing-3 << "Api-Version: 1.30[\r][\n]"
[DEBUG] http-outgoing-3 << "Docker-Experimental: false[\r][\n]"
[DEBUG] http-outgoing-3 << "Ostype: linux[\r][\n]"
[DEBUG] http-outgoing-3 << "Server: Docker/17.06.0-ce (linux)[\r][\n]"
[DEBUG] http-outgoing-3 << "Date: Mon, 24 Jul 2017 12:43:45 GMT[\r][\n]"
[DEBUG] http-outgoing-3 << "[\r][\n]"
[DEBUG] http-outgoing-3 << HTTP/1.1 204 No Content
[DEBUG] http-outgoing-3 << Api-Version: 1.30
[DEBUG] http-outgoing-3 << Docker-Experimental: false
[DEBUG] http-outgoing-3 << Ostype: linux
[DEBUG] http-outgoing-3 << Server: Docker/17.06.0-ce (linux)
[DEBUG] http-outgoing-3 << Date: Mon, 24 Jul 2017 12:43:45 GMT
[DEBUG] Connection can be kept alive indefinitely
[DEBUG] Connection [id: 1][route: {}->unix://127.0.0.1:1] can be kept alive indefinitely
[DEBUG] Connection released: [id: 1][route: {}->unix://127.0.0.1:1][total kept alive: 1; route allocated: 1 of 100; total allocated: 1 of 20]
[INFO] DOCKER> [hsgmbh/kisserver2:latest] "kisserver": Stop and removed container 80d9ceaa4f3b after 0 ms
[DEBUG] DOCKER> shutdown will wait max of 0 seconds before removing container
[DEBUG] CookieSpec selected: default
[DEBUG] Auth cache not set in the context
[DEBUG] Connection request: [route: {}->unix://127.0.0.1:1][total kept alive: 1; route allocated: 1 of 100; total allocated: 1 of 20]
[DEBUG] Connection leased: [id: 1][route: {}->unix://127.0.0.1:1][total kept alive: 0; route allocated: 1 of 100; total allocated: 1 of 20]
[DEBUG] Executing request POST /v1.18/containers/226d222c62c9/stop HTTP/1.1
[DEBUG] Target auth state: UNCHALLENGED
[DEBUG] Proxy auth state: UNCHALLENGED
#
# container A is stopped
#
[DEBUG] http-outgoing-3 >> POST /v1.18/containers/226d222c62c9/stop HTTP/1.1
[DEBUG] http-outgoing-3 >> Accept: */*
[DEBUG] http-outgoing-3 >> Content-Type: application/json; charset=utf-8
[DEBUG] http-outgoing-3 >> Content-Length: 0
[DEBUG] http-outgoing-3 >> Host: 127.0.0.1:1
[DEBUG] http-outgoing-3 >> Connection: Keep-Alive
[DEBUG] http-outgoing-3 >> User-Agent: Apache-HttpClient/4.5.2 (Java/1.8.0_131)
[DEBUG] http-outgoing-3 >> Accept-Encoding: gzip,deflate
[DEBUG] http-outgoing-3 >> "POST /v1.18/containers/226d222c62c9/stop HTTP/1.1[\r][\n]"
[DEBUG] http-outgoing-3 >> "Accept: */*[\r][\n]"
[DEBUG] http-outgoing-3 >> "Content-Type: application/json; charset=utf-8[\r][\n]"
[DEBUG] http-outgoing-3 >> "Content-Length: 0[\r][\n]"
[DEBUG] http-outgoing-3 >> "Host: 127.0.0.1:1[\r][\n]"
[DEBUG] http-outgoing-3 >> "Connection: Keep-Alive[\r][\n]"
[DEBUG] http-outgoing-3 >> "User-Agent: Apache-HttpClient/4.5.2 (Java/1.8.0_131)[\r][\n]"
[DEBUG] http-outgoing-3 >> "Accept-Encoding: gzip,deflate[\r][\n]"
[DEBUG] http-outgoing-3 >> "[\r][\n]"
#
# container A sends log output on http-outgoing-1 (the connection used during the start goal),
# which was already shut down in the start goal!
#
[DEBUG] http-outgoing-1 << "45[\r][\n]"
[DEBUG] http-outgoing-1 << "[0x2][0x0][0x0][0x0][0x0][0x0][0x0]=2017-07-24T12:43:46.182453151Z caught SIGTERM, shutting down[\n]"
[DEBUG] http-outgoing-1 << "[\r][\n]"
#
# This is the response for the stop request. It should come in on http-outgoing-3,
# but is also received on the already shut down http-outgoing-1.
#
[DEBUG] http-outgoing-1 << "HTTP/1.1 204 No Content[\r][\n]"
[DEBUG] http-outgoing-1 << "Api-Version: 1.30[\r][\n]"
[DEBUG] http-outgoing-1 << "Docker-Experimental: false[\r][\n]"
[DEBUG] http-outgoing-1 << "Ostype: linux[\r][\n]"
[DEBUG] http-outgoing-1 << "Server: Docker/17.06.0-ce (linux)[\r][\n]"
[DEBUG] http-outgoing-1 << "Date: Mon, 24 Jul 2017 12:43:46 GMT[\r][\n]"
[DEBUG] http-outgoing-1 << "[\r][\n]"
[DEBUG] DOCKER> Closing LogWaitChecker callback
#
# no DELETE request is sent.
#
docker info 
Containers: 13
 Running: 3
 Paused: 0
 Stopped: 10
Images: 238
Server Version: 17.06.0-ce
Storage Driver: aufs
 Root Dir: /var/lib/docker/aufs
 Backing Filesystem: extfs
 Dirs: 186
 Dirperm1 Supported: true
Logging Driver: json-file
Cgroup Driver: cgroupfs
Plugins:
 Volume: local
 Network: bridge host macvlan null overlay
 Log: awslogs fluentd gcplogs gelf journald json-file logentries splunk syslog
Swarm: active
 NodeID: iy2u091keal36syj2zngygjrs
 Is Manager: true
 ClusterID: mvfp3wt4xi2let3rttiy1n0xw
 Managers: 1
 Nodes: 1
 Orchestration:
  Task History Retention Limit: 5
 Raft:
  Snapshot Interval: 10000
  Number of Old Snapshots to Retain: 0
  Heartbeat Tick: 1
  Election Tick: 3
 Dispatcher:
  Heartbeat Period: 5 seconds
 CA Configuration:
  Expiry Duration: 3 months
  Force Rotate: 0
 Root Rotation In Progress: false
 Node Address: 10.0.1.51
 Manager Addresses:
  10.0.1.51:2377
Runtimes: runc
Default Runtime: runc
Init Binary: docker-init
containerd version: cfb82a876ecc11b5ca0977d1733adbe58599088a
runc version: 2d41c047c83e09a6d61d464906feb2a2f3c52aa4
init version: 949e6fa
Security Options:
 apparmor
 seccomp
  Profile: default
Kernel Version: 4.4.0-83-generic
Operating System: Ubuntu 16.04.2 LTS
OSType: linux
Architecture: x86_64
CPUs: 6
Total Memory: 3.855GiB
Name: docker4
ID: BHDU:YEDX:7NMN:QIHK:PFXZ:MWOX:5WZF:FZTK:3RDE:GAEY:U7L2:NP72
Docker Root Dir: /var/lib/docker
Debug Mode (client): false
Debug Mode (server): true
 File Descriptors: 58
 Goroutines: 176
 System Time: 2017-07-24T16:58:39.902483953+02:00
 EventsListeners: 2
Registry: https://index.docker.io/v1/
Experimental: false
Insecure Registries:
 127.0.0.0/8
Live Restore Enabled: false

WARNING: No swap limit support
Maven version 
Apache Maven 3.5.0 (ff8f5e7444045639af65f6095c62210b5713f426; 2017-04-03T21:39:06+02:00)
Maven home: /usr/share/apache-maven-3.5.0
Java version: 1.8.0_131, vendor: Oracle Corporation
Java home: /usr/lib/jvm/java-8-openjdk-amd64/jre
Default locale: de_DE, platform encoding: UTF-8
OS name: "linux", version: "4.4.0-83-generic", arch: "amd64", family: "unix"
koscejev commented 7 years ago

@albers in our case autokill after 10 minutes is done by our CI server - it's not something that this plugin does.

As a workaround we had to switch to HTTP communication, which has no issues.

albers commented 7 years ago

Thanks, @koscejev. Yes, switching back to HTTP is possible but not a good option for me. I'm just transitioning to a build infrastructure that bases its build agents on https://hub.docker.com/_/docker/ so that the agents have direct access to the host's Docker socket. The whole point of this is that I don't want to open the HTTP port on the Docker hosts any more, and I want to avoid dealing with certs.

albers commented 7 years ago

@jgangemi also mentions this issue in https://github.com/fabric8io/docker-maven-plugin/pull/672#issuecomment-269244302

albers commented 7 years ago

This might be a Docker issue. I checked against older versions of Docker: 17.06.0, 17.04.0, 1.13.1 and 1.13.0 all had the issue. But I could not reproduce it on Docker 1.12.6. (This might still be incidental because in my setup, the stop command occasionally succeeds). All tests were performed on the same Ubuntu 16.04.2 LTS box running in VMware Workstation 8.0.6

@koscejev Can you please verify whether your issue exists against Docker 1.12.6 (and maybe 1.13.0)?

koscejev commented 7 years ago

@albers I cannot change docker version on our CI, and I'm working on Windows. But a colleague of mine has been helping with investigation of this issue as he's on Ubuntu. He said he could still reproduce the issue on Docker 1.12.6. From our previous investigation it appears that the issue could be related to a bunch of other things, such as chosen storage for Docker (see original report). Could it be that your storage setting was changed when you downgraded Docker?

albers commented 7 years ago

Thanks @koscejev for investigating. I used aufs with ext4, see docker info for the relevant versions.

1.12.6 (working) 
Containers: 0
 Running: 0
 Paused: 0
 Stopped: 0
Images: 2
Server Version: 1.12.6
Storage Driver: aufs
 Root Dir: /var/lib/docker/aufs
 Backing Filesystem: extfs
 Dirs: 22
 Dirperm1 Supported: true
Logging Driver: json-file
Cgroup Driver: cgroupfs
Plugins:
 Volume: local
 Network: null bridge host overlay
Swarm: inactive
Runtimes: runc
Default Runtime: runc
Security Options: apparmor seccomp
Kernel Version: 4.4.0-87-generic
Operating System: Ubuntu 16.04.2 LTS
OSType: linux
Architecture: x86_64
CPUs: 6
Total Memory: 3.855 GiB
Name: docker4
ID: BHDU:YEDX:7NMN:QIHK:PFXZ:MWOX:5WZF:FZTK:3RDE:GAEY:U7L2:NP72
Docker Root Dir: /var/lib/docker
Debug Mode (client): false
Debug Mode (server): false
Registry: https://index.docker.io/v1/
WARNING: No swap limit support
Insecure Registries:
 127.0.0.0/8
1.13.0 (blocking) 
Containers: 0
 Running: 0
 Paused: 0
 Stopped: 0
Images: 2
Server Version: 1.13.0
Storage Driver: aufs
 Root Dir: /var/lib/docker/aufs
 Backing Filesystem: extfs
 Dirs: 22
 Dirperm1 Supported: true
Logging Driver: json-file
Cgroup Driver: cgroupfs
Plugins:
 Volume: local
 Network: bridge host macvlan null overlay
Swarm: inactive
Runtimes: runc
Default Runtime: runc
Init Binary: docker-init
containerd version: 03e5862ec0d8d3b3f750e19fca3ee367e13c090e
runc version: 2f7393a47307a16f8cee44a37b262e8b81021e3e
init version: 949e6fa
Security Options:
 apparmor
 seccomp
  Profile: default
Kernel Version: 4.4.0-87-generic
Operating System: Ubuntu 16.04.2 LTS
OSType: linux
Architecture: x86_64
CPUs: 6
Total Memory: 3.855 GiB
Name: docker4
ID: BHDU:YEDX:7NMN:QIHK:PFXZ:MWOX:5WZF:FZTK:3RDE:GAEY:U7L2:NP72
Docker Root Dir: /var/lib/docker
Debug Mode (client): false
Debug Mode (server): false
Registry: https://index.docker.io/v1/
WARNING: No swap limit support
Experimental: false
Insecure Registries:
 127.0.0.0/8
Live Restore Enabled: false
17.06.0-ce (blocking) 
Containers: 0
 Running: 0
 Paused: 0
 Stopped: 0
Images: 224
Server Version: 17.06.0-ce
Storage Driver: aufs
 Root Dir: /var/lib/docker/aufs
 Backing Filesystem: extfs
 Dirs: 112
 Dirperm1 Supported: true
Logging Driver: json-file
Cgroup Driver: cgroupfs
Plugins:
 Volume: local
 Network: bridge host macvlan null overlay
 Log: awslogs fluentd gcplogs gelf journald json-file logentries splunk syslog
Swarm: inactive
Runtimes: runc
Default Runtime: runc
Init Binary: docker-init
containerd version: cfb82a876ecc11b5ca0977d1733adbe58599088a
runc version: 2d41c047c83e09a6d61d464906feb2a2f3c52aa4
init version: 949e6fa
Security Options:
 apparmor
 seccomp
  Profile: default
Kernel Version: 4.4.0-87-generic
Operating System: Ubuntu 16.04.2 LTS
OSType: linux
Architecture: x86_64
CPUs: 8
Total Memory: 5.824GiB
Name: docker4
ID: BHDU:YEDX:7NMN:QIHK:PFXZ:MWOX:5WZF:FZTK:3RDE:GAEY:U7L2:NP72
Docker Root Dir: /var/lib/docker
Debug Mode (client): false
Debug Mode (server): false
Registry: https://index.docker.io/v1/
Experimental: false
Insecure Registries:
 127.0.0.0/8
Live Restore Enabled: false