search

testcontainers / testcontainers-java

Testcontainers is a Java library that supports JUnit tests, providing lightweight, throwaway instances of common databases, Selenium web browsers, or anything else that can run in a Docker container.
https://testcontainers.org
MIT License
7.97k stars 1.64k forks source link

[Bug]: Timed out waiting for log output matching '.*DATABASE IS READY TO USE!.*\s' #9057

Closed andytael closed 1 month ago

andytael commented 1 month ago

Module

Oracle Free

Testcontainers version

1.20.0

Using the latest Testcontainers version?

Yes

Host OS

Mac OS Sonoma 14.5

Host Arch

ARM (M1)

Docker version

Client:
 Version:           26.1.0-rd
 API version:       1.45
 Go version:        go1.21.9
 Git commit:        cca8e72
 Built:             Tue Apr 23 16:25:03 2024
 OS/Arch:           darwin/arm64
 Context:           default

Server: Docker Engine - Community
 Engine:
  Version:          26.1.1
  API version:      1.45 (minimum version 1.24)
  Go version:       go1.21.9
  Git commit:       ac2de55
  Built:            Tue Apr 30 11:47:54 2024
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          1.6.31
  GitCommit:        e377cd56a71523140ca6ae87e30244719194a521
 runc:
  Version:          1.1.12
  GitCommit:        v1.1.12-0-g51d5e94
 docker-init:
  Version:          0.19.0
  GitCommit:        de40ad0

What happened?

When using the oracle-free testcontainer module in a Spring Boot 3.2.7 applcation the tests fails with the following error:

15:29:00.058 [main] INFO tc.gvenzl/oracle-free:23.4-slim-faststart -- Creating container for image: gvenzl/oracle-free:23.4-slim-faststart
15:29:00.369 [main] INFO tc.gvenzl/oracle-free:23.4-slim-faststart -- Container gvenzl/oracle-free:23.4-slim-faststart is starting: 6ac2fe26143584eb9c1029046f5505b70e14250f4bc180cc18b9718c5b989904
15:30:03.352 [main] ERROR tc.gvenzl/oracle-free:23.4-slim-faststart -- Could not start container
org.testcontainers.containers.ContainerLaunchException: Timed out waiting for log output matching '.*DATABASE IS READY TO USE!.*\s'

By looking the source code there seems to be a hardcoded time for 60 seconds private static final int DEFAULT_STARTUP_TIMEOUT_SECONDS = 60; and startup time is Time elapsed: 63.39 s

Relevant log output

15:06:23.563 [main] INFO org.testcontainers.images.PullPolicy -- Image pull policy will be performed by: DefaultPullPolicy()
15:06:23.567 [main] INFO org.testcontainers.utility.ImageNameSubstitutor -- Image name substitution will be performed by: DefaultImageNameSubstitutor (composite of 'ConfigurationFileImageNameSubstitutor' and 'PrefixingImageNameSubstitutor')
15:06:23.599 [main] INFO org.testcontainers.DockerClientFactory -- Testcontainers version: 1.20.0
15:06:23.734 [main] INFO org.testcontainers.dockerclient.DockerClientProviderStrategy -- Loaded org.testcontainers.dockerclient.UnixSocketClientProviderStrategy from ~/.testcontainers.properties, will try it first
15:06:23.972 [main] INFO org.testcontainers.dockerclient.DockerClientProviderStrategy -- Found Docker environment with Environment variables, system properties and defaults. Resolved dockerHost=unix:///Users/atael/.colima/default/docker.sock
15:06:23.973 [main] INFO org.testcontainers.DockerClientFactory -- Docker host IP address is localhost
15:06:24.039 [main] INFO org.testcontainers.DockerClientFactory -- Connected to docker: 
  Server Version: 26.1.1
  API Version: 1.45
  Operating System: Ubuntu 24.04 LTS
  Total Memory: 7937 MB
15:06:24.041 [main] WARN org.testcontainers.utility.ResourceReaper -- 
********************************************************************************
Ryuk has been disabled. This can cause unexpected behavior in your environment.
********************************************************************************
15:06:24.042 [main] INFO org.testcontainers.DockerClientFactory -- Checking the system...
15:06:24.043 [main] INFO org.testcontainers.DockerClientFactory -- ✔︎ Docker server version should be at least 1.6.0
15:06:24.060 [main] INFO tc.gvenzl/oracle-free:23.4-slim-faststart -- Creating container for image: gvenzl/oracle-free:23.4-slim-faststart
15:06:24.142 [main] INFO org.testcontainers.utility.RegistryAuthLocator -- Credential helper/store (docker-credential-osxkeychain) does not have credentials for https://index.docker.io/v1/
15:06:24.453 [main] INFO tc.gvenzl/oracle-free:23.4-slim-faststart -- Container gvenzl/oracle-free:23.4-slim-faststart is starting: 1e82c63d05d5b90009c6a72441aa3636b38494c3402ec7c130c656f7c2565dc7
15:07:27.379 [main] ERROR tc.gvenzl/oracle-free:23.4-slim-faststart -- Could not start container
org.testcontainers.containers.ContainerLaunchException: Timed out waiting for log output matching '.*DATABASE IS READY TO USE!.*\s'
    at org.testcontainers.containers.wait.strategy.LogMessageWaitStrategy.waitUntilReady(LogMessageWaitStrategy.java:47)
    at org.testcontainers.containers.wait.strategy.AbstractWaitStrategy.waitUntilReady(AbstractWaitStrategy.java:52)
    at org.testcontainers.oracle.OracleContainer.waitUntilContainerStarted(OracleContainer.java:81)
    at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:500)
    at org.testcontainers.containers.GenericContainer.lambda$doStart$0(GenericContainer.java:354)
    at org.rnorth.ducttape.unreliables.Unreliables.retryUntilSuccess(Unreliables.java:81)
    at org.testcontainers.containers.GenericContainer.doStart(GenericContainer.java:344)
    at org.testcontainers.containers.GenericContainer.start(GenericContainer.java:330)
    at org.testcontainers.junit.jupiter.TestcontainersExtension$StoreAdapter.start(TestcontainersExtension.java:276)
    at org.testcontainers.junit.jupiter.TestcontainersExtension$StoreAdapter.access$200(TestcontainersExtension.java:263)
    at org.testcontainers.junit.jupiter.TestcontainersExtension.lambda$null$4(TestcontainersExtension.java:83)
    at org.junit.platform.engine.support.store.NamespacedHierarchicalStore.lambda$getOrComputeIfAbsent$5(NamespacedHierarchicalStore.java:147)
    at org.junit.platform.engine.support.store.NamespacedHierarchicalStore$MemoizingSupplier.computeValue(NamespacedHierarchicalStore.java:372)
    at org.junit.platform.engine.support.store.NamespacedHierarchicalStore$MemoizingSupplier.get(NamespacedHierarchicalStore.java:361)
    at org.junit.platform.engine.support.store.NamespacedHierarchicalStore$StoredValue.evaluate(NamespacedHierarchicalStore.java:308)
    at org.junit.platform.engine.support.store.NamespacedHierarchicalStore$StoredValue.access$200(NamespacedHierarchicalStore.java:287)
    at org.junit.platform.engine.support.store.NamespacedHierarchicalStore.getOrComputeIfAbsent(NamespacedHierarchicalStore.java:149)
    at org.junit.jupiter.engine.execution.NamespaceAwareStore.lambda$getOrComputeIfAbsent$2(NamespaceAwareStore.java:57)
    at org.junit.jupiter.engine.execution.NamespaceAwareStore.accessStore(NamespaceAwareStore.java:90)
    at org.junit.jupiter.engine.execution.NamespaceAwareStore.getOrComputeIfAbsent(NamespaceAwareStore.java:57)
    at org.testcontainers.junit.jupiter.TestcontainersExtension.lambda$startContainers$5(TestcontainersExtension.java:83)
    at java.base/java.util.ArrayList.forEach(ArrayList.java:1596)
    at org.testcontainers.junit.jupiter.TestcontainersExtension.startContainers(TestcontainersExtension.java:83)
    at org.testcontainers.junit.jupiter.TestcontainersExtension.beforeAll(TestcontainersExtension.java:57)
    at org.junit.jupiter.engine.descriptor.ClassBasedTestDescriptor.lambda$invokeBeforeAllCallbacks$12(ClassBasedTestDescriptor.java:396)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.jupiter.engine.descriptor.ClassBasedTestDescriptor.invokeBeforeAllCallbacks(ClassBasedTestDescriptor.java:396)
    at org.junit.jupiter.engine.descriptor.ClassBasedTestDescriptor.before(ClassBasedTestDescriptor.java:212)
    at org.junit.jupiter.engine.descriptor.ClassBasedTestDescriptor.before(ClassBasedTestDescriptor.java:85)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:148)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
    at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
    at java.base/java.util.ArrayList.forEach(ArrayList.java:1596)
    at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:41)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:155)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141)
    at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139)
    at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138)
    at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95)
    at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.submit(SameThreadHierarchicalTestExecutorService.java:35)
    at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor.execute(HierarchicalTestExecutor.java:57)
    at org.junit.platform.engine.support.hierarchical.HierarchicalTestEngine.execute(HierarchicalTestEngine.java:54)
    at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:198)
    at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:169)
    at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:93)
    at org.junit.platform.launcher.core.EngineExecutionOrchestrator.lambda$execute$0(EngineExecutionOrchestrator.java:58)
    at org.junit.platform.launcher.core.EngineExecutionOrchestrator.withInterceptedStreams(EngineExecutionOrchestrator.java:141)
    at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:57)
    at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:103)
    at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:85)
    at org.junit.platform.launcher.core.DelegatingLauncher.execute(DelegatingLauncher.java:47)
    at org.junit.platform.launcher.core.SessionPerRequestLauncher.execute(SessionPerRequestLauncher.java:63)
    at com.intellij.junit5.JUnit5IdeaTestRunner.startRunnerWithArgs(JUnit5IdeaTestRunner.java:57)
    at com.intellij.rt.junit.IdeaTestRunner$Repeater$1.execute(IdeaTestRunner.java:38)
    at com.intellij.rt.execution.junit.TestsRepeater.repeat(TestsRepeater.java:11)
    at com.intellij.rt.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:35)
    at com.intellij.rt.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:232)
    at com.intellij.rt.junit.JUnitStarter.main(JUnitStarter.java:55)
15:07:27.465 [main] ERROR tc.gvenzl/oracle-free:23.4-slim-faststart -- Log output from the failed container:
CONTAINER: starting up...
CONTAINER: first database startup, initializing...
CONTAINER: starting up Oracle Database...

LSNRCTL for Linux: Version 23.0.0.0.0 - Production on 02-AUG-2024 20:06:28

Copyright (c) 1991, 2024, Oracle.  All rights reserved.

Starting /opt/oracle/product/23ai/dbhomeFree/bin/tnslsnr: please wait...

TNSLSNR for Linux: Version 23.0.0.0.0 - Production
System parameter file is /opt/oracle/product/23ai/dbhomeFree/network/admin/listener.ora
Log messages written to /opt/oracle/diag/tnslsnr/1e82c63d05d5/listener/alert/log.xml
Listening on: (DESCRIPTION=(ADDRESS=(PROTOCOL=ipc)(KEY=EXTPROC_FOR_FREE)))
Listening on: (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=0.0.0.0)(PORT=1521)))

Connecting to (DESCRIPTION=(ADDRESS=(PROTOCOL=IPC)(KEY=EXTPROC_FOR_FREE)))
STATUS of the LISTENER
------------------------
Alias                     LISTENER
Version                   TNSLSNR for Linux: Version 23.0.0.0.0 - Production
Start Date                02-AUG-2024 20:06:28
Uptime                    0 days 0 hr. 0 min. 0 sec
Trace Level               off
Security                  ON: Local OS Authentication
SNMP                      OFF
Default Service           FREE
Listener Parameter File   /opt/oracle/product/23ai/dbhomeFree/network/admin/listener.ora
Listener Log File         /opt/oracle/diag/tnslsnr/1e82c63d05d5/listener/alert/log.xml
Listening Endpoints Summary...
  (DESCRIPTION=(ADDRESS=(PROTOCOL=ipc)(KEY=EXTPROC_FOR_FREE)))
  (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=0.0.0.0)(PORT=1521)))
The listener supports no services
The command completed successfully
ORACLE instance started.

Total System Global Area 1603726344 bytes
Fixed Size          5360648 bytes
Variable Size         788529152 bytes
Database Buffers      805306368 bytes
Redo Buffers            4530176 bytes
Database mounted.

Test ignored.

Test ignored.

Test ignored.

Test ignored.

Test ignored.

Test ignored.

Test ignored.

Test ignored.

Test ignored.

Test ignored.

Test ignored.

Test ignored.

org.testcontainers.containers.ContainerLaunchException: Container startup failed for image gvenzl/oracle-free:23.4-slim-faststart

    at org.testcontainers.containers.GenericContainer.doStart(GenericContainer.java:359)
    at org.testcontainers.containers.GenericContainer.start(GenericContainer.java:330)
    at org.testcontainers.junit.jupiter.TestcontainersExtension$StoreAdapter.start(TestcontainersExtension.java:276)
    at org.testcontainers.junit.jupiter.TestcontainersExtension$StoreAdapter.access$200(TestcontainersExtension.java:263)
    at org.testcontainers.junit.jupiter.TestcontainersExtension.lambda$null$4(TestcontainersExtension.java:83)
    at org.testcontainers.junit.jupiter.TestcontainersExtension.lambda$startContainers$5(TestcontainersExtension.java:83)
    at java.base/java.util.ArrayList.forEach(ArrayList.java:1596)
    at org.testcontainers.junit.jupiter.TestcontainersExtension.startContainers(TestcontainersExtension.java:83)
    at org.testcontainers.junit.jupiter.TestcontainersExtension.beforeAll(TestcontainersExtension.java:57)
    at java.base/java.util.ArrayList.forEach(ArrayList.java:1596)
Caused by: org.rnorth.ducttape.RetryCountExceededException: Retry limit hit with exception
    at org.rnorth.ducttape.unreliables.Unreliables.retryUntilSuccess(Unreliables.java:88)
    at org.testcontainers.containers.GenericContainer.doStart(GenericContainer.java:344)
    ... 9 more
Caused by: org.testcontainers.containers.ContainerLaunchException: Could not create/start container
    at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:563)
    at org.testcontainers.containers.GenericContainer.lambda$doStart$0(GenericContainer.java:354)
    at org.rnorth.ducttape.unreliables.Unreliables.retryUntilSuccess(Unreliables.java:81)
    ... 10 more
Caused by: org.testcontainers.containers.ContainerLaunchException: Timed out waiting for log output matching '.*DATABASE IS READY TO USE!.*\s'
    at org.testcontainers.containers.wait.strategy.LogMessageWaitStrategy.waitUntilReady(LogMessageWaitStrategy.java:47)
    at org.testcontainers.containers.wait.strategy.AbstractWaitStrategy.waitUntilReady(AbstractWaitStrategy.java:52)
    at org.testcontainers.oracle.OracleContainer.waitUntilContainerStarted(OracleContainer.java:81)
    at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:500)
    ... 12 more

Process finished with exit code 255

Additional Information

Colima is used and is started like this:

colima start --arch x86_64 --memory 8 --vm-type=vz --mount-type virtiofs --network-address

the following ENV vars are set:

export TESTCONTAINERS_DOCKER_SOCKET_OVERRIDE=/var/run/docker.sock
export DOCKER_HOST="unix://${HOME}/.colima/default/docker.sock"
export TESTCONTAINERS_RYUK_DISABLED=true
andytael commented 1 month ago

If the timeout can be increased it might solve the problem. Even better make the timeout a parameter?

andytael commented 1 month ago

Upgrade to version 1.20.1, unfortunately no difference

andytael commented 1 month ago

Running the test outside of IntelliJ the log file looks like this: logfile.txt

eddumelendez commented 1 month ago

Hi, @andytael this is similar to #7621. Please check this comment

andytael commented 1 month ago

@eddumelendez Oracle-XE is not the same thing. This is the current version, XE is old :-)

I can run Oracle Database 23ai Free on my M1 Mac just fine using colima

Please reopen the issue, it is a blocker currently

andytael commented 1 month ago 
INFO[0000] colima is running using macOS Virtualization.Framework
INFO[0000] arch: x86_64
INFO[0000] runtime: docker
INFO[0000] mountType: virtiofs
INFO[0000] socket: unix:///Users/atael/.colima/default/docker.sock
INFO[0001] cpu: 6
INFO[0001] mem: 8GiB
INFO[0001] disk: 60GiB```

`docker run -d -p 1521:1521 -e ORACLE_PASSWORD=Welcome12345 gvenzl/oracle-free:slim`

From the DB log;

######################### DATABASE IS READY TO USE! #########################

#################################################################### CONTAINER: The following output is now from the alert_FREE.log file: ####################################################################

=========================================================== (3):--ATTENTION-- (3):PARALLEL_MAX_SERVERS (with value 1) is insufficient. This may affect transaction recovery performance. Modify PARALLEL_MAX_SERVERS parameter to a value > 4 (= parallel servers count computed from parameter FAST_START_PARALLEL_ROLLBACK) in PDB ID 3 FREEPDB1(3):Autotune of undo retention is turned on. 2024-08-05T20:39:48.249510+00:00 FREEPDB1(3):Opening pdb with Resource Manager plan: DEFAULT_PLAN 2024-08-05T20:39:49.945362+00:00 Completed: Pluggable database FREEPDB1 opened read write Completed: ALTER DATABASE OPEN

eddumelendez commented 1 month ago

Have you tried the following config? There is no even need to disable ryuk.

andytael commented 1 month ago

Unset the var:

env | grep TESTCONTAINERS_RYUK_DISABLED
TESTCONTAINERS_RYUK_DISABLED=

Tried again and gives this:


15:46:33.174 [testcontainers-ryuk] WARN org.testcontainers.utility.RyukResourceReaper -- Can not connect to Ryuk at localhost:32780
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:682)
    at java.base/sun.nio.ch.NioSocketImpl.timedFinishConnect(NioSocketImpl.java:542)
    at java.base/sun.nio.ch.NioSocketImpl.connect(NioSocketImpl.java:592)
    at java.base/java.net.SocksSocketImpl.connect(SocksSocketImpl.java:327)
    at java.base/java.net.Socket.connect(Socket.java:751)
    at org.testcontainers.utility.RyukResourceReaper.lambda$null$1(RyukResourceReaper.java:105)
    at org.rnorth.ducttape.ratelimits.RateLimiter.doWhenReady(RateLimiter.java:27)
    at org.testcontainers.utility.RyukResourceReaper.lambda$maybeStart$2(RyukResourceReaper.java:101)
    at java.base/java.lang.Thread.run(Thread.java:1583)```
andytael commented 1 month ago

Unfortunately no difference, still get timeout error.

eddumelendez commented 1 month ago

You can do something like this and override the default startupTimeout

OracleContainer oracle = new OracleContainer(ORACLE_DOCKER_IMAGE_NAME)
            .withStartupTimeout(Duration.ofMinutes(2))

This should fix your issue.

andytael commented 1 month ago

Yes it did. Thank you!