Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Fixed
-
3.0.4, 3.1.3
-
None
-
Win 10
MariaDB 10.6.5
Java 17 (also Java 11)
SpringBoot 2.7.9, Hibernate 5.6
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.