OracleContainer JDBC connection on startup does not succeed with version 1.16.0 using image oracleinanutshell

[smcvb]

Within my project, we have a couple of integration tests that use the oracle-xe artifact.
These integration tests worked fine in version 1.15.3 of that dependency but started failing as soon as we moved to 1.16.0.

The tougher issue is that they (of course) do not fail locally, but only when the build is run from within GitHub Actions.
The exact exception I get is Caused by: java.lang.IllegalStateException: Container is started, but cannot be accessed by (JDBC URL: jdbc:oracle:thin:system/oracle@localhost:49159:xe), please check container logs.

Although I get the message, I am currently hard-pressed to figure out how to enter the test containers constructed within the test containers of GitHub Actions.
A hint here would be greatly appreciated, as I am confident of finding the predicament there.

We construct the test container through the OracleContainer constructor, by the way, pairing this with the @Container annotation on the field and @Testcontainers annotation on the integration test class.

For completions-sake, here's the complete stack trace:

[INFO] Running org.axonframework.integrationtests.eventsourcing.eventstore.jdbc.Oracle11EventTableFactoryTest
2021-07-21 14:38:27,722 [main] INFO  0]                             [] - Creating container for image: oracleinanutshell/oracle-xe-11g:1.0.0
2021-07-21 14:38:27,749 [main] INFO  0]                             [] - Starting container with ID: b5a42cf68188cdba98b229698343c65e81d85e425f391e4b232f9bd2deb35536
2021-07-21 14:38:28,133 [main] INFO  0]                             [] - Container oracleinanutshell/oracle-xe-11g:1.0.0 is starting: b5a42cf68188cdba98b229698343c65e81d85e425f391e4b232f9bd2deb35536
2021-07-21 14:38:28,138 [main] INFO  0]                             [] - Waiting for database connection to become available at jdbc:oracle:thin:system/oracle@localhost:49159:xe using query 'SELECT 1 FROM DUAL'
2021-07-21 14:42:28,525 [main] ERROR 0]                             [] - Could not start container
java.lang.IllegalStateException: Container is started, but cannot be accessed by (JDBC URL: jdbc:oracle:thin:system/oracle@localhost:49159:xe), please check container logs
	at org.testcontainers.containers.JdbcDatabaseContainer.waitUntilContainerStarted(JdbcDatabaseContainer.java:165) ~[jdbc-1.16.0.jar:?]
	at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:466) ~[testcontainers-1.16.0.jar:?]
	at org.testcontainers.containers.GenericContainer.lambda$doStart$0(GenericContainer.java:329) ~[testcontainers-1.16.0.jar:?]
	at org.rnorth.ducttape.unreliables.Unreliables.retryUntilSuccess(Unreliables.java:81) ~[duct-tape-1.0.8.jar:?]
	at org.testcontainers.containers.GenericContainer.doStart(GenericContainer.java:327) ~[testcontainers-1.16.0.jar:?]
	at org.testcontainers.containers.GenericContainer.start(GenericContainer.java:315) ~[testcontainers-1.16.0.jar:?]
	at org.testcontainers.junit.jupiter.TestcontainersExtension$StoreAdapter.start(TestcontainersExtension.java:242) ~[junit-jupiter-1.16.0.jar:?]
	at org.testcontainers.junit.jupiter.TestcontainersExtension$StoreAdapter.access$200(TestcontainersExtension.java:229) ~[junit-jupiter-1.16.0.jar:?]
	at org.testcontainers.junit.jupiter.TestcontainersExtension.lambda$null$1(TestcontainersExtension.java:59) ~[junit-jupiter-1.16.0.jar:?]
	at org.junit.jupiter.engine.execution.ExtensionValuesStore.lambda$getOrComputeIfAbsent$4(ExtensionValuesStore.java:86) ~[junit-jupiter-engine-5.7.2.jar:5.7.2]
	at org.junit.jupiter.engine.execution.ExtensionValuesStore$MemoizingSupplier.computeValue(ExtensionValuesStore.java:223) ~[junit-jupiter-engine-5.7.2.jar:5.7.2]
	at org.junit.jupiter.engine.execution.ExtensionValuesStore$MemoizingSupplier.get(ExtensionValuesStore.java:211) ~[junit-jupiter-engine-5.7.2.jar:5.7.2]
	at org.junit.jupiter.engine.execution.ExtensionValuesStore$StoredValue.evaluate(ExtensionValuesStore.java:191) ~[junit-jupiter-engine-5.7.2.jar:5.7.2]
	at org.junit.jupiter.engine.execution.ExtensionValuesStore$StoredValue.access$100(ExtensionValuesStore.java:171) ~[junit-jupiter-engine-5.7.2.jar:5.7.2]
	at org.junit.jupiter.engine.execution.ExtensionValuesStore.getOrComputeIfAbsent(ExtensionValuesStore.java:89) ~[junit-jupiter-engine-5.7.2.jar:5.7.2]
	at org.junit.jupiter.engine.execution.NamespaceAwareStore.getOrComputeIfAbsent(NamespaceAwareStore.java:53) ~[junit-jupiter-engine-5.7.2.jar:5.7.2]
	at org.testcontainers.junit.jupiter.TestcontainersExtension.lambda$beforeAll$2(TestcontainersExtension.java:59) ~[junit-jupiter-1.16.0.jar:?]
	at java.util.ArrayList.forEach(ArrayList.java:1259) ~[?:1.8.0_302]
	at org.testcontainers.junit.jupiter.TestcontainersExtension.beforeAll(TestcontainersExtension.java:59) ~[junit-jupiter-1.16.0.jar:?]
	at org.junit.jupiter.engine.descriptor.ClassBasedTestDescriptor.lambda$invokeBeforeAllCallbacks$8(ClassBasedTestDescriptor.java:368) ~[junit-jupiter-engine-5.7.2.jar:5.7.2]
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73) ~[junit-platform-engine-1.7.2.jar:1.7.2]
	at org.junit.jupiter.engine.descriptor.ClassBasedTestDescriptor.invokeBeforeAllCallbacks(ClassBasedTestDescriptor.java:368) ~[junit-jupiter-engine-5.7.2.jar:5.7.2]
	at org.junit.jupiter.engine.descriptor.ClassBasedTestDescriptor.before(ClassBasedTestDescriptor.java:192) ~[junit-jupiter-engine-5.7.2.jar:5.7.2]
	at org.junit.jupiter.engine.descriptor.ClassBasedTestDescriptor.before(ClassBasedTestDescriptor.java:78) ~[junit-jupiter-engine-5.7.2.jar:5.7.2]
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:136) ~[junit-platform-engine-1.7.2.jar:1.7.2]
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73) ~[junit-platform-engine-1.7.2.jar:1.7.2]
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:129) ~[junit-platform-engine-1.7.2.jar:1.7.2]
	at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137) ~[junit-platform-engine-1.7.2.jar:1.7.2]
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:127) ~[junit-platform-engine-1.7.2.jar:1.7.2]
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73) ~[junit-platform-engine-1.7.2.jar:1.7.2]
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:126) ~[junit-platform-engine-1.7.2.jar:1.7.2]
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:84) ~[junit-platform-engine-1.7.2.jar:1.7.2]
	at java.util.ArrayList.forEach(ArrayList.java:1259) ~[?:1.8.0_302]
	at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:38) ~[junit-platform-engine-1.7.2.jar:1.7.2]
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:143) ~[junit-platform-engine-1.7.2.jar:1.7.2]
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73) ~[junit-platform-engine-1.7.2.jar:1.7.2]
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:129) ~[junit-platform-engine-1.7.2.jar:1.7.2]
	at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137) ~[junit-platform-engine-1.7.2.jar:1.7.2]
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:127) ~[junit-platform-engine-1.7.2.jar:1.7.2]
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73) ~[junit-platform-engine-1.7.2.jar:1.7.2]
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:126) ~[junit-platform-engine-1.7.2.jar:1.7.2]
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:84) ~[junit-platform-engine-1.7.2.jar:1.7.2]
	at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.submit(SameThreadHierarchicalTestExecutorService.java:32) ~[junit-platform-engine-1.7.2.jar:1.7.2]
	at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor.execute(HierarchicalTestExecutor.java:57) ~[junit-platform-engine-1.7.2.jar:1.7.2]
	at org.junit.platform.engine.support.hierarchical.HierarchicalTestEngine.execute(HierarchicalTestEngine.java:51) ~[junit-platform-engine-1.7.2.jar:1.7.2]
	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:220) ~[junit-platform-launcher-1.3.1.jar:1.3.1]
	at org.junit.platform.launcher.core.DefaultLauncher.lambda$execute$6(DefaultLauncher.java:188) ~[junit-platform-launcher-1.3.1.jar:1.3.1]
	at org.junit.platform.launcher.core.DefaultLauncher.withInterceptedStreams(DefaultLauncher.java:202) [junit-platform-launcher-1.3.1.jar:1.3.1]
	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:181) [junit-platform-launcher-1.3.1.jar:1.3.1]
	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:128) [junit-platform-launcher-1.3.1.jar:1.3.1]
	at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.invokeAllTests(JUnitPlatformProvider.java:150) [surefire-junit-platform-2.22.2.jar:2.22.2]
	at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.invoke(JUnitPlatformProvider.java:124) [surefire-junit-platform-2.22.2.jar:2.22.2]
	at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:384) [surefire-booter-2.22.2.jar:2.22.2]
	at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:345) [surefire-booter-2.22.2.jar:2.22.2]
	at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:126) [surefire-booter-2.22.2.jar:2.22.2]
	at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:418) [surefire-booter-2.22.2.jar:2.22.2]
2021-07-21 14:42:28,577 [main] ERROR 0]                             [] - Log output from the failed container:
Starting Oracle Net Listener.
Starting Oracle Database 11g Express Edition instance.


Error:  Tests run: 1, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 240.855 s <<< FAILURE! - in org.axonframework.integrationtests.eventsourcing.eventstore.jdbc.Oracle11EventTableFactoryTest
Error:  org.axonframework.integrationtests.eventsourcing.eventstore.jdbc.Oracle11EventTableFactoryTest  Time elapsed: 240.855 s  <<< ERROR!
org.testcontainers.containers.ContainerLaunchException: Container startup failed
Caused by: org.rnorth.ducttape.RetryCountExceededException: Retry limit hit with exception
Caused by: org.testcontainers.containers.ContainerLaunchException: Could not create/start container
Caused by: java.lang.IllegalStateException: Container is started, but cannot be accessed by (JDBC URL: jdbc:oracle:thin:system/oracle@localhost:49159:xe), please check container logs

[kiview]

Hey @smcvb,

thanks a lot for bringing this to our attention. I will try to reproduce and investigate this.
In the meantime, would you give this image from gvenzel a try?

Note that this image as a never Oracle-XE version and therefore needs to be configured a little bit differently. Therefore, OracleContainer does not work OOTB, but this should work:

String oracleImage = "gvenzl/oracle-xe";
String password = "foobar";
OracleContainer oracle = new OracleContainer(oracleImage)
    .withPassword(password )
    .withEnv("ORACLE_PASSWORD", password )

Update:
I could reproduce it with GHA and image oracleinanutshell/oracle-xe-11g:1.0.0, while it works with gvenzl/oracle-xe in GHA.

[smcvb]

Thanks for the recommendation @kiview.
We already jumped from one oracle-xe container to another to see if that solved the problem.
I guess we jumped from one failing container to another.

Your suggestion works though, so thanks a bunch!

[kiview]

After some debugging, I found out, that the port mappings look different on GHA.

That's how I see them on GHA:

     "Ports": {
            "1521/tcp": [
                {
                    "HostIp": "0.0.0.0",
                    "HostPort": "49155"
                },
                {
                    "HostIp": "::",
                    "HostPort": "49155"
                }
            ],
            "22/tcp": null,
            "8080/tcp": [
                {
                    "HostIp": "0.0.0.0",
                    "HostPort": "49154"
                },
                {
                    "HostIp": "::",
                    "HostPort": "49154"
                }
            ]
        }

and that's what I have locally with Docker for Windows:

"Ports": {
            "1521/tcp": [
                {
                    "HostIp": "0.0.0.0",
                    "HostPort": "56896"
                }
            ],
            "22/tcp": null,
            "8080/tcp": [
                {
                    "HostIp": "0.0.0.0",
                    "HostPort": "56897"
                }
            ]
        }

So we can see some additional IPv6 like mappings. Besides this, I could not see a difference in the created container.

Besides, I was able to identify #3015 as the PR, that introduced this problem for this image on GHA.

Edit:
After further investigating the changes in #3015 and the related issue #2878, this change from behaviour came due to Testcontainers previously ignoring error in the test query. And indeed, the oracleinanutshell image will fail its query because of:

Caused by: java.sql.SQLException: ORA-00604: error occurred at recursive SQL level 1
ORA-01882: timezone region not found

Also see https://github.com/testcontainers/testcontainers-java/pull/607/files#diff-21b1fe66043572c76c549a4fc5f186e9a69c330b186fc91116b9b70a4d047902R39-R40 for a possible fix for the GHA environment, i.e. by configuring a timezone (this was for CircleCI, but there might be a similar way to configure it in GHA).

While I think we should improve the logging for this case, I feel the actual issue at hand is resolved through this analysis and can be mitigated by either using a different image (e.g. gvenzl/oracle-xe) or configuring the timezone on CI.

[smcvb]

Thanks for the information here @kiview. The investigation is much appreciated.