hanging on HornetQRASessionFactoryImpl.createSession()

[terry.paterson]

We have an application in production on a number of sites running JBoss EAP 6.3 ..( non clustered, each running on a single machine/VM )

On these sites, we are occasionally seeing timeout errors from Session Beans, and other beans run on a Schedule ..

the common factor for all of these failures - seem to be that we are trying to publish a message to a Queue or Topic.

and each stacktrace seems to indicate the problem occur's when attempting to create the JMS session...

for example :

00:00:36,424 WARN  [com.arjuna.ats.jta] (EJB default - 3) ARJUNA016086: TransactionImple.enlistResource setTransactionTimeout on XAResource < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffc0a80146:-12e90125:56a47da7:438

12c, node_name=1, branch_uid=0:ffffc0a80146:-12e90125:56a47da7:43848b, subordinatenodename=null, eis_name=java:/JmsXA > threw: XAException.XAER_RMERR: javax.transaction.xa.XAException

        at org.hornetq.core.client.impl.ClientSessionImpl.setTransactionTimeout(ClientSessionImpl.java:1784) [hornetq-core-client-2.3.20.Final-redhat-1.jar:2.3.20.Final-redhat-1]

        at org.hornetq.ra.HornetQRAXAResource.setTransactionTimeout(HornetQRAXAResource.java:249)

        at org.jboss.jca.core.tx.jbossts.XAResourceWrapperImpl.setTransactionTimeout(XAResourceWrapperImpl.java:194)

        at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.enlistResource(TransactionImple.java:621)

        at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.enlistResource(TransactionImple.java:407)

        at org.jboss.jca.core.connectionmanager.listener.TxConnectionListener$TransactionSynchronization.enlist(TxConnectionListener.java:692)

        at org.jboss.jca.core.connectionmanager.listener.TxConnectionListener.enlist(TxConnectionListener.java:338)

        at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.managedConnectionReconnected(TxConnectionManagerImpl.java:483)

        at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.reconnectManagedConnection(AbstractConnectionManager.java:623)

        at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.allocateConnection(AbstractConnectionManager.java:491)

        at org.hornetq.ra.HornetQRASessionFactoryImpl.allocateConnection(HornetQRASessionFactoryImpl.java:832)

        at org.hornetq.ra.HornetQRASessionFactoryImpl.createSession(HornetQRASessionFactoryImpl.java:465)

        at com.xxxx.utils.jms_utils.JMSUtils.sendMessage(JMSUtils.java:95) [my-utils.jar:]

        at com.xxxx.session.ejb3.license.ScheduledClientNotificationBean.execute(ScheduledClientNotificationBean.java:169) [my-ejb.jar:]

        at sun.reflect.GeneratedMethodAccessor100.invoke(Unknown Source) [:1.7.0_45]

        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_45]

        at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_45]

        at org.jboss.as.ee.component.ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptor.java:52) [jboss-as-ee-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]

        at org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]

        at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:61) [jboss-as-ee-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]

        at org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]

        at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:61) [jboss-as-ee-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]

        at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:374) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]

        at org.jboss.as.ejb3.concurrency.ContainerManagedConcurrencyInterceptor.processInvocation(ContainerManagedConcurrencyInterceptor.java:104) [jboss-as-ejb3-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]

        at org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:21) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]

        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]

        at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]

        at org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:53) [jboss-as-ee-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]

        at org.jboss.as.ejb3.component.singleton.SingletonComponentInstanceAssociationInterceptor.processInvocation(SingletonComponentInstanceAssociationInterceptor.java:52) [jboss-as-ejb3-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]

        at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:272) [jboss-as-ejb3-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

        at org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:339) [jboss-as-ejb3-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

        at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:238) [jboss-as-ejb3-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]

        at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) [jboss-as-ejb3-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]

        at org.jboss.as.ejb3.security.SecurityContextInterceptor.processInvocation(SecurityContextInterceptor.java:86) [jboss-as-ejb3-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]

        at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64) [jboss-as-ejb3-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]

        at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50) [jboss-as-ee-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]

        at org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:55) [jboss-as-ejb3-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]

        at org.jboss.as.ee.component.TCCLInterceptor.processInvocation(TCCLInterceptor.java:45) [jboss-as-ee-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]

        at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]

        at org.jboss.as.ejb3.timerservice.TimedObjectInvokerImpl.callTimeout(TimedObjectInvokerImpl.java:101) [jboss-as-ejb3-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

        at org.jboss.as.ejb3.timerservice.task.CalendarTimerTask.callTimeout(CalendarTimerTask.java:60) [jboss-as-ejb3-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

        at org.jboss.as.ejb3.timerservice.task.TimerTask.run(TimerTask.java:132) [jboss-as-ejb3-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) [rt.jar:1.7.0_45]

        at java.util.concurrent.FutureTask.run(FutureTask.java:262) [rt.jar:1.7.0_45]

        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [rt.jar:1.7.0_45]

        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [rt.jar:1.7.0_45]

        at java.lang.Thread.run(Thread.java:744) [rt.jar:1.7.0_45]

        at org.jboss.threads.JBossThread.run(JBossThread.java:122)

Caused by: HornetQException[errorType=CONNECTION_TIMEDOUT message=HQ119014: Timed out waiting for response when sending packet 63]

        at org.hornetq.core.protocol.core.impl.ChannelImpl.sendBlocking(ChannelImpl.java:385) [hornetq-core-client-2.3.20.Final-redhat-1.jar:2.3.20.Final-redhat-1]

        at org.hornetq.core.client.impl.ClientSessionImpl.setTransactionTimeout(ClientSessionImpl.java:1777) [hornetq-core-client-2.3.20.Final-redhat-1.jar:2.3.20.Final-redhat-1]

        ... 60 more

Is this a problem anyone else has seen ?

it only seems to happen occasionally, and is intermittent ..

restarting JBoss seems to get rid of the problem for a while

[jbertram]

A few questions...

• Do you see a lot of these at once or just a few?  Please quantify.
• Is there any kind of retry mechanism for the message sending operation?  If so, does it succeed on subsequent attempts?
• Based on the stack-trace the message is being sent to a remote broker.  Is that true?  If so, what's the state of the remote broker when you see the timeout (e.g. any errors, high message volume, high CPU utilization, etc.)?

[terry.paterson]

* we tend to see a lot of these together .. the system may go for days without any of these messages at all, then all of a sudden we get lots

so - for example - on one machine, on Sunday the messages started at 00:36, and continued until JBoss was restarted at 02:30, in which time we had 177 of these messages,

(it seems like the majority of these messages came from a Scheduled bean on a 1 minute schedule)

it seems like once the messages start, the only way to stop them - is to restart JBoss

* we have not coded any specific re-try mechanism, although - where the messages are being added by a @Scheduled bean, the bean may be on a 1 or 5 minute schedule and sometimes the subsequent attempt is successful

* the Queue / Topic we are attempting to add the message to, is always local and accessed via java:/JmsXA

we think that that the problem may coincide with a period of heavy loading (while the system backup is running for example),

but seems to continue even once the load has dropped

[jbertram]

Couple more questions...

• How are the beans handling the JMS connection (e.g. opening/closing every time)?  Are they injecting the connection or looking it up in JNDI?  Could you share the code in use here?
• Are these beans doing work with other XA resources?  If not, can you disable XA for them?

[terry.paterson]

Thanks again for your interest Justin

* We are looking up the ConnectionFactory (java:/JmsXA) both via Injection, and via JNDI

* The destination Queue/Topic is always looked up using JNDI

* We do have some cases, where we are updating some entities followed by sending some JMS messages, although in other cases we are only using the EntityManager for read-only operations

* We _could_ disable XA for the read-only cases .. but in the cases where we are actually writing to the database we want XA really ? since otherwise if our transactions roll back our JMS messages will still be sent ?

* also - as of yet -- we don't have any test or similar to replicate the problem .. and so - no easy way to determine if/what changes might help

here is a rough example of one of our scheduled beans (I've simplified it somewhat so that the code is all in one class, etc) :

@Singleton

@RunAs(RoleConstants.SERVER)

public class ScheduledClientNotificationBean {

    @NonNls

    private static final Logger logger = Logger.getLogger(ScheduledClientNotificationBean.class);

    @PersistenceContext

    private EntityManager em;

    @Resource(mappedName = "java:/JmsXA")

    private ConnectionFactory connectionFactory;

    @Schedule(second = "0", minute = "*", hour = "*", persistent = false)

    private void execute() {

        final String destinationName= "topic/ClientNotificationTopic";

        Connection connection = null;

        Session session = null;

        MessageProducer producer = null;

        // use the entity manager to lookup a preference (no write operations!)

        final Query q = em.createNamedQuery("Preference.findByTagName");

        q.setParameter("tagName", "preferenceName");

        final List<PreferenceEntity> preferenceEntityList = q.getResultList();

        final String preferenceValue;

        if (preferenceEntityList.isEmpty()) {

            preferenceValue = null;

        } else {

            preferenceValue = preferenceEntityList.get(0).getPrefValue();

        }

        Context ctx = null;

        try {

            // Get access to JNDI

            ctx = new InitialContext();

            connection = connectionFactory.createConnection();

            session = connection.createSession(false, // No LOCAL transaction

                    Session.AUTO_ACKNOWLEDGE); // Auto ack

            final Destination dest = (Destination) ctx.lookup(destinationName);        // lookup our Queue/Topic

            producer = session.createProducer(dest);                                    // create a Producer

            final Message msg = session.createObjectMessage();                          // create a new message

            msg.setObjectProperty("messageType", preferenceValue);                      // set some headers

            producer.send(msg);                                                        // send the message

            logger.warn(" sent message to " + destinationName);

        } catch (JMSException e) {

            logger.error(e, e);

        } catch (NamingException e) {

            logger.error(e, e);

        } finally {

            try {

                close(producer, session, connection);                                  // cleanup

            } finally {

                closeContext(ctx);

            }

        }

    }

    public void close(final MessageProducer sender, final Session session, final Connection connection) {

        try {

            if (sender != null) {

                sender.close();

            }

        } catch (JMSException e) {

            logger.warn(e, e);

        } finally {

            closeSession(session, connection);

        }

    }

    public void closeSession(final Session session, final Connection connection) {

        try {

            if (session != null) {

                session.close();

            }

        } catch (JMSException e) {

            logger.warn(e, e);

        } finally {

            closeConnection(connection);

        }

    }

    public void closeConnection(final Connection connection) {

        if (connection != null) {

            try {

                connection.close();

            } catch (JMSException e) {

                logger.warn(e, e);

            }

        }

    }

    private void closeContext(final Context ctx) {

        try {

            ctx.close();

        } catch (NamingException e) {

            logger.error(e, e);

        }

    }

}

it feels like -- during the period of high loading, some resource becomes broken ?

(I'm taking a guess that this problem starts mostly when they system is heavily loaded)

and that perhaps whatever that resource is (ConnectionFactory ?), it's stored in some kind of pool ?

so that - even once the the high load period is over, we are still occasionally allocated the broken resource from the Pool -- and continue to see these timeouts ?

whereas on other occasions we are allocated another non-broken resource from the pool, and are able to go about our business normally ?

what do you think ?

[jbertram]

The code looks fine as far as I can see.

The connections from the JmsXA connection factory do indeed come from a pool.  However, each of those connections has a listener attached to it so that when a connection-level error occurs it should be kicked out of the pool automatically by the JCA implementation.  The strangest thing about your issue is that everything is local so there shouldn't be any broken connections or any connectivity problems of any sort.

At this point I recommend you capture thread dumps at regular intervals so that when this problem occurs again you can see exactly what the broker is doing.  Hopefully that will allow you to identify the underlying cause of the packet timeout.

[terry.paterson]

Hello once again

We have now successfully obtained several thread dumps from one of the systems experiencing this problem..

you can see in each case that there are one or more "EJB default - X" threads

(usually a @Singleton bean with a @Schedule annotation),

which are waiting on a org.hornetq.ra.HornetQRASessionFactoryImpl.createSession() call

and in-turn org.hornetq.core.protocol.core.impl.ChannelImpl.sendBlocking().

I have attached the thread-dumps for your perusal

from profiling and looking at thread dumps when the system works correctly -- it appears that some thread in the "HornetQ-remoting-threads-HornetQServerImpl" grouping ?

should probably be responding to these calls / packets ? but from the look of our thread-dumps -- these threads seem to be waiting for work ?

(perhaps another thread is supposed to add work to their Queue ?)

[jbertram]

Can you attach your server configuration as well?

[terry.paterson]

find attached

(I've obfuscated some auth credentials, package names, but nothing I think important :)

[jbertram]

I don't see anything in the configuration or thread dumps to indicate what's causing the timeout.  Could you be hitting GC pauses?  Those will sometimes cause issues like this.

[terry.paterson]

I don't _think_ it's anything to do with Garbage Collection...

particularly since -- we may not see any problems for days - then it starts happening, and once it's started it won't go away until JBoss is restarted...

(although it doesn't happen on every call -- only some calls .. so the users can sometimes continue to use the system)

here's an example of the exception occurring on one site this morning, along with the corresponding entries from gc.log :

server.log

(seems like the timeout must be 30 seconds ? 00:54:00 - 00:54:30 )

00:54:00,013 DEBUG [com.xxx.server.session.ejb3.license.ScheduledClientNotificationBean] (EJB default - 10) execute

00:54:00,013 DEBUG [com.xxx.server.session.ejb3.license.ScheduledClientNotificationBean] (EJB default - 10)  sending message to : topic/ClientNotificationTopic

00:54:30,021 WARN  [com.arjuna.ats.jta] (EJB default - 10) ARJUNA016086: TransactionImple.enlistResource setTransactionTimeout on XAResource < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffc0a80146:-3fa4bbb7:56b9cde7:33

660a, node_name=1, branch_uid=0:ffffc0a80146:-3fa4bbb7:56b9cde7:33660c, subordinatenodename=null, eis_name=java:/JmsXA > threw: XAException.XAER_RMERR: javax.transaction.xa.XAException

        at org.hornetq.core.client.impl.ClientSessionImpl.setTransactionTimeout(ClientSessionImpl.java:1784) [hornetq-core-client-2.3.20.Final-redhat-1.jar:2.3.20.Final-redhat-1]

        at org.hornetq.ra.HornetQRAXAResource.setTransactionTimeout(HornetQRAXAResource.java:249)

        at org.jboss.jca.core.tx.jbossts.XAResourceWrapperImpl.setTransactionTimeout(XAResourceWrapperImpl.java:194)

        at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.enlistResource(TransactionImple.java:621)

        at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.enlistResource(TransactionImple.java:407)

        at org.jboss.jca.core.connectionmanager.listener.TxConnectionListener$TransactionSynchronization.enlist(TxConnectionListener.java:692)

        at org.jboss.jca.core.connectionmanager.listener.TxConnectionListener.enlist(TxConnectionListener.java:338)

        at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.managedConnectionReconnected(TxConnectionManagerImpl.java:483)

        at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.reconnectManagedConnection(AbstractConnectionManager.java:623)

        at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.allocateConnection(AbstractConnectionManager.java:491)

        at org.hornetq.ra.HornetQRASessionFactoryImpl.allocateConnection(HornetQRASessionFactoryImpl.java:832)

        at org.hornetq.ra.HornetQRASessionFactoryImpl.createSession(HornetQRASessionFactoryImpl.java:465)

        at com.xxx.jms_utils.JMSUtils.sendMessage(JMSUtils.java:95) [yyy.jar:]

        at com.xxx.server.session.ejb3.license.ScheduledClientNotificationBean.execute(ScheduledClientNotificationBean.java:169) [xxx-ejb.jar:]

        at sun.reflect.GeneratedMethodAccessor74.invoke(Unknown Source) [:1.7.0_45]

        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_45]

        at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_45]

        at org.jboss.as.ee.component.ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptor.java:52) [jboss-as-ee-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]

        at org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]

        at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:61) [jboss-as-ee-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]

        at org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]

        at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:61) [jboss-as-ee-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]

        at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:374) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]

        at org.jboss.as.ejb3.concurrency.ContainerManagedConcurrencyInterceptor.processInvocation(ContainerManagedConcurrencyInterceptor.java:104) [jboss-as-ejb3-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]

        at org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:21) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]

        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]

        at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]

        at org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:53) [jboss-as-ee-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]

        at org.jboss.as.ejb3.component.singleton.SingletonComponentInstanceAssociationInterceptor.processInvocation(SingletonComponentInstanceAssociationInterceptor.java:52) [jboss-as-ejb3-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]

        at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:272) [jboss-as-ejb3-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

        at org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:339) [jboss-as-ejb3-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

        at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:238) [jboss-as-ejb3-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]

        at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) [jboss-as-ejb3-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]

        at org.jboss.as.ejb3.security.SecurityContextInterceptor.processInvocation(SecurityContextInterceptor.java:86) [jboss-as-ejb3-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]

        at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64) [jboss-as-ejb3-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]

        at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50) [jboss-as-ee-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]

        at org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:55) [jboss-as-ejb3-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]

        at org.jboss.as.ee.component.TCCLInterceptor.processInvocation(TCCLInterceptor.java:45) [jboss-as-ee-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

        at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]

        at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation-1.1.2.Final-redhat-1.jar:1.1.2.Final-redhat-1]

        at org.jboss.as.ejb3.timerservice.TimedObjectInvokerImpl.callTimeout(TimedObjectInvokerImpl.java:101) [jboss-as-ejb3-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

        at org.jboss.as.ejb3.timerservice.task.CalendarTimerTask.callTimeout(CalendarTimerTask.java:60) [jboss-as-ejb3-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

        at org.jboss.as.ejb3.timerservice.task.TimerTask.run(TimerTask.java:132) [jboss-as-ejb3-7.4.0.Final-redhat-19.jar:7.4.0.Final-redhat-19]

        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) [rt.jar:1.7.0_45]

        at java.util.concurrent.FutureTask.run(FutureTask.java:262) [rt.jar:1.7.0_45]

        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [rt.jar:1.7.0_45]

        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [rt.jar:1.7.0_45]

        at java.lang.Thread.run(Thread.java:744) [rt.jar:1.7.0_45]

        at org.jboss.threads.JBossThread.run(JBossThread.java:122)

Caused by: HornetQException[errorType=CONNECTION_TIMEDOUT message=HQ119014: Timed out waiting for response when sending packet 63]

        at org.hornetq.core.protocol.core.impl.ChannelImpl.sendBlocking(ChannelImpl.java:385) [hornetq-core-client-2.3.20.Final-redhat-1.jar:2.3.20.Final-redhat-1]

        at org.hornetq.core.client.impl.ClientSessionImpl.setTransactionTimeout(ClientSessionImpl.java:1777) [hornetq-core-client-2.3.20.Final-redhat-1.jar:2.3.20.Final-redhat-1]

        ... 60 more

gc.log

2016-02-10T00:47:56.166-0500: 65841.307: [GC [PSYoungGen: 285072K->32760K(287232K)] 838451K->586139K(986624K), 0.0526510 secs] [Times: user=0.23 sys=0.00, real=0.05 secs]

2016-02-10T00:51:00.261-0500: 66025.402: [GC [PSYoungGen: 187866K->38312K(296960K)] 741245K->591691K(996352K), 0.0475340 secs] [Times: user=0.27 sys=0.01, real=0.05 secs]

2016-02-10T00:51:00.309-0500: 66025.450: [Full GC [PSYoungGen: 38312K->0K(296960K)] [ParOldGen: 553379K->433232K(699392K)] 591691K->433232K(996352K) [PSPermGen: 153635K->152783K(205824K)], 2.6309170 secs] [Times: user=16.40 sys=0.17, real=2.63 secs]

2016-02-10T00:52:24.101-0500: 66109.241: [GC [PSYoungGen: 248320K->11808K(260608K)] 681552K->445040K(960000K), 0.0381950 secs] [Times: user=0.14 sys=0.01, real=0.04 secs]

2016-02-10T00:54:33.582-0500: 66238.723: [GC [PSYoungGen: 260128K->24256K(301056K)] 693360K->457488K(1000448K), 0.0640680 secs] [Times: user=0.20 sys=0.00, real=0.18 secs]

2016-02-10T00:57:17.846-0500: 66402.987: [GC [PSYoungGen: 274112K->31184K(298496K)] 707344K->464416K(997888K), 0.0611950 secs] [Times: user=0.23 sys=0.00, real=0.06 secs]

2016-02-10T00:58:33.087-0500: 66478.228: [GC [PSYoungGen: 281040K->29024K(301056K)] 714272K->462256K(1000448K), 0.0530160 secs] [Times: user=0.22 sys=0.01, real=0.05 secs]

[daniel.dragoix86]

Hi Justin,

I also encountered the same issue on Wildfly 9.0.0Final (with hornetq-2.4.7.Final).

Besides the stacktrace that Terry posted in the original post, I've  also got errors like :

Caused by: javax.resource.ResourceException: IJ000453: Unable to get managed connection for java:/JmsXA

at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.getManagedConnection(AbstractConnectionManager.java:646)

at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.getManagedConnection(TxConnectionManagerImpl.java:430)

at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.allocateConnection(AbstractConnectionManager.java:737)

at org.hornetq.ra.HornetQRASessionFactoryImpl.allocateConnection(HornetQRASessionFactoryImpl.java:948)

... 74 more

Caused by: javax.resource.ResourceException: IJ000655: No managed connections available within configured blocking timeout (30000 [ms])

at org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreArrayListManagedConnectionPool.getConnection(SemaphoreArrayListManagedConnectionPool.java:553)

at org.jboss.jca.core.connectionmanager.pool.AbstractPool.getTransactionNewConnection(AbstractPool.java:702)

at org.jboss.jca.core.connectionmanager.pool.AbstractPool.getConnection(AbstractPool.java:603)

at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.getManagedConnection(AbstractConnectionManager.java:579)

... 77 more

I can understand that either GC pause or some sort of CPU starvation might lead to this type of errors, but I can't understand  why the system did  not recover from this(after 12 hours these errors were still popping up, only a restart solved it) . Somehow the JmsXA connection pool got 'jammed'. Unfortunately I have no thread dump(I'm currently trying to reproduce this locally).

I would increase the JmsXA pool size and the 30 seconds timeout but I'm afraid that would not really solve the issue.

terry.paterson : Have you found a solution for this?

[andey]

This managed connection pool can be exhausted and the IJ000453 message indicates this. usually indicate the fact that you may have run out of connections.

If you are not configuring max-pool-size then HornetQ's pooled connection factory(max-pool-size) defaults to 20. if max-pool-size is not seen in the pooled-connection-factory that is an indication that the default size is being used, so max-pool-size would need to be entered with the appropriate value arrived at via load testing.

Add a max-pool-size parameter to the hornetq-ra pooled-connection-factory block in the hornetq-server section of the messaging subsystem in $JBOSS_HOME/standalone/configuration/standalone.xml or $JBOSS_HOME/domain/configuration/domain.xml files.

If require you can also increase the max-pool-size of connection factory by adding the parameter to the hornetq-ra pooled-connection-factory block in the hornetq-server like below.

<subsystem xmlns="urn:jboss:domain:messaging:1.2">

  <hornetq-server>

  <jms-connection-factories>

  ...

  <pooled-connection-factory name="hornetq-ra">

  ...

  <max-pool-size>30</max-pool-size>

  ...

  </pooled-connection-factory>

  ...

  </jms-connection-factories>

  </hornetq-server>

  </subsystem>