Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

mvn initialize docker:start stuck #862

Open
vinayak03 opened this issue Sep 12, 2017 · 8 comments
Open

mvn initialize docker:start stuck #862

vinayak03 opened this issue Sep 12, 2017 · 8 comments

Comments

@vinayak03
Copy link

when I am trying to start the container using mvn initialize docker:start it stucks does not proceed further.
I am able to create docker image with the same configuration and it push this image in local repo.
but after that when I try to start this it stucks.

  • d-m-p version : 0.22.1
  • Maven version (mvn -v) : 3.3.9

  • Docker version 17.06.2-ce

Added debug file
debug.txt

Any pointers appreciated.

Thanks,
Vinayak

@rhuss
Copy link
Collaborator

rhuss commented Sep 14, 2017

As I see, you are running on Windows. Do you use Docker for Windows here ? Any chance that you could share your project (pom.xml).

TBH, its always hard for me to check Windows issues and it takes a fair amount of time to get and update my Window environment. I hope I can tackle the issue ASAP, but I can't promise anything as I'm currently super busy with other works.

@FSeidinger
Copy link
Contributor

FSeidinger commented Nov 22, 2017

Hi Roland,

I've created a very simple project demonstrating this error. Have a look on:

https://github.com/novityFS/docker-maven-plugin-waitlog-scenario

The readme will give you more detailed info.

I've analyzed that the error is not with the LogWaitChecker. Via debug output I could see, that the wait matched the given pattern.

I also think that it's not a race condition. For this reason I've created an alternative version of the LogWaitChecker where checking and signaling the match is not runtime dependend. If you want to try this, please have a look on my fork of the plugin:

https://github.com/novityFS/docker-maven-plugin

I can only guess, that the error may be with the startImage tasks running asynchronously by the StartMojo. But that's totally a shot in the dark.

Kind regards,

Frank.

@FSeidinger
Copy link
Contributor

FSeidinger commented Nov 28, 2017

Dear Roland,

with my projects mentioned above I was able to get some light here. After rearranging the thread synchronisation of the LogRequestor (used by LogWaitChecker) and the signalling to the tasks started by startImage, I could reproduce the error in Windows and Linux.

The problem is this piece of code in the method parseResponse of the LogRequestor:

try (InputStream is = response.getEntity().getContent()) {
    while (true) {
        if (!readStreamFrame(is)) {
            return;
        }
    }
} catch (IOException e) {
    callback.error("Cannot process chunk response: " + e);
    finish();
} catch (LogCallback.DoneException e) {
    // Can be thrown by a log callback which indicates that we are done.
    finish();
}

The try-with-resources statement implicitly closes the input stream is when the block is left. For some reason this leads to a blocking IO-operation. Consider the following thread-dump of the LogRequestor thread:

"Thread-1@4801" prio=5 tid=0xe nid=NA runnable
  java.lang.Thread.State: RUNNABLE
	 blocks main@1
	  at com.kenai.jffi.Foreign.invokeN3O1(Foreign.java:-1)
	  at com.kenai.jffi.Invoker.invokeN3(Invoker.java:1061)
	  at jnr.enxio.channels.Native$LibC$jnr$ffi$1.read(Unknown Source:-1)
	  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 <0x133d> (a java.lang.Object)
	  at sun.nio.ch.ChannelInputStream.read(ChannelInputStream.java:109)
	  at sun.nio.ch.ChannelInputStream.read(ChannelInputStream.java:103)
	  - locked <0x1333> (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.io.ChunkedInputStream.getChunkSize(ChunkedInputStream.java:264)
	  at org.apache.http.impl.io.ChunkedInputStream.nextChunk(ChunkedInputStream.java:225)
	  at org.apache.http.impl.io.ChunkedInputStream.read(ChunkedInputStream.java:184)
	  at org.apache.http.impl.io.ChunkedInputStream.read(ChunkedInputStream.java:213)
	  at org.apache.http.impl.io.ChunkedInputStream.close(ChunkedInputStream.java:315)
	  at org.apache.http.impl.execchain.ResponseEntityProxy.streamClosed(ResponseEntityProxy.java:143)
	  at org.apache.http.conn.EofSensorInputStream.checkClose(EofSensorInputStream.java:228)
	  at org.apache.http.conn.EofSensorInputStream.close(EofSensorInputStream.java:172)
	  at io.fabric8.maven.docker.access.log.LogRequestor.parseResponse(LogRequestor.java:208)
	  at io.fabric8.maven.docker.access.log.LogRequestor.run(LogRequestor.java:111)
	  - locked <0x133e> (a java.lang.Object)

As you can see, the close operation tries to read the next chunk from the input stream. As there is no input left to read at that time, the IO-blocking causes the thread to hang and wait forever for new input from the stream.

The main thread is then blocked as well, because it waits on the lock-object used to synchronise the external finish method of the LogRequestor.

Why the Apache chunked-stream thinks, there is still some input to read? I don't know.

Also there is a workaround using the following code in LogRequestor.parseResponse:

private void parseResponse(HttpResponse response) throws LogCallback.DoneException, IOException {
    final StatusLine status = response.getStatusLine();
    if (status.getStatusCode() != 200) {
        exception = new DockerAccessException("Error while reading logs (" + status + ")");
        throw new LogCallback.DoneException();
    }

    final InputStream is = response.getEntity().getContent();

    try {
        while (true) {
            if (!readStreamFrame(is)) {
                return;
            }
        }
    } finally {
        if ((is != null) && (is.available() > 0)) {
            is.close();
        }
    }
}

Kind regards,

Frank

@rhuss
Copy link
Collaborator

rhuss commented Nov 28, 2017

@novityFS awesome, thanks a lot for the research and investigation ! I'm going to dive into this later and try to make a release with a fix at the end of this weeks.

Thanks a lot !

@FSeidinger
Copy link
Contributor

You can use my pull request, if you like.

#904

@rhuss
Copy link
Collaborator

rhuss commented Dec 12, 2017

@novityFS sorry, still super busy. But Christmas is soon, with some spare time ;-)

rhuss added a commit that referenced this issue Jan 16, 2018
@koscejev
Copy link

koscejev commented Mar 9, 2018

Using d-m-p 0.24.0 with this change, my builds with <startParallel>true</startParallel> are stuck after

Waited on log out 'Server startup complete' 5043 ms

However, without <startParallel>true</startParallel> everything works as before.

@rhuss
Copy link
Collaborator

rhuss commented Mar 12, 2018

Ah, good data point. Let me check this later, too.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants