Testcontainers-java: Oracle XE container doesn't wait till database is ready / wait-strategy ignored

[nussbam]

The oracle-xe container doesn't wait till the container signals its readiness with the

Database ready to use. Enjoy! ;) -message

Instead it will wait till the select 1 from dual can be executed. Additionally wait-strategy that is set seems to be ignored.

I tried setting a not fulfilling waiting strategy like:

val container = OracleContainerProvider().newInstance().withInitScript("setup_oracle.sql")
container.setWaitStrategy(
       Wait.forLogMessage("XYZZZZZZ", 99)
)
container.start()

However the application still continued regardless, after select 1 from dual could be executed.
Since the db is not completely ready at this point I get broken connections in my Hikari-Pool:

Here the stacktrace:

2019-03-05 10:28:26.618 INFO 19048 --- [ Test worker] o.t.d.DockerClientProviderStrategy : Loaded org.testcontainers.dockerclient.NpipeSocketClientProviderStrategy from ~/.testcontainers.properties, will try it first
2019-03-05 10:28:26.651 INFO 19048 --- [ Test worker] o.t.d.DockerClientProviderStrategy : Will use 'okhttp' transport
2019-03-05 10:28:27.523 INFO 19048 --- [ Test worker] o.t.d.NpipeSocketClientProviderStrategy : Accessing docker with local Npipe socket (npipe:////./pipe/docker_engine)
2019-03-05 10:28:27.523 INFO 19048 --- [ Test worker] o.t.d.DockerClientProviderStrategy : Found Docker environment with local Npipe socket (npipe:////./pipe/docker_engine)
2019-03-05 10:28:27.525 INFO 19048 --- [ Test worker] o.t.DockerClientFactory : Docker host IP address is localhost
2019-03-05 10:28:27.686 INFO 19048 --- [ Test worker] o.t.DockerClientFactory : Connected to docker:
Server Version: 18.06.1-ce
API Version: 1.38
Operating System: Docker for Windows
Total Memory: 14746 MB
2019-03-05 10:28:27.873 INFO 19048 --- [ Test worker] o.t.u.RegistryAuthLocator : Credentials not found for host (quay.io) when using credential helper/store (docker-credential-wincred)
2019-03-05 10:28:28.800 INFO 19048 --- [ Test worker] o.t.DockerClientFactory : Ryuk started - will monitor and terminate Testcontainers containers on JVM exit
?? Checking the system...
? Docker version should be at least 1.6.0
? Docker environment should have more than 2GB free disk space
2019-03-05 10:28:28.997 INFO 19048 --- [ Test worker] integrationtest : Starting database container for oracle
2019-03-05 10:28:28.998 INFO 19048 --- [ Test worker] h:5043/XXXXX-docker/oracle-xe-11g:latest] : Creating container for image: XXXX.XX:5043/XXXX-docker/oracle-xe-11g:latest
2019-03-05 10:28:29.273 INFO 19048 --- [ Test worker] h:5043/XXXX-docker/oracle-xe-11g:latest] : Starting container with ID: 81ad022645a500069dfd52c472a3c8768fae1828bbd87d8ad209d6b8dbd93737
2019-03-05 10:28:29.845 INFO 19048 --- [ Test worker] h:5043/XXXX-docker/oracle-xe-11g:latest] : Container XXXXX.ch:5043/XXXX-docker/oracle-xe-11g:latest is starting: 81ad022645a500069dfd52c472a3c8768fae1828bbd87d8ad209d6b8dbd93737
> 2019-03-05 10:28:29.860 INFO 19048 --- [ Test worker] h:5043/XXXX-docker/oracle-xe-11g:latest] : Waiting for database connection to become available at jdbc:oracle:thin:system/oracle@localhost:32781:xe using query 'SELECT 1 FROM DUAL'
2019-03-05 10:29:24.543 INFO 19048 --- [ ducttape-0] h:5043/XXXX-docker/oracle-xe-11g:latest] : Obtained a connection to container (jdbc:oracle:thin:system/oracle@localhost:32781:xe)
2019-03-05 10:29:24.546 INFO 19048 --- [ Test worker] h:5043/XXXX-docker/oracle-xe-11g:latest] : Container XXXX.ch:5043/XXXX-docker/oracle-xe-11g:latest started
2019-03-05 10:29:24.553 INFO 19048 --- [ Test worker] o.t.e.ScriptUtils : Executing database script from setup_oracle.sql
2019-03-05 10:29:26.703 INFO 19048 --- [ Test worker] o.t.e.ScriptUtils : Executed database script from setup_oracle.sql in 2150 ms.
2019-03-05 10:29:26.720 DEBUG 19048 --- [tream-500746611] c.t.c.l.t.oracle-container : Database not initialized. Initializing database.
2019-03-05 10:29:26.721 DEBUG 19048 --- [tream-500746611] c.t.c.l.t.oracle-container : Setting up:
2019-03-05 10:29:26.721 DEBUG 19048 --- [tream-500746611] c.t.c.l.t.oracle-container : processes=500
2019-03-05 10:29:26.721 DEBUG 19048 --- [tream-500746611] c.t.c.l.t.oracle-container : sessions=555
2019-03-05 10:29:26.722 DEBUG 19048 --- [tream-500746611] c.t.c.l.t.oracle-container : transactions=610
2019-03-05 10:29:26.722 DEBUG 19048 --- [tream-500746611] c.t.c.l.t.oracle-container : If you want to use different parameters set processes, sessions, transactions env variables and consider this formula:
2019-03-05 10:29:26.722 DEBUG 19048 --- [tream-500746611] c.t.c.l.t.oracle-container : processes=x
2019-03-05 10:29:26.723 DEBUG 19048 --- [tream-500746611] c.t.c.l.t.oracle-container : sessions=x1.1+5
2019-03-05 10:29:26.723 DEBUG 19048 --- [tream-500746611] c.t.c.l.t.oracle-container : transactions=sessions1.1
2019-03-05 10:29:26.723 DEBUG 19048 --- [tream-500746611] c.t.c.l.t.oracle-container : Oracle Database 11g Express Edition Configuration
2019-03-05 10:29:26.724 DEBUG 19048 --- [tream-500746611] c.t.c.l.t.oracle-container : -------------------------------------------------
2019-03-05 10:29:26.725 DEBUG 19048 --- [tream-500746611] c.t.c.l.t.oracle-container : This will configure on-boot properties of Oracle Database 11g Express
2019-03-05 10:29:26.726 DEBUG 19048 --- [tream-500746611] c.t.c.l.t.oracle-container : Edition. The following questions will determine whether the database should
2019-03-05 10:29:26.726 DEBUG 19048 --- [tream-500746611] c.t.c.l.t.oracle-container : be starting upon system boot, the ports it will use, and the passwords that
2019-03-05 10:29:26.727 DEBUG 19048 --- [tream-500746611] c.t.c.l.t.oracle-container : will be used for database accounts. Press to accept the defaults.
2019-03-05 10:29:26.727 DEBUG 19048 --- [tream-500746611] c.t.c.l.t.oracle-container : Ctrl-C will abort.
2019-03-05 10:29:26.727 DEBUG 19048 --- [tream-500746611] c.t.c.l.t.oracle-container : Specify the HTTP port that will be used for Oracle Application Express [8080]:
2019-03-05 10:29:26.728 DEBUG 19048 --- [tream-500746611] c.t.c.l.t.oracle-container : Specify a port that will be used for the database listener [1521]:
2019-03-05 10:29:26.728 DEBUG 19048 --- [tream-500746611] c.t.c.l.t.oracle-container : Specify a password to be used for database accounts. Note that the same
2019-03-05 10:29:26.728 DEBUG 19048 --- [tream-500746611] c.t.c.l.t.oracle-container : password will be used for SYS and SYSTEM. Oracle recommends the use of
2019-03-05 10:29:26.728 DEBUG 19048 --- [tream-500746611] c.t.c.l.t.oracle-container : different passwords for each database account. This can be done after
2019-03-05 10:29:26.729 DEBUG 19048 --- [tream-500746611] c.t.c.l.t.oracle-container : initial configuration:
2019-03-05 10:29:26.729 DEBUG 19048 --- [tream-500746611] c.t.c.l.t.oracle-container : Confirm the password:
2019-03-05 10:29:26.729 DEBUG 19048 --- [tream-500746611] c.t.c.l.t.oracle-container : Do you want Oracle Database 11g Express Edition to be started on boot (y/n) [y]:
2019-03-05 10:29:26.730 DEBUG 19048 --- [tream-500746611] c.t.c.l.t.oracle-container : Starting Oracle Net Listener...Done
2019-03-05 10:29:30.463 INFO 19048 --- [ Test worker] c.t.c.l.database : Registering JDBC driver for 'jdbc:oracle:thin:system/oracle@localhost:32781:xe'.
2019-03-05 10:29:30.485 INFO 19048 --- [ Test worker] c.t.c.l.database : Running liquibase changelogs for tenant default
2019-03-05 10:29:30.490 INFO 19048 --- [ Test worker] c.z.h.HikariDataSource : HikariPool-1 - Starting...
2019-03-05 10:29:30.676 INFO 19048 --- [ Test worker] c.z.h.HikariDataSource : HikariPool-1 - Start completed.
2019-03-05 10:29:31.824 INFO 19048 --- [ Test worker] liquibase : Successfully acquired change log lock
2019-03-05 10:29:32.875 INFO 19048 --- [ Test worker] liquibase : Creating database history table with name: SYSTEM.DATABASECHANGELOG

//Liquibase logs executed

2019-03-05 10:29:47.156 WARN 19048 --- [ Test worker] c.z.h.p.ProxyConnection : HikariPool-1 - Connection oracle.jdbc.driver.T4CConnection@485a924b marked as broken because of SQLSTATE(08006), ErrorCode(1089)
java.sql.SQLRecoverableException: ORA-01089: immediate shutdown in progress - no operations are permitted

at oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:494) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0]
at oracle.jdbc.driver.T4CTTIoer11.processError(T4CTTIoer11.java:446) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0]
at oracle.jdbc.driver.T4C8Oall.processError(T4C8Oall.java:1054) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0]
at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:623) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0]
at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:252) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0]
at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:612) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0]
at oracle.jdbc.driver.T4CStatement.doOall8(T4CStatement.java:213) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0]
at oracle.jdbc.driver.T4CStatement.doOall8(T4CStatement.java:37) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0]
at oracle.jdbc.driver.T4CStatement.executeForRows(T4CStatement.java:896) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0]
at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1119) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0]
at oracle.jdbc.driver.OracleStatement.executeInternal(OracleStatement.java:1737) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0]
at oracle.jdbc.driver.OracleStatement.execute(OracleStatement.java:1692) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0]
at oracle.jdbc.driver.OracleStatementWrapper.execute(OracleStatementWrapper.java:300) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0]
at com.zaxxer.hikari.pool.ProxyStatement.execute(ProxyStatement.java:95) ~[HikariCP-2.7.4.jar:?]
at com.zaxxer.hikari.pool.HikariProxyStatement.execute(HikariProxyStatement.java) ~[HikariCP-2.7.4.jar:?]
at liquibase.executor.jvm.JdbcExecutor$ExecuteStatementCallback.doInStatement(JdbcExecutor.java:307) ~[liquibase-core-3.5.3.jar:?]
at liquibase.executor.jvm.JdbcExecutor.execute(JdbcExecutor.java:55) ~[liquibase-core-3.5.3.jar:?]
at liquibase.executor.jvm.JdbcExecutor.execute(JdbcExecutor.java:113) ~[liquibase-core-3.5.3.jar:?]
at liquibase.database.AbstractJdbcDatabase.execute(AbstractJdbcDatabase.java:1277) ~[liquibase-core-3.5.3.jar:?]
at liquibase.database.AbstractJdbcDatabase.executeStatements(AbstractJdbcDatabase.java:1259) ~[liquibase-core-3.5.3.jar:?]
at liquibase.changelog.ChangeSet.execute(ChangeSet.java:582) ~[liquibase-core-3.5.3.jar:?]
at liquibase.changelog.visitor.UpdateVisitor.visit(UpdateVisitor.java:51) ~[liquibase-core-3.5.3.jar:?]
at liquibase.changelog.ChangeLogIterator.run(ChangeLogIterator.java:79) ~[liquibase-core-3.5.3.jar:?]
at liquibase.Liquibase.update(Liquibase.java:214) ~[liquibase-core-3.5.3.jar:?]
at liquibase.Liquibase.update(Liquibase.java:192) ~[liquibase-core-3.5.3.jar:?]
at liquibase.Liquibase.update(Liquibase.java:188) ~[liquibase-core-3.5.3.jar:?]
at liquibase.Liquibase.update(Liquibase.java:181) ~[liquibase-core-3.5.3.jar:?]

Other stacktrace that can't be disclosed

... 85 more
Caused by: java.sql.SQLException: Connection is closed
at com.zaxxer.hikari.pool.ProxyConnection$ClosedConnection.lambda$getClosedConnection$0(ProxyConnection.java:490) ~[HikariCP-2.7.4.jar:?]
at com.sun.proxy.$Proxy59.getAutoCommit(Unknown Source) ~[?:?]
at com.zaxxer.hikari.pool.HikariProxyConnection.getAutoCommit(HikariProxyConnection.java) ~[HikariCP-2.7.4.jar:?]
at liquibase.database.jvm.JdbcConnection.rollback(JdbcConnection.java:336) ~[liquibase-core-3.5.3.jar:?]
at liquibase.database.AbstractJdbcDatabase.rollback(AbstractJdbcDatabase.java:1166) ~[liquibase-core-3.5.3.jar:?]
at liquibase.lockservice.StandardLockService.releaseLock(StandardLockService.java:266) ~[liquibase-core-3.5.3.jar:?]
... 85 more

2019-03-05 10:30:03.174 DEBUG 19048 --- [tream-500746611] c.t.c.l.t.oracle-container : Configuring database...Done
2019-03-05 10:30:03.244 DEBUG 19048 --- [tream-500746611] c.t.c.l.t.oracle-container : Starting Oracle Database 11g Express Edition instance...Done
2019-03-05 10:30:03.244 DEBUG 19048 --- [tream-500746611] c.t.c.l.t.oracle-container : Installation completed successfully.
2019-03-05 10:30:03.248 DEBUG 19048 --- [tream-500746611] c.t.c.l.t.oracle-container : Setting sys/system passwords
2019-03-05 10:30:03.359 DEBUG 19048 --- [tream-500746611] c.t.c.l.t.oracle-container : Database initialized. Please visit http://#containeer:8080/apex to proceed with configuration
2019-03-05 10:30:03.402 DEBUG 19048 --- [tream-500746611] c.t.c.l.t.oracle-container : Oracle Database 11g Express Edition instance is already started
2019-03-05 10:30:03.403 DEBUG 19048 --- [tream-500746611] c.t.c.l.t.oracle-container : Starting import scripts from '/docker-entrypoint-initdb.d':
2019-03-05 10:30:03.421 DEBUG 19048 --- [tream-500746611] c.t.c.l.t.oracle-container : /entrypoint.sh: line 108: /docker-entrypoint-initdb.d/.cache: No such file or directory
2019-03-05 10:30:03.431 DEBUG 19048 --- [tream-500746611] c.t.c.l.t.oracle-container : /entrypoint.sh: line 109: /docker-entrypoint-initdb.d/.cache: No such file or directory
2019-03-05 10:30:03.432 DEBUG 19048 --- [tream-500746611] c.t.c.l.t.oracle-container : /entrypoint.sh: line 110: /docker-entrypoint-initdb.d/.cache: No such file or directory
2019-03-05 10:30:03.440 DEBUG 19048 --- [tream-500746611] c.t.c.l.t.oracle-container : Import finished
2019-03-05 10:30:03.440 DEBUG 19048 --- [tream-500746611] c.t.c.l.t.oracle-container : Database ready to use. Enjoy! ;)

Sometimes I also get:

2019-03-05 10:36:58.769 liquibase ERROR 19328 --- [ main] c.z.h.p.HikariPool : HikariPool-2 - Exception during pool initialization.
java.sql.SQLRecoverableException: I/O-Fehler: Got minus one from a read call, connect lapse 13 ms., Authentication lapse 0 ms.
at oracle.jdbc.driver.T4CConnection.logon(T4CConnection.java:794) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0]
at oracle.jdbc.driver.PhysicalConnection.connect(PhysicalConnection.java:688) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0]
at oracle.jdbc.driver.T4CDriverExtension.getConnection(T4CDriverExtension.java:39) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0]
at oracle.jdbc.driver.OracleDriver.connect(OracleDriver.java:691) ~[ojdbc8-12.2.0.1.jar:12.2.0.1.0]
at com.zaxxer.hikari.util.DriverDataSource.getConnection(DriverDataSource.java:117) ~[HikariCP-2.7.4.jar:?]
at com.zaxxer.hikari.util.DriverDataSource.getConnection(DriverDataSource.java:123) ~[HikariCP-2.7.4.jar:?]
at com.zaxxer.hikari.pool.PoolBase.newConnection(PoolBase.java:375) ~[HikariCP-2.7.4.jar:?]
at com.zaxxer.hikari.pool.PoolBase.newPoolEntry(PoolBase.java:204) ~[HikariCP-2.7.4.jar:?]
at com.zaxxer.hikari.pool.HikariPool.createPoolEntry(HikariPool.java:459) ~[HikariCP-2.7.4.jar:?]
at com.zaxxer.hikari.pool.HikariPool.checkFailFast(HikariPool.java:533) ~[HikariCP-2.7.4.jar:?]
at com.zaxxer.hikari.pool.HikariPool.(HikariPool.java:114) ~[HikariCP-2.7.4.jar:?]
at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:97) ~[HikariCP-2.7.4.jar:?]
...

If I manually implement Wait.forLogMessage like this:

    private fun JdbcDatabaseContainer<*>.waitUntilLogReady(waitForThisString: String) {
        val containerLatch = CountDownLatch(1)
        this.followOutput { outputFrame ->
            if (outputFrame.utf8String.contains(waitForThisString)) {
                containerLatch.countDown()
            }
        }
        containerLatch.await()
    }
    // Method where the container is started
    val container = OracleContainerProvider().newInstance().withInitScript("setup_oracle.sql")
    container.start()
    container.waitUntilLogReady("Database ready to use. Enjoy! ;)")

Then I don't have any connection issues anymore

[kiview]

Hey @nussbam,
you are correct, OracleContainer does not override waitUntilContainerStarted (as opposed to e.g. PostgreSQLContainer).

So this is kind of a bug (but also a legacy design in JdbcDatabaseContainer).

[mumukiller]

@kiview how to check a fix for the issue? All tests related to OracleContainer are ignored and i suppose it's related to Docker DMCA Takedown Notice.

[AnEmortalKid]

If it helps any, there was an update on the wnameless repo:

+ The new DockerHub [wnameless/oracle-xe-11g-r2] has been released, because
+ the old [wnameless/oracle-xe-11g] is banned by DockerHub and I cannot restore it.
+ Thanks for the help from the staff in Oracle with my DMCA Takedown issue, however this problem
+ is totally ignored by the DockerHub and I barely can't do anything but to open a new repo.
+ Sep 29 2019

[ashleyfrieze]

I have a workaround for this. I subclassed OracleContainer and then put this method in:

    @Override
    protected void waitUntilContainerStarted() {
        // wait for Oracle to be fully initialized
        WaitStrategy waitStrategy = getWaitStrategy();
        if (waitStrategy != null) {
            waitStrategy.waitUntilReady(this);
        }

        // now, the JDBC connection should definitely work without lots of wasteful polling
        super.waitUntilContainerStarted();
    }

Given our Oracle container was taking a long time to start up, and our wait strategy was for the _Done_ message in the logs, I thought it would be sensible to prevent the JDBC polling until after the message appeared in the logs.

For other wait strategies you might flip these round.

Is it worth a PR on OracleContainer itself to do something like the above?

[KyleAure]

@kiview Now that oracle has an official container that anyone can easily build should we update the container wait strategy to look for the following output in logs?

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

If so let me know and I can work on delivering that.
The official container also does use the docker health check so that is another option as well.