lastResource.disallow, but only one PC

[jakec]

I occasionally (not quite once a week) get a catastrophic failure of the DB. It starts with a LazyInitializationException (which I believe is a symptom, not a cause), with the following line directly below it:

2009-02-27 08:34:59,945 WARN  [com.arjuna.ats.jta.logging.loggerI18N] [com.arjuna.ats.internal.jta.transaction.arjunacore.lastResource.disallow] [com.arjuna.ats.internal.jta.transaction.arjunacore.lastResource.disallow] Adding multiple last resources is disallowed. Current resource is org.jboss.resource.connectionmanager.TxConnectionManager$LocalXAResource@12bad63

However, we only have a single PC, and this error seems to be related to using multiple LocalTX Resources.

Once this happens, any access to the DB results in Could not enlist in transaction on entering meta-aware object! and Trying to start a new tx when old is not complete messages until I restart JBoss.

Components.xml snippet

   <persistence:managed-persistence-context name="entityManager"
                                     auto-create="true"
                      persistence-unit-jndi-name="java:/myAppEntityManagerFactory"/>

persistence.xml

<?xml version="1.0" encoding="UTF-8"?>
<!-- Persistence deployment descriptor for prod profile -->
<persistence 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_1_0.xsd" 
             version="1.0">
             
   <persistence-unit name="myApp">
      <provider>org.hibernate.ejb.HibernatePersistence</provider>
      <jta-data-source>java:/myAppDatasource</jta-data-source>
      <properties>
         <property name="hibernate.dialect" value="org.hibernate.dialect.MySQLDialect"/>
         <property name="hibernate.hbm2ddl.auto" value="validate"/>
         <property name="hibernate.cache.use_query_cache" value="true"/>
         <property name="hibernate.jdbc.batch_size" value="20"/>
         <property name="jboss.entity.manager.factory.jndi.name" value="java:/myAppEntityManagerFactory"/>
         <property name="hibernate.default_catalog" value="myDatabase"/>
      </properties>
   </persistence-unit>
    
</persistence>

myApp-ds.xml

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

<!DOCTYPE datasources
    PUBLIC "-//JBoss//DTD JBOSS JCA Config 1.5//EN"
    "http://www.jboss.org/j2ee/dtd/jboss-ds_1_5.dtd">
    
<datasources>
   
   <local-tx-datasource>
      <jndi-name>myAppDatasource</jndi-name>
      <connection-url>jdbc:mysql:///myDatabase</connection-url>
      <driver-class>com.mysql.jdbc.Driver</driver-class>
      <user-name>USERNAME</user-name>
      <password>PASSWORD</password>
   </local-tx-datasource>
    
</datasources>

The stack trace is too long to post in full, but I'll include some relevant parts:

2009-02-27 08:34:59,945 INFO  [STDOUT] 08:34:59,945 INFO  [DefaultLoadEventListener] Error performing load command
org.hibernate.SessionException: Session is closed!
     at org.hibernate.impl.AbstractSessionImpl.errorIfClosed(AbstractSessionImpl.java:49)
     at org.hibernate.impl.SessionImpl.getBatcher(SessionImpl.java:260)
     at org.hibernate.loader.Loader.getResultSet(Loader.java:1787)
     at org.hibernate.loader.Loader.doQuery(Loader.java:674)
     at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:236)
     at org.hibernate.loader.Loader.loadEntity(Loader.java:1860)
     at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:48)
     at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:42)
     at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:3044)
     at org.hibernate.event.def.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:395)
     at org.hibernate.event.def.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:375)
     at org.hibernate.event.def.DefaultLoadEventListener.load(DefaultLoadEventListener.java:139)
     at org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:98)
     at org.hibernate.impl.SessionImpl.fireLoad(SessionImpl.java:878)
     at org.hibernate.impl.SessionImpl.immediateLoad(SessionImpl.java:836)
     at org.hibernate.proxy.AbstractLazyInitializer.initialize(AbstractLazyInitializer.java:66)
     at org.hibernate.proxy.AbstractLazyInitializer.getImplementation(AbstractLazyInitializer.java:111)
     at org.hibernate.proxy.pojo.javassist.JavassistLazyInitializer.invoke(JavassistLazyInitializer.java:166)
     at com.companyName.myDatabase.Person_$$_javassist_16.getLastName(Person_$$_javassist_16.java)
     at com.companyName.myDatabase.DataObject.toString(DataObject.java:395)
     at java.lang.String.valueOf(String.java:2827)
     at java.lang.StringBuilder.append(StringBuilder.java:115)
     at org.jboss.seam.Component.injectDataModelSelection(Component.java:1499)
     at org.jboss.seam.Component.injectDataModelSelections(Component.java:1478)
[SNIP]
2009-02-27 08:34:59,945 INFO  [STDOUT] 08:34:59,945 ERROR [LazyInitializationException] failed to lazily initialize a collection of role: com.companyName.myDatabase.DataObject.items, no session or session was closed
org.hibernate.LazyInitializationException: failed to lazily initialize a collection of role: com.companyName.myDatabase.DataObject.items, no session or session was closed
     at org.hibernate.collection.AbstractPersistentCollection.throwLazyInitializationException(AbstractPersistentCollection.java:358)
     at org.hibernate.collection.AbstractPersistentCollection.throwLazyInitializationExceptionIfNotConnected(AbstractPersistentCollection.java:350)
     at org.hibernate.collection.AbstractPersistentCollection.readSize(AbstractPersistentCollection.java:97)
     at org.hibernate.collection.PersistentList.size(PersistentList.java:91)
     at com.companyName.myDatabase.DataObject.toString(DataObject.java:421)
     at java.lang.String.valueOf(String.java:2827)
     at java.lang.StringBuilder.append(StringBuilder.java:115)
     at org.jboss.seam.Component.injectDataModelSelection(Component.java:1499)
     at org.jboss.seam.Component.injectDataModelSelections(Component.java:1478)
     at org.jboss.seam.Component.inject(Component.java:1417)
[SNIP]
2009-02-27 08:34:59,945 WARN  [com.arjuna.ats.jta.logging.loggerI18N] [com.arjuna.ats.internal.jta.transaction.arjunacore.lastResource.disallow] [com.arjuna.ats.internal.jta.transaction.arjunacore.lastResource.disallow] Adding multiple last resources is disallowed. Current resource is org.jboss.resource.connectionmanager.TxConnectionManager$LocalXAResource@12bad63
2009-02-27 08:34:59,961 INFO  [STDOUT] 08:34:59,961 WARN  [JDBCExceptionReporter] SQL Error: 0, SQLState: null
2009-02-27 08:34:59,961 INFO  [STDOUT] 08:34:59,961 ERROR [JDBCExceptionReporter] Could not enlist in transaction on entering meta-aware object!; - nested throwable: (javax.transaction.SystemException: java.lang.Throwable: Unabled to enlist resource, see the previous warnings. tx=TransactionImple < ac, BasicAction: -3f577ab4:12e9:49a785be:8f3 status: ActionStatus.ABORT_ONLY >); - nested throwable: (org.jboss.resource.JBossResourceException: Could not enlist in transaction on entering meta-aware object!; - nested throwable: (javax.transaction.SystemException: java.lang.Throwable: Unabled to enlist resource, see the previous warnings. tx=TransactionImple < ac, BasicAction: -3f577ab4:12e9:49a785be:8f3 status: ActionStatus.ABORT_ONLY >))
2009-02-27 08:34:59,961 WARN  [javax.enterprise.resource.webcontainer.jsf.lifecycle] executePhase(RENDER_RESPONSE 6,com.sun.faces.context.FacesContextImpl@1e46a19) threw exception
javax.faces.el.EvaluationException: /WEB-INF/template/application.txml @157,100 suggestionAction="#{lookupAction.suggestName}": javax.persistence.PersistenceException: org.hibernate.exception.GenericJDBCException: Cannot open connection
     at com.sun.facelets.el.LegacyMethodBinding.invoke(LegacyMethodBinding.java:73)
     at org.richfaces.component.UISuggestionBox.setupValue(UISuggestionBox.java:343)
     at org.richfaces.renderkit.html.SuggestionBoxRenderer.encodeChildren(SuggestionBoxRenderer.java:255)
     at javax.faces.component.UIComponentBase.encodeChildren(UIComponentBase.java:812)
     at org.ajax4jsf.renderkit.RendererBase.renderChild(RendererBase.java:282)
[SNIP]
Caused by: org.jboss.util.NestedSQLException: Could not enlist in transaction on entering meta-aware object!; - nested throwable: (javax.transaction.SystemException: java.lang.Throwable: Unabled to enlist resource, see the previous warnings. tx=TransactionImple < ac, BasicAction: -3f577ab4:12e9:49a785be:8f3 status: ActionStatus.ABORT_ONLY >); - nested throwable: (org.jboss.resource.JBossResourceException: Could not enlist in transaction on entering meta-aware object!; - nested throwable: (javax.transaction.SystemException: java.lang.Throwable: Unabled to enlist resource, see the previous warnings. tx=TransactionImple < ac, BasicAction: -3f577ab4:12e9:49a785be:8f3 status: ActionStatus.ABORT_ONLY >))
     at org.jboss.resource.adapter.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:94)
     at org.hibernate.ejb.connection.InjectedDataSourceConnectionProvider.getConnection(InjectedDataSourceConnectionProvider.java:47)
     at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:423)
     ... 116 more
Caused by: org.jboss.resource.JBossResourceException: Could not enlist in transaction on entering meta-aware object!; - nested throwable: (javax.transaction.SystemException: java.lang.Throwable: Unabled to enlist resource, see the previous warnings. tx=TransactionImple < ac, BasicAction: -3f577ab4:12e9:49a785be:8f3 status: ActionStatus.ABORT_ONLY >)
     at org.jboss.resource.connectionmanager.TxConnectionManager.managedConnectionReconnected(TxConnectionManager.java:343)
     at org.jboss.resource.connectionmanager.BaseConnectionManager2.reconnectManagedConnection(BaseConnectionManager2.java:518)
     at org.jboss.resource.connectionmanager.BaseConnectionManager2.allocateConnection(BaseConnectionManager2.java:399)
     at org.jboss.resource.connectionmanager.BaseConnectionManager2$ConnectionManagerProxy.allocateConnection(BaseConnectionManager2.java:842)
     at org.jboss.resource.adapter.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:88)
     ... 118 more
Caused by: javax.transaction.SystemException: java.lang.Throwable: Unabled to enlist resource, see the previous warnings. tx=TransactionImple < ac, BasicAction: -3f577ab4:12e9:49a785be:8f3 status: ActionStatus.ABORT_ONLY >
     at org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener$TransactionSynchronization.checkEnlisted(TxConnectionManager.java:744)
     at org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener.enlist(TxConnectionManager.java:577)
     at org.jboss.resource.connectionmanager.TxConnectionManager.managedConnectionReconnected(TxConnectionManager.java:337)
     ... 122 more

[swd847]

Do you use any other transaction aware resources in your project? Or create a second entityManagerFactory? Or just do anything out of the ordinary involving transactions?
This error generally occurs when you enlist two seperate resources that do not support two phase commit in a transaction (even two seperate connections from the same datasource). 

Two quick and dirty ways to fix this:

- Change your datasource to an xa datasource

- set the property com.arjuna.ats.jta.allowMultipleLastResources in conf/jbossjta-properties.xml to true (this is almost certainly a bad idea)

The first one is almost certainly the way to go.

You might want to have a look at this article for more information.

[jakec]

Well, I only have the one <persistance> node in my components.xml file. That is how I would have to define another EMF, right?

What other transaction aware resources are there? We don't use any Timer stuff.

We use Events.instance().raiseTransactionSuccessEvent(), and have an interceptor for DB auditing.

We have a totally separate application that accesses the same DB. That can't really interfere in this way, can it?

Don't XA datasources impose a performance hit over local?

How do I find out if we are using other transaction aware resources. Is there a list somewhere of JBoss/Seam functionality that does this?

[swd847]

When the DB interceptor is called it the transaction still active? If so can you post the code?

Well, I only have the one <persistance> node in my components.xml file. That is how I would have to define another EMF, right?

Yes, although you can create them in code

What other transaction aware resources are there? We don't use any Timer stuff.

Database connections, JMS etc. There are more, I just can't think of them off the top of my head right now. As long as you only have one non-xa resource it does not matter though.

We use Events.instance().raiseTransactionSuccessEvent(), and have an interceptor for DB auditing.

Can you post this code? Is the event raised while the transaction is still active?

We have a totally separate application that accesses the same DB. That can't really interfere in this way, can it?

Not for this sort of error.

Don't XA datasources impose a performance hit over local?

Yes, though I am not sure how significant it is. You probably will not even notice it.

How do I find out if we are using other transaction aware resources. Is there a list somewhere of JBoss/Seam functionality that does this?

If you are just using the core stuff you should be fine. At the moment your Audit interceptor sounds like the most likely culprit.

[jakec]

The raiseTransactionSuccessEvent() stuff is pretty basic. It just uses the EntityManager that was injected by Seam.

Five seconds before the crash, someone successfully logged in. Fifteen seconds before THAT, a record update was audited.

So, it is possible. It was a bear to get working. It has to function outside the JBoss context in our stand-alone application as well as in JBoss.

If it is running within JBoss, it uses reflection to call Contexts.getConversationContext().get(entityManager).getEntityManager().getDelagate() to get the Session.

When I need to persist a History record, I call:

Session newSession = session.getSessionFactory().openSession();
newSession.merge(history);
newSession.flush();
newSession.close();

I thought that since I was getting the EntityManager from the ConversationContext, I was safe.

It is configured in the persistence.xml with the following lines:

         <property name="hibernate.ejb.interceptor" value="com.companyName.myDatabase.audit.AuditInterceptor"/>
         <property name="hibernate.ejb.event.post-insert" value="com.companyName.myDatabase.audit.AuditInterceptor"/>
         <property name="hibernate.ejb.event.post-delete" value="com.companyName.myDatabase.audit.AuditInterceptor"/>

I changed my myApp-ds.xml file from above the the following:

   <xa-datasource>
      <jndi-name>myAppDatasource</jndi-name>
      <xa-datasource-class>com.mysql.jdbc.jdbc2.optional.MysqlXADataSource</xa-datasource-class>
      <xa-datasource-property name="URL">jdbc:mysql:///myDatabase</xa-datasource-property>
      <track-connection-by-tx/>
      <user-name>USERNAME</user-name>
      <password>PASSWORD</password>
   </xa-datasource>

Is the track-connection-by-tx necessary? I saw it in several examples, but I don-t really understand what it does.

[swd847]

openSession() will use a different connection to the mysql database than the existing session. This means that you have two non XA resources in the same transaction, and anjunta does not like it (the only way to sync a transaction between two separate connections is with 2 phase commit, which means you need XA datasources).

Opening a new session is necessary in the interceptor however, as it is not safe to use methods on the original session from inside the interceptor.

A different approach you could use is to save your history inside a new transaction, however that means that your history may not be reliable as one transaction may commit and the other may be rolled back, so probably not recommended.

The only way that I can think of to get reliable history without using 2 phase commit is to use the underlying JDBC connection of the entityManager to manually persist the record, without going through hibernate at all.

Stuart

[jakec]

It looks like going XA is the safest all around.

Thanks for the help!