[CONJ-1071] Error during Bulk execution might result in connection wrong state Created: 2023-04-13  Updated: 2023-06-06  Resolved: 2023-04-26

Status: Closed
Project: MariaDB Connector/J
Component/s: batch
Affects Version/s: 3.0.4, 3.1.3
Fix Version/s: 3.1.4

Type: Bug Priority: Major
Reporter: Radek Wikturna Assignee: Diego Dupin
Resolution: Fixed Votes: 0
Labels: None
Environment:

Win 10
MariaDB 10.6.5
Java 17 (also Java 11)
SpringBoot 2.7.9, Hibernate 5.6


Attachments: Text File corrupted connection.log     Zip Archive jdbc-driver-bug.zip    

 Description   

With any 3.x driver, default jdbc url (no special connection params), in a SpringBoot & Hibernate project I experience the following extremely wierd behaviour:

Note that we use batching (spring.jpa.properties.hibernate.jdbc.batch_size: 10)

Table DDL:

{{CREATE TABLE `usu_servicedesk_agent` (
`sys_pk` int(11) NOT NULL,
`sys_id` binary(16) NOT NULL,
`first_name` varchar(40) COLLATE utf8mb4_unicode_ci NOT NULL,
`last_name` varchar(40) COLLATE utf8mb4_unicode_ci NOT NULL,
`title` varchar(10) COLLATE utf8mb4_unicode_ci NOT NULL DEFAULT 'MX',
`email` varchar(320) COLLATE utf8mb4_unicode_ci DEFAULT NULL,
`phone` varchar(15) COLLATE utf8mb4_unicode_ci DEFAULT NULL,
`sys_user_id` varchar(255) COLLATE utf8mb4_unicode_ci NOT NULL,
`availability` varchar(30) COLLATE utf8mb4_unicode_ci NOT NULL DEFAULT 'OFFLINE',
`sys_change_count` int(11) NOT NULL,
`sys_user_changed` varchar(40) COLLATE utf8mb4_unicode_ci NOT NULL,
`sys_user_created` varchar(40) COLLATE utf8mb4_unicode_ci NOT NULL,
`sys_when_changed` datetime(6) NOT NULL,
`sys_when_created` datetime(6) NOT NULL,
PRIMARY KEY (`sys_pk`),
UNIQUE KEY `sys_id` (`sys_id`),
UNIQUE KEY `sys_user_id` (`sys_user_id`),
KEY `i_usu_servicedesk_agent_last_name_first_name` (`last_name`,`first_name`),
CONSTRAINT `c_usu_servicedesk_agent_01` CHECK (`title` in ('MR','MS','MX')),
CONSTRAINT `c_usu_servicedesk_agent_02` CHECK (`availability` in ('ONLINE','BUSY','OFFLINE'))
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_unicode_ci;

CREATE OR REPLACE SEQUENCE `usu_servicedesk_agent_sys_pk_seq` start with 1 minvalue 1 maxvalue 9223372036854775806 increment by 1 cache 1000 nocycle ENGINE=InnoDB;
}}
The application attempts to insert 7 records into the table using a batch insert (this is done by Hibernate when the persistence context is flushed).

The logged SQL with all values logged in Params:[...]

{{2023-04-13 16:03:18.155 ERROR 26236 — [nio-8080-exec-1] d.u.v.core.config.logging.sql.SqlLogger : Connection:1, Time:7, Query: insert into usu_servicedesk_agent (sys_change_count, sys_id, sys_user_changed, sys_user_created, sys_when_changed, sys_when_created, availability, email, first_name, last_name, phone, sys_user_id, title, sys_pk) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?), Params:[(0,X'2B08A219B2A24DE78A0C2477DAD20EFF' /* 2b08a219-b2a2-4de7-8a0c-2477dad20eff */,'Somebody DevMode','Somebody DevMode',TIMESTAMP '2023-04-13 16:03:18.0270854',TIMESTAMP '2023-04-13 16:03:18.0270854','OFFLINE','kenny.roggers@singers.com','Kenny','Roggers',NULL,'b154a0d6-aea8-4b91-be89-d1f76e4e2d09','MR',1022),(0,X'C4FA2F916160499697F82650629FBD66' /* c4fa2f91-6160-4996-97f8-2650629fbd66 */,'Somebody DevMode','Somebody DevMode',TIMESTAMP '2023-04-13 16:03:18.0735957',TIMESTAMP '2023-04-13 16:03:18.0735957','OFFLINE','mark.knopfler@singers.com','Mark','Knopfler','+493012345678','f0a5f4c5-70d1-4d42-9563-aabedf6c535b','MR',1023),(0,X'929BBCA2C5B94B5F9091ABFAFFC76C3A' /* 929bbca2-c5b9-4b5f-9091-abfaffc76c3a */,'Somebody DevMode','Somebody DevMode',TIMESTAMP '2023-04-13 16:03:18.0755702',TIMESTAMP '2023-04-13 16:03:18.0755702','OFFLINE','kurt.cobain@singers.com','Kurt','Cobain','+493012345678','3e36215a-307e-4e30-b6a2-bfbaf4d8b302','MR',1024),(0,X'D43ADD0275004A7DBFE92A3566D80729' /* d43add02-7500-4a7d-bfe9-2a3566d80729 */,'Somebody DevMode','Somebody DevMode',TIMESTAMP '2023-04-13 16:03:18.0775789',TIMESTAMP '2023-04-13 16:03:18.0775789','OFFLINE','alanis.morissette@singers.com','Alanis','Morissette','+493012345678','f7d7d282-92e0-4ed9-bc9e-f7bf53cd8eb6','MR',1025),(0,X'EF71438807E84E489C866E42C0297E5A' /* ef714388-07e8-4e48-9c86-6e42c0297e5a */,'Somebody DevMode','Somebody DevMode',TIMESTAMP '2023-04-13 16:03:18.0795689',TIMESTAMP '2023-04-13 16:03:18.0795689','OFFLINE','dolly.parton@singers.com','Dolly','Parton','+493012345678','47392abd-861a-414b-bc32-87b0e5272e6d','MS',1026),(0,X'850F24B6FEAB4D128F325A5340606B1A' /* 850f24b6-feab-4d12-8f32-5a5340606b1a */,'Somebody DevMode','Somebody DevMode',TIMESTAMP '2023-04-13 16:03:18.0825704',TIMESTAMP '2023-04-13 16:03:18.0825704','OFFLINE','waldemar.matuska@singers.com','Waldemar','Matuška','+420582319111','22f75839-c62c-46cd-bc2b-ff8403498774','MR',1027),(0,X'0CFE4179CB8E4D41B993F6AF57299F7B' /* 0cfe4179-cb8e-4d41-b993-f6af57299f7b */,'Somebody DevMode','Somebody DevMode',TIMESTAMP '2023-04-13 16:03:18.0846134',TIMESTAMP '2023-04-13 16:03:18.0846134','OFFLINE','yvonne.prenosilova@singers.com','Yvonne','Prenosilová','+493012345678','570e6127-6302-4370-8743-2b86bd212be3','MS',1028)]
}}

but because these records are already in the table and there's a unique constraint on `sys_user_id` it fails with a SQL constraint violation exception, which is expected. So far so good.

Now the weird thing: the connection gets somehow corrupted. Since then, any SELECT statement from any table executed in that connection returns no rows (the SQL execution succeeds but the result list is empty) even though there are records in the table. Even something as simple as SELECT count from <table> returns now rows, which normally returns a Long value (at least 0).

After restart the problem is gone - new connection don't suffer from this problem.

I can reproduce it any time, it's deterministic.

I found one workaround: setting useBulkStmts=false in the connection url. With that setting, which we need anyway for optimistic locking anyway, the problem doesn't occur.

I've tried various JDBC drivers:
works: 2.7.9 (regardless whether useBulkStmts is set to true or false)
fails when useBulkStmts=true (which is the default): 3.0.4, 3.0.10, 3.1.3 (with 3.0.3 our project doesn't start so I could not test it)

Included is a very detailed log of the failed insert. It's long becuase I enabled logging of transaction manager activity and also all JDBC operations.



 Comments   
Comment by Diego Dupin [ 2023-04-14 ]

I've not been able to reproduce the problem using the same DDL you provide.
It is possible to have network trace (either using wireshark or just setting log "org.mariadb.jdbc" to trace) ?

Comment by Radek Wikturna [ 2023-04-24 ]

I've tried hard to write a simple program that only uses JDBC calls to reproduce the bug. But I didn't succeed.
Nevertheless, I created a very small SpringBoot project (Kotlin, Gradle, Java11) which makes it possible to reproduce it.
Just import the attached project to IntelliJ IDEA (or some other IDE) and follow README.MD for instructions how to reproduce it. The program logs all JDBC calls, SQL's and transaction manager activity.
Feel free to contact me if you have any troubles.

Comment by Diego Dupin [ 2023-04-26 ]

Thanks for this reproductible case. It would have been very difficult to understand !

Problem resided when using BULK insert that are separated into different queries sent to server (It can occurs when having big command or in this case when data type of parameters are changed during batch), if some errors occurs during one of those queries, then connectors might not read the whole results of all queries, state being then wrong. Next command will then get the remaining result, returning completly wrong data.

Comment by Radek Wikturna [ 2023-04-26 ]

So if I understand, you were able to reproduce the bug using the attached project, correct?

As I wrote, the problem doesn't occur with 2.x driver, and it doesn't occur when `useBulkStmts=false` is set.

I see this a pretty critical problem which can confuse a lot of developers wondering why no data is returned after a failed batched insert (they may not associate this)

Comment by Radek Wikturna [ 2023-04-26 ]

I've just notice the issue is closed and marked as fixed in 3.1.4.
The fix was that quick? Do you have an automated test covering this problem?

Comment by Diego Dupin [ 2023-06-06 ]

yes, you have seen https://github.com/mariadb-corporation/mariadb-connector-j/commit/1ea84e3d85a991893344f64bd01f54ecde3026ed that fix the issue, with the additional test case added.

Generated at Thu Feb 08 03:20:24 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.