hibernate.connection.handling_mode and REQUIRES_NEW Transactions (Hibernate 5.2+Spring 4.3)

I am noticing very different behaviors in our JPA/JTA application, when I set the hibernate.connection.handling_mode and when I do not set it. I have the following entity defined -

@Cache(usage = CacheConcurrencyStrategy.TRANSACTIONAL)
@Entity
public class Notification {

    @Id
    @GeneratedValue()
    private long id;

    @OneToMany(mappedBy = "notification", cascade = CascadeType.ALL, fetch = FetchType.EAGER)
    private Set<ErrorDetails> errorDetails;

    ....
}

And my hiberate properties are set as follows -

    hibernate.dialect=com.CustomMariaDBDialect
    hibernate.transaction.flush_before_completion=true
    hibernate.cache.use_second_level_cache=true
    hibernate.transaction.auto_close_session=true
    hibernate.show_sql=false
    hibernate.id.new_generator_mappings=false
    hibernate.jta.UserTransaction=UserTransaction
    hibernate.cache.infinispan.cachemanager=java:jboss/infinispan/hibernate
    hibernate.transaction.coordinator_class=com.CustomJTATransactionFactory //A JtaTransactionCoordinatorBuilderImpl Uses JNDI Lookup for getUserTransaction
    hibernate.transaction.jta.platform=org.hibernate.engine.transaction.jta.platform.internal.JBossAppServerJtaPlatform
    hibernate.cache.region.factory_class=org.hibernate.cache.infinispan.JndiInfinispanRegionFactory
    hibernate.connection.handling_mode=DELAYED_ACQUISITION_AND_RELEASE_AFTER_STATEMENT

I have multiple Notification entities being saved within a single thread, but all in thier own transactions(managed by Spring TxManager with PropagationLevel set to REQUIRES_NEW). I created a custom Hibernate SessionEventListener to log the session activity. What I noticed was that when I have the connection.handling_mode not set, then all my entities get committed and flushed without issues -

2018-09-24 22:33:29,740 INFO  [default task-56]-[SessionEventListener] partialFlushStart com.myorg.model.Notification@7efedb5d
2018-09-24 22:33:29,741 INFO  [default task-56]-[SessionEventListener] dirtyCalculationStart 0;0;com.myorg.model.Notification@7efedb5d
2018-09-24 22:33:29,741 INFO  [default task-56]-[SessionEventListener] jdbcPrepareStatementStart com.myorg.model.Notification@7efedb5d
2018-09-24 22:33:29,741 INFO  [default task-56]-[SessionEventListener] jdbcConnectionAcquisitionStart com.myorg.model.Notification@7efedb5d
2018-09-24 22:33:29,741 INFO  [default task-56]-[SessionEventListener] jdbcConnectionAcquisitionEnd com.myorg.model.Notification@7efedb5d
2018-09-24 22:33:29,741 INFO  [default task-56]-[SessionEventListener] jdbcPrepareStatementEnd com.myorg.model.Notification@7efedb5d
2018-09-24 22:33:29,741 INFO  [default task-56]-[SessionEventListener] jdbcExecuteStatementStart com.myorg.model.Notification@7efedb5d
2018-09-24 22:33:29,742 INFO  [default task-56]-[SessionEventListener] jdbcExecuteStatementEnd com.myorg.model.Notification@7efedb5d
2018-09-24 22:33:29,742 INFO  [default task-56]-[SessionEventListener] jdbcPrepareStatementStart com.myorg.model.Notification@7efedb5d
2018-09-24 22:33:29,743 INFO  [default task-56]-[SessionEventListener] jdbcPrepareStatementEnd com.myorg.model.Notification@7efedb5d
2018-09-24 22:33:29,743 INFO  [default task-56]-[SessionEventListener] jdbcExecuteStatementStart com.myorg.model.Notification@7efedb5d
2018-09-24 22:33:29,743 INFO  [default task-56]-[SessionEventListener] jdbcExecuteStatementEnd com.myorg.model.Notification@7efedb5d
2018-09-24 22:33:29,743 INFO  [default task-56]-[SessionEventListener] flushStart com.myorg.model.Notification@7efedb5d
2018-09-24 22:33:29,743 INFO  [default task-56]-[SessionEventListener] dirtyCalculationStart com.myorg.model.Notification@7efedb5d
2018-09-24 22:33:29,743 INFO  [default task-56]-[SessionEventListener] dirtyCalculationEnd false com.myorg.model.Notification@7efedb5d
2018-09-24 22:33:29,744 INFO  [default task-56]-[SessionEventListener] partialFlushStart 1;0;com.myorg.model.Notification@7efedb5d
2018-09-24 22:33:29,744 INFO  [default task-56]-[SessionEventListener] Tx completed truefor entity com.myorg.model.Notification@7efedb5d
2018-09-24 22:33:29,744 INFO  [default task-56]-[SessionEventListener] END com.myorg.model.Notification@7efedb5d
2018-09-24 22:33:29,744 INFO  [default task-56]-[SessionEventListener] jdbcConnectionReleaseStart com.myorg.model.Notification@7efedb5d
2018-09-24 22:33:29,744 INFO  [default task-56]-[SessionEventListener] jdbcConnectionReleaseEnd com.myorg.model.Notification@7efedb5d
2018-09-24 22:33:29,761 INFO  [default task-56]-[SessionEventListener] partialFlushStart com.myorg.model.Notification@68c6c90d
2018-09-24 22:33:29,761 INFO  [default task-56]-[SessionEventListener] dirtyCalculationStart 0;0;com.myorg.model.Notification@68c6c90d
2018-09-24 22:33:29,761 INFO  [default task-56]-[SessionEventListener] jdbcPrepareStatementStart com.myorg.model.Notification@68c6c90d
2018-09-24 22:33:29,761 INFO  [default task-56]-[SessionEventListener] jdbcConnectionAcquisitionStart com.myorg.model.Notification@68c6c90d
2018-09-24 22:33:29,761 INFO  [default task-56]-[SessionEventListener] jdbcConnectionAcquisitionEnd com.myorg.model.Notification@68c6c90d
2018-09-24 22:33:29,762 INFO  [default task-56]-[SessionEventListener] jdbcPrepareStatementEnd com.myorg.model.Notification@68c6c90d
2018-09-24 22:33:29,762 INFO  [default task-56]-[SessionEventListener] jdbcExecuteStatementStart com.myorg.model.Notification@68c6c90d
2018-09-24 22:33:29,762 INFO  [default task-56]-[SessionEventListener] jdbcExecuteStatementEnd com.myorg.model.Notification@68c6c90d
2018-09-24 22:33:29,762 INFO  [default task-56]-[SessionEventListener] jdbcPrepareStatementStart com.myorg.model.Notification@68c6c90d
2018-09-24 22:33:29,762 INFO  [default task-56]-[SessionEventListener] jdbcPrepareStatementEnd com.myorg.model.Notification@68c6c90d
2018-09-24 22:33:29,762 INFO  [default task-56]-[SessionEventListener] jdbcExecuteStatementStart com.myorg.model.Notification@68c6c90d
2018-09-24 22:33:29,763 INFO  [default task-56]-[SessionEventListener] jdbcExecuteStatementEnd com.myorg.model.Notification@68c6c90d
2018-09-24 22:33:29,763 INFO  [default task-56]-[SessionEventListener] flushStart com.myorg.model.Notification@68c6c90d
2018-09-24 22:33:29,763 INFO  [default task-56]-[SessionEventListener] dirtyCalculationStart com.myorg.model.Notification@68c6c90d
2018-09-24 22:33:29,763 INFO  [default task-56]-[SessionEventListener] dirtyCalculationEnd false com.myorg.model.Notification@68c6c90d
2018-09-24 22:33:29,763 INFO  [default task-56]-[SessionEventListener] partialFlushStart 1;0;com.myorg.model.Notification@68c6c90d
2018-09-24 22:33:29,763 INFO  [default task-56]-[SessionEventListener] Tx completed truefor entity com.myorg.model.Notification@68c6c90d
2018-09-24 22:33:29,763 INFO  [default task-56]-[SessionEventListener] END com.myorg.model.Notification@68c6c90d

But, when I have the connection.handling_mode set to DELAYED_ACQUISITION_AND_RELEASE_AFTER_STATEMENT, the session hangs in jdbcExecuteStatementStart, and after the Transaction times out after 5 minutes, then it proceeds to commit - Notice that jdbcExecuteStatementStart is at 23:28:32 and ends at 23:33:32 which is after the parent Transaction had timed out -

2018-09-24 23:28:32,506 INFO  [default task-64]-[SessionEventListener] partialFlushStart com.myorg.model.Notification@482bb8c8
2018-09-24 23:28:32,506 INFO  [default task-64]-[SessionEventListener] dirtyCalculationStart 0;0;com.myorg.model.Notification@482bb8c8
2018-09-24 23:28:32,506 INFO  [default task-64]-[SessionEventListener] jdbcPrepareStatementStart com.myorg.model.Notification@482bb8c8
2018-09-24 23:28:32,506 INFO  [default task-64]-[SessionEventListener] jdbcConnectionAcquisitionStart com.myorg.model.Notification@482bb8c8
2018-09-24 23:28:32,507 INFO  [default task-64]-[SessionEventListener] jdbcConnectionAcquisitionEnd com.myorg.model.Notification@482bb8c8
2018-09-24 23:28:32,507 INFO  [default task-64]-[SessionEventListener] jdbcPrepareStatementEnd com.myorg.model.Notification@482bb8c8
2018-09-24 23:28:32,507 INFO  [default task-64]-[SessionEventListener] jdbcExecuteStatementStart com.myorg.model.Notification@482bb8c8
2018-09-24 23:28:32,508 INFO  [default task-64]-[SessionEventListener] jdbcExecuteStatementEnd com.myorg.model.Notification@482bb8c8
2018-09-24 23:28:32,508 INFO  [default task-64]-[SessionEventListener] jdbcConnectionReleaseStart com.myorg.model.Notification@482bb8c8
2018-09-24 23:28:32,508 INFO  [default task-64]-[SessionEventListener] jdbcConnectionReleaseEnd com.myorg.model.Notification@482bb8c8
2018-09-24 23:28:32,508 INFO  [default task-64]-[SessionEventListener] jdbcPrepareStatementStart com.myorg.model.Notification@482bb8c8
2018-09-24 23:28:32,508 INFO  [default task-64]-[SessionEventListener] jdbcConnectionAcquisitionStart com.myorg.model.Notification@482bb8c8
2018-09-24 23:28:32,508 INFO  [default task-64]-[SessionEventListener] jdbcConnectionAcquisitionEnd com.myorg.model.Notification@482bb8c8
2018-09-24 23:28:32,508 INFO  [default task-64]-[SessionEventListener] jdbcPrepareStatementEnd com.myorg.model.Notification@482bb8c8
2018-09-24 23:28:32,508 INFO  [default task-64]-[SessionEventListener] jdbcExecuteStatementStart com.myorg.model.Notification@482bb8c8
2018-09-24 23:33:32,494 INFO  [default task-64]-[SessionEventListener] jdbcExecuteStatementEnd com.myorg.model.Notification@482bb8c8
2018-09-24 23:33:32,495 INFO  [default task-64]-[SessionEventListener] jdbcConnectionReleaseStart com.myorg.model.Notification@482bb8c8
2018-09-24 23:33:32,495 INFO  [default task-64]-[SessionEventListener] jdbcConnectionReleaseEnd com.myorg.model.Notification@482bb8c8
2018-09-24 23:33:32,495 INFO  [default task-64]-[SessionEventListener] flushStart com.myorg.model.Notification@482bb8c8
2018-09-24 23:33:32,536 INFO  [default task-64]-[SessionEventListener] dirtyCalculationStart com.myorg.model.Notification@482bb8c8
2018-09-24 23:33:32,536 INFO  [default task-64]-[SessionEventListener] dirtyCalculationEnd false com.myorg.model.Notification@482bb8c8
2018-09-24 23:33:32,536 INFO  [default task-64]-[SessionEventListener] partialFlushStart 1;0;com.myorg.model.Notification@482bb8c8
2018-09-24 23:33:32,538 INFO  [default task-64]-[SessionEventListener] Tx completed truefor entity com.myorg.model.Notification@482bb8c8
2018-09-24 23:33:32,538 INFO  [default task-64]-[SessionEventListener] END com.myorg.model.Notification@482bb8c8

For the record, I had migrated my application from Hibernate 4.x in which we had not faced such issues. In general, I noticed that Hibernate 5.2 seems to be behaving very odd with nested transactions which require suspending the parent transactions. I am pretty much stumped :/

Update

I decided to take a thread dump while the thread was hung, and I noticed that infact the statement is submitted to MariaDB for execution, and in fact the SHOW PROCESSLIST listed the hung update statement. The thread stack while Java was waiting for the statement execution to complete -

java.lang.Thread.State: RUNNABLE
        at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
        at java.net.SocketInputStream.read(SocketInputStream.java:171)
        at java.net.SocketInputStream.read(SocketInputStream.java:141)
        at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
        at java.io.BufferedInputStream.read1(BufferedInputStream.java:286)
        at java.io.BufferedInputStream.read(BufferedInputStream.java:345)
        - locked <0x0000000699da2af0> (a java.io.BufferedInputStream)
        at org.mariadb.jdbc.internal.common.packet.buffer.ReadUtil.readFully(ReadUtil.java:82)
        at org.mariadb.jdbc.internal.common.packet.buffer.ReadUtil.readFully(ReadUtil.java:92)
        at org.mariadb.jdbc.internal.common.packet.RawPacket.nextPacket(RawPacket.java:77)
        at org.mariadb.jdbc.internal.common.packet.SyncPacketFetcher.getRawPacket(SyncPacketFetcher.java:67)
        at org.mariadb.jdbc.internal.mysql.MySQLProtocol.getResult(MySQLProtocol.java:957)
        at org.mariadb.jdbc.internal.mysql.MySQLProtocol.executeQuery(MySQLProtocol.java:1066)
        at org.mariadb.jdbc.internal.mysql.MySQLProtocol.executeQuery(MySQLProtocol.java:1046)
        at org.mariadb.jdbc.MySQLStatement.execute(MySQLStatement.java:289)
        - locked <0x0000000699da2b18> (a org.mariadb.jdbc.internal.mysql.MySQLProtocol)
        at org.mariadb.jdbc.MySQLStatement.executeUpdate(MySQLStatement.java:364)
        at org.mariadb.jdbc.MySQLPreparedStatement.executeUpdate(MySQLPreparedStatement.java:148)
        at org.jboss.jca.adapters.jdbc.WrappedPreparedStatement.executeUpdate(WrappedPreparedStatement.java:537)
        at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:175)
        at org.hibernate.dialect.identity.GetGeneratedKeysDelegate.executeAndExtract(GetGeneratedKeysDelegate.java:57)

Solution

Finally, I got it solved! It was a deadlock due to updates on related tables. There was this following relationship present on the table -

Notification *<-->* Sources

And the Source was updated before the child transaction was triggered.

After being sure that the query was being submitted to MySQL but was not getting executed, I made sure that it was not a case of a broken JDBC driver by updating the driver, but the issue persisted.

So, finally checking the MySQL SHOW INNODB ENGINE STATUS TRANSACTION logs helped in understanding the reason behind the 'deadlock' -

---TRANSACTION 2735824, ACTIVE 104 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 5 lock struct(s), heap size 1184, 2 row lock(s), undo log entries 1
MySQL thread id 59, OS thread handle 0x7f72d8fb4b00, query id 47941 localhost 127.0.0.1 adminuser update
insert into Notification (id, sourceId, message) values (NULL, 17, 'MISSING')
Trx #rec lock waits 1 #table lock waits 0
Trx total rec lock wait time 0 SEC
Trx total table lock wait time 0 SEC
------- TRX HAS BEEN WAITING 104 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 2726 page no 3 n bits 104 index `PRIMARY` of table `sample`.`Sources` trx table locks 3 total table locks 2  trx id 2735824 lock mode S locks rec but not gap waiting lock hold time 104 wait time before grant 0 
------------------
---TRANSACTION 2735810, ACTIVE 104 sec
5 lock struct(s), heap size 1184, 2 row lock(s), undo log entries 2
MySQL thread id 60, OS thread handle 0x7f72d83feb00, query id 47927 localhost 127.0.0.1 adminuser cleaning up
Trx #rec lock waits 0 #table lock waits 0
Trx total rec lock wait time 0 SEC
Trx total table lock wait time 0 SEC

TRANSACTION 2735810 holds a row lock on the Sources` table because it was 'saved' in the parent transaction.
TRANSACTION 2735824 is now waiting on this lock. The reason being that one of the columns in the Notification table defines a Foreign Key to the Sources table. So, apparently, since the row has been locked, the child transaction has entered a deadlocked.

Vlad's blog explains this - https://vladmihalcea.com/how-does-database-pessimistic-locking-interact-with-insert-update-and-delete-sql-statements/

What is important to note here is that the Notification entity did not define a Hibernate relation to the Sources` entity, and the constraint is present only in the MySQL database.

So, I decided to update the parent Sources` entity after the child transaction had completed so as to avoid locking the parent table .

I am wondering if the relationship had been defined, Hibernate would have treated it differently.