-
15. Re: WildFly 8 CR1: Problem with calling methods from EJB inside ManagedBean (via @EJB)
smarlow Feb 10, 2014 9:49 PM (in response to 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 Feb 11, 2014 12:21 AM (in response to smarlow)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 Feb 11, 2014 8:53 AM (in response to mandrosen)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 Feb 11, 2014 10:35 AM (in response to daniell)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:
- Connection returned from Synchronization.beforeCompletion() when transaction is being committed.
- 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 Feb 11, 2014 11:40 AM (in response to smarlow)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 Feb 11, 2014 12:51 PM (in response to smarlow)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.
-
standalone_closing1.log.zip 4.3 KB
-
-
21. Re: Re: Re: WildFly 8 CR1: Problem with calling methods from EJB inside ManagedBean (via @EJB)
smarlow Feb 12, 2014 9:42 AM (in response to mandrosen)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 Feb 12, 2014 10:00 AM (in response to mandrosen)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 Feb 12, 2014 11:25 AM (in response to smarlow)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
-
standalone_aftercomp_debug1.log.zip 273.7 KB
-
-
24. Re: Re: Re: Re: Re: WildFly 8 CR1: Problem with calling methods from EJB inside ManagedBean (via @EJB)
smarlow Feb 12, 2014 12:32 PM (in response to mandrosen)
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