Regressions comparing with 0.1

[dstepanov]

I'm hitting a lot of errors trying to upgrade the dependency to 0.2 in Micronaut R2dbc integration

• We used to generate the boolean representation as NUMBER(3) and it used to work, now it fails because every boolean is expected to be BOOLEAN type which we don't have in version 18, the only one available officially at https://hub.docker.com/r/gvenzl/oracle-xe
• It looks like byte[] type is not supported anymore and ByteBuffer is the only one supported

[Michael-A-McMahon]

Thanks for reporting this, @dstepanov.

We have a pull request that will restore support for Java Boolean to NUMBER and byte[] to RAW mappings. The pull request is here: #31.

In the PR, I added some test cases to catch regressions for Boolean and byte[] bind values. We can depend on these mappings to remain supported going forward.

Please note that while Oracle R2DBC will support byte[] bind values, it is not guaranteed that all R2DBC drivers will also support this. The R2DBC 0.9 Specification lists ByteBuffer as the type mapping guideline. For portability across all drivers, ByteBuffer might be a safer choice.

BTW: For some reason, GitHub didn't send me a notification email for this issue. Sorry for the slow response; I didn't see this until today.

[dstepanov]

Thanks, @Michael-A-McMahon I will wait for the next release to upgrade. Regarding byte[] you might be right and we should always wrap it in ByteByffer.

BTW: I'm trying to enable the tests for 0.1 and there is some kind of deadlock micronaut-projects/micronaut-data#1081
I remember reading byte[] was a bit problematic for Oracle DB and might cause the issue, currently we have this method:

        try {
            return resultSet.get(index, byte[].class);
        } catch (Exception e) {
            // Ignore
        }
        // Second try for Oracle and H2
        Object o = resultSet.get(index);
        if (o == null) {
            return null;
        }
        if (o instanceof byte[]) {
            return null;
        }
        if (o instanceof ByteBuffer) {
            return ((ByteBuffer) o).array();
        }
        if (o instanceof Blob) {
            return Mono.from(((Blob) o).stream()).block().array();
        }
        return convertRequired(o, byte[].cl

[Michael-A-McMahon]

@dstepanov I'd like to investigate this deadlock, but I can't tell what I should be looking at. Is there a particular test you have that can recreate the deadlock?
After 0.1.0, we resolved a deadlock that could occur when using io.r2dbc.spi.Batch. We also resolved some deadlocks where OraclePreparedStatement.close() appears in a thread dump as a symptom. It's possible you've uncovered a new case, so I'd really like to debug it.

ResultSet.getObject(int, byte[].class) should be supported for columns of type RAW (aka: BINARY, VARBINARY) and LONG RAW (aka: LONGVARBINARY). This is specified in Table B-5 of the JDBC 4.3 Specification. Can you let me know how to recreate the failure? I work on the Oracle JDBC driver too, so if there's a bug I can fix it.
One case where we've seen byte[] mapping fail is for queries like "SELECT null FROM sys.dual". In this case, the Oracle Database describes the column type as VARCHAR, and Oracle JDBC throws an exception because VARCHAR to byte[] mapping is not supported. Handling this case is on my TODO list; If a column value is the null literal, then JDBC shouldn't care what class it needs to be mapped into, the return value is always null.

[dstepanov]

Regarding byte[] it doesn't work if I use resultSet.get(index, byte[].class);

I'm getting an exception:

Index: 21, Java Type: [B
  oracle.r2dbc.impl.OracleR2dbcExceptions$OracleR2dbcNonTransientException: Unsupported SQL to Java type mapping. SQL Type: BLOB, Column Index: 21, Java Type: [B
        at oracle.r2dbc.impl.OracleR2dbcExceptions.newNonTransientException(OracleR2dbcExceptions.java:287)
        at oracle.r2dbc.impl.OracleRowImpl.unsupportedTypeMapping(OracleRowImpl.java:401)
        at oracle.r2dbc.impl.OracleRowImpl.requireSupportedTypeMapping(OracleRowImpl.java:381)
        at oracle.r2dbc.impl.OracleRowImpl.convertColumnValue(OracleRowImpl.java:242)
        at oracle.r2dbc.impl.OracleRowImpl.get(OracleRowImpl.java:208)
        at io.micronaut.data.r2dbc.mapper.ColumnNameR2dbcResultReader.readBlob(ColumnNameR2dbcResultReader.java:105)

Regarding the deadlock I think it's only happening at the CI, you can try it yourself by running ./gradlew :data-r2dbc:test --tests "io.micronaut.data.r2dbc.oraclexe.*" you wound need to have docker running and also remove the exclude in data-r2dbc/build.gradle

[dstepanov]

I have tried to run the tests locally and they pass but on the Github actions it's stuck at the beginning where tables are created:

    19:14:32.391 [Test worker] INFO  o.testcontainers.DockerClientFactory - ✔︎ Docker environment should have more than 2GB free disk space
    19:14:32.544 [Test worker] INFO  🐳 [gvenzl/oracle-xe:18] - Pulling docker image: gvenzl/oracle-xe:18. Please be patient; this may take some time but only needs to be done once.
    19:14:32.878 [docker-java-stream-1884762495] INFO  🐳 [gvenzl/oracle-xe:18] - Starting to pull image
    19:14:32.879 [docker-java-stream-1884762495] INFO  🐳 [gvenzl/oracle-xe:18] - Pulling image layers:  0 pending,  0 downloaded,  0 extracted, (0 bytes/0 bytes)
    19:14:33.558 [docker-java-stream-1884762495] INFO  🐳 [gvenzl/oracle-xe:18] - Pulling image layers:  1 pending,  1 downloaded,  0 extracted, (102 MB/? MB)
    19:14:36.654 [docker-java-stream-1884762495] INFO  🐳 [gvenzl/oracle-xe:18] - Pulling image layers:  1 pending,  1 downloaded,  1 extracted, (394 MB/? MB)
    19:14:50.269 [docker-java-stream-1884762495] INFO  🐳 [gvenzl/oracle-xe:18] - Pulling image layers:  0 pending,  2 downloaded,  1 extracted, (1 GB/1 GB)
    19:15:40.686 [docker-java-stream-1884762495] INFO  🐳 [gvenzl/oracle-xe:18] - Pulling image layers:  0 pending,  2 downloaded,  2 extracted, (1 GB/1 GB)
    19:15:40.774 [docker-java-stream-1884762495] INFO  🐳 [gvenzl/oracle-xe:18] - Pull complete. 2 layers, pulled in 67s (downloaded 1 GB at 26 MB/s)
    19:15:40.833 [Test worker] INFO  🐳 [gvenzl/oracle-xe:18] - Creating container for image: gvenzl/oracle-xe:18
    19:15:40.910 [Test worker] INFO  🐳 [gvenzl/oracle-xe:18] - Starting container with ID: dfe047439a6cc981999b3d7c368467912fabe6773745082fd97569b78774cd05
    19:15:41.622 [Test worker] INFO  🐳 [gvenzl/oracle-xe:18] - Container gvenzl/oracle-xe:18 is starting: dfe047439a6cc981999b3d7c368467912fabe6773745082fd97569b78774cd05
    19:15:41.724 [Test worker] INFO  🐳 [gvenzl/oracle-xe:18] - Waiting for database connection to become available at jdbc:oracle:thin:system/password@localhost:49154:xe using query 'SELECT 1 FROM DUAL'
    19:16:27.078 [Test worker] INFO  🐳 [gvenzl/oracle-xe:18] - Container is started (JDBC URL: jdbc:oracle:thin:system/password@localhost:49154:xe)
    19:16:27.079 [Test worker] INFO  🐳 [gvenzl/oracle-xe:18] - Container gvenzl/oracle-xe:18 started in PT1M54.554733S
    19:16:27.229 [Test worker] INFO  i.m.context.env.DefaultEnvironment - Established active environments: [test]
    19:16:35.039 [Test worker] DEBUG i.m.d.r.o.DefaultR2dbcRepositoryOperations - Creating a new Connection for DataSource: default
    19:16:35.515 [ForkJoinPool.commonPool-worker-3] DEBUG io.micronaut.data.query - Creating Table: 
    CREATE SEQUENCE "MEAL_SEQ" MINVALUE 1 START WITH 1 NOCACHE NOCYCLE
    19:16:35.574 [ForkJoinPool.commonPool-worker-3] DEBUG io.micronaut.data.query - Creating Table: 
    CREATE TABLE "MEAL" ("MID" NUMBER(19) NOT NULL PRIMARY KEY,"CURRENT_BLOOD_GLUCOSE" NUMBER(10) NOT NULL,"CREATED_ON" DATE,"UPDATED_ON" DATE)

I'm now sure what would it cause.

[dstepanov]

Link to the code that does create tables etc:
https://github.com/micronaut-projects/micronaut-data/blob/753b357133acc2d35133857b59089921221abe92/data-r2dbc/src/main/java/io/micronaut/data/r2dbc/config/R2dbcSchemaGenerator.java

[dstepanov]

Looks like 0.2 fixed the create table deadlock, tests are running and failing at the regressions reported.
I can observe another deadlock with a table created by:

    CREATE TABLE "SALE" ("ID" NUMBER(19) NOT NULL PRIMARY KEY,"NAME" VARCHAR(255) NOT NULL,"DATA" CLOB,"QUANTITIES" CLOB,"EXTRA_DATA" CLOB)

The json test is stuck with log:

OracleXEJsonSpec > test read and write json STANDARD_OUT
    20:04:36.801 [Test worker] DEBUG i.m.d.r.o.DefaultR2dbcRepositoryOperations - Creating a new Connection for DataSource: default
    20:04:36.853 [ForkJoinPool.commonPool-worker-3] DEBUG i.m.d.r.o.DefaultR2dbcRepositoryOperations - Transaction Begin for DataSource: default
    20:04:36.856 [ForkJoinPool.commonPool-worker-3] DEBUG io.micronaut.data.query - Executing SQL Insert: INSERT INTO "SALE" ("NAME","DATA","QUANTITIES","EXTRA_DATA","ID") VALUES (?,?,?,?,"SALE_SEQ".nextval)
    20:04:36.860 [ForkJoinPool.commonPool-worker-3] TRACE io.micronaut.data.query - Binding parameter at position 0 to value test 1 with data type: STRING
    20:04:37.082 [ForkJoinPool.commonPool-worker-3] TRACE io.micronaut.data.query - Binding parameter at position 1 to value {"foo":"bar"} with data type: JSON
    20:04:37.085 [ForkJoinPool.commonPool-worker-3] TRACE io.micronaut.data.query - Binding parameter at position 2 to value {"foo":10} with data type: JSON
    20:04:37.092 [ForkJoinPool.commonPool-worker-3] TRACE io.micronaut.data.query - Binding parameter at position 3 to value null with data type: JSON
    20:04:37.179 [ForkJoinPool.commonPool-worker-3] DEBUG i.m.d.r.o.DefaultR2dbcRepositoryOperations - Committing transaction for DataSource default.
    20:04:37.182 [ForkJoinPool.commonPool-worker-3] DEBUG i.m.d.r.o.DefaultR2dbcRepositoryOperations - Closing Connection for DataSource: default
    20:04:37.187 [Test worker] DEBUG i.m.d.r.o.DefaultR2dbcRepositoryOperations - Creating a new Connection for DataSource: default
    20:04:37.258 [ForkJoinPool.commonPool-worker-3] DEBUG i.m.d.r.o.DefaultR2dbcRepositoryOperations - Transaction Begin for DataSource: default
    20:04:37.261 [ForkJoinPool.commonPool-worker-3] DEBUG io.micronaut.data.query - Executing Query: SELECT sale_."ID",sale_."NAME",sale_."DATA",sale_."QUANTITIES",sale_."EXTRA_DATA",sale_items_."ID" AS items_id,sale_items_."FK_SALE_ID" AS items_fk_sale_id,sale_items_."NAME" AS items_name,sale_items_."DATA" AS items_data FROM "SALE" sale_ LEFT JOIN "SALE_ITEM" sale_items_ ON sale_."ID"=sale_items_."FK_SALE_ID" WHERE (sale_."ID" = ?)
    20:04:37.272 [ForkJoinPool.commonPool-worker-3] TRACE io.micronaut.data.query - Binding parameter at position 0 to value 1 with data type: LONG

[Michael-A-McMahon]

Thanks for sharing these details.

The BLOB to byte[] mapping should be fixed by #36.

I'll try running the json test to see where the things are getting locked up. I should have time to do that over the next few days.
Dumping stack traces with the jstack command might provide a hint about what's going on. When debugging deadlocks, jstack is usually my first step. If you can provide a dump, please share.

[dstepanov]

Thanks, it’s only happening when it’s run on the github actions so I cannot dump the stack

[Michael-A-McMahon]

In the JSON case, I believe the cause is a bug in Oracle R2DBC 0.2.0 where cancelling the Subscription to a Blob/Clob.stream() causes a thread to become blocked. This bug will be fixed with #33.
The symptom for this bug is a stack trace like this:

  java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@11.0.1/Native Method)
	- parking to wait for  <0x000000078fbcdc78> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(java.base@11.0.1/LockSupport.java:194)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@11.0.1/AbstractQueuedSynchronizer.java:2081)
	at oracle.jdbc.driver.OracleClob.awaitPublishing(OracleClob.java:2188)
	at oracle.jdbc.driver.OracleClob.lockBeforePublishing(OracleClob.java:2170)
	at oracle.jdbc.driver.OracleClob.freeAsyncOracle(OracleClob.java:2001)
	at oracle.sql.CLOB.freeAsyncOracle(CLOB.java:403)
...

When creating tables, it looks like micronaut has a Flux.flatMap operator that allows a single Connection to be shared between multiple threads. I see this here:
https://github.com/micronaut-projects/micronaut-data/blob/fa62a8f3a4cb39e4d9b936c899816acd80e2016e/data-r2dbc/src/main/java/io/micronaut/data/r2dbc/config/R2dbcSchemaGenerator.java#L100
https://github.com/micronaut-projects/micronaut-data/blob/fa62a8f3a4cb39e4d9b936c899816acd80e2016e/data-r2dbc/src/main/java/io/micronaut/data/r2dbc/config/R2dbcSchemaGenerator.java#L117
Oracle R2DBC does not support concurrent database calls on a single Connection. If a connection is already executing a database call, then it will block any thread that attempts to start another call. The blocked thread will only become unblocked after the current call has completed. This leads into a deadlock where the connection needs a thread to complete the current call, but the thread pool has none available because all threads are blocked waiting for the current call to complete. We see this play out in environments like github actions where the common ForkJoinPool has a small size because there are few CPU processors. If just one thread becomes blocked, then no threads will be left to execute the unblocking callback.

The use of Flux.concatMap rather than flatMap might be one way to handle this. While the flatMap operator allows concurrent subscriptions to flat mapped Publishers, the concatMap operator serially subscribes to each flat mapped Publisher.