docker-maven-plugin hangs when waiting for log

Created on 31 May 2017 · 25Comments · Source: fabric8io/docker-maven-plugin

I configured mysql image to wait for log with a timeout. It was able to match the pattern from the log. However it got stuck cleaning up the connection afterwards.

Everything works if I remove the log wait.

d-m-p version : 0.21.0
Maven version: 3.3.9
Docker version : 17.03.1-ce-win12 (12058)

Pom:

                                <image>
                                    <name>mysql/mysql-server:5.7</name>

                                        <wait>
                                            <log>MySQL init process done. Ready for start up.</log>
                                            <time>60000</time>
                                        </wait>
                                    </run>
                                </image>

Maven log:

[DEBUG] Releasing connection 
[DEBUG] Connection can be kept alive indefinitely
[DEBUG] Cancelling request execution
[DEBUG] http-outgoing-4: Shutdown connection

Thread dump:

"main" #1 prio=5 os_prio=0 tid=0x000000000332e800 nid=0x26cc in Object.wait() [0x000000000315d000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    at sun.nio.ch.NativeThreadSet.signalAndWait(NativeThreadSet.java:101)
    - locked <0x000000076f1f1c50> (a sun.nio.ch.NativeThreadSet)
    at sun.nio.ch.FileChannelImpl.implCloseChannel(FileChannelImpl.java:130)
    at java.nio.channels.spi.AbstractInterruptibleChannel.close(AbstractInterruptibleChannel.java:115)
    - locked <0x000000076f1f1c40> (a java.lang.Object)
    at io.fabric8.maven.docker.access.hc.win.NamedPipe.close(NamedPipe.java:255)
    at org.apache.http.impl.BHttpConnectionBase.shutdown(BHttpConnectionBase.java:311)
    at org.apache.http.impl.conn.DefaultManagedHttpClientConnection.shutdown(DefaultManagedHttpClientConnection.java:97)
    at org.apache.http.impl.conn.LoggingManagedHttpClientConnection.shutdown(LoggingManagedHttpClientConnection.java:100)
    at org.apache.http.impl.execchain.ConnectionHolder.abortConnection(ConnectionHolder.java:127)
    - locked <0x000000076f1ea858> (a org.apache.http.impl.conn.LoggingManagedHttpClientConnection)
    at org.apache.http.impl.execchain.ConnectionHolder.cancel(ConnectionHolder.java:145)
    at org.apache.http.client.methods.AbstractExecutionAwareRequest.abort(AbstractExecutionAwareRequest.java:90)
    at io.fabric8.maven.docker.access.log.LogRequestor.finish(LogRequestor.java:228)
    - locked <0x000000076f0142d0> (a java.lang.Object)
    at io.fabric8.maven.docker.wait.LogWaitChecker.cleanUp(LogWaitChecker.java:49)
    at io.fabric8.maven.docker.wait.WaitUtil.cleanup(WaitUtil.java:80)
    at io.fabric8.maven.docker.wait.WaitUtil.wait(WaitUtil.java:64)
    at io.fabric8.maven.docker.service.WaitService.wait(WaitService.java:53)
    at io.fabric8.maven.docker.StartMojo$1.call(StartMojo.java:249)
    at io.fabric8.maven.docker.StartMojo$1.call(StartMojo.java:235)
    at com.google.common.util.concurrent.TrustedListenableFutureTask$TrustedFutureInterruptibleTask.runInterruptibly(TrustedListenableFutureTask.java:108)
    at com.google.common.util.concurrent.InterruptibleTask.run(InterruptibleTask.java:41)
    at com.google.common.util.concurrent.TrustedListenableFutureTask.run(TrustedListenableFutureTask.java:77)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at com.google.common.util.concurrent.MoreExecutors$DirectExecutorService.execute(MoreExecutors.java:310)
    at java.util.concurrent.ExecutorCompletionService.submit(ExecutorCompletionService.java:181)
    at io.fabric8.maven.docker.StartMojo.startImage(StartMojo.java:235)
    at io.fabric8.maven.docker.StartMojo.executeInternal(StartMojo.java:132)
    - locked <0x000000076e96f3b8> (a io.fabric8.maven.docker.StartMojo)
    at io.fabric8.maven.docker.AbstractDockerMojo.execute(AbstractDockerMojo.java:223)
    at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:134)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:207)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:153)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:145)
    at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:116)
    at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:80)
    at org.apache.maven.lifecycle.internal.builder.singlethreaded.SingleThreadedBuilder.build(SingleThreadedBuilder.java:51)
    at org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:128)
    at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:307)
    at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:193)
    at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:106)
    at org.apache.maven.cli.MavenCli.execute(MavenCli.java:863)
    at org.apache.maven.cli.MavenCli.doMain(MavenCli.java:288)
    at org.apache.maven.cli.MavenCli.main(MavenCli.java:199)
    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)
    at org.codehaus.classworlds.Launcher.main(Launcher.java:47)

Source

drycup

👍2

Most helpful comment

@rhuss I seem to be stuck with a similar problem under Windows, with dmp 0.27.2 and Oracle JDK 8.171 (works fine in a jenkins-slim Docker container with OpenJDK 8.181).

The behaviour is the following:

. DMP starts the container
. DMP finds the log ([INFO] DOCKER> Pattern '<my pattern>' matched for container 34100e85616e
. DMP just waits, not finishing...

Windows 10
Java: Oracle JDK 8.171
Maven 3.5.3
DMP 0.27.2

cyChop on 6 Nov 2018

👍4

All 25 comments

This seems to be a problem with Windows' NamedPipes. As I understand from the thread dump, the current thread is waiting on an object monitor which another thread holds. Could you check which thread this could be? I suspect it's our own lock we are using to synchronise logging handlers. (BTW, have you switched on log output during running the containers ?)

Unfortunately, I don't have access to a Windows box right now, it would be awesome if you could post the full thread dump.

rhuss on 1 Jun 2017

Thanks for your reply. I do suspect this is a Windows specific issue. The behavior is repeatable. I didn't change docker log setting when running the containers.

Here is the full thread dump.

Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.111-b14 mixed mode):

"Thread-1" #24 daemon prio=5 os_prio=0 tid=0x000000001fb52800 nid=0x2e04 runnable [0x000000002511e000]
   java.lang.Thread.State: RUNNABLE
    at sun.nio.ch.FileDispatcherImpl.read0(Native Method)
    at sun.nio.ch.FileDispatcherImpl.read(FileDispatcherImpl.java:61)
    at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)
    at sun.nio.ch.IOUtil.read(IOUtil.java:197)
    at sun.nio.ch.FileChannelImpl.read(FileChannelImpl.java:159)
    - locked <0x0000000786794c38> (a java.lang.Object)
    at sun.nio.ch.ChannelInputStream.read(ChannelInputStream.java:65)
    at sun.nio.ch.ChannelInputStream.read(ChannelInputStream.java:109)
    at sun.nio.ch.ChannelInputStream.read(ChannelInputStream.java:103)
    - locked <0x0000000786795d48> (a sun.nio.ch.ChannelInputStream)
    at java.io.FilterInputStream.read(FilterInputStream.java:133)
    at io.fabric8.maven.docker.access.hc.win.NamedPipe$1.read(NamedPipe.java:118)
    at org.apache.http.impl.conn.LoggingInputStream.read(LoggingInputStream.java:87)
    at org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:139)
    at org.apache.http.impl.io.SessionInputBufferImpl.fillBuffer(SessionInputBufferImpl.java:155)
    at org.apache.http.impl.io.SessionInputBufferImpl.readLine(SessionInputBufferImpl.java:284)
    at org.apache.http.impl.io.ChunkedInputStream.getChunkSize(ChunkedInputStream.java:266)
    at org.apache.http.impl.io.ChunkedInputStream.nextChunk(ChunkedInputStream.java:227)
    at org.apache.http.impl.io.ChunkedInputStream.read(ChunkedInputStream.java:186)
    at org.apache.http.impl.io.ChunkedInputStream.read(ChunkedInputStream.java:215)
    at org.apache.http.impl.io.ChunkedInputStream.close(ChunkedInputStream.java:316)
    at org.apache.http.impl.execchain.ResponseEntityProxy.streamClosed(ResponseEntityProxy.java:140)
    at org.apache.http.conn.EofSensorInputStream.checkClose(EofSensorInputStream.java:228)
    at org.apache.http.conn.EofSensorInputStream.close(EofSensorInputStream.java:174)
    at io.fabric8.maven.docker.access.log.LogRequestor.parseResponse(LogRequestor.java:198)
    at io.fabric8.maven.docker.access.log.LogRequestor.run(LogRequestor.java:108)

"Service Thread" #10 daemon prio=9 os_prio=0 tid=0x000000001c3ce800 nid=0x358 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C1 CompilerThread2" #9 daemon prio=9 os_prio=2 tid=0x000000001c3b1000 nid=0xa84 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" #8 daemon prio=9 os_prio=2 tid=0x000000001c3ad000 nid=0x2954 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #7 daemon prio=9 os_prio=2 tid=0x000000001c3a9800 nid=0x19fc waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Monitor Ctrl-Break" #6 daemon prio=5 os_prio=0 tid=0x000000001da13000 nid=0x3fc runnable [0x000000001dece000]
   java.lang.Thread.State: RUNNABLE
    at java.net.SocketInputStream.socketRead0(Native Method)
    at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
    at java.net.SocketInputStream.read(SocketInputStream.java:170)
    at java.net.SocketInputStream.read(SocketInputStream.java:141)
    at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:284)
    at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:326)
    at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:178)
    - locked <0x00000006c213e8b8> (a java.io.InputStreamReader)
    at java.io.InputStreamReader.read(InputStreamReader.java:184)
    at java.io.BufferedReader.fill(BufferedReader.java:161)
    at java.io.BufferedReader.readLine(BufferedReader.java:324)
    - locked <0x00000006c213e8b8> (a java.io.InputStreamReader)
    at java.io.BufferedReader.readLine(BufferedReader.java:389)
    at com.intellij.rt.execution.application.AppMainV2$1.run(AppMainV2.java:64)

"Attach Listener" #5 daemon prio=5 os_prio=2 tid=0x000000001c36e000 nid=0xbd8 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" #4 daemon prio=9 os_prio=2 tid=0x000000001c36d000 nid=0x2ad4 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" #3 daemon prio=8 os_prio=1 tid=0x0000000002d35800 nid=0x1970 in Object.wait() [0x000000001d6df000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000006c213e920> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
    - locked <0x00000006c213e920> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164)
    at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)

"Reference Handler" #2 daemon prio=10 os_prio=2 tid=0x0000000002d30000 nid=0x5c0 in Object.wait() [0x000000001d5df000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000006c213e978> (a java.lang.ref.Reference$Lock)
    at java.lang.Object.wait(Object.java:502)
    at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
    - locked <0x00000006c213e978> (a java.lang.ref.Reference$Lock)
    at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)

"main" #1 prio=5 os_prio=0 tid=0x00000000029ce000 nid=0x14b4 in Object.wait() [0x0000000002aed000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x0000000786794c00> (a sun.nio.ch.NativeThreadSet)
    at sun.nio.ch.NativeThreadSet.signalAndWait(NativeThreadSet.java:101)
    - locked <0x0000000786794c00> (a sun.nio.ch.NativeThreadSet)
    at sun.nio.ch.FileChannelImpl.implCloseChannel(FileChannelImpl.java:130)
    at java.nio.channels.spi.AbstractInterruptibleChannel.close(AbstractInterruptibleChannel.java:115)
    - locked <0x0000000786794bf0> (a java.lang.Object)
    at io.fabric8.maven.docker.access.hc.win.NamedPipe.close(NamedPipe.java:255)
    at org.apache.http.impl.BHttpConnectionBase.shutdown(BHttpConnectionBase.java:311)
    at org.apache.http.impl.conn.DefaultManagedHttpClientConnection.shutdown(DefaultManagedHttpClientConnection.java:97)
    at org.apache.http.impl.conn.LoggingManagedHttpClientConnection.shutdown(LoggingManagedHttpClientConnection.java:100)
    at org.apache.http.impl.execchain.ConnectionHolder.abortConnection(ConnectionHolder.java:127)
    - locked <0x000000078678d808> (a org.apache.http.impl.conn.LoggingManagedHttpClientConnection)
    at org.apache.http.impl.execchain.ConnectionHolder.cancel(ConnectionHolder.java:145)
    at org.apache.http.client.methods.AbstractExecutionAwareRequest.abort(AbstractExecutionAwareRequest.java:90)
    at io.fabric8.maven.docker.access.log.LogRequestor.finish(LogRequestor.java:228)
    - locked <0x0000000786510050> (a java.lang.Object)
    at io.fabric8.maven.docker.wait.LogWaitChecker.cleanUp(LogWaitChecker.java:49)
    at io.fabric8.maven.docker.wait.WaitUtil.cleanup(WaitUtil.java:80)
    at io.fabric8.maven.docker.wait.WaitUtil.wait(WaitUtil.java:64)
    at io.fabric8.maven.docker.service.WaitService.wait(WaitService.java:53)
    at io.fabric8.maven.docker.StartMojo$1.call(StartMojo.java:249)
    at io.fabric8.maven.docker.StartMojo$1.call(StartMojo.java:235)
    at com.google.common.util.concurrent.TrustedListenableFutureTask$TrustedFutureInterruptibleTask.runInterruptibly(TrustedListenableFutureTask.java:108)
    at com.google.common.util.concurrent.InterruptibleTask.run(InterruptibleTask.java:41)
    at com.google.common.util.concurrent.TrustedListenableFutureTask.run(TrustedListenableFutureTask.java:77)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at com.google.common.util.concurrent.MoreExecutors$DirectExecutorService.execute(MoreExecutors.java:310)
    at java.util.concurrent.ExecutorCompletionService.submit(ExecutorCompletionService.java:181)
    at io.fabric8.maven.docker.StartMojo.startImage(StartMojo.java:235)
    at io.fabric8.maven.docker.StartMojo.executeInternal(StartMojo.java:132)
    - locked <0x0000000785e9b658> (a io.fabric8.maven.docker.StartMojo)
    at io.fabric8.maven.docker.AbstractDockerMojo.execute(AbstractDockerMojo.java:223)
    at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:134)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:207)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:153)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:145)
    at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:116)
    at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:80)
    at org.apache.maven.lifecycle.internal.builder.singlethreaded.SingleThreadedBuilder.build(SingleThreadedBuilder.java:51)
    at org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:128)
    at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:307)
    at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:193)
    at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:106)
    at org.apache.maven.cli.MavenCli.execute(MavenCli.java:863)
    at org.apache.maven.cli.MavenCli.doMain(MavenCli.java:288)
    at org.apache.maven.cli.MavenCli.main(MavenCli.java:199)
    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)
    at org.codehaus.classworlds.Launcher.main(Launcher.java:47)

"VM Thread" os_prio=2 tid=0x000000001c338000 nid=0x2254 runnable 

"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x0000000002c57000 nid=0xd98 runnable 

"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x0000000002c59000 nid=0x1f28 runnable 

"GC task thread#2 (ParallelGC)" os_prio=0 tid=0x0000000002c5a800 nid=0x5c4 runnable 

"GC task thread#3 (ParallelGC)" os_prio=0 tid=0x0000000002c5c000 nid=0x250c runnable 

"VM Periodic Task Thread" os_prio=2 tid=0x000000001daa8000 nid=0x2ddc waiting on condition 

JNI global references: 84

drycup on 1 Jun 2017

Thanks !

"main" #1 prio=5 os_prio=0 tid=0x00000000029ce000 nid=0x14b4 in Object.wait() [0x0000000002aed000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)

waiting on <0x0000000786794c00> (a sun.nio.ch.NativeThreadSet)
at sun.nio.ch.NativeThreadSet.signalAndWait(NativeThreadSet.java:101)

locked <0x0000000786794c00> (a sun.nio.ch.NativeThreadSet)
at sun.nio.ch.FileChannelImpl.implCloseChannel(FileChannelImpl.java:130)

This puzzles me quite a bit since it first locks on 786794c00 and then waits on its own lock later on ???

rhuss on 1 Jun 2017

@drycup Which version of the JDK are you running?

pvorb on 1 Jun 2017

There's a related bug in OpenJDK (JDK-8024833). Probably an upgrade to jdk-8u131 will help.

pvorb on 1 Jun 2017

Hi @pvorb . I was running 1.8.0_111. Unfortunately switching to 1.8.0_131 didn't help.

drycup on 2 Jun 2017

What a bummer.

pvorb on 2 Jun 2017

@drycup we have the same problem. I expected the log to only work on the because that's where it's defined but it somehow also runs on stop and therefore it hangs.

We solved it updating our log regex to
<log>port: 3306|Shutdown complete</log>

tbilou on 4 Oct 2017

I have the same problem using OSX and java version "1.8.0_162"
On our CI-servers with version 1.8.0_131 there is no problem.

Rokko11 on 27 Apr 2018

👍1

@Rokko11 which version of d-m-p are you using ? There has been some tuning in the latest releases ...

rhuss on 27 Apr 2018

@rhuss I seem to be stuck with a similar problem under Windows, with dmp 0.27.2 and Oracle JDK 8.171 (works fine in a jenkins-slim Docker container with OpenJDK 8.181).

The behaviour is the following:

. DMP starts the container
. DMP finds the log ([INFO] DOCKER> Pattern '<my pattern>' matched for container 34100e85616e
. DMP just waits, not finishing...

Windows 10
Java: Oracle JDK 8.171
Maven 3.5.3
DMP 0.27.2

cyChop on 6 Nov 2018

👍4

Hi, try using 0.24.0 version.
Probably due to https://github.com/fabric8io/docker-maven-plugin/pull/904 being lost in further updates.

ebouvi01 on 15 Apr 2019

👎1 👍1

This part in the log handling has been changed due to https://github.com/fabric8io/docker-maven-plugin/pull/965 which adresses possibly other regression. At the moment, I'm not sure where we stand with this issue.

rhuss on 16 Apr 2019

I have run into this issue today on version 0.30.0.
I went back to 0.24.0 as suggested above and it seemed to work.

That said, it is intermittent. Sometimes it works as expected on a project, but with the same config in a different project, it doesn't. Never see the problem on linux.

Also, I don't know if this is relevant, but I get different results based on the value specified in the time element(!)

Windows 10, Maven 3.5.3, Oracle JDK 1.8.0_162

phil-nicholls on 24 Apr 2019

I also ran into this on version 0.30.0 on Windows. This is a rather serious problem, any chance it can be addressed soon? Or is there a workaround?

LeeBreisacher on 10 Aug 2019

We have the same problem.

only happens on Windows, Linux is fine
d-m-p at least 0.27.2 and 0.31.0 broken
d-m-p 0.24.0 is working

config snippet:

                        <image>
                            <name
                            <run>

                                <wait>
                                    <log>started successfully</log>
                                    <time>30000</time>
                                </wait>
                            </run>
                        </image>

It even recognizes the pattern but hangs. Removing log and only using time works.
log, hangs at that line:

[INFO] --- docker-maven-plugin:0.31.0:start (setup-it-dependencies) @ service ---
[INFO] DOCKER> [service-image] "service": Start container 4a9e2d814dbf
[INFO] DOCKER> Pattern 'started successfully' matched for container 4a9e2d814dbf

Madanor on 3 Dec 2019

👍3

I dug through the stack trace provided and the related code. It looks like the issue is related to handling of the file channel. Details follow...

The "main" thread is doing this:

at java.lang.Object.wait(Native Method)
- waiting on <0x0000000786794c00> (a sun.nio.ch.NativeThreadSet)
at sun.nio.ch.NativeThreadSet.signalAndWait(NativeThreadSet.java:101)
- locked <0x0000000786794c00> (a sun.nio.ch.NativeThreadSet)
at sun.nio.ch.FileChannelImpl.implCloseChannel(FileChannelImpl.java:130)

Looking at the code for NativeThreadSet.signalAndWait, it appears this is waiting until all threads are removed from its set (see the NativeThreadSet snippet below).
Looking at the code for FileChannelImpl, it appears the thread set is being used to track all uses of the file channel (see the FileChannelImpl.java snippet below).
Calls to FileChannelImpl's read(...) and write(...) methods (and others) call threads.add() and threads.remove()
Thread "Thread-1" is calling sun.nio.ch.FileChannelImpl.read(FileChannelImpl.java:159), therefore holding a place in the thread set. This traces back to
io.fabric8.maven.docker.access.hc.win.NamedPipe$1.read(NamedPipe.java:118)
Thread "main" is calling NativeThreadSet.signalAndWait(NativeThreadSet.java:101). This traces back to
io.fabric8.maven.docker.access.log.LogRequestor.finish(LogRequestor.java:228)

So - given all of this, I believe the attempt to close the named pipe in LogRequestor.finish() needs to make sure that all other threads listening to the same log
are terminated, or it needs to not attempt to close the named pipe. I haven't taken the time to dig through that code, so the solution is unclear. What does seem
clear based on this - it is not a JDK bug.

NativeThreadSet.java snippet (https://github.com/frohoff/jdk8u-jdk/blob/master/src/share/classes/sun/nio/ch/NativeThreadSet.java)

    synchronized void signalAndWait() {
        boolean interrupted = false;
        while (used > 0) {
            int u = used;
            int n = elts.length;
            for (int i = 0; i < n; i++) {
                long th = elts[i];
                if (th == 0)
                    continue;
                if (th != -1)
                    NativeThread.signal(th);
                if (--u == 0)
                    break;
            }
            waitingToEmpty = true;
            try {
                wait(50);                             //// <<<< this is line 101
            } catch (InterruptedException e) {
                interrupted = true;
            } finally {
                waitingToEmpty = false;
            }
        }
        if (interrupted)
            Thread.currentThread().interrupt();
    }

FileChannelImpl.java snippet ()

        // signal any threads blocked on this channel
        threads.signalAndWait();                      //// <<<< this is line 130

artnaseef on 5 Dec 2019

👍2

Testing with the TCP connection to the daemon shows good results. The TCP connection works without problem.

So, that is a viable work-around. For example, in power shell, $env:DOCKER_HOST=tcp://localhost:2375 may do the trick (assuming the daemon is listening on port 2375).

Would be great to see this fixed!

artnaseef on 9 Dec 2019

Thanks for you investigation ! I hope I have time to jump onto this evergreen issue over the x-mas break (but no promise :(

rhuss on 16 Dec 2019

👍2 👀1

Adding my 2c here - it'd be helpful if the wait time out applied to successful matches too. It seems to me that whatever goes wrong goes wrong after the time out timer has been killed/cleaned up/flagged. Fortunately in our case using healthy=true is a viable option. Worth noting that for some reason I'm pinned to 0.24.0 on Windows, but 0.31.0 on Mac/Linux - will ask my colleague about that when he's next available.

fredcooke on 19 Dec 2019

The tip that @artnaseef posted gave me some direction into a workaround, yet unfortunately setting the environment variable didn't do anything towards my Docker server. What did work is adding the following to the configuration of the docker-maven-plugin to my pom.xml:

<configuration>
    <dockerHost>tcp://localhost:2375</dockerHost>
</configuration>

Please do make sure that you enable the TCP daemon in the Docker for Windows settings.

ostecke on 12 Jan 2020

👍3

Tried 0.30 , 0.32 does not work, reverse to 0.24.0 and still hang.

af6140 on 28 Jun 2020

@ostecke's workaround works well but as this is an environmental issue I'd suggest putting it in an automatically activated profile in the settings.xml file so that you don't have to modify project pom.xml files:

<!--
 | Direct the docker-maven-plugin to connect to the Docker Host using TCP.
-->
<profile>
    <id>set-docker-host</id>
    <activation>
        <activeByDefault>true</activeByDefault>
    </activation>
    <properties>
        <docker.host>tcp://localhost:2375</docker.host>
    </properties>
</profile>

dermot-hardy on 29 Jun 2020

👍1

config snippet:

                        <image>
                            <name
                            <run>

                                <wait>
                                    <log>started successfully</log>
                                    <time>30000</time>
                                </wait>
                            </run>
                        </image>

It even recognizes the pattern but hangs. Removing log and only using time works.
log, hangs at that line:

[INFO] --- docker-maven-plugin:0.31.0:start (setup-it-dependencies) @ service ---
[INFO] DOCKER> [service-image] "service": Start container 4a9e2d814dbf
[INFO] DOCKER> Pattern 'started successfully' matched for container 4a9e2d814dbf

Thank you everyone for hints analyzing this issue. I have exactly same problem (on Windows 10). I think one time it hung after matching pattern for some long time, but eventually execution was continued (and finished successfully). Since then it only hangs after printing "pattern xyz matched for container".
I decided to stay only with <time> for now, without <log>.

jmayday on 16 Jul 2020

Also running into this issue after migrating from Docker Toolbox to Docker Desktop: the plugin hangs after the pattern has been matched.

In case this helps in determining the root cause: the pattern I'm waiting for indicates the container has been started successfully, and is the last line in the log file (at that moment). However, when I invoke an operation on the application that generates an additional log message, the process unblocks and the plugin continues again as normal.

The suggested workaround with DOCKER_HOST=tcp://localhost:2375 also fixes the problem for me, however the Docker Desktop warning for enabling this is quite scary.