1 2 Previous Next 24 Replies Latest reply on Feb 12, 2014 12:32 PM by smarlow Go to original post
      • 15. Re: WildFly 8 CR1: Problem with calling methods from EJB inside ManagedBean (via @EJB)
        smarlow

        Could you also show us your persistence.xml contents?

         

        If you specified the transaction-type, it should be JTA (JdbcTransactionFactory would be used for RESOURCE_LOCAL).  If you didn't specify the transaction-type, we should be using Hibernate's CMTTransactionFactory.

        • 16. Re: WildFly 8 CR1: Problem with calling methods from EJB inside ManagedBean (via @EJB)
          mandrosen

          Here is the persistence.xml

           

          <?xml version="1.0" encoding="UTF-8"?>

          <persistence version="2.0" xmlns="http://java.sun.com/xml/ns/persistence" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://java.sun.com/xml/ns/persistence http://java.sun.com/xml/ns/persistence/persistence_2_0.xsd">

            <persistence-unit name="atPersistence">

            <provider>org.hibernate.ejb.HibernatePersistence</provider>

            <jta-data-source>jboss/datasources/atDS</jta-data-source>

            <jar-file>lib/athib.jar</jar-file>

            <shared-cache-mode>ENABLE_SELECTIVE</shared-cache-mode>

            <properties>

            <property name="hibernate.archive.autodetection" value="class"/>

            <property name="hibernate.dialect" value="com.at.hib.helpers.ATDialectV4" />

            <property name="jboss.entity.manager.factory.jndi.name" value="java:app/atEntityManagerFactory" />

            <property name="hibernate.transaction.manager_lookup_class" value="org.hibernate.transaction.JBossTransactionManagerLookup"/>

            <property name="hibernate.cache.use_second_level_cache" value="true" />

            <property name="hibernate.cache.use_query_cache" value="true" />

            <property name="hibernate.cache.use_minimal_puts" value="true"/>

            <property name="hibernate.cache.infinispan.statistics" value="true"/>

            <property name="hibernate.cache.region.factory_class" value="org.jboss.as.jpa.hibernate4.infinispan.InfinispanRegionFactory" />

                   <property name="hibernate.cache.infinispan.cachemanager" value="java:jboss/infinispan/container/hibernate" />

            <property name="hibernate.transaction.flush_before_completion" value="true" />

            <property name="hibernate.transaction.auto_close_session" value="true" />

            </properties>

            </persistence-unit>

          </persistence>

          • 17. Re: Re: WildFly 8 CR1: Problem with calling methods from EJB inside ManagedBean (via @EJB)
            smarlow

            What happens if you comment or remove the following properties from your persistence.xml?

             

              <property name="hibernate.transaction.flush_before_completion" value="true" />

              <property name="hibernate.transaction.auto_close_session" value="true" />

             

            I'm not saying that you have to remove these permanently, I'm just curious if they influence when the data source is closed by Hibernate. 

             

            My theory at this point, is that I see nothing wrong with closing the database connection when Hibernate is done with it.  I think the warning is just covering a different case.  I'm not yet satisfied though.

            • 18. Re: WildFly 8 CR1: Problem with calling methods from EJB inside ManagedBean (via @EJB)
              smarlow

               

              But I would be very glad to know the reason why I'm getting this exception now and how to avoid it in the future...

               

              From my discussion with the IronJacamar team, the warning is trying to cover the case where the connection didn't come from the CCM (cache connection manager).  From the two different exception call stacks (logged as a INFO) mentioned in this thread, it is not an error.  For your reference, links to the two exceptions are:

              1. Connection returned from Synchronization.beforeCompletion() when transaction is being committed.
              2. Connection returned as part of Hibernate EntityManager invocation (during JTA transaction).

               

              Scott

              • 19. Re: Re: WildFly 8 CR1: Problem with calling methods from EJB inside ManagedBean (via @EJB)
                mandrosen

                I removed those two options, but I still get the IllegalStateException.

                • 20. Re: Re: Re: WildFly 8 CR1: Problem with calling methods from EJB inside ManagedBean (via @EJB)
                  mandrosen

                  If I add the following

                   

                                      <statement>

                                          <track-statements>true</track-statements>

                                      </statement>

                   

                  to the standalone.xml, I get another warning:

                   

                  2014-02-11 10:10:21,839 WARN  [org.jboss.jca.adapters.jdbc.WrappedConnection] (default task-4) Closing a statement you left open, please do your own housekeeping: java.lang.Throwable: STACKTRACE

                   

                  This seems to be related, but I might be wrong.

                   

                  Full stack trace is attached.

                  • 21. Re: Re: Re: WildFly 8 CR1: Problem with calling methods from EJB inside ManagedBean (via @EJB)
                    smarlow

                    The physical database connection is associated with the JTA transaction and will be used each time that the database connection is requested. I heard from Jesper about this situation (leads the Ironjacimar project) and he mentioned that you could add <cached-connection-manager debug="true"/> to get more information in the output log.  I'm not sure what else will be logged exactly but it might be helpful to show the calls to get connections from the pool and releasing the connections.

                     

                    In the call stack (2) from your earlier log file, we can see that your application is calling Hibernate directly.  From the details that you have told me already, I believe that the org.hibernate.engine.transaction.internal.jta.CMTTransactionFactory class is used internally by the Hibernate session for determining when the DB connection should be released (see release mode doc here).

                     

                    It looks to me that Hibernate (in the above call stack) is using AFTER_STATEMENT mode instead of AFTER_TRANSACTION as I would expect.  If the connection was released using AFTER_TRANSACTION, we could still see the INFO warning as others saw with call stack (1).

                     

                    As of yet, I don't see any harm yet from what the INFO warning is complaining about.  Hibernate is returning a database connection to the connection pool, in a JTA transaction.  If Hibernate asks for the database connection in the same JTA transaction again, it will get the same phyiscal one back (with a different logical connection wrapper).

                     

                    Sometimes framework libraries add warnings for certain cases and they miss that other valid cases may get the warning.  I suspect that is the case here but cannot say for sure yet.

                     

                    Scott

                    • 22. Re: Re: Re: WildFly 8 CR1: Problem with calling methods from EJB inside ManagedBean (via @EJB)
                      smarlow

                      Hard to tell from the log whether there is a leak here or not.  It sounds like it could be a leak.  I copied the log output here for easy viewing for others.

                       

                      I don't see the Hibernate "Closing prepared statement" in the output log, which I think should be shown if we reached the org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.close().

                      • 23. Re: Re: Re: Re: WildFly 8 CR1: Problem with calling methods from EJB inside ManagedBean (via @EJB)
                        mandrosen

                        Again, I appreciate your help.

                         

                        I added

                        <property name="hibernate.connection.release_mode" value="after_transaction" /> to the persistence.xml

                         

                        and

                        <cached-connection-manager debug="true"/> to the standalone.xml


                        With these two, I now see

                        2014-02-12 10:15:31,879 DEBUG [org.jboss.jca.core.api.connectionmanager.ccm.CachedConnectionManager] (default task-13) Unable to synchronize with transaction: java.lang.IllegalStateException: No transaction is running

                        • 24. Re: Re: Re: Re: Re: WildFly 8 CR1: Problem with calling methods from EJB inside ManagedBean (via @EJB)
                          smarlow

                          With these two, I now see

                          2014-02-12 10:15:31,879 DEBUG [org.jboss.jca.core.api.connectionmanager.ccm.CachedConnectionManager] (default task-13) Unable to synchronize with transaction: java.lang.IllegalStateException: No transaction is running

                          I understand what that is about and can be ignored as an internal detail.  In the Synchronization.afterCompletion(), the transaction manager knows that the transaction has completed (its not running any more).  Not much more to it then that.

                           

                          I'm wondering why in many of the logs, that we see "registering connection from connection manager" messages paired with a "unregistering connection from connection manager" which looks correct. 

                          2014-02-10 14:17:02,378 TRACE [org.jboss.jca.core.api.connectionmanager.ccm.CachedConnectionManager] (default task-5) registering connection from connection manager: org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl@1700bb24, connection : org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7@2438e83, key: org.jboss.as.connector.deployers.ra.processors.CachedConnectionManagerSetupProcessor$CachedConnectionManagerSetupAction@4f8ef57a

                          2014-02-10 14:17:02,379 TRACE [org.jboss.jca.core.api.connectionmanager.ccm.CachedConnectionManager] (default task-5) unregistering connection from connection manager: org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl@1700bb24, connection: org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7@2438e83, key: org.jboss.as.connector.deployers.ra.processors.CachedConnectionManagerSetupProcessor$CachedConnectionManagerSetupAction@4f8ef57a

                          2

                           

                          But then, we get the error when a "unregistering connection from connection manager" is not preceded by a "registering..." message.  From standalone.log:

                          2014-02-10 14:17:02,382 TRACE [com.arjuna.ats.jta] (default task-5) TransactionImpleManager.resume

                          2014-02-10 14:17:02,382 TRACE [com.arjuna.ats.arjuna] (default task-5) BasicAction::addChildThread () action 0:ffff7f000001:2a4614d6:52f93166:3b1 adding Thread[default task-5,5,main]

                          2014-02-10 14:17:02,382 TRACE [com.arjuna.ats.arjuna] (default task-5) BasicAction::addChildThread () action 0:ffff7f000001:2a4614d6:52f93166:3b1 adding Thread[default task-5,5,main] result = true

                          2014-02-10 14:17:02,383 TRACE [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

                          2014-02-10 14:17:02,383 TRACE [com.arjuna.ats.jta] (default task-5) TransactionSynchronizationRegistryImple.getResource

                          2014-02-10 14:17:02,383 TRACE [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

                          2014-02-10 14:17:02,383 DEBUG [org.jboss.as.jpa] (default task-5) default task-5:[transaction scoped EntityManager]: reuse entity manager session already in tx TransactionImple < ac, BasicAction: 0:ffff7f000001:2a4614d6:52f93166:3b1 status: ActionStatus.RUNNING >

                          2014-02-10 14:17:02,383 TRACE [org.jboss.as.jpa.messages] (default task-5) getDelegate took 0ms

                          2014-02-10 14:17:02,384 TRACE [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

                          2014-02-10 14:17:02,386 TRACE [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

                          2014-02-10 14:17:02,386 TRACE [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

                          2014-02-10 14:17:02,387 TRACE [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

                          2014-02-10 14:17:02,387 TRACE [com.arjuna.ats.jta] (default task-5) TransactionImple.getStatus: javax.transaction.Status.STATUS_ACTIVE

                          2014-02-10 14:17:02,388 TRACE [org.jboss.jca.core.api.connectionmanager.ccm.CachedConnectionManager] (default task-5) unregistering connection from connection manager: org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl@1700bb24, connection: org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7@4de27c01, key: org.jboss.as.connector.deployers.ra.processors.CachedConnectionManagerSetupProcessor$CachedConnectionManagerSetupAction@4f8ef57a

                          2014-02-10 14:17:02,388 INFO  [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (default task-5) IJ000311: Throwable from unregister connection: java.lang.IllegalStateException: IJ000152: Trying to return an unknown connection: org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7@4de27c01

                                  at org.jboss.jca.core.connectionmanager.ccm.CachedConnectionManagerImpl.unregisterConnection(CachedConnectionManagerImpl.java:385)

                                  at org.jboss.jca.core.connectionmanager.listener.TxConnectionListener.connectionClosed(TxConnectionListener.java:587)

                                  at org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnection.closeHandle(BaseWrapperManagedConnection.java:581)

                           

                           

                          It might be time for you to hack out a test case for this.  Could either be a standalone or a unit test. 

                           

                          https://github.com/wildfly/wildfly/ contains the source for WildFly and https://community.jboss.org/wiki/HackingOnWildFly describes getting the source and building it.  Unit tests are in wildfly/testsuite/integration/basic (there are Hibernate and JPA tests here as well as others).  A standalone test would also be good to think about.

                           

                          Scott

                          1 2 Previous Next