8 Replies Latest reply on Dec 17, 2017 11:36 AM by siggi-k.

    SQLException Transaction Status Rollback in WrapperDataSource without any notice

    siggi-k.

      We are migrating from JBoss 4.2.3 GA and MS SQL Server 2008 R2 to Wildfly 11 and PostgreSQL 10. We use the Hibernate version shipped with Wildfly (5.1.10.Final)

       

      We have a very complex application where we use an external API that cannot be debugged by myself. We are using EJB remote proxies of this API for executing operations.

      There are several DB-Operations executed with JPA (NamedQuery on an Entity) in one container managed transaction (xa-datasource configured in Wildfly 11).

      The NamedQuery works fine for most cases, but there's one case an error occurs without any visible notice in the logfiles.

       

      The transaction is marked with status rollback, but I don't have any idea why. No exception, no debug message, nothing.

       

      The only difference to the same NamedQuery in this scenario is that rows are deleted from the tables a few steps before within the same transaction.

      We already had some problems with PostgreSQL and our application as PostgreSQL does not implement standard transaction isolation level "read uncommited" as the MS SQL Server does, see https://www.postgresql.org/docs/10/static/transaction-iso.html

      I don't know if this may be related to my problem.

       

      The only guess I have right now is an error and supressed exception in the external API, e. g. locking.

       

      This is the relevant Stacktrace where Hibernate fails to prepare the statement:

      Caused by: org.hibernate.exception.GenericJDBCException: could not prepare statement at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:47) at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:111) at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:182) at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareQueryStatement(StatementPreparerImpl.java:148) at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1934) at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1903) at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1881) at org.hibernate.loader.Loader.doQuery(Loader.java:925) at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:342) at org.hibernate.loader.Loader.doList(Loader.java:2622) at org.hibernate.loader.Loader.doList(Loader.java:2605) at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2434) at org.hibernate.loader.Loader.list(Loader.java:2429) at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:501) at org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:371) at org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:216) at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1339) at org.hibernate.internal.QueryImpl.list(QueryImpl.java:87) at org.hibernate.jpa.internal.QueryImpl.list(QueryImpl.java:606) at org.hibernate.jpa.internal.QueryImpl.getResultList(QueryImpl.java:483) ... 172 more

      Caused by: java.sql.SQLException: IJ031070: Transaction cannot proceed: STATUS_MARKED_ROLLBACK at org.jboss.jca.adapters.jdbc.WrapperDataSource.checkTransactionActive(WrapperDataSource.java:245) at org.jboss.jca.adapters.jdbc.WrappedConnection.checkTransactionActive(WrappedConnection.java:1928) at org.jboss.jca.adapters.jdbc.WrappedConnection.checkStatus(WrappedConnection.java:1943) at org.jboss.jca.adapters.jdbc.WrappedConnection.checkTransaction(WrappedConnection.java:1917) at org.jboss.jca.adapters.jdbc.WrappedConnection.prepareStatement(WrappedConnection.java:447) at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:146) at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:172) ... 189 more

       

      I set the log level of nearly anything to debug/trace, switched on Spy (as mentioned in the IronJacamar documentation).

       

      The last thing printed with level debug is "getConnection()" and the prepared statement from Hibernate, which is executable via pgadmin.

       

      Does anyone have an idea what may cause such an error without any further notice?

       

      Siggi

        • 1. Re: SQLException Transaction Status Rollback in WrapperDataSource without any notice
          jaikiran

          Can you please post that entire exception stacktrace? That might help understand a bit about what's going on.

          • 2. Re: SQLException Transaction Status Rollback in WrapperDataSource without any notice
            siggi-k.

            Find the full stacktrace attached. But it only seems to be a following error. What I think is going on:

             

            1. First statement is executed, transaction is set to status rollback.

            2. Next statement is going to be prepared

            3. connection.preparedStatement is called, which is wrapped in IronJacamar WrappedConnection

            4. WrappedConnection is calling WrapperDataSource which detects that the transaction is already set to rollback and fails.

             

                  try       {        

                      int status = userTransaction.getStatus();

                 

                     if (status == Status.STATUS_NO_TRANSACTION)             return;

                   

                           // Only allow states that will actually succeed     

                          if (status != Status.STATUS_ACTIVE && status != Status.STATUS_PREPARING &&              status != Status.STATUS_PREPARED && status != Status.STATUS_COMMITTING)      

                         {

                             throw new SQLException("Transaction cannot proceed " + TxUtils.getStatusAsString(status));      

                         }

                  }  

                  catch (SQLException se)

                  {

                     throw se;

                  }

            ---------------------------------------------------------------------------------------------------------------------

             

            But the real reason why the transaction is set to rollback must be swallowed in the statement a step before. This is the trace from arjuna (suddently the transaction is not active anymore):

             

            2017-12-15 08:37:39,418 DEBUG [jboss.jdbc.spy] (default task-49) java:/EEDataSource [DataSource] getConnection()

            2017-12-15 08:37:39,418 TRACE [com.arjuna.ats.jta] (default task-49) TransactionImple.equals

            2017-12-15 08:37:39,418 TRACE [com.arjuna.ats.jta] (default task-49) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

            2017-12-15 08:37:39,418 TRACE [com.arjuna.ats.jta] (default task-49) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

            2017-12-15 08:37:39,418 DEBUG [jboss.jdbc.spy] (default task-49) java:/EEDataSource [Connection] prepareStatement(/* select p from MyEntity p)

            2017-12-15 08:37:39,418 DEBUG [jboss.jdbc.spy] (default task-49) java:/EEDataSource [PreparedStatement] setString(1, 12345678)

            2017-12-15 08:37:39,418 TRACE [com.arjuna.ats.jta] (default task-49) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

            2017-12-15 08:37:39,418 DEBUG [jboss.jdbc.spy] (default task-49) java:/EEDataSource [PreparedStatement] executeQuery()

            2017-12-15 08:37:39,419 DEBUG [jboss.jdbc.spy] (default task-49) java:/EEDataSource [ResultSet] next()

            2017-12-15 08:37:39,419 DEBUG [jboss.jdbc.spy] (default task-49) java:/EEDataSource [ResultSet] close()

            2017-12-15 08:37:39,419 DEBUG [jboss.jdbc.spy] (default task-49) java:/EEDataSource [PreparedStatement] isClosed()

            2017-12-15 08:37:39,419 DEBUG [jboss.jdbc.spy] (default task-49) java:/EEDataSource [PreparedStatement] getMaxRows()

            2017-12-15 08:37:39,419 DEBUG [jboss.jdbc.spy] (default task-49) java:/EEDataSource [PreparedStatement] getQueryTimeout()

            2017-12-15 08:37:39,419 DEBUG [jboss.jdbc.spy] (default task-49) java:/EEDataSource [PreparedStatement] close()

            2017-12-15 08:37:39,419 DEBUG [jboss.jdbc.spy] (default task-49) java:/EEDataSource [Connection] isClosed()

            2017-12-15 08:37:39,419 DEBUG [org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl] (default task-49) Initiating JDBC connection release from afterStatement

            2017-12-15 08:37:39,419 DEBUG [jboss.jdbc.spy] (default task-49) java:/EEDataSource [Connection] isClosed()

            2017-12-15 08:37:39,419 TRACE [com.arjuna.ats.jta] (default task-49) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

            2017-12-15 08:37:39,419 DEBUG [jboss.jdbc.spy] (default task-49) java:/EEDataSource [Connection] getWarnings()

            2017-12-15 08:37:39,419 TRACE [com.arjuna.ats.jta] (default task-49) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

            2017-12-15 08:37:39,419 DEBUG [jboss.jdbc.spy] (default task-49) java:/EEDataSource [Connection] clearWarnings()

            2017-12-15 08:37:39,419 DEBUG [jboss.jdbc.spy] (default task-49) java:/EEDataSource [Connection] close()

            2017-12-15 08:37:39,419 TRACE [com.arjuna.ats.jta] (default task-49) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

            2017-12-15 08:37:39,420 TRACE [com.arjuna.ats.jta] (default task-49) TransactionImple.setRollbackOnly

            2017-12-15 08:37:39,420 TRACE [com.arjuna.ats.arjuna] (default task-49) BasicAction::preventCommit( BasicAction: 0:ffffc0a8050b:5431ff44:5a337af4:2cb status: ActionStatus.RUNNING)

            2017-12-15 08:37:39,421 TRACE [com.arjuna.ats.jta] (default task-49) TransactionImple.equals

            2017-12-15 08:37:39,421 TRACE [com.arjuna.ats.jta] (default task-49) TransactionImple.getStatus: javax.transaction.Status.STATUS_MARKED_ROLLBACK

            2017-12-15 08:37:39,421 TRACE [com.arjuna.ats.jta] (default task-49) TransactionImpleManager.suspend

            2017-12-15 08:37:39,421 TRACE [com.arjuna.ats.arjuna] (default task-49) BasicAction::removeChildThread () action 0:ffffc0a8050b:5431ff44:5a337af4:2cb removing 49

            2017-12-15 08:37:39,421 TRACE [com.arjuna.ats.arjuna] (default task-49) BasicAction::removeChildThread () action 0:ffffc0a8050b:5431ff44:5a337af4:2cb removing 49 result = true

            2017-12-15 08:37:39,421 TRACE [com.arjuna.ats.jta] (default task-49) TransactionImple.equals

            2017-12-15 08:37:39,421 TRACE [com.arjuna.ats.jta] (default task-49) TransactionImpleManager.resume

            2017-12-15 08:37:39,421 TRACE [com.arjuna.ats.arjuna] (default task-49) BasicAction::addChildThread () action 0:ffffc0a8050b:5431ff44:5a337af4:2cb adding Thread[default task-49,5,main]

            2017-12-15 08:37:39,421 TRACE [com.arjuna.ats.arjuna] (default task-49) BasicAction::addChildThread () action 0:ffffc0a8050b:5431ff44:5a337af4:2cb adding Thread[default task-49,5,main] result = false

            2017-12-15 08:37:39,421 TRACE [com.arjuna.ats.jta] (default task-49) TransactionImple.equals

            • 3. Re: SQLException Transaction Status Rollback in WrapperDataSource without any notice
              jaikiran

              From the looks of that stacktrace, it appears that a remote call is coming to a stateful EJB (a new transaction gets created) which then invokes another stateful EJB (existing incoming transaction being used) and that then runs into this exception? Is that right?

               

              The arjuna logs indicate there's an explicit call to setRollbackOnly() from somewhere in this flow.

               

              What does the code in this bean class/method look like de.itr.Verfahren.java?

              • 4. Re: SQLException Transaction Status Rollback in WrapperDataSource without any notice
                jaikiran

                Furthermore, this looks odd:

                2017-12-15 08:37:39,419 DEBUG [jboss.jdbc.spy] (default task-49) java:/EEDataSource [Connection] close()

                2017-12-15 08:37:39,419 TRACE [com.arjuna.ats.jta] (default task-49) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

                2017-12-15 08:37:39,420 TRACE [com.arjuna.ats.jta] (default task-49) TransactionImple.setRollbackOnly

                2017-12-15 08:37:39,420 TRACE [com.arjuna.ats.arjuna] (default task-49) BasicAction::preventCommit( BasicAction: 0:ffffc0a8050b:5431ff44:5a337af4:2cb status: ActionStatus.RUNNING)

                 

                 

                There seems to be close() being called on the connection. What does your connection handling code look like in the EJB?

                • 5. Re: SQLException Transaction Status Rollback in WrapperDataSource without any notice
                  siggi-k.

                  For me right now it's these two lines resp. something that get's not printed in the log.

                   

                  2017-12-15 08:37:39,420 TRACE [com.arjuna.ats.jta] (default task-49) TransactionImple.setRollbackOnly

                  2017-12-15 08:37:39,420 TRACE [com.arjuna.ats.arjuna] (default task-49) BasicAction::preventCommit( BasicAction: 0:ffffc0a8050b:5431ff44:5a337af4:2cb status: ActionStatus.RUNNING)

                   

                  The close() is always printed after each statement. But I'm also wondering there is no "return to pool" instead.

                   

                  Regarding connection handling: the EJB (remote proxy) is part of the external API I don't have access to, but it's container managed and I have a stateful EJB, that starts the process with:

                   

                  @TransactionAttribute(TransactionAttributeType.REQUIRES_NEW).

                   

                  I'm going to try a intermediate version with Wildfly 11 and MS SQL Server to see if the error occurs.

                  • 6. Re: SQLException Transaction Status Rollback in WrapperDataSource without any notice
                    siggi-k.

                    oh, sorry, I've overseen this post.

                     

                    The flow is:

                     

                    1. Stateful EJB1 (from our client application) opens transaction (REQUIRES_NEW)

                    2. EJB1 is getting the stateful remote EJB2 (from external API) via EJB-Client call, should be transaction REQUIRED

                    3. EJB1 is executing a method on EJB2 proxy, that starts a chain of database operations.

                    4. EJB2 deletes one row from a database table, a few steps later it tries to insert a new row in the same table

                     

                    The process is working fine when there is no deletion before insertion of a new row.

                     

                    I don't have the source of EJB2.

                     

                    Can the setRollbackOnly() method be called directly? I would have guessed it is called from the container managing the transaction.

                    • 7. Re: SQLException Transaction Status Rollback in WrapperDataSource without any notice
                      jaikiran

                      siggi-k.  wrote:

                       

                      oh, sorry, I've overseen this post.

                       

                      The flow is:

                       

                       

                      Can the setRollbackOnly() method be called directly? I would have guessed it is called from the container managing the transaction.

                      The application/EJB itself can explicitly call the setRollbackOnly() on the session context through this API EJBContext (Java EE 6 ) It looks like that EJB is indeed doing that.

                      • 8. Re: SQLException Transaction Status Rollback in WrapperDataSource without any notice
                        siggi-k.

                        ok. I think I've found the problem.

                         

                        There's another stateful EJB in the application that is called in the background and has a separate datasource with transaction isolation level READ_UNCOMMITED. This Bean seems to be designed to make dirty reads (transaction attribute NOT_SUPPORTED on some methods).

                         

                        As PostgreSQL does not support this (READ_UNCOMMITED = READ_COMMITED) my change (to transaction REQUIRED) solved a problem I had before (dirty read within the same transaction), but now causes my current problem, as the EJB of the external API reads to much (including the uncommited deletion).

                         

                        Why the real error is swallowed I can only imagine...

                         

                        This is really weired design and needs some refactoring.

                         

                        jaikiran many thanks for your hints.