docker-maven-plugin: docker-maven-plugin hangs when waiting for log

@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

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.

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

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

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)

1. 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).
2. 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).
3. Calls to FileChannelImpl’s read(...) and write(...) methods (and others) call threads.add() and threads.remove()
4. 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)
5. 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

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

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.

@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>

</profiles>

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.