• Spring Boot Version: 2.4.1
  • OS: Ubuntu 20.04.1 on WSL (Linux under Windows)
  • DockerVersion: 20.10.2 on WSL

Greetings. I am trying to use mvn spring-boot:build-image to generate a standard OCI image for docker/kubernetes (as per the documentation). However, the client hangs and does not keep building.

The following are the debug informations given by Maven, as best as I can trim:

[...]
[INFO]  > Running creator
[...]
[DEBUG] Executing request POST /v1.24/containers/create HTTP/1.1
[DEBUG] http-outgoing-0 << HTTP/1.1 201 Created
[DEBUG] http-outgoing-0 << Api-Version: 1.41
[...]
[DEBUG] Executing request PUT /v1.24/containers/<uuid>/archive?path=%2Fworkspace HTTP/1.1
[DEBUG] http-outgoing-0: Close connection
[DEBUG] http-outgoing-0: Shutdown connection
[DEBUG] Connection discarded
[DEBUG] Releasing connection [Not bound]
[...]
[DEBUG] Executing request DELETE /v1.24/volumes/pack-layers-<id>?force=1 HTTP/1.1
[DEBUG] http-outgoing-1 << HTTP/1.1 409 Conflict
[DEBUG] http-outgoing-0 << Api-Version: 1.41
[...]
[DEBUG] Executing request DELETE /v1.24/images/pack.local/builder/<id>:latest?force=1 HTTP/1.1
[Hangs indefinitely]

I don't have a sufficient knowledge about the Docker API to even surmise what the error might be, even if the

[DEBUG] Connection discarded

seems kinda fishy.

If it may help, as I have seen in questions for other builders: the command docker-credential-wincred is registered Windows-side (and presented to WSL as docker-credential-wincred.exe); the execution of docker-credential-wincred get hangs indefinitely, but the execution of

echo https://index.docker.io/v1/ | docker-credential-wincred get

responds promptly with the correct data

{"ServerURL":"https://index.docker.io/v1/","Username":"xxx",Secret":"xxx"}

I remain at disposal for any more information it may be needed. Thanks!

Comment From: wilkinsona

Can you please capture a thread dump from the process that's running Maven when the build has hung and share it with us?

Comment From: amarchino

dump.txt I tried to make a thread dump via jstack (with -l and -e flags). If the dump is not sufficient, I ask for directions as to how to create it correctly.

I also found out I missed a... maybe important information in the issue opening comment. - Java version: OpenJDK 64-Bit Server VM AdoptOpenJDK (build 11.0.7+10, mixed mode)

Comment From: amarchino

---One last information came to mind. My internet connection is SLOW (talking sub-1Mbps)... May it be that the hang is actually due to a network wait? Given that the (seemingly) not working requests are a PUT into a container, and a DELETE of an image, I do not think so, but it might just be a concause.

Comment From: wilkinsona

Thanks for the thread dump. The thread that's of interest to us is attempting to read from the socket that's used to communicate with the Docker daemon when deleting an image:

"main" #1 prio=5 os_prio=0 cpu=9680.83ms elapsed=135.40s allocated=498M defined_classes=6506 tid=0x00007f9efc015800 nid=0x30b runnable  [0x00007f9f02054000]
   java.lang.Thread.State: RUNNABLE
    at org.springframework.boot.buildpack.platform.socket.DomainSocket.read(Native Method)
    at org.springframework.boot.buildpack.platform.socket.DomainSocket.read(DomainSocket.java:82)
    at org.springframework.boot.buildpack.platform.socket.DomainSocket.access$200(DomainSocket.java:37)
    at org.springframework.boot.buildpack.platform.socket.DomainSocket$DomainSocketInputStream.read(DomainSocket.java:168)
    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:280)
    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.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:186)
    at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89)
    at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:110)
    at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185)
    at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:118)
    at org.springframework.boot.buildpack.platform.docker.transport.HttpClientTransport.execute(HttpClientTransport.java:148)
    at org.springframework.boot.buildpack.platform.docker.transport.HttpClientTransport.delete(HttpClientTransport.java:130)
    at org.springframework.boot.buildpack.platform.docker.DockerApi$ImageApi.remove(DockerApi.java:256)
    at org.springframework.boot.buildpack.platform.build.Builder.build(Builder.java:109)
    at org.springframework.boot.maven.BuildImageMojo.buildImage(BuildImageMojo.java:181)
    at org.springframework.boot.maven.BuildImageMojo.execute(BuildImageMojo.java:171)
    at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:137)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:210)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:156)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:148)
    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:957)
    at org.apache.maven.cli.MavenCli.doMain(MavenCli.java:289)
    at org.apache.maven.cli.MavenCli.main(MavenCli.java:193)
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base@11.0.7/Native Method)
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base@11.0.7/NativeMethodAccessorImpl.java:62)
    at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@11.0.7/DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(java.base@11.0.7/Method.java:566)
    at org.codehaus.plexus.classworlds.launcher.Launcher.launchEnhanced(Launcher.java:282)
    at org.codehaus.plexus.classworlds.launcher.Launcher.launch(Launcher.java:225)
    at org.codehaus.plexus.classworlds.launcher.Launcher.mainWithExitCode(Launcher.java:406)
    at org.codehaus.plexus.classworlds.launcher.Launcher.main(Launcher.java:347)
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base@11.0.7/Native Method)
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base@11.0.7/NativeMethodAccessorImpl.java:62)
    at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@11.0.7/DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(java.base@11.0.7/Method.java:566)
    at org.apache.maven.wrapper.BootstrapMainStarter.start(BootstrapMainStarter.java:39)
    at org.apache.maven.wrapper.WrapperExecutor.execute(WrapperExecutor.java:122)
    at org.apache.maven.wrapper.MavenWrapperMain.main(MavenWrapperMain.java:61)

This tallies with the last line of the log output that you shared above:

[DEBUG] Executing request DELETE /v1.24/images/pack.local/builder/<id>:latest?force=1 HTTP/1.1

I think the first sign of a problem is when the volume DELETE request fails with a 409:

[DEBUG] Executing request DELETE /v1.24/volumes/pack-layers-<id>?force=1 HTTP/1.1
[DEBUG] http-outgoing-1 << HTTP/1.1 409 Conflict
[DEBUG] http-outgoing-0 << Api-Version: 1.41

This indicates that the volume is in use and cannot be removed. I would expect a 204 response such as the following:

[DEBUG] Executing request DELETE /v1.24/volumes/pack-app-pkmtiqjbnq?force=1 HTTP/1.1
[DEBUG] Target auth state: UNCHALLENGED
[DEBUG] Proxy auth state: UNCHALLENGED
[DEBUG] http-outgoing-0 >> DELETE /v1.24/volumes/pack-app-pkmtiqjbnq?force=1 HTTP/1.1
[DEBUG] http-outgoing-0 >> Host: localhost
[DEBUG] http-outgoing-0 >> Connection: Keep-Alive
[DEBUG] http-outgoing-0 >> User-Agent: Apache-HttpClient/4.5.13 (Java/11.0.7)
[DEBUG] http-outgoing-0 >> Accept-Encoding: gzip,deflate
[DEBUG] http-outgoing-0 << HTTP/1.1 204 No Content
[DEBUG] http-outgoing-0 << Api-Version: 1.40
[DEBUG] http-outgoing-0 << Date: Mon, 11 Jan 2021 09:59:19 GMT
[DEBUG] http-outgoing-0 << Docker-Experimental: false
[DEBUG] http-outgoing-0 << Ostype: linux
[DEBUG] http-outgoing-0 << Server: Docker/19.03.12 (linux)

My current guess is that this volume delete failure is then causing the image delete to hang. This hang may be a Docker bug, but I think it's only a symptom of the earlier failure to delete the volume so let's try to get to the bottom of that. Can you please share the complete debug output from Maven so that we can see the entire sequence of requests and responses between Maven and the Docker daemon?

Comment From: amarchino

maven-debug-output.txt This is the debug output of the Maven command. I have removed the listing of the compiled classes and the tests, since they contain project-specific informations (yet they are only some Unit tests which pass, and the compilation report of some classes).

I hope the listing may help.

Comment From: wilkinsona

Thanks. The discard of the connection does indeed seem to be fishy. It appears that the connection is being aborted before a response is received:

[DEBUG] http-outgoing-0 >> PUT /v1.24/containers/9e2d56b316f41b9af0ce30f5bb2abd17275a841f5eda676aa53cf0397db129db/archive?path=%2Fworkspace HTTP/1.1
[DEBUG] http-outgoing-0 >> Transfer-Encoding: chunked
[DEBUG] http-outgoing-0 >> Content-Type: application/x-tar
[DEBUG] http-outgoing-0 >> Host: localhost
[DEBUG] http-outgoing-0 >> Connection: Keep-Alive
[DEBUG] http-outgoing-0 >> User-Agent: Apache-HttpClient/4.5.13 (Java/11.0.7)
[DEBUG] http-outgoing-0 >> Accept-Encoding: gzip,deflate
[DEBUG] http-outgoing-0: Close connection
[DEBUG] http-outgoing-0: Shutdown connection
[DEBUG] Connection discarded
[DEBUG] Releasing connection [Not bound]

Unfortunately, HTTP client's logging doesn't reveal why the connection was aborted. It's also not clear why, apparently, no exception was thrown so it appears from the caller's perspective as if the PUT has succeeded.

I believe the close and shutdown is happening due to a call to org.apache.http.impl.execchain.ConnectionHolder.abortConnection(). Can you please try debugging your Maven build so that we can see exactly why the connection is being aborted? The following is one way to do so:

$ MAVEN_OPTS=-agentlib:jdwp=transport=dt_socket,server=y,suspend=y,address=8000 ./mvnw spring-boot:build-image

Abreakpoint on abortConnection() will hopefully make it possible to identify why the connection is being aborted.

Comment From: amarchino

Ok, I might be able to give some more informations; I am sorry for the big delay, but I had actually no experience in debugging a Maven module, so it took a long time to setup my IDE to make the required test.

It seems to me that it is a problem due to a multi-module build. I tried to build a single-module spring boot application, and it worked correctly. I tried both the application whose error gave rise to this issue, and a similar application I had developed before (but without Docker integration), and both hang.

Furthermore, while analyzing logs and debug steps, it occurred to me that the build-image execution was actually done inside a module which does not expose a main class. Therefore, I think I might have been in the same case as issue #21621, with the only difference that somehow the docker integration hangs indefinitely instead of exiting with an error.

The hang of the Docker runtime may be due to a Docker issue (for example, the build containers created by the Maven plugin are still in a "created" state, but cannot be deleted even by the Docker CLI prior to a full Docker shutdown).

Given this, I tried to add the spring-boot.build-image.skip property to the module which does not contain the main class... And, lo and behold, the execution of the goal was skipped for the example-client module, the execution started for the example-app module (which contains the main class)... And the image was built successfully!

A fast execution check showed that the create image works correctly.

Therefore, I will consider the issue closed (please, add any and all labels that apply), but may I suggest to make a note for this use case? The multi-module use case is not terribly uncommon, even if I don't know whether it is a best- or worst-practice in microservice architecture, and therefore it may be useful for someone that may fall into the same problem in the future.

Thanks @wilkinsona for the time you spent following this issue!!