search

quarkusio / quarkus

Quarkus: Supersonic Subatomic Java.
https://quarkus.io
Apache License 2.0
13.73k stars 2.67k forks source link

Dev Services for Postgresql not working with Rancher #25682

Closed edeandrea closed 6 months ago

edeandrea commented 2 years ago

Describe the bug

Last week I got a new laptop - a 2021 MacBook M1Pro. Since then whenever I try to use Dev Services for Postgresql (either in Quarkus Dev mode or when running tests) it seems to be broken with some kind of race condition between the starting of the Postgres container & the creation of the username/password). When Hibernate kicks in to create the tables its getting an authentication error, as if the user hasn’t yet been created. I’m hoping my new machine isn’t too fast!

Expected behavior

I would expect the dev service for postgresql to work.

Actual behavior

It does not

How to Reproduce?

I can reproduce this pretty regularly. I put together a repo on GitHub [1] detailing what I’m seeing (it’s a pretty basic hello world). I also recorded a 2 minute video [2] showing what I’m seeing. The README file in the repo has a very detailed explanation of the problem & what I'm seeing.

[1] https://github.com/edeandrea/quarkus-devservice-postgresql [2] https://github.com/edeandrea/quarkus-devservice-postgresql/raw/main/Dev-Services-postgres-failing.mov

Output of uname -a or ver

Darwin edeandrea-m1pro 21.5.0 Darwin Kernel Version 21.5.0: Tue Apr 26 21:08:37 PDT 2022; root:xnu-8020.121.3~4/RELEASE_ARM64_T6000 arm64

Output of java -version

openjdk version "17.0.3" 2022-04-19
OpenJDK Runtime Environment Temurin-17.0.3+7 (build 17.0.3+7)
OpenJDK 64-Bit Server VM Temurin-17.0.3+7 (build 17.0.3+7, mixed mode)

Quarkus version or git rev

2.9.1.Final

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

Apache Maven 3.8.4 (9b656c72d54e5bacbed989b64718c159fe39b537)
Maven home: /Users/edeandre/.m2/wrapper/dists/apache-maven-3.8.4-bin/52ccbt68d252mdldqsfsn03jlf/apache-maven-3.8.4
Java version: 17.0.3, vendor: Eclipse Adoptium, runtime: /Users/edeandre/.sdkman/candidates/java/17.0.3-tem
Default locale: en_US, platform encoding: UTF-8
OS name: "mac os x", version: "12.4", arch: "aarch64", family: "mac"

Additional information

No response

quarkus-bot[bot] commented 2 years ago

/cc @stuartwdouglas

gastaldi commented 2 years ago

Thanks, @edeandrea, I tried to reproduce this in my M1 but no luck so far. I got two questions for you:

edeandrea commented 2 years ago

Yes it happens when I run ./mvnw test. Here's the output with quarkus.log.category."org.testcontainers".level=FINEST

[INFO] -------------------------------------------------------
[INFO]  T E S T S
[INFO] -------------------------------------------------------
[INFO] Running org.acme.GreetingResourceTest
2022-05-19 12:42:08,873 WARN  [io.qua.run.log.LoggingSetupRecorder] (main) Log level FINEST for category 'org.testcontainers' set below minimum logging level DEBUG, promoting it to DEBUG
2022-05-19 12:42:09,470 INFO  [org.jbo.threads] (main) JBoss Threads version 3.4.2.Final
2022-05-19 12:42:09,583 WARN  [io.qua.run.log.LoggingSetupRecorder] (build-7) Log level FINEST for category 'org.testcontainers' set below minimum logging level DEBUG, promoting it to DEBUG
2022-05-19 12:42:09,606 DEBUG [org.tes.uti.TestcontainersConfiguration] (build-8) Testcontainers configuration overrides will be loaded from file:/Users/edeandre/.testcontainers.properties
2022-05-19 12:42:09,613 INFO  [org.tes.doc.DockerClientProviderStrategy] (build-8) Loaded org.testcontainers.dockerclient.UnixSocketClientProviderStrategy from ~/.testcontainers.properties, will try it first
2022-05-19 12:42:09,614 DEBUG [org.tes.doc.DockerClientProviderStrategy] (build-8) Trying out strategy: EnvironmentAndSystemPropertyClientProviderStrategy
2022-05-19 12:42:09,735 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:09,752 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:09,883 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:09,883 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:09,989 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:09,989 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:10,092 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:10,093 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:10,194 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:10,194 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:10,301 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:10,301 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:10,408 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:10,413 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:10,519 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:10,519 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:10,625 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:10,626 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:10,731 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:10,732 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:10,839 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:10,839 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:10,942 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:10,942 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:11,051 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:11,052 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:11,160 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:11,162 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:11,269 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:11,270 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:11,377 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:11,378 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:11,483 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:11,484 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:11,588 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:11,588 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:11,695 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:11,696 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:11,803 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:11,803 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:11,908 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:11,909 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:12,018 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:12,018 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:12,122 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:12,123 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:12,228 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:12,229 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:12,333 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:12,334 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:12,436 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:12,436 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:12,540 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:12,540 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:12,646 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:12,647 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:12,752 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:12,753 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:12,860 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:12,861 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:12,966 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:12,967 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:13,074 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:13,074 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:13,179 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:13,180 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:13,283 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:13,284 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:13,386 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:13,386 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:13,492 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:13,493 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:13,600 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:13,601 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:13,704 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:13,704 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:13,811 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:13,813 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:13,919 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:13,920 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:14,026 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:14,027 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:14,129 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:14,130 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:14,236 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:14,236 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:14,345 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:14,345 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:14,452 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:14,452 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:14,559 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:14,560 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:14,665 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:14,665 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:14,767 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:14,768 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:14,874 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:14,874 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:14,983 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:14,984 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:15,090 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:15,090 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:15,195 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:15,196 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:15,300 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:15,300 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:15,407 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:15,408 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:15,518 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:15,519 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:15,626 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:15,627 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:15,733 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:15,734 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:15,836 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:15,837 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:15,946 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:15,948 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:16,053 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:16,054 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:16,165 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:16,166 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:16,271 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:16,272 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:16,376 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:16,376 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:16,480 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:16,480 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:16,587 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:16,587 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:16,695 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:16,696 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:16,803 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:16,803 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:16,909 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:16,909 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:17,017 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:17,019 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:17,127 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:17,127 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:17,234 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:17,234 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:17,337 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:17,337 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:17,443 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:17,443 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:17,549 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:17,549 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:17,658 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:17,661 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:17,767 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:17,767 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:17,873 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:17,874 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:17,976 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:17,977 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:18,082 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:18,083 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:18,188 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:18,188 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:18,294 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:18,295 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:18,401 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:18,401 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:18,508 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:18,509 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:18,615 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:18,615 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:18,723 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:18,723 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:18,827 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:18,828 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:18,932 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:18,933 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:19,040 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:19,040 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:19,145 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:19,146 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:19,250 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:19,251 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:19,354 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:19,355 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:19,459 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:19,460 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:19,566 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:19,566 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:19,672 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:19,673 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:19,748 DEBUG [org.tes.doc.DockerClientProviderStrategy] (build-8) EnvironmentAndSystemPropertyClientProviderStrategy: failed with exception TimeoutException (Timeout waiting for result with exception). Root cause HttpHostConnectException (Connect to http://127.0.0.1:49951 [/127.0.0.1] failed: Connection refused)
2022-05-19 12:42:19,748 DEBUG [org.tes.doc.DockerClientProviderStrategy] (build-8) Trying out strategy: UnixSocketClientProviderStrategy
2022-05-19 12:42:19,762 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-1) Pinging docker daemon...
2022-05-19 12:42:19,763 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-1) Cmd: 
2022-05-19 12:42:19,777 DEBUG [org.tes.doc.DockerClientProviderStrategy] (ducttape-0) Pinging docker daemon...
2022-05-19 12:42:19,777 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-0) Cmd: 
2022-05-19 12:42:19,855 INFO  [org.tes.doc.DockerClientProviderStrategy] (build-8) Found Docker environment with local Unix socket (unix:///var/run/docker.sock)
2022-05-19 12:42:19,855 DEBUG [org.tes.doc.DockerClientProviderStrategy] (build-8) Transport type: 'httpclient5', Docker host: 'unix:///var/run/docker.sock'
2022-05-19 12:42:19,855 DEBUG [org.tes.doc.DockerClientProviderStrategy] (build-8) Checking Docker OS type for local Unix socket (unix:///var/run/docker.sock)
2022-05-19 12:42:19,856 INFO  [org.tes.DockerClientFactory] (build-8) Docker host IP address is localhost
2022-05-19 12:42:19,856 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (build-8) Cmd: 
2022-05-19 12:42:19,883 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (build-8) Cmd: 
2022-05-19 12:42:19,894 INFO  [org.tes.DockerClientFactory] (build-8) Connected to docker: 
  Server Version: 20.10.14
  API Version: 1.41
  Operating System: Alpine Linux v3.15
  Total Memory: 5925 MB
2022-05-19 12:42:19,896 DEBUG [org.tes.DockerClientFactory] (build-8) Checks are enabled
2022-05-19 12:42:19,896 INFO  [org.tes.DockerClientFactory] (build-8) Checking the system...
2022-05-19 12:42:19,897 INFO  [org.tes.DockerClientFactory] (build-8) ✔︎ Docker server version should be at least 1.6.0
2022-05-19 12:42:19,900 INFO  [org.tes.uti.ImageNameSubstitutor] (build-8) Image name substitution will be performed by: DefaultImageNameSubstitutor (composite of 'ConfigurationFileImageNameSubstitutor' and 'PrefixingImageNameSubstitutor')
2022-05-19 12:42:19,900 DEBUG [org.tes.uti.PrefixingImageNameSubstitutor] (build-8) No prefix is configured
2022-05-19 12:42:19,900 DEBUG [org.tes.uti.ImageNameSubstitutor] (build-8) Did not find a substitute image for alpine:3.14 (using image substitutor: DefaultImageNameSubstitutor (composite of 'ConfigurationFileImageNameSubstitutor' and 'PrefixingImageNameSubstitutor'))
2022-05-19 12:42:19,902 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (build-8) Cmd: ListImagesCmdImpl[filters=org.testcontainers.shaded.com.github.dockerjava.core.util.FiltersBuilder@0,imageNameFilter=<null>,showAll=false]
2022-05-19 12:42:19,910 DEBUG [org.tes.ima.AbstractImagePullPolicy] (build-8) Using locally available and not pulling image: alpine:3.14
2022-05-19 12:42:19,915 DEBUG [org.tes.uti.RegistryAuthLocator] (build-8) Looking up auth config for image: alpine:3.14 at registry: index.docker.io
2022-05-19 12:42:19,915 DEBUG [org.tes.uti.RegistryAuthLocator] (build-8) RegistryAuthLocator has configFile: /Users/edeandre/.docker/config.json (exists) and commandPathPrefix: 
2022-05-19 12:42:19,915 DEBUG [org.tes.uti.RegistryAuthLocator] (build-8) registryName [index.docker.io] for dockerImageName [alpine:3.14]
2022-05-19 12:42:19,916 DEBUG [org.tes.uti.RegistryAuthLocator] (build-8) found existing auth config [AuthConfig{username=edeandrea, password=hidden non-blank value, auth=hidden non-blank value, email=null, registryAddress=https://index.docker.io/v1/, registryToken=blank}]
2022-05-19 12:42:19,916 DEBUG [org.tes.uti.RegistryAuthLocator] (build-8) Cached auth found: [AuthConfig{username=edeandrea, password=hidden non-blank value, auth=hidden non-blank value, email=null, registryAddress=https://index.docker.io/v1/, registryToken=blank}]
2022-05-19 12:42:19,916 DEBUG [org.tes.doc.AuthDelegatingDockerClientConfig] (build-8) Effective auth config [AuthConfig{username=edeandrea, password=hidden non-blank value, auth=hidden non-blank value, email=null, registryAddress=https://index.docker.io/v1/, registryToken=blank}]
2022-05-19 12:42:19,921 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (build-8) Cmd: org.testcontainers.shaded.com.github.dockerjava.core.command.CreateContainerCmdImpl@63e77b85[aliases=<null>,argsEscaped=<null>,attachStderr=<null>,attachStdin=<null>,attachStdout=<null>,authConfig=AuthConfig(username=edeandrea, email=null, registryAddress=https://index.docker.io/v1/, stackOrchestrator=null),cmd={tail,-f,/dev/null},domainName=<null>,entrypoint=<null>,env=<null>,exposedPorts=ExposedPorts(exposedPorts=[]),healthcheck=<null>,hostConfig=HostConfig(binds=[], blkioWeight=null, blkioWeightDevice=null, blkioDeviceReadBps=null, blkioDeviceWriteBps=null, blkioDeviceReadIOps=null, blkioDeviceWriteIOps=null, memorySwappiness=null, nanoCPUs=null, capAdd=null, capDrop=null, containerIDFile=null, cpuPeriod=null, cpuRealtimePeriod=null, cpuRealtimeRuntime=null, cpuShares=null, cpuQuota=null, cpusetCpus=null, cpusetMems=null, devices=null, deviceCgroupRules=null, deviceRequests=null, diskQuota=null, dns=null, dnsOptions=null, dnsSearch=null, extraHosts=null, groupAdd=null, ipcMode=null, cgroup=null, links=[], logConfig=LogConfig(type=null, config=null), lxcConf=null, memory=null, memorySwap=null, memoryReservation=null, kernelMemory=null, networkMode=null, oomKillDisable=null, init=null, autoRemove=true, oomScoreAdj=null, portBindings=null, privileged=null, publishAllPorts=null, readonlyRootfs=null, restartPolicy=null, ulimits=null, cpuCount=null, cpuPercent=null, ioMaximumIOps=null, ioMaximumBandwidth=null, volumesFrom=null, mounts=null, pidMode=null, isolation=null, securityOpts=null, storageOpt=null, cgroupParent=null, volumeDriver=null, shmSize=null, pidsLimit=null, runtime=null, tmpFs=null, utSMode=null, usernsMode=null, sysctls=null, consoleSize=null, cgroupnsMode=null),hostName=<null>,image=alpine:3.14,ipv4Address=<null>,ipv6Address=<null>,labels={org.testcontainers=true, org.testcontainers.sessionId=c5a99ea7-47cb-46de-ba5b-2171b148d560},macAddress=<null>,name=testcontainers-checks-c5a99ea7-47cb-46de-ba5b-2171b148d560,networkDisabled=<null>,networkingConfig=<null>,onBuild=<null>,platform=<null>,portSpecs=<null>,shell=<null>,stdInOnce=<null>,stdinOpen=<null>,stopSignal=<null>,stopTimeout=<null>,tty=<null>,user=<null>,volumes=Volumes(volumes=[]),workingDir=<null>]
2022-05-19 12:42:19,980 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (build-8) Cmd: 045ab24e86b9f673936cd559cb447d23bd242de89132dc5a6a506c1dd88e0a98
2022-05-19 12:42:20,216 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (build-8) Cmd: <null>,<null>,true,{df,-P},045ab24e86b9f673936cd559cb447d23bd242de89132dc5a6a506c1dd88e0a98,<null>,<null>,<null>,<null>,<null>
2022-05-19 12:42:20,332 INFO  [org.tes.DockerClientFactory] (build-8) ✔︎ Docker environment should have more than 2GB free disk space
2022-05-19 12:42:20,334 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (build-8) Cmd: 045ab24e86b9f673936cd559cb447d23bd242de89132dc5a6a506c1dd88e0a98,true,true
2022-05-19 12:42:20,537 DEBUG [org.tes.uti.PrefixingImageNameSubstitutor] (build-8) No prefix is configured
2022-05-19 12:42:20,539 DEBUG [org.tes.uti.ImageNameSubstitutor] (build-8) Did not find a substitute image for docker.io/postgres:14.2 (using image substitutor: DefaultImageNameSubstitutor (composite of 'ConfigurationFileImageNameSubstitutor' and 'PrefixingImageNameSubstitutor'))
2022-05-19 12:42:20,539 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (build-8) Cmd: docker.io/postgres:14.2
2022-05-19 12:42:20,555 DEBUG [org.tes.ima.AbstractImagePullPolicy] (build-8) Using locally available and not pulling image: docker.io/postgres:14.2
2022-05-19 12:42:20,555 INFO  [🐳 .io/.2]] (build-8) Creating container for image: docker.io/postgres:14.2
2022-05-19 12:42:20,555 DEBUG [org.tes.uti.RegistryAuthLocator] (build-8) Looking up auth config for image: docker.io/postgres:14.2 at registry: docker.io
2022-05-19 12:42:20,555 DEBUG [org.tes.uti.RegistryAuthLocator] (build-8) RegistryAuthLocator has configFile: /Users/edeandre/.docker/config.json (exists) and commandPathPrefix: 
2022-05-19 12:42:20,555 DEBUG [org.tes.uti.RegistryAuthLocator] (build-8) registryName [docker.io] for dockerImageName [docker.io/postgres:14.2]
2022-05-19 12:42:20,555 DEBUG [org.tes.uti.RegistryAuthLocator] (build-8) No matching Auth Configs - falling back to defaultAuthConfig [null]
2022-05-19 12:42:20,555 DEBUG [org.tes.doc.AuthDelegatingDockerClientConfig] (build-8) Effective auth config [null]
2022-05-19 12:42:20,558 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (build-8) Cmd: org.testcontainers.shaded.com.github.dockerjava.core.command.CreateContainerCmdImpl@20536b8f[aliases=<null>,argsEscaped=<null>,attachStderr=<null>,attachStdin=<null>,attachStdout=<null>,authConfig=<null>,cmd={postgres,-c,fsync=off},domainName=<null>,entrypoint=<null>,env={POSTGRES_USER=quarkus,POSTGRES_PASSWORD=quarkus,POSTGRES_DB=default},exposedPorts=ExposedPorts(exposedPorts=[5432/tcp]),healthcheck=<null>,hostConfig=HostConfig(binds=[], blkioWeight=null, blkioWeightDevice=null, blkioDeviceReadBps=null, blkioDeviceWriteBps=null, blkioDeviceReadIOps=null, blkioDeviceWriteIOps=null, memorySwappiness=null, nanoCPUs=null, capAdd=null, capDrop=null, containerIDFile=null, cpuPeriod=null, cpuRealtimePeriod=null, cpuRealtimeRuntime=null, cpuShares=null, cpuQuota=null, cpusetCpus=null, cpusetMems=null, devices=null, deviceCgroupRules=null, deviceRequests=null, diskQuota=null, dns=null, dnsOptions=null, dnsSearch=null, extraHosts=[], groupAdd=null, ipcMode=null, cgroup=null, links=[], logConfig=LogConfig(type=null, config=null), lxcConf=null, memory=null, memorySwap=null, memoryReservation=null, kernelMemory=null, networkMode=null, oomKillDisable=null, init=null, autoRemove=null, oomScoreAdj=null, portBindings={5432/tcp=[Lcom.github.dockerjava.api.model.Ports$Binding;@10cc2bbf}, privileged=null, publishAllPorts=null, readonlyRootfs=null, restartPolicy=null, ulimits=null, cpuCount=null, cpuPercent=null, ioMaximumIOps=null, ioMaximumBandwidth=null, volumesFrom=[], mounts=null, pidMode=null, isolation=null, securityOpts=null, storageOpt=null, cgroupParent=null, volumeDriver=null, shmSize=null, pidsLimit=null, runtime=null, tmpFs=null, utSMode=null, usernsMode=null, sysctls=null, consoleSize=null, cgroupnsMode=null),hostName=<null>,image=docker.io/postgres:14.2,ipv4Address=<null>,ipv6Address=<null>,labels={org.testcontainers=true, org.testcontainers.sessionId=c5a99ea7-47cb-46de-ba5b-2171b148d560},macAddress=<null>,name=<null>,networkDisabled=<null>,networkingConfig=<null>,onBuild=<null>,platform=<null>,portSpecs=<null>,shell=<null>,stdInOnce=<null>,stdinOpen=<null>,stopSignal=<null>,stopTimeout=<null>,tty=<null>,user=<null>,volumes=Volumes(volumes=[]),workingDir=<null>]
2022-05-19 12:42:20,576 INFO  [🐳 .io/.2]] (build-8) Container docker.io/postgres:14.2 is starting: 56f9083bdfc9461f2c98e3b0e1726db8c66f9c203ff136f286763cfc67512915
2022-05-19 12:42:20,576 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (build-8) Cmd: 56f9083bdfc9461f2c98e3b0e1726db8c66f9c203ff136f286763cfc67512915
2022-05-19 12:42:20,923 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (build-8) Cmd: 56f9083bdfc9461f2c98e3b0e1726db8c66f9c203ff136f286763cfc67512915,false
2022-05-19 12:42:20,924 DEBUG [org.tes.sha.com.git.doc.cor.exe.InspectContainerCmdExec] (build-8) GET: DefaultWebTarget{path=[/containers/56f9083bdfc9461f2c98e3b0e1726db8c66f9c203ff136f286763cfc67512915/json], queryParams={}}
2022-05-19 12:42:20,961 DEBUG [org.tes.sha.com.git.doc.cor.com.AbstrDockerCmd] (ducttape-1) Cmd: 56f9083bdfc9461f2c98e3b0e1726db8c66f9c203ff136f286763cfc67512915,false
2022-05-19 12:42:20,961 DEBUG [org.tes.sha.com.git.doc.cor.exe.InspectContainerCmdExec] (ducttape-1) GET: DefaultWebTarget{path=[/containers/56f9083bdfc9461f2c98e3b0e1726db8c66f9c203ff136f286763cfc67512915/json], queryParams={}}
2022-05-19 12:42:20,968 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: The files belonging to this database system will be owned by user "postgres".
2022-05-19 12:42:20,968 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: creating configuration files ... ok
2022-05-19 12:42:20,968 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: selecting default time zone ... Etc/UTC
2022-05-19 12:42:20,968 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: selecting default shared_buffers ... 128MB
2022-05-19 12:42:20,968 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: selecting default max_connections ... 100
2022-05-19 12:42:20,968 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: selecting dynamic shared memory implementation ... posix
2022-05-19 12:42:20,968 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: creating subdirectories ... ok
2022-05-19 12:42:20,968 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: fixing permissions on existing directory /var/lib/postgresql/data ... ok
2022-05-19 12:42:20,968 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: 
2022-05-19 12:42:20,968 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: Data page checksums are disabled.
2022-05-19 12:42:20,968 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: 
2022-05-19 12:42:20,968 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: The default text search configuration will be set to "english".
2022-05-19 12:42:20,968 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: The default database encoding has accordingly been set to "UTF8".
2022-05-19 12:42:20,969 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: The database cluster will be initialized with locale "en_US.utf8".
2022-05-19 12:42:20,969 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: 
2022-05-19 12:42:20,969 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: This user must also own the server process.
2022-05-19 12:42:21,030 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: running bootstrap script ... ok
2022-05-19 12:42:21,234 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: performing post-bootstrap initialization ... ok
2022-05-19 12:42:21,330 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: syncing data to disk ... ok
2022-05-19 12:42:21,331 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDERR: --auth-local and --auth-host, the next time you run initdb.
2022-05-19 12:42:21,331 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDERR: You can change this by editing pg_hba.conf or using the option -A, or
2022-05-19 12:42:21,331 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDERR: initdb: warning: enabling "trust" authentication for local connections
2022-05-19 12:42:21,332 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: 
2022-05-19 12:42:21,332 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT:     pg_ctl -D /var/lib/postgresql/data -l logfile start
2022-05-19 12:42:21,332 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: 
2022-05-19 12:42:21,332 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: Success. You can now start the database server using:
2022-05-19 12:42:21,332 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: 
2022-05-19 12:42:21,332 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: 
2022-05-19 12:42:21,356 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: waiting for server to start....2022-05-19 16:42:21.174 UTC [48] LOG:  starting PostgreSQL 14.2 (Debian 14.2-1.pgdg110+1) on aarch64-unknown-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit
2022-05-19 12:42:21,356 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: 2022-05-19 16:42:21.174 UTC [48] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2022-05-19 12:42:21,371 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: 2022-05-19 16:42:21.179 UTC [48] LOG:  database system is ready to accept connections
2022-05-19 12:42:21,372 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: 2022-05-19 16:42:21.176 UTC [49] LOG:  database system was shut down at 2022-05-19 16:42:21 UTC
2022-05-19 12:42:21,447 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: server started
2022-05-19 12:42:21,447 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT:  done
2022-05-19 12:42:21,502 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: CREATE DATABASE
2022-05-19 12:42:21,503 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: 
2022-05-19 12:42:21,503 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: /usr/local/bin/docker-entrypoint.sh: ignoring /docker-entrypoint-initdb.d/*
2022-05-19 12:42:21,503 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: 
2022-05-19 12:42:21,503 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: 
2022-05-19 12:42:21,516 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: 2022-05-19 16:42:21.332 UTC [48] LOG:  database system is shut down
2022-05-19 12:42:21,517 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: 2022-05-19 16:42:21.328 UTC [50] LOG:  shutting down
2022-05-19 12:42:21,517 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: waiting for server to shut down....2022-05-19 16:42:21.326 UTC [48] LOG:  background worker "logical replication launcher" (PID 55) exited with exit code 1
2022-05-19 12:42:21,517 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: 2022-05-19 16:42:21.323 UTC [48] LOG:  aborting any active transactions
2022-05-19 12:42:21,517 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: 2022-05-19 16:42:21.323 UTC [48] LOG:  received fast shutdown request
2022-05-19 12:42:21,607 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: 
2022-05-19 12:42:21,608 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: PostgreSQL init process complete; ready for start up.
2022-05-19 12:42:21,608 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: 
2022-05-19 12:42:21,608 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT: server stopped
2022-05-19 12:42:21,608 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDOUT:  done
2022-05-19 12:42:21,621 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDERR: 2022-05-19 16:42:21.440 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2022-05-19 12:42:21,621 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDERR: 2022-05-19 16:42:21.440 UTC [1] LOG:  listening on IPv6 address "::", port 5432
2022-05-19 12:42:21,622 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDERR: 2022-05-19 16:42:21.440 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
2022-05-19 12:42:21,622 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDERR: 2022-05-19 16:42:21.440 UTC [1] LOG:  starting PostgreSQL 14.2 (Debian 14.2-1.pgdg110+1) on aarch64-unknown-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit
2022-05-19 12:42:21,633 DEBUG [org.tes.con.out.WaitingConsumer] (build-8) STDERR: 2022-05-19 16:42:21.445 UTC [1] LOG:  database system is ready to accept connections
2022-05-19 12:42:21,635 INFO  [🐳 .io/.2]] (build-8) Container docker.io/postgres:14.2 started in PT1.097993S
2022-05-19 12:42:21,636 INFO  [io.qua.dev.pos.dep.PostgresqlDevServicesProcessor] (build-8) Dev Services for PostgreSQL started.
2022-05-19 12:42:21,638 INFO  [io.qua.dat.dep.dev.DevServicesDatasourceProcessor] (build-8) Dev Services for the default datasource (postgresql) started.
2022-05-19 12:42:21,641 INFO  [io.qua.hib.orm.dep.HibernateOrmProcessor] (build-8) Setting quarkus.hibernate-orm.database.generation=drop-and-create to initialize Dev Services managed database
2022-05-19 12:42:21,773 WARN  [io.qua.config] (main) Unrecognized configuration key "quarkus.log.category.org.testcontainers.level" was provided; it will be ignored; verify that the dependency extension for this configuration is set or that you did not make a typo
2022-05-19 12:42:22,079 WARN  [io.qua.run.log.LoggingSetupRecorder] (main) Log level FINEST for category 'org.testcontainers' set below minimum logging level DEBUG, promoting it to DEBUG
2022-05-19 12:42:22,103 WARN  [io.agr.pool] (agroal-11) Datasource '<default>': Connection to localhost:49178 refused. Check that the hostname and port are correct and that the postmaster is accepting TCP/IP connections.
2022-05-19 12:42:22,103 WARN  [org.hib.eng.jdb.env.int.JdbcEnvironmentInitiator] (JPA Startup Thread: <default>) HHH000342: Could not obtain connection to query metadata: org.postgresql.util.PSQLException: Connection to localhost:49178 refused. Check that the hostname and port are correct and that the postmaster is accepting TCP/IP connections.
    at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:319)
    at org.postgresql.core.ConnectionFactory.openConnection(ConnectionFactory.java:49)
    at org.postgresql.jdbc.PgConnection.<init>(PgConnection.java:223)
    at org.postgresql.Driver.makeConnection(Driver.java:400)
    at org.postgresql.Driver.connect(Driver.java:259)
    at io.agroal.pool.ConnectionFactory.createConnection(ConnectionFactory.java:226)
    at io.agroal.pool.ConnectionPool$CreateConnectionTask.call(ConnectionPool.java:535)
    at io.agroal.pool.ConnectionPool$CreateConnectionTask.call(ConnectionPool.java:516)
    at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
    at io.agroal.pool.util.PriorityScheduledExecutor.beforeExecute(PriorityScheduledExecutor.java:75)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
    at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: java.net.ConnectException: Connection refused
    at java.base/sun.nio.ch.Net.pollConnect(Native Method)
    at java.base/sun.nio.ch.Net.pollConnectNow(Net.java:672)
    at java.base/sun.nio.ch.NioSocketImpl.timedFinishConnect(NioSocketImpl.java:549)
    at java.base/sun.nio.ch.NioSocketImpl.connect(NioSocketImpl.java:597)
    at java.base/java.net.SocksSocketImpl.connect(SocksSocketImpl.java:327)
    at java.base/java.net.Socket.connect(Socket.java:633)
    at org.postgresql.core.PGStream.createSocket(PGStream.java:241)
    at org.postgresql.core.PGStream.<init>(PGStream.java:98)
    at org.postgresql.core.v3.ConnectionFactoryImpl.tryConnect(ConnectionFactoryImpl.java:109)
    at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:235)
    ... 12 more

2022-05-19 12:42:22,182 WARN  [io.agr.pool] (agroal-11) Datasource '<default>': Connection to localhost:49178 refused. Check that the hostname and port are correct and that the postmaster is accepting TCP/IP connections.
2022-05-19 12:42:22,182 WARN  [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) SQL Error: 0, SQLState: 08001
2022-05-19 12:42:22,182 ERROR [org.hib.eng.jdb.spi.SqlExceptionHelper] (JPA Startup Thread: <default>) Connection to localhost:49178 refused. Check that the hostname and port are correct and that the postmaster is accepting TCP/IP connections.
[ERROR] Tests run: 1, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 13.386 s <<< FAILURE! - in org.acme.GreetingResourceTest
[ERROR] org.acme.GreetingResourceTest.testHelloEndpoint  Time elapsed: 0.001 s  <<< ERROR!
java.lang.RuntimeException: java.lang.RuntimeException: Failed to start quarkus
Caused by: java.lang.RuntimeException: Failed to start quarkus
Caused by: java.lang.RuntimeException: javax.persistence.PersistenceException: [PersistenceUnit: <default>] Unable to build Hibernate SessionFactory
Caused by: javax.persistence.PersistenceException: [PersistenceUnit: <default>] Unable to build Hibernate SessionFactory
Caused by: org.hibernate.exception.JDBCConnectionException: Unable to open JDBC Connection for DDL execution
Caused by: org.postgresql.util.PSQLException: Connection to localhost:49178 refused. Check that the hostname and port are correct and that the postmaster is accepting TCP/IP connections.
Caused by: java.net.ConnectException: Connection refused

[INFO] 
[INFO] Results:
[INFO] 
[ERROR] Errors: 
[ERROR]   GreetingResourceTest.testHelloEndpoint » Runtime java.lang.RuntimeException: F...
[INFO] 
[ERROR] Tests run: 1, Failures: 0, Errors: 1, Skipped: 0
[INFO] 
[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time:  15.567 s
[INFO] Finished at: 2022-05-19T12:42:22-04:00
[INFO] ------------------------------------------------------------------------
edeandrea commented 2 years ago

@gastaldi could it be related to the docker daemon i'm running? I'm mostly using Rancher Desktop (I don't even have docker desktop installed on my machine).

gastaldi commented 2 years ago

That's possible, I am using Docker Desktop. Can you give it a try?

edeandrea commented 2 years ago

You have $5 for me to pay them? :)

Just kidding - let me go download & install it.

edeandrea commented 2 years ago

as thats downloading in the background I switched off Rancher Desktop and started up podman. So far I can't seem to reproduce it using podman.

gastaldi commented 2 years ago

@edeandrea you can expense Docker Desktop if you need it, talk to Dimitri about it.

I compared the output and the only difference I noticed with my output is that I don't see the listening on IPv4 address "0.0.0.0", port 5432 in the logs

edeandrea commented 2 years ago

ran it a bunch of times with docker desktop & podman - can't reproduce it. I blew away my rancher desktop instance & re-created it. Ran ok a few times but then started up again.

I'd say go ahead and close this for now. If it crops back up I'll come back & re-open.

edeandrea commented 2 years ago

Thank you @gastaldi for looking at it!

gastaldi commented 2 years ago

/cc @tqvarnst

therealjsie commented 2 years ago

@gastaldi @tqvarnst

Just wanted to let you know that this is a reproducible problem with 2021 MacBook M1 Pros and Rancher Desktop. When running quarkus dev (for example) it is possible to connect to a testcontainers Postgres instance on the first run but not on any of the following runs. We've tested it on multiple MacBooks and we always see the same behaviour. No issues with Docker Desktop. I'll add the logs of gradle quarkusTest to give you some context.

Logs: quarkus-test-rancher-desktop.log

kiview commented 2 years ago

Does quarkus dev keep the containers running? If this is achieved via reusable mode in Testcontainers, note that this is an experimental alpha feature and it might not work with alternative container engines, since they might break certain assumptions.

From your logs I see, that your code tried to connect to localhost:49260, where was the container actually run, and which port was exposed?

therealjsie commented 2 years ago

quarkus dev keeps the containers running but I'm not sure how this is implemented. The problems also occurs with other commands that don't keep the containers running, e.g. gradle quarkusTest.

Network setup seems finde overall. The targeted URI is correct. The container was run at localhost:42960 and I was able to connect to the URI from my cli via psql. I'm not sure if this is an issue where Testcontainers tries to connect to the DB before it's started and times out right away.

kiview commented 2 years ago

The log you shared had no errors from Testcontainers, they came from Liquibase.

edeandrea commented 2 years ago

In my original comment when I created this issue I was not using liquibase. Just postgresql. The problem does not exist with any of the other jdbc drivers (MySQL/etc).

I don't know if it's a testcontainers thing or a Quarkus thing. I just know that it consistently doesn't work with rancher desktop but is fine with docker desktop.

kiview commented 2 years ago

Oh, now I have an idea... The PostgresSQL image behaves very differently when there is already data present. I haven't checked your example in detail, but it could be related to this issue: https://github.com/testcontainers/testcontainers-java/pull/5501

edeandrea commented 2 years ago

Nope no sample data. Just a REST endpoint and a JPA Entity object.

edeandrea commented 2 years ago

FWIW - this is where the PostgreSQL container is stood up by Quarkus Dev Services: https://github.com/quarkusio/quarkus/blob/main/extensions/devservices/postgresql/src/main/java/io/quarkus/devservices/postgresql/deployment/PostgresqlDevServicesProcessor.java

InfoSec812 commented 2 years ago

I'm seeing this as well on both a Debian machine and a Fedora 36 machine (podman 4.1.0 and 4.1.1 respectively)... 

Database for the default datasource (postgresql) starting: 2022-08-03 11:00:11,185 INFO  [🐳 .io/postgres:14]] (build-22) Container docker.io/postgres:14 is starting: f2749623012b1e8249cdc4fd2abd0d34262c2b53ad66963f8e7592e87dabf402

It just hangs at this point.

Installing and using docker works

Quarkus 2.11.1 Termurin OpenJDK 17.0.4 (also tried 11.0.5 and Mandrel)

edeandrea commented 2 years ago

I'm re-opening this because others seem to be reporting it (or similar things) on non-mac m1 machines.

InfoSec812 commented 2 years ago

I have also found that with Podman it is apparently only ever the LAST service which causes the hang. When inspecting the containers, the service is UP and running, but DevServices does not recognize whatever the last service to complete is. If I add Kafka or SSO or whatever, it's only the last one starting which gets stuck and not just PostgreSQL

agoncal commented 2 years ago

I'm giving the Super Heroes workshop to a bunch of developers. The ones Rancher Desktop on Mac M1 (eg. @ggui) can't make the workshop work because of DevServices (TestContainers) pulling the Postgres image. This is the stack trace that they have:

2022-09-23 15:56:27,693 ERROR [io.qua.dep.dev.IsolatedDevModeMain] (main) Failed to start quarkus: java.lang.RuntimeException: io.quarkus.builder.BuildException: Build failure: Build failed due to errors
[error]: Build step io.quarkus.datasource.deployment.devservices.DevServicesDatasourceProcessor#launchDatabases threw an exception: java.lang.RuntimeException: java.lang.IllegalStateException: Previous attempts to find a Docker environment failed. Will not retry. Please see logs and check configuration
at io.quarkus.datasource.deployment.devservices.DevServicesDatasourceProcessor.startDevDb(DevServicesDatasourceProcessor.java:312)
at io.quarkus.datasource.deployment.devservices.DevServicesDatasourceProcessor.launchDatabases(DevServicesDatasourceProcessor.java:125)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:568)
at io.quarkus.deployment.ExtensionLoader$3.execute(ExtensionLoader.java:925)
at io.quarkus.builder.BuildContext.run(BuildContext.java:277)
at org.jboss.threads.ContextHandler$1.runWith(ContextHandler.java:18)
at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2449)
at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1478)
at java.base/java.lang.Thread.run(Thread.java:833)
at org.jboss.threads.JBossThread.run(JBossThread.java:501)
Caused by: java.lang.IllegalStateException: Previous attempts to find a Docker environment failed. Will not retry. Please see logs and check configuration
at org.testcontainers.dockerclient.DockerClientProviderStrategy.getFirstValidStrategy(DockerClientProviderStrategy.java:115)
at org.testcontainers.DockerClientFactory.getOrInitializeStrategy(DockerClientFactory.java:147)
at org.testcontainers.DockerClientFactory.client(DockerClientFactory.java:188)
at org.testcontainers.DockerClientFactory$1.getDockerClient(DockerClientFactory.java:102)
at com.github.dockerjava.api.DockerClientDelegate.authConfig(DockerClientDelegate.java:108)
at org.testcontainers.containers.GenericContainer.start(GenericContainer.java:325)
at io.quarkus.devservices.postgresql.deployment.PostgresqlDevServicesProcessor$1.startDatabase(PostgresqlDevServicesProcessor.java:51)
at io.quarkus.datasource.deployment.devservices.DevServicesDatasourceProcessor.startDevDb(DevServicesDatasourceProcessor.java:265)
... 12 more

at io.quarkus.runner.bootstrap.AugmentActionImpl.runAugment(AugmentActionImpl.java:330)
at io.quarkus.runner.bootstrap.AugmentActionImpl.createInitialRuntimeApplication(AugmentActionImpl.java:252)
at io.quarkus.runner.bootstrap.AugmentActionImpl.createInitialRuntimeApplication(AugmentActionImpl.java:60)
at io.quarkus.deployment.dev.IsolatedDevModeMain.firstStart(IsolatedDevModeMain.java:95)
at io.quarkus.deployment.dev.IsolatedDevModeMain.accept(IsolatedDevModeMain.java:485)
at io.quarkus.deployment.dev.IsolatedDevModeMain.accept(IsolatedDevModeMain.java:68)
at io.quarkus.bootstrap.app.CuratedApplication.runInCl(CuratedApplication.java:142)
at io.quarkus.bootstrap.app.CuratedApplication.runInAugmentClassLoader(CuratedApplication.java:97)
at io.quarkus.deployment.dev.DevModeMain.start(DevModeMain.java:132)
at io.quarkus.deployment.dev.DevModeMain.main(DevModeMain.java:62)
Caused by: io.quarkus.builder.BuildException: Build failure: Build failed due to errors
[error]: Build step io.quarkus.datasource.deployment.devservices.DevServicesDatasourceProcessor#launchDatabases threw an exception: java.lang.RuntimeException: java.lang.IllegalStateException: Previous attempts to find a Docker environment failed. Will not retry. Please see logs and check configuration
at io.quarkus.datasource.deployment.devservices.DevServicesDatasourceProcessor.startDevDb(DevServicesDatasourceProcessor.java:312)
at io.quarkus.datasource.deployment.devservices.DevServicesDatasourceProcessor.launchDatabases(DevServicesDatasourceProcessor.java:125)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:568)
at io.quarkus.deployment.ExtensionLoader$3.execute(ExtensionLoader.java:925)
at io.quarkus.builder.BuildContext.run(BuildContext.java:277)
at org.jboss.threads.ContextHandler$1.runWith(ContextHandler.java:18)
at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2449)
at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1478)
at java.base/java.lang.Thread.run(Thread.java:833)
at org.jboss.threads.JBossThread.run(JBossThread.java:501)
Caused by: java.lang.IllegalStateException: Previous attempts to find a Docker environment failed. Will not retry. Please see logs and check configuration
at org.testcontainers.dockerclient.DockerClientProviderStrategy.getFirstValidStrategy(DockerClientProviderStrategy.java:115)
at org.testcontainers.DockerClientFactory.getOrInitializeStrategy(DockerClientFactory.java:147)
at org.testcontainers.DockerClientFactory.client(DockerClientFactory.java:188)
at org.testcontainers.DockerClientFactory$1.getDockerClient(DockerClientFactory.java:102)
at com.github.dockerjava.api.DockerClientDelegate.authConfig(DockerClientDelegate.java:108)
at org.testcontainers.containers.GenericContainer.start(GenericContainer.java:325)
at io.quarkus.devservices.postgresql.deployment.PostgresqlDevServicesProcessor$1.startDatabase(PostgresqlDevServicesProcessor.java:51)
at io.quarkus.datasource.deployment.devservices.DevServicesDatasourceProcessor.startDevDb(DevServicesDatasourceProcessor.java:265)
... 12 more

at io.quarkus.builder.Execution.run(Execution.java:116)
at io.quarkus.builder.BuildExecutionBuilder.execute(BuildExecutionBuilder.java:79)
at io.quarkus.deployment.QuarkusAugmentor.run(QuarkusAugmentor.java:157)
at io.quarkus.runner.bootstrap.AugmentActionImpl.runAugment(AugmentActionImpl.java:328)
... 9 more
Caused by: java.lang.RuntimeException: java.lang.IllegalStateException: Previous attempts to find a Docker environment failed. Will not retry. Please see logs and check configuration
at io.quarkus.datasource.deployment.devservices.DevServicesDatasourceProcessor.startDevDb(DevServicesDatasourceProcessor.java:312)
at io.quarkus.datasource.deployment.devservices.DevServicesDatasourceProcessor.launchDatabases(DevServicesDatasourceProcessor.java:125)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:568)
at io.quarkus.deployment.ExtensionLoader$3.execute(ExtensionLoader.java:925)
at io.quarkus.builder.BuildContext.run(BuildContext.java:277)
GGui commented 2 years ago

I was able to run the container by adding the following environment variables: export TESTCONTAINERS_DOCKER_SOCKET_OVERRIDE=/var/run/docker.sock export DOCKER_HOST="unix://${HOME}/.rd/docker.sock"

kiview commented 2 years ago

@agoncal I think the Rancher Desktop part of the docs should be augmented to include the necessary config, as pointed out by @GGui.

Furthermore, I found the recommendation to set RYUK_DISABLED=true. This is not recommended for desktop usage and is normally not necessary. I would prefer if we can discuss removing the paragraph, or else highlighting, that this can have unintended consequences.

adroste commented 2 years ago

I can confirm the race condition when starting containers with Rancher Desktop. Seems like quarkus continues with the init process before the postgres container/docker network is ready. Docker Desktop works fine.

Env: M1 Mac, macOS 12.6

I think that is is a Rancher Desktop issue rather than a quarkus one. ( https://github.com/rancher-sandbox/rancher-desktop/issues/2609 )

2022-09-28 09:50:00,067 INFO  [io.qua.dat.dep.dev.DevServicesDatasourceProcessor] (build-62) Dev Services for the default datasource (postgresql) started.
2022-09-28 09:50:00,843 INFO  [io.agr.pool] (Quarkus Main Thread) Datasource '<default>': Initial size smaller than min. Connections will be created when necessary
[... flyway output ...]
2022-09-28 09:50:05,932 ERROR [io.qua.run.Application] (Quarkus Main Thread) Failed to start application (with profile dev): java.util.concurrent.TimeoutException
        at java.base/java.util.concurrent.FutureTask.get(FutureTask.java:204)
        at io.agroal.pool.ConnectionPool.handlerFromSharedCache(ConnectionPool.java:279)
        at io.agroal.pool.ConnectionPool.getConnection(ConnectionPool.java:248)
        at io.agroal.pool.DataSource.getConnection(DataSource.java:86)
        at org.flywaydb.core.internal.jdbc.JdbcUtils.openConnection(JdbcUtils.java:48)
        at org.flywaydb.core.internal.jdbc.JdbcConnectionFactory.<init>(JdbcConnectionFactory.java:75)
        at org.flywaydb.core.FlywayExecutor.execute(FlywayExecutor.java:147)
        at org.flywaydb.core.Flyway.migrate(Flyway.java:124)
        at io.quarkus.flyway.runtime.FlywayRecorder.doStartActions(FlywayRecorder.java:76)
        at io.quarkus.deployment.steps.FlywayProcessor$createBeansAndStartActions2063183959.deploy_0(Unknown Source)
        at io.quarkus.deployment.steps.FlywayProcessor$createBeansAndStartActions2063183959.deploy(Unknown Source)
        at io.quarkus.runner.ApplicationImpl.doStart(Unknown Source)
        at io.quarkus.runtime.Application.start(Application.java:101)
        at io.quarkus.runtime.ApplicationLifecycleManager.run(ApplicationLifecycleManager.java:103)
        at io.quarkus.runtime.Quarkus.run(Quarkus.java:67)
        at io.quarkus.runtime.Quarkus.run(Quarkus.java:41)
        at io.quarkus.runtime.Quarkus.run(Quarkus.java:120)
        at io.quarkus.runner.GeneratedMain.main(Unknown Source)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:568)
        at io.quarkus.runner.bootstrap.StartupActionImpl$1.run(StartupActionImpl.java:103)
        at java.base/java.lang.Thread.run(Thread.java:833)

2022-09-28 09:50:05,959 INFO  [io.qua.dep.dev.IsolatedDevModeMain] (main) Attempting to start live reload endpoint to recover from previous Quarkus startup failure
2022-09-28 09:50:05,959 INFO  [io.qua.dep.dev.IsolatedDevModeMain] (main) Attempting to start live reload endpoint to recover from previous Quarkus startup failure
2022-09-28 09:50:06,054 WARN  [io.net.uti.con.DefaultPromise] (vert.x-acceptor-thread-0) An exception was thrown by io.vertx.core.net.impl.TCPServerBase$$Lambda$1454/0x0000000801736ed8.operationComplete(): java.lang.IllegalStateException: HttpBinderConfiguration was not found
        at io.quarkus.micrometer.runtime.binder.vertx.VertxMeterBinderAdapter.createHttpServerMetrics(VertxMeterBinderAdapter.java:50)
        at io.vertx.core.http.impl.HttpServerImpl.createMetrics(HttpServerImpl.java:71)
        at io.vertx.core.net.impl.TCPServerBase.lambda$listen$2(TCPServerBase.java:186)
        at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:578)
        at io.netty.util.concurrent.DefaultPromise.notifyListeners0(DefaultPromise.java:571)
        at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:550)
        at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:491)
        at io.netty.util.concurrent.DefaultPromise.setValue0(DefaultPromise.java:616)
        at io.netty.util.concurrent.DefaultPromise.setSuccess0(DefaultPromise.java:605)
        at io.netty.util.concurrent.DefaultPromise.setSuccess(DefaultPromise.java:96)
        at io.vertx.core.net.impl.AsyncResolveConnectHelper.lambda$null$1(AsyncResolveConnectHelper.java:61)
        at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:578)
        at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:552)
        at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:491)
        at io.netty.util.concurrent.DefaultPromise.setValue0(DefaultPromise.java:616)
        at io.netty.util.concurrent.DefaultPromise.setSuccess0(DefaultPromise.java:605)
        at io.netty.util.concurrent.DefaultPromise.trySuccess(DefaultPromise.java:104)
        at io.netty.channel.DefaultChannelPromise.trySuccess(DefaultChannelPromise.java:84)
        at io.netty.channel.AbstractChannel$AbstractUnsafe.safeSetSuccess(AbstractChannel.java:990)
        at io.netty.channel.AbstractChannel$AbstractUnsafe.bind(AbstractChannel.java:578)
        at io.netty.channel.DefaultChannelPipeline$HeadContext.bind(DefaultChannelPipeline.java:1334)
        at io.netty.channel.AbstractChannelHandlerContext.invokeBind(AbstractChannelHandlerContext.java:506)
        at io.netty.channel.AbstractChannelHandlerContext.bind(AbstractChannelHandlerContext.java:491)
        at io.netty.channel.DefaultChannelPipeline.bind(DefaultChannelPipeline.java:973)
        at io.netty.channel.AbstractChannel.bind(AbstractChannel.java:260)
        at io.netty.bootstrap.AbstractBootstrap$2.run(AbstractBootstrap.java:356)
        at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasksFrom(SingleThreadEventExecutor.java:425)
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:374)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:491)
        at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986)
        at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.base/java.lang.Thread.run(Thread.java:833)

and 

2022-09-28 09:48:41,435 INFO  [org.tes.uti.RyukResourceReaper] (build-26) Ryuk started - will monitor and terminate Testcontainers containers on JVM exit
2022-09-28 09:48:41,436 INFO  [org.tes.DockerClientFactory] (build-26) Checking the system...
2022-09-28 09:48:41,436 INFO  [org.tes.DockerClientFactory] (build-26) ✔︎ Docker server version should be at least 1.6.0
2022-09-28 09:48:41,450 INFO  [🐳 .io/.2]] (build-26) Creating container for image: docker.io/postgres:14.2
2022-09-28 09:48:41,479 INFO  [org.tes.uti.RegistryAuthLocator] (build-26) Credential helper/store (docker-credential-osxkeychain) does not have credentials for docker.io
2022-09-28 09:48:41,479 WARN  [🐳 .io/.2]] (build-26) Reuse was requested but the environment does not support the reuse of containers
To enable reuse of containers, you must set 'testcontainers.reuse.enable=true' in a file located at /Users/adroste/.testcontainers.properties
2022-09-28 09:48:41,502 INFO  [🐳 .io/.2]] (build-26) Container docker.io/postgres:14.2 is starting: 9c9df89b3c53c727dbde6d9913b84ef6515b33c2e4d16ff8b3c97ad1e49e1455
2022-09-28 09:48:42,899 INFO  [🐳 .io/.2]] (build-26) Container docker.io/postgres:14.2 started in PT1.459478S
2022-09-28 09:48:42,899 INFO  [io.qua.dev.pos.dep.PostgresqlDevServicesProcessor] (build-26) Dev Services for PostgreSQL started.
2022-09-28 09:48:42,900 INFO  [io.qua.dat.dep.dev.DevServicesDatasourceProcessor] (build-26) Dev Services for the default datasource (postgresql) started.
2022-09-28 09:48:43,626 INFO  [io.agr.pool] (main) Datasource '<default>': Initial size smaller than min. Connections will be created when necessary
[... flyway output ...]
2022-09-28 09:48:43,756 WARN  [io.agr.pool] (agroal-11) Datasource '<default>': Connection to localhost:49160 refused. Check that the hostname and port are correct and that the postmaster is accepting TCP/IP connections.
[ERROR] Tests run: 1, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 8.928 s <<< FAILURE! - in org.tkit.portal.rs.internal.AdminUserApiTest
[ERROR] org.tkit.portal.rs.internal.AdminUserApiTest  Time elapsed: 8.928 s  <<< ERROR!
java.lang.RuntimeException: java.lang.RuntimeException: Failed to start quarkus
Caused by: java.lang.RuntimeException: Failed to start quarkus
Caused by: org.flywaydb.core.internal.exception.FlywaySqlException: 
Unable to obtain connection from database: Connection to localhost:49160 refused. Check that the hostname and port are correct and that the postmaster is accepting TCP/IP connections.
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL State  : 08001
Error Code : 0
Message    : Connection to localhost:49160 refused. Check that the hostname and port are correct and that the postmaster is accepting TCP/IP connections.

Caused by: org.postgresql.util.PSQLException: Connection to localhost:49160 refused. Check that the hostname and port are correct and that the postmaster is accepting TCP/IP connections.
Caused by: java.net.ConnectException: Connection refused
kiview commented 2 years ago

@adroste AFAIK Rancher Desktop has very different timing behavior regarding its networking and exposing ports as compared to Docker, so it breaks Testcontainers' assumptions of a Docker-compatible API.

bpasson commented 7 months ago

@gastaldi Any news on this one. The closed issue mentions it has something to do with ports being available on different times for docker-desktop and rancher-desktop. The suggestion is to use different waiting strategy Wait.forListeningPort(). Quarkus already uses a customized waiting strategy can this be added as it might help out rancher-desktop users.

gastaldi commented 7 months ago

Quarkus already uses a customized waiting strategy can this be added as it might help out rancher-desktop users.

Added where exactly? In our guides?

bpasson commented 7 months ago

@gastaldi see the line below. There a custom strategy is introduces for waiting the container to be ready. https://github.com/quarkusio/quarkus/blob/e7f2a1ee4aff4c5efeba2d414fb696d0ac47f1f4/extensions/devservices/postgresql/src/main/java/io/quarkus/devservices/postgresql/deployment/PostgresqlDevServicesProcessor.java#L109

If that could be combined with the Wait.forListeningPort() strategy my guess is it would work for rancher-desktop too as the PR https://github.com/testcontainers/testcontainers-java/pull/6309 suggests.

gastaldi commented 7 months ago

Interesting, can you test and submit a PR? That would be awesome if it worked

gsmet commented 7 months ago

Yeah, I was having a look at all this and I think it makes sense.

If you can push a PR combining the existing one with the one waiting for the port to open using WaitAllStrategy, it's something we could merge.

bpasson commented 7 months ago

Sure, I'll see if I can get it working. Never poked around in a dev service before, but this change seems simple enough.

gsmet commented 7 months ago

Ping us if you have questions but yes, it should be a fairly simple change.

bpasson commented 7 months ago

@gsmet @gastaldi I hit a snag with current main, quarkus-flyway uses flyway 10.10.0, but it seems the change mentioned here https://github.com/flyway/flyway/issues/3780 where flyway is split up per database was not accounted for. This is probably a completely different issue, but I ran into it using one of my many projects to test the postgres container. Is this on the radar?

gastaldi commented 7 months ago

Yes, it's described here: https://github.com/quarkusio/quarkus/wiki/Migration-Guide-3.10#flyway-10

bpasson commented 7 months ago

Good. The notes also tells me how to fix my snag. Thnx @gastaldi