Having "Could not find a valid Docker environment. " error what causes test flakiness.
private fun initContainerDatabase(): Database {
println("Initialising container database")
val dockerImage =
System.getProperty(
"postgresdaltest.testcontainers.postgresdockerimagename",
"postgres:11"
)
val localContainer = PostgreSQLContainer<Nothing>(dockerImage)
.apply {
if (isRunning) {
return@apply
}
start()
Flyway.configure()
.dataSource(jdbcUrl, username, password)
.load()
.migrate()
}
but not sure if exact docker image does matter.
We have seen this issue on JVM 11 as well but on JVM 17 it becomes even more painful. Assume issue can be related to changes in 1.16.1 where a sort of race-conditions are possible so looks like fix #4597 does not solve issue completely.
Initialising container database
17:33:28.992 [Test worker] DEBUG org.testcontainers.utility.TestcontainersConfiguration - Testcontainers configuration overrides will be loaded from file:/Users/alexey/.testcontainers.properties
17:33:29.217 [Test worker] INFO org.testcontainers.dockerclient.DockerClientProviderStrategy - Loaded org.testcontainers.dockerclient.UnixSocketClientProviderStrategy from ~/.testcontainers.properties, will try it first
17:33:29.338 [Test worker] DEBUG org.testcontainers.dockerclient.DockerClientProviderStrategy - Trying out strategy: UnixSocketClientProviderStrategy
17:33:36.874 [ducttape-0] DEBUG org.testcontainers.dockerclient.DockerClientProviderStrategy - Pinging docker daemon...
17:33:37.071 [ducttape-0] DEBUG org.testcontainers.shaded.com.github.dockerjava.core.command.AbstrDockerCmd - Cmd:
17:33:37.605 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.classic.InternalHttpClient - ex-00000001: preparing request execution
17:33:37.749 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.protocol.RequestAddCookies - Cookie spec selected: strict
17:33:37.960 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.protocol.RequestAuthCache - Auth cache not set in the context
17:33:37.960 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.classic.ProtocolExec - ex-00000001: target auth state: UNCHALLENGED
17:33:37.964 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.classic.ProtocolExec - ex-00000001: proxy auth state: UNCHALLENGED
17:33:37.965 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.classic.ConnectExec - ex-00000001: acquiring connection with route {}->unix://localhost:2375
17:33:37.966 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.classic.InternalHttpClient - ex-00000001: acquiring endpoint (3 MINUTES)
17:33:37.973 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager - ex-00000001: endpoint lease request (3 MINUTES) [route: {}->unix://localhost:2375][total available: 0; route allocated: 0 of 2147483647; total allocated: 0 of 2147483647]
17:33:38.102 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager - ex-00000001: endpoint leased [route: {}->unix://localhost:2375][total available: 0; route allocated: 1 of 2147483647; total allocated: 1 of 2147483647]
17:33:38.464 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager - ex-00000001: acquired ep-00000000
17:33:38.465 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.classic.InternalHttpClient - ex-00000001: acquired endpoint ep-00000000
17:33:38.465 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.classic.ConnectExec - ex-00000001: opening connection {}->unix://localhost:2375
17:33:38.468 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.classic.InternalHttpClient - ep-00000000: connecting endpoint (3 MINUTES)
17:33:38.468 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager - ep-00000000: connecting endpoint to unix://localhost:2375 (3 MINUTES)
17:33:38.577 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.io.DefaultHttpClientConnectionOperator - http-outgoing-0: connecting to localhost/127.0.0.1:2375
17:33:38.618 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.io.DefaultHttpClientConnectionOperator - http-outgoing-0: connection established /var/run/docker.sock<->/var/run/docker.sock
17:33:38.627 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager - ep-00000000: connected http-outgoing-0
17:33:38.628 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.classic.InternalHttpClient - ep-00000000: endpoint connected
17:33:38.634 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.classic.MainClientExec - ex-00000001: executing GET /v1.32/info HTTP/1.1
17:33:38.637 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.classic.InternalHttpClient - ep-00000000: start execution ex-00000001
17:33:38.637 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager - ep-00000000: executing exchange ex-00000001 over http-outgoing-0
17:33:38.638 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers - http-outgoing-0 >> GET /v1.32/info HTTP/1.1
17:33:38.639 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers - http-outgoing-0 >> Accept-Encoding: gzip, x-gzip, deflate
17:33:38.639 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers - http-outgoing-0 >> Host: localhost:2375
17:33:38.639 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers - http-outgoing-0 >> Connection: keep-alive
17:33:38.640 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers - http-outgoing-0 >> User-Agent: Apache-HttpClient/5.0.3 (Java/17.0.2)
17:33:38.641 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire - http-outgoing-0 >> "GET /v1.32/info HTTP/1.1[\r][\n]"
17:33:38.641 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire - http-outgoing-0 >> "Accept-Encoding: gzip, x-gzip, deflate[\r][\n]"
17:33:38.641 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire - http-outgoing-0 >> "Host: localhost:2375[\r][\n]"
17:33:38.641 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire - http-outgoing-0 >> "Connection: keep-alive[\r][\n]"
17:33:38.642 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire - http-outgoing-0 >> "User-Agent: Apache-HttpClient/5.0.3 (Java/17.0.2)[\r][\n]"
17:33:38.642 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire - http-outgoing-0 >> "[\r][\n]"
17:33:39.367 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire - http-outgoing-0 << "HTTP/1.1 200 OK[\r][\n]"
17:33:39.367 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire - http-outgoing-0 << "Api-Version: 1.41[\r][\n]"
17:33:39.367 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire - http-outgoing-0 << "Content-Type: application/json[\r][\n]"
17:33:39.367 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire - http-outgoing-0 << "Date: Fri, 04 Feb 2022 14:33:39 GMT[\r][\n]"
17:33:39.367 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire - http-outgoing-0 << "Docker-Experimental: false[\r][\n]"
17:33:39.367 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire - http-outgoing-0 << "Ostype: linux[\r][\n]"
17:33:39.368 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire - http-outgoing-0 << "Server: Docker/20.10.12 (linux)[\r][\n]"
17:33:39.368 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire - http-outgoing-0 << "Transfer-Encoding: chunked[\r][\n]"
17:33:39.368 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire - http-outgoing-0 << "[\r][\n]"
17:33:39.379 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers - http-outgoing-0 << HTTP/1.1 200 OK
17:33:39.380 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers - http-outgoing-0 << Api-Version: 1.41
17:33:39.380 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers - http-outgoing-0 << Content-Type: application/json
17:33:39.380 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers - http-outgoing-0 << Date: Fri, 04 Feb 2022 14:33:39 GMT
17:33:39.380 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers - http-outgoing-0 << Docker-Experimental: false
17:33:39.380 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers - http-outgoing-0 << Ostype: linux
17:33:39.380 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers - http-outgoing-0 << Server: Docker/20.10.12 (linux)
17:33:39.380 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.headers - http-outgoing-0 << Transfer-Encoding: chunked
17:33:39.404 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.classic.MainClientExec - ex-00000001: connection can be kept alive for 3 MINUTES
17:33:39.532 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire - http-outgoing-0 << "8f5[\r][\n]"
17:33:39.535 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire - http-outgoing-0 << "{"ID":"4WGZ:I5FG:XPZ2:SZ7D:KA7B:J7XL:BORT:UWZR:Y5QG:ON4U:EUZO:4SCN","Containers":90,"ContainersRunning":11,"ContainersPaused":0,"ContainersStopped":79,"Images":14,"Driver":"overlay2","DriverStatus":[["Backing Filesystem","extfs"],["Supports d_type","true"],["Native Overlay Diff","true"],["userxattr","false"]],"Plugins":{"Volume":["local"],"Network":["bridge","host","ipvlan","macvlan","null","overlay"],"Authorization":null,"Log":["awslogs","fluentd","gcplogs","gelf","journald","json-file","local","logentries","splunk","syslog"]},"MemoryLimit":true,"SwapLimit":true,"KernelMemory":false,"KernelMemoryTCP":false,"CpuCfsPeriod":true,"CpuCfsQuota":true,"CPUShares":true,"CPUSet":true,"PidsLimit":true,"IPv4Forwarding":true,"BridgeNfIptables":true,"BridgeNfIp6tables":true,"Debug":false,"NFd":94,"OomKillDisable":false,"NGoroutines":84,"SystemTime":"2022-02-04T14:33:38.8004248Z","LoggingDriver":"json-file","CgroupDriver":"cgroupfs","CgroupVersion":"2","NEventsListener":7,"KernelVersion":"5.10.76-linuxkit","OperatingSystem":"Docker Desktop","OSVersion":"","OSType":"linux","Architecture":"x86_64","IndexServerAddress":"https://index.docker.io/v1/","RegistryConfig":{"AllowNondistributableArtifactsCIDRs":[],"AllowNondistributableArtifactsHostnames":[],"InsecureRegistryCIDRs":["127.0.0.0/8"],"IndexConfigs":{"docker.io":{"Name":"docker.io","Mirrors":[],"Secure":true,"Official":true}},"Mirrors":[]},"NCPU":4,"MemTotal":2082197504,"GenericResources":null,"DockerRootDir":"/var/lib/docker","HttpProxy":"","HttpsProxy":"","NoProxy":"","Name":"docker-desktop","Labels":[],"ExperimentalBuild":false,"ServerVersion":"20.10.12","Runtimes":{"io.containerd.runc.v2":{"path":"runc"},"io.containerd.runtime.v1.linux":{"path":"runc"},"runc":{"path":"runc"}},"DefaultRuntime":"runc","Swarm":{"NodeID":"","NodeAddr":"","LocalNodeState":"inactive","ControlAvailable":false,"Error":"","RemoteManagers":null},"LiveRestoreEnabled":false,"Isolation":"","InitBinary":"docker-init","ContainerdCommit":{"ID":"7b11cfaabd73bb80907dd23182b9347b4245eb5d","Expected":"7b11cfaabd73bb80907dd23182b9347b4245eb5d"},"RuncCommit":{"ID":"v1.0.2-0-g52b36a2","Expected":"v1.0.2-0-g52b36a2"},"InitCommit":{"ID":"de40ad0","Expected":"de40ad0"},"SecurityOptions":["name=seccomp,profile=default","name=cgroupns"],"Warnings":null}[\n]"
17:33:39.546 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire - http-outgoing-0 << "[\r][\n]"
17:33:39.558 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire - http-outgoing-0 << "0[\r][\n]"
17:33:39.558 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.wire - http-outgoing-0 << "[\r][\n]"
17:33:41.913 [Test worker] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager - Shutdown connection pool GRACEFUL
17:33:41.913 [Test worker] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.io.DefaultManagedHttpClientConnection - http-outgoing-0: close connection GRACEFUL
17:33:41.916 [Test worker] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager - Connection pool shut down
17:33:41.920 [Test worker] DEBUG org.testcontainers.dockerclient.DockerClientProviderStrategy - UnixSocketClientProviderStrategy: failed with exception TimeoutException (org.rnorth.ducttape.TimeoutException: java.util.concurrent.TimeoutException). Root cause TimeoutException (null)
17:33:41.923 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.classic.InternalHttpClient - ep-00000000: releasing valid endpoint
17:33:41.924 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager - ep-00000000: releasing endpoint
17:33:41.925 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager - ep-00000000: connection is not kept alive
17:33:41.926 [ducttape-0] DEBUG com.github.dockerjava.zerodep.shaded.org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager - ep-00000000: connection released [route: {}->unix://localhost:2375][total available: 0; route allocated: 0 of 2147483647; total allocated: 0 of 2147483647]
17:33:41.934 [Test worker] DEBUG org.testcontainers.utility.CommandLine - Executing shell command: `docker-machine ls -q`
17:33:41.981 [Test worker] DEBUG org.testcontainers.shaded.org.zeroturnaround.exec.ProcessExecutor - Executing [docker-machine, ls, -q].
17:33:41.998 [Test worker] DEBUG org.testcontainers.shaded.org.zeroturnaround.exec.ProcessExecutor - Started Process[pid=15977, exitValue="not exited"]
17:33:42.097 [Test worker] DEBUG org.testcontainers.shaded.org.zeroturnaround.exec.WaitForProcess - Process[pid=15977, exitValue=0] stopped with exit code 0
17:33:42.102 [Test worker] DEBUG org.testcontainers.utility.DockerMachineClient - DOCKER_MACHINE_NAME is not set and no machine named 'default' found; Using first machine found with `docker-machine ls`:
17:33:42.102 [Test worker] DEBUG org.testcontainers.dockerclient.DockerClientProviderStrategy - Trying out strategy: DockerMachineClientProviderStrategy
17:33:42.103 [Test worker] DEBUG org.testcontainers.utility.CommandLine - Executing shell command: `docker-machine ls -q`
17:33:42.103 [Test worker] DEBUG org.testcontainers.shaded.org.zeroturnaround.exec.ProcessExecutor - Executing [docker-machine, ls, -q].
17:33:42.117 [Test worker] DEBUG org.testcontainers.shaded.org.zeroturnaround.exec.ProcessExecutor - Started Process[pid=15978, exitValue="not exited"]
17:33:42.135 [Test worker] DEBUG org.testcontainers.shaded.org.zeroturnaround.exec.WaitForProcess - Process[pid=15978, exitValue=0] stopped with exit code 0
17:33:42.135 [Test worker] DEBUG org.testcontainers.utility.DockerMachineClient - DOCKER_MACHINE_NAME is not set and no machine named 'default' found; Using first machine found with `docker-machine ls`:
17:33:42.135 [Test worker] INFO org.testcontainers.dockerclient.DockerMachineClientProviderStrategy - Found docker-machine, and will use machine named
17:33:42.135 [Test worker] DEBUG org.testcontainers.utility.CommandLine - Executing shell command: `docker-machine status `
17:33:42.135 [Test worker] DEBUG org.testcontainers.shaded.org.zeroturnaround.exec.ProcessExecutor - Executing [docker-machine, status, ].
17:33:42.148 [Test worker] DEBUG org.testcontainers.shaded.org.zeroturnaround.exec.ProcessExecutor - Started Process[pid=15979, exitValue="not exited"]
17:33:42.166 [Test worker] DEBUG org.testcontainers.shaded.org.zeroturnaround.exec.WaitForProcess - Process[pid=15979, exitValue=1] stopped with exit code 1
17:33:42.168 [Test worker] DEBUG org.testcontainers.dockerclient.DockerClientProviderStrategy - DockerMachineClientProviderStrategy: failed with exception ShellCommandException (Exception when executing docker-machine status ). Root cause InvalidExitValueException (Unexpected exit value: 1, allowed exit values: [0], executed command [docker-machine, status, ], output was 122 bytes:
Docker machine "" does not exist. Use "docker-machine ls" to list machines. Use "docker-machine create" to add a new one.)
17:33:42.168 [Test worker] ERROR org.testcontainers.dockerclient.DockerClientProviderStrategy - Could not find a valid Docker environment. Please check configuration. Attempted configurations were:
17:33:42.169 [Test worker] ERROR org.testcontainers.dockerclient.DockerClientProviderStrategy - UnixSocketClientProviderStrategy: failed with exception TimeoutException (org.rnorth.ducttape.TimeoutException: java.util.concurrent.TimeoutException). Root cause TimeoutException (null)
17:33:42.169 [Test worker] ERROR org.testcontainers.dockerclient.DockerClientProviderStrategy - DockerMachineClientProviderStrategy: failed with exception ShellCommandException (Exception when executing docker-machine status ). Root cause InvalidExitValueException (Unexpected exit value: 1, allowed exit values: [0], executed command [docker-machine, status, ], output was 122 bytes:
Docker machine "" does not exist. Use "docker-machine ls" to list machines. Use "docker-machine create" to add a new one.)
17:33:42.169 [Test worker] ERROR org.testcontainers.dockerclient.DockerClientProviderStrategy - As no valid configuration was found, execution cannot continue
please let me know if any help such as additional logs are required. Thanks!
Having "Could not find a valid Docker environment. " error what causes test flakiness.
Environment:
Engine: 20.10.12on Mac OS12.1. issue is reproduced on Github Actions as well.17.0.2 (x86_64) "Homebrew" - "OpenJDK 17.0.2",17.0.2 (x86_64) "Oracle Corporation" - "OpenJDK 17.0.2",17.0.2 (x86_64) "Eclipse Temurin" - "Eclipse Temurin 17"but not sure if exact docker image does matter.
Workaround:
1.16.0. Looks like this version is more stable on JVM 17.We have seen this issue on JVM 11 as well but on JVM 17 it becomes even more painful. Assume issue can be related to changes in
1.16.1where a sort of race-conditions are possible so looks like fix #4597 does not solve issue completely.debug logs are below
please let me know if any help such as additional logs are required. Thanks!