Warning when docker is not running

[Postremus]

Describe the bug

Quarkus prints an warning message if I start in dev mode, and have no docker runtime running.
It also does not matter If I have an extensions present offering dev services or not.

Could this warning please be silenced or turned into an debug log?
This only happens since 2.16.4.Final, I did not notice this log in 2.16.2.Final.

The log is written here:

quarkus/core/runtime/src/main/java/io/quarkus/runtime/util/ContainerRuntimeUtil.java

Lines 66 to 77 in ac43aae

	private static boolean getRootlessStateFor(ContainerRuntime containerRuntime) {
	Process rootlessProcess = null;
	try {
	ProcessBuilder pb = new ProcessBuilder(containerRuntime.getExecutableName(), "info")
	.redirectErrorStream(true);
	rootlessProcess = pb.start();
	int exitCode = rootlessProcess.waitFor();
	if (exitCode != 0) {
	log.warnf("Command \"%s\" exited with error code %d. " +
	"Rootless container runtime detection might not be reliable.",
	containerRuntime.getExecutableName(), exitCode);
	}

Expected behavior

No response

Actual behavior

2023-03-07 17:36:08,542 WARN  [io.qua.run.uti.ContainerRuntimeUtil] (main) Command "docker" exited with error code 1. Rootless container runtime detection might not be reliable.
__  ____  __  _____   ___  __ ____  ______
 --/ __ \/ / / / _ | / _ \/ //_/ / / / __/
 -/ /_/ / /_/ / __ |/ , _/ ,< / /_/ /\ \
--\___\_\____/_/ |_/_/|_/_/|_|\____/___/
2023-03-07 17:36:10,733 INFO  [io.quarkus] (Quarkus Main Thread) rootless-docker 1.0.0-SNAPSHOT on JVM (powered by Quarkus 2.16.4.Final) started in 3.073s. Listening on: http://localhost:8080

2023-03-07 17:36:10,736 INFO  [io.quarkus] (Quarkus Main Thread) Profile dev activated. Live Coding activated.
2023-03-07 17:36:10,737 INFO  [io.quarkus] (Quarkus Main Thread) Installed features: [cdi, resteasy-reactive, smallrye-context-propagation, vertx]

How to Reproduce?

Download a fresh app from code.quarkus.io, extensions do not matter.

Stop your docker deamon.
mvn clean compile quarkus:dev

Warning from above is printed.

Output of uname -a or ver

MINGW64_NT-10.0-19044 NANBCHL9NG3 3.3.6-341.x86_64 2022-09-05 20:28 UTC x86_64 Msys

Output of java -version

openjdk 17.0.4 2022-07-19
OpenJDK Runtime Environment Temurin-17.0.4+8 (build 17.0.4+8)
OpenJDK 64-Bit Server VM Temurin-17.0.4+8 (build 17.0.4+8, mixed mode, sharing)

GraalVM version (if different from Java)

No response

Quarkus version or git rev

2.16.4.Final

Build tool (ie. output of mvnw --version or gradlew --version)

$ mvn --version
Apache Maven 3.8.4 (9b656c72d54e5bacbed989b64718c159fe39b537)
Maven home: C:\eclipse\tools\java\maven
Java version: 17.0.4, vendor: Eclipse Adoptium, runtime: C:\eclipse\tools\java\17
Default locale: de_DE, platform encoding: Cp1252
OS name: "windows 10", version: "10.0", arch: "amd64", family: "windows"

Additional information

No response

[geoand]

I think it makes sense. @zakkak WDYT?

[Karm]

Since I'm already in there with #31490, I'll take a look. I'd like to detect when/why and call it based on that condition rather to simply silence the log.

[Sanne]

@Karm please see here too: https://quarkusio.zulipchat.com/#narrow/stream/187038-dev/topic/ContainerRuntimeUtil.20warning

Summary: while clearly the log is a bit annoying, it also seems rather slow. I didn't have time to investigate but I suspect it's hitting some timeout - the fact that InterruptedException is being caught is suspicious :)

[Karm]

So I'll just add a commit to #31490 that would cache the state, i.e. established container runtime and whether it's rootless. It's not like it would change mid air for either the build or the test, so it's enough to call it once to find out.

[Karm]

I have the warning away, it's not called when it's not used (the rootless detection).
The container runtime detection is still called three times though, within three different classloaders...

CALLING detectContainerRuntime Classloder: app,  Thread:main, Thread classloader: app
CALLING detectContainerRuntime Classloder: Augmentation Class Loader: PROD,  Thread:main, Thread classloader: Deployment Class Loader: PROD
CALLING detectContainerRuntime Classloder: Augmentation Class Loader: TEST,  Thread:main, Thread classloader: Deployment Class Loader: TEST

So, that's still wasteful...

[Karm]

I created a small "audit" device:

$ cat ~/bin/docker
#!/bin/bash
echo "$(date) docker $@" >> ~/.docker_karm.log
/bin/docker $@

And the result is somewhat sad. Even though I got the number of docker|podman info to 1, the amount of version calls is very high for no good reason. Examples (reproducible with branch from #31490 :

$ ./mvnw verify -f integration-tests/pom.xml -pl awt -Ddocker -Dnative -Dnative.surefire.skip -Dquarkus.native.container-build=true -Dquarkus.container-image.build=true -Dquarkus.native.builder-image=quay.io/quarkus/ubi-quarkus-mandrel-builder-image:22.3-java17 -Dquarkus.native.container-runtime=docker
Log:
Mon Mar 13 11:22:26 CET 2023 docker --version
Mon Mar 13 11:22:28 CET 2023 docker info
Mon Mar 13 11:22:28 CET 2023 docker pull quay.io/quarkus/ubi-quarkus-mandrel-builder-image:22.3-java17
Mon Mar 13 11:22:39 CET 2023 docker run --env LANG=C --rm --user 1000:1000 --rm quay.io/quarkus/ubi-quarkus-mandrel-builder-image:22.3-java17 --version
Mon Mar 13 11:22:40 CET 2023 docker run --env LANG=C --rm --user 1000:1000 -v /home/karm/workspaceRH/quarkus/integration-tests/awt/target/quarkus-integration-test-awt-999-SNAPSHOT-native-image-source-jar:/project:z --name build-native-MYMPK quay.io/quarkus/ubi-quarkus-mandrel-builder-image:22.3-java17 -J-Djava.util.logging.manager=org.jboss.logmanager.LogManager -J-Dsun.nio.ch.maxUpdateArraySize=100 -J-Dlogging.initial-configurator.min-level=500 -J-Dio.netty.noUnsafe=true -J-Dio.netty.leakDetection.level=DISABLED -J-Dio.netty.allocator.maxOrder=3 -J-Dvertx.logger-delegate-factory-class-name=io.quarkus.vertx.core.runtime.VertxLogDelegateFactory -J-Dvertx.disableDnsResolver=true -J-Duser.language=en -J-Duser.country=US -J-Dfile.encoding=UTF-8 --features=io.quarkus.runner.Feature,io.quarkus.awt.runtime.graal.AwtFeature,io.quarkus.runtime.graal.DisableLoggingFeature,io.quarkus.awt.runtime.graal.DarwinAwtFeature -J--add-exports=java.security.jgss/sun.security.krb5=ALL-UNNAMED -J--add-opens=java.base/java.text=ALL-UNNAMED -J--add-opens=java.base/java.io=ALL-UNNAMED -J--add-opens=java.base/java.lang.invoke=ALL-UNNAMED -J--add-opens=java.base/java.util=ALL-UNNAMED -H:+CollectImageBuildStatistics -H:ImageBuildStatisticsFile=quarkus-integration-test-awt-999-SNAPSHOT-runner-timing-stats.json -H:BuildOutputJSONFile=quarkus-integration-test-awt-999-SNAPSHOT-runner-build-output-stats.json -H:+AllowFoldMethods -J-Djava.awt.headless=true --no-fallback --link-at-build-time -H:+ReportExceptionStackTraces -H:-AddAllCharsets --enable-url-protocols=http -H:-UseServiceLoaderFeature -H:+StackTrace -J--add-exports=org.graalvm.sdk/org.graalvm.nativeimage.impl=ALL-UNNAMED --exclude-config io\.netty\.netty-codec /META-INF/native-image/io\.netty/netty-codec/generated/handlers/reflect-config\.json --exclude-config io\.netty\.netty-handler /META-INF/native-image/io\.netty/netty-handler/generated/handlers/reflect-config\.json quarkus-integration-test-awt-999-SNAPSHOT-runner -jar quarkus-integration-test-awt-999-SNAPSHOT-runner.jar
Mon Mar 13 11:24:29 CET 2023 docker run --env LANG=C --rm --user 1000:1000 -v /home/karm/workspaceRH/quarkus/integration-tests/awt/target/quarkus-integration-test-awt-999-SNAPSHOT-native-image-source-jar:/project:z --entrypoint /bin/bash quay.io/quarkus/ubi-quarkus-mandrel-builder-image:22.3-java17 -c objcopy --strip-debug quarkus-integration-test-awt-999-SNAPSHOT-runner
Mon Mar 13 11:24:30 CET 2023 docker -v
Mon Mar 13 11:24:30 CET 2023 docker version --format '{{.Server.Version}}'
Mon Mar 13 11:24:30 CET 2023 docker build -f /home/karm/workspaceRH/quarkus/integration-tests/awt/src/main/docker/Dockerfile.native -t karm/quarkus-integration-test-awt:999-SNAPSHOT /home/karm/workspaceRH/quarkus/integration-tests/awt
Mon Mar 13 11:24:32 CET 2023 docker --version
Mon Mar 13 11:24:33 CET 2023 docker --version
Mon Mar 13 11:24:34 CET 2023 docker network create quarkus-integration-test-zBWmo
Mon Mar 13 11:24:34 CET 2023 docker run --name quarkus-integration-test-OLZCS -i --rm -p 8081:8081 -p 8444:8444 --net=quarkus-integration-test-zBWmo --env QUARKUS_LOG_CATEGORY__IO_QUARKUS__LEVEL=INFO --env QUARKUS_HTTP_PORT=8081 --env QUARKUS_HTTP_SSL_PORT=8444 --env TEST_URL=http://localhost:8081 --env QUARKUS_NATIVE_CONTAINER_RUNTIME=docker --env QUARKUS_HTTP_HOST=localhost --env QUARKUS_CONTAINER_IMAGE_BUILD=true --env QUARKUS_NATIVE_CONTAINER_BUILD=true --env QUARKUS_HTTP_PORT=8081 --env QUARKUS_NATIVE_BUILDER_IMAGE=quay.io/quarkus/ubi-quarkus-mandrel-builder-image:22.3-java17 karm/quarkus-integration-test-awt:999-SNAPSHOT
Mon Mar 13 11:24:44 CET 2023 docker stop quarkus-integration-test-OLZCS
Mon Mar 13 11:24:44 CET 2023 docker network rm quarkus-integration-test-zBWmo


$ ./mvnw verify -f integration-tests/pom.xml -pl awt -Ddocker -Dnative -Dnative.surefire.skip -Dquarkus.native.container-build=true
Log:
Mon Mar 13 11:50:34 CET 2023 docker --version
Mon Mar 13 11:50:36 CET 2023 docker info
Mon Mar 13 11:50:36 CET 2023 docker pull quay.io/quarkus/ubi-quarkus-mandrel-builder-image:22.3-java17
Mon Mar 13 11:50:46 CET 2023 docker run --env LANG=C --rm --user 1000:1000 --rm quay.io/quarkus/ubi-quarkus-mandrel-builder-image:22.3-java17 --version
Mon Mar 13 11:50:47 CET 2023 docker run --env LANG=C --rm --user 1000:1000 -v /home/karm/workspaceRH/quarkus/integration-tests/awt/target/quarkus-integration-test-awt-999-SNAPSHOT-native-image-source-jar:/project:z --name build-native-maiuf quay.io/quarkus/ubi-quarkus-mandrel-builder-image:22.3-java17 -J-Dsun.nio.ch.maxUpdateArraySize=100 -J-Djava.util.logging.manager=org.jboss.logmanager.LogManager -J-Dlogging.initial-configurator.min-level=500 -J-Dvertx.logger-delegate-factory-class-name=io.quarkus.vertx.core.runtime.VertxLogDelegateFactory -J-Dvertx.disableDnsResolver=true -J-Dio.netty.noUnsafe=true -J-Dio.netty.leakDetection.level=DISABLED -J-Dio.netty.allocator.maxOrder=3 -J-Duser.language=en -J-Duser.country=US -J-Dfile.encoding=UTF-8 --features=io.quarkus.runner.Feature,io.quarkus.runtime.graal.DisableLoggingFeature,io.quarkus.awt.runtime.graal.AwtFeature,io.quarkus.awt.runtime.graal.DarwinAwtFeature -J--add-exports=java.security.jgss/sun.security.krb5=ALL-UNNAMED -J--add-opens=java.base/java.text=ALL-UNNAMED -J--add-opens=java.base/java.io=ALL-UNNAMED -J--add-opens=java.base/java.lang.invoke=ALL-UNNAMED -J--add-opens=java.base/java.util=ALL-UNNAMED -H:+CollectImageBuildStatistics -H:ImageBuildStatisticsFile=quarkus-integration-test-awt-999-SNAPSHOT-runner-timing-stats.json -H:BuildOutputJSONFile=quarkus-integration-test-awt-999-SNAPSHOT-runner-build-output-stats.json -H:+AllowFoldMethods -J-Djava.awt.headless=true --no-fallback --link-at-build-time -H:+ReportExceptionStackTraces -H:-AddAllCharsets --enable-url-protocols=http -H:-UseServiceLoaderFeature -H:+StackTrace -J--add-exports=org.graalvm.sdk/org.graalvm.nativeimage.impl=ALL-UNNAMED --exclude-config io\.netty\.netty-codec /META-INF/native-image/io\.netty/netty-codec/generated/handlers/reflect-config\.json --exclude-config io\.netty\.netty-handler /META-INF/native-image/io\.netty/netty-handler/generated/handlers/reflect-config\.json quarkus-integration-test-awt-999-SNAPSHOT-runner -jar quarkus-integration-test-awt-999-SNAPSHOT-runner.jar
Mon Mar 13 11:52:48 CET 2023 docker run --env LANG=C --rm --user 1000:1000 -v /home/karm/workspaceRH/quarkus/integration-tests/awt/target/quarkus-integration-test-awt-999-SNAPSHOT-native-image-source-jar:/project:z --entrypoint /bin/bash quay.io/quarkus/ubi-quarkus-mandrel-builder-image:22.3-java17 -c objcopy --strip-debug quarkus-integration-test-awt-999-SNAPSHOT-runner
Mon Mar 13 11:52:50 CET 2023 docker --version
Mon Mar 13 11:52:51 CET 2023 docker --version


$ ./mvnw verify -f integration-tests/pom.xml -pl awt -Dnative
Log:
Mon Mar 13 11:57:22 CET 2023 docker --version
Mon Mar 13 11:57:23 CET 2023 docker --version
Mon Mar 13 11:57:28 CET 2023 docker --version
Mon Mar 13 11:57:30 CET 2023 docker --version
Mon Mar 13 11:57:36 CET 2023 docker --version
Mon Mar 13 11:57:37 CET 2023 docker --version
Mon Mar 13 11:57:51 CET 2023 docker --version
Mon Mar 13 12:00:00 CET 2023 docker --version
Mon Mar 13 12:00:01 CET 2023 docker --version

So I'll cache the result in a file and see how it goes.