Uploaded image for project: 'Agroal'
  1. Agroal
  2. AG-171

ConnectionHandler returned to pool when hibernate hasn't called close

    XMLWordPrintable

Details

    • Bug
    • Resolution: Not a Bug
    • Major
    • None
    • 1.11
    • narayana, pool
    • None
    • False
    • False
    • Undefined

    Description

      We have a spring (5.2.6.RELEASE) based app using narayana jta 5.10.0.Final, hibernate orm 5.4.31.Final (although we also use some direct jdbc vai datasources) and with agroal connection pool.  We noticed that we were seeing errors and warnings in he log:

      2021-05-11 12:12:09,282 | o.h.e.jdbc.spi.SqlExceptionHelper | ERROR | chTaskExecuter-8 | o.h.e.j.s.SqlExceptionHelper     | gine.jdbc.spi.SqlExceptionHelper  142 |          | Enlisted connection used without active transaction

      2021-05-11 12:12:09,283 | com.arjuna.ats.jta | WARN  | chTaskExecuter-8 | c.a.a.jta                        | reflect.NativeMethodAccessorImpl   -2 |          | ARJUNA016029: SynchronizationImple.afterCompletion - failed for org.hibernate.resource.transaction.backend.jta.internal.synchronization.RegisteredSynchronization@49f1e5ae with exception

      java.sql.SQLException: Enlisted connection used without active transaction

              at io.agroal.pool.ConnectionHandler.verifyEnlistment(ConnectionHandler.java:376)

              at io.agroal.pool.wrapper.ConnectionWrapper.isClosed(ConnectionWrapper.java:570)

       

      I put some debugging in the agroal source code and was able to see that the ConnectionHandler.transactionEnd is called which sets enlisted to false and makes the handler avaialable to another thread for connection reuse, after this the hibernate code will call isClose (where an exception is thrown if another thread happens to check out this same handler) and close on the data source wrapper.  This race condition could happen after isClose is called (so no exception/warn) but before close is complete leaving the handler in an unknown state. I have attached files showing the ordering of the calls is transactionEnd->isClosed->close and that enlisted had been set true by the time close was called - though after the log in isClosed (but it threw the exception as another thread checked out the connection handler soon after that.  Looking at the stack trace, it seems that the issue arises because the afterCompletion of the agroal InterposedSynchronization is called before the hibernate registered SynchronizationImple (which is also an interposed synchronization).

      Attachments

        1. closeloaderthread.txt
          12 kB
          Tom Dearman
        2. isclosedloaderthread.txt
          12 kB
          Tom Dearman
        3. transactionendloaderthread.txt
          12 kB
          Tom Dearman

        Activity

          People

            lbarreiro-1 Luis Barreiro
            tomdearman Tom Dearman (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: