HornetQ fails "Error trying to connect to any providers for xa recovery"

[oranheim]

I use JBoss 7.1.0.Final and Seam JMS 3.1.0.Final and HornetQ in my app to queue e-mails that will be sent out. I experience a strange error, becasue it worked for a long time and all of a sudden HornetQ stops working. My standalone-full.xml looks like this:

<subsystem xmlns="urn:jboss:domain:messaging:1.1">
    <hornetq-server>
        <persistence-enabled>true</persistence-enabled>
        <journal-file-size>102400</journal-file-size>
        <journal-min-files>2</journal-min-files>


        <connectors>
            <netty-connector name="netty" socket-binding="messaging"/>
            <netty-connector name="netty-throughput" socket-binding="messaging-throughput">
                <param key="batch-delay" value="50"/>
            </netty-connector>
            <in-vm-connector name="in-vm" server-id="0"/>
        </connectors>


        <acceptors>
            <netty-acceptor name="netty" socket-binding="messaging"/>
            <netty-acceptor name="netty-throughput" socket-binding="messaging-throughput">
                <param key="batch-delay" value="50"/>
                <param key="direct-deliver" value="false"/>
            </netty-acceptor>
            <in-vm-acceptor name="in-vm" server-id="0"/>
        </acceptors>


        <security-settings>
            <security-setting match="#">
                <permission type="send" roles="guest"/>
                <permission type="consume" roles="guest"/>
                <permission type="createNonDurableQueue" roles="guest"/>
                <permission type="deleteNonDurableQueue" roles="guest"/>
            </security-setting>
        </security-settings>


        <address-settings>
            <address-setting match="#">
                <dead-letter-address>jms.queue.DLQ</dead-letter-address>
                <expiry-address>jms.queue.ExpiryQueue</expiry-address>
                <redelivery-delay>0</redelivery-delay>
                <max-size-bytes>10485760</max-size-bytes>
                <address-full-policy>BLOCK</address-full-policy>
                <message-counter-history-day-limit>10</message-counter-history-day-limit>
            </address-setting>
        </address-settings>


        <jms-connection-factories>
            <connection-factory name="InVmConnectionFactory">
                <connectors>
                    <connector-ref connector-name="in-vm"/>
                </connectors>
                <entries>
                    <entry name="java:/ConnectionFactory"/>
                </entries>
            </connection-factory>
            <connection-factory name="RemoteConnectionFactory">
                <connectors>
                    <connector-ref connector-name="netty"/>
                </connectors>
                <entries>
                    <entry name="RemoteConnectionFactory"/>
                    <entry name="java:jboss/exported/jms/RemoteConnectionFactory"/>
                </entries>
            </connection-factory>
            <pooled-connection-factory name="hornetq-ra">
                <transaction mode="xa"/>
                <connectors>
                    <connector-ref connector-name="in-vm"/>
                </connectors>
                <entries>
                    <entry name="java:/JmsXA"/>
                </entries>
            </pooled-connection-factory>
        </jms-connection-factories>


        <jms-destinations>
            <jms-queue name="testQueue">
                <entry name="queue/test"/>
                <entry name="java:jboss/exported/jms/queue/test"/>
            </jms-queue>
            <jms-queue name="sendMailQueue">
                <entry name="queue/sendMail"/>
                <entry name="java:jboss/exported/jms/queue/sendMail"/>
            </jms-queue>
            <jms-topic name="testTopic">
                <entry name="topic/test"/>
                <entry name="java:jboss/exported/jms/topic/test"/>
            </jms-topic>
        </jms-destinations>
    </hornetq-server>
</subsystem>

The exception thrown from JBoss Messaging are:

14:05:34,303 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) ReaperThread.run ()
14:05:34,303 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) TransactionReaper::check ()
14:05:34,304 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) TransactionReaper::check - comparing 1330175134303
14:05:34,304 TRACE [com.arjuna.ats.arjuna] (Transaction Reaper) Thread Thread[Transaction Reaper,5,main] sleeping for 9223370706679641503


14:06:59,534 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== SCANNING
14:06:59,534 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread scanning
14:06:59,535 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery first pass at Sat, 25 Feb 2012 14:06:59
14:06:59,535 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
14:06:59,536 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule first pass
14:06:59,536 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, InputObjectState Uid   : 0:0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , -1)
14:06:59,537 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
14:06:59,538 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) processing /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction transactions
14:06:59,538 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)  
14:06:59,539 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - first pass
14:06:59,539 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
14:06:59,539 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allTypes(InputObjectState Uid   : 0:0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: )
14:06:59,540 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
14:06:59,541 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)  
14:06:59,541 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - first pass
14:06:59,541 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) InputObjectState::InputObjectState()
14:06:59,542 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) FileSystemStore.allObjUids(/StateManager/AbstractRecord/XAResourceRecord, InputObjectState Uid   : 0:0:0:0:0
InputObjectState Type  : null
InputObjectState Size  : 0
InputObjectState Buffer: , -1)
14:06:59,542 TRACE [com.arjuna.ats.arjuna] (Periodic Recovery) OutputObjectState::OutputObjectState()
14:06:59,543 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)  
14:07:09,543 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) Periodic recovery second pass at Sat, 25 Feb 2012 14:07:09
14:07:09,544 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) AtomicActionRecoveryModule second pass
14:07:09,544 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)  
14:07:09,544 DEBUG [com.arjuna.ats.txoj] (Periodic Recovery) TORecoveryModule - second pass
14:07:09,544 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)  
14:07:09,545 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule - second pass
14:07:09,545 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.transactionInitiatedRecovery completed
14:07:09,546 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) xarecovery of HornetQXAResourceWrapper [serverLocator=null, csf=null, delegate=null, xaRecoveryConfigs=[XARecoveryConfig [hornetQConnectionFactory=HornetQConnectionFactory [serverLocator=ServerLocatorImpl [initialConnectors=[org-hornetq-core-remoting-impl-invm-InVMConnectorFactory?server-id=0], discoveryGroupConfiguration=null], clientID=null, dupsOKBatchSize=1048576, transactionBatchSize=1048576, readOnly=false], username=null, password=null]], instance=827123588]
14:07:09,547 WARN  [com.arjuna.ats.jta] (Periodic Recovery) ARJUNA016027: Local XARecoveryModule.xaRecovery got XA exception XAException.XAER_RMERR: javax.transaction.xa.XAException: Error trying to connect to any providers for xa recovery
          at org.hornetq.jms.server.recovery.HornetQXAResourceWrapper.getDelegate(HornetQXAResourceWrapper.java:275) [hornetq-jms-2.2.11.Final.jar:]
          at org.hornetq.jms.server.recovery.HornetQXAResourceWrapper.recover(HornetQXAResourceWrapper.java:77) [hornetq-jms-2.2.11.Final.jar:]
          at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.xaRecovery(XARecoveryModule.java:503) [jbossjts-4.16.2.Final.jar:]
          at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.resourceInitiatedRecoveryForRecoveryHelpers(XARecoveryModule.java:471) [jbossjts-4.16.2.Final.jar:]
          at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.bottomUpRecovery(XARecoveryModule.java:385) [jbossjts-4.16.2.Final.jar:]
          at com.arjuna.ats.internal.jta.recovery.arjunacore.XARecoveryModule.periodicWorkSecondPass(XARecoveryModule.java:166) [jbossjts-4.16.2.Final.jar:]
          at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.doWorkInternal(PeriodicRecovery.java:789) [jbossjts-4.16.2.Final.jar:]
          at com.arjuna.ats.internal.arjuna.recovery.PeriodicRecovery.run(PeriodicRecovery.java:371) [jbossjts-4.16.2.Final.jar:]
Caused by: java.lang.IllegalStateException: Cannot create session factory, server locator is closed (maybe it has been garbage collected)
          at org.hornetq.core.client.impl.ServerLocatorImpl.assertOpen(ServerLocatorImpl.java:1823) [hornetq-core-2.2.11.Final.jar:]
          at org.hornetq.core.client.impl.ServerLocatorImpl.createSessionFactory(ServerLocatorImpl.java:699) [hornetq-core-2.2.11.Final.jar:]
          at org.hornetq.jms.server.recovery.HornetQXAResourceWrapper.connect(HornetQXAResourceWrapper.java:321) [hornetq-jms-2.2.11.Final.jar:]
          at org.hornetq.jms.server.recovery.HornetQXAResourceWrapper.getDelegate(HornetQXAResourceWrapper.java:251) [hornetq-jms-2.2.11.Final.jar:]
          ... 7 more


14:07:09,573 DEBUG [com.arjuna.ats.jta] (Periodic Recovery) Local XARecoveryModule.resourceInitiatedRecovery completed
14:07:09,573 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery)  
14:07:09,574 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread Status <== INACTIVE
14:07:09,574 DEBUG [com.arjuna.ats.arjuna] (Periodic Recovery) PeriodicRecovery: background thread backing off

The consequence of this error is that HornetQ stops functioning. To make HornetQ to work again, I must delete data and tmp directory in JBoss and restart the server. It's clearly a showstopper for us.

What makes this error hard is that I do not know how to reproduce it. It normally occurrs when the server has been active for 2-3 hours and after the queue has reached 20 messages.

Please advise!

[jbertram]

Try to get a thread dump when this happens and post it here.

Also, try using a different <address-full-policy> (e.g. PAGE).

[erhard]

I have the same problem. In my case however there is no needto put messages into the queue to reproduce ist. Its' just deployed for a while. I use a demo-appplication downloaded from the internet that I migrated to JBoss 7.1.0. So if this problem is persistent, I could provide this application to reproduce the problem.

[oranheim]

If you have a test case that demonstrates this issue, please attach it to a reply. That would be really helpful.

[oranheim]

Yet again it crashes and jstack reports 1 deadlock situation. I have attached two files: 1) jstack-2012-02-27_08_49.txt (as71 works fine) and 2) jstack-2012-02-27_09_58_crash.txt (as71 HornetQ has crashed).

I also watched over the data/messaging* folders while testing. They persistently stays at the same size before and after the HornetQ crash.

stage:/opt/jboss7/standalone/data# du -b m*
4198400          messagingbindings
311315          messagingjournal
4096                  messaginglargemessages

After shuting down the server, I change address-full-policy from BLOCK to PAGE. Upon start an exception was thrown:

10:09:56,964 INFO  [org.hornetq.core.server.impl.HornetQServerImpl] (MSC service thread 1-1) Waiting to obtain live lock
10:09:56,989 INFO  [org.hornetq.core.persistence.impl.journal.JournalStorageManager] (MSC service thread 1-1) Using AIO Journal
10:09:57,077 INFO  [com.arjuna.ats.jbossatx] (MSC service thread 1-3) ARJUNA032010: JBossTS Recovery Service (tag: JBOSSTS_4_16_2_Final) - JBoss Inc.
10:09:57,094 INFO  [com.arjuna.ats.arjuna] (MSC service thread 1-3) ARJUNA012324: Start RecoveryActivators
10:09:57,138 INFO  [com.arjuna.ats.arjuna] (Transaction Expired Entry Monitor) ARJUNA012296: ExpiredEntryMonitor running at Mon, 27 Feb 2012 10:09:57
10:09:57,253 INFO  [org.jboss.ws.common.management.AbstractServerConfig] (MSC service thread 1-8) JBoss Web Services - Stack CXF Server 4.0.1.GA
10:09:57,338 INFO  [org.hornetq.core.server.impl.AIOFileLockNodeManager] (MSC service thread 1-1) Waiting to obtain live lock
10:09:57,338 INFO  [org.hornetq.core.server.impl.AIOFileLockNodeManager] (MSC service thread 1-1) Live Server Obtained live lock
10:09:57,389 INFO  [com.arjuna.ats.arjuna] (MSC service thread 1-3) ARJUNA012343: RecoveryManagerImple is ready. Socket listener is turned off.
10:09:57,390 INFO  [com.arjuna.ats.jbossatx] (MSC service thread 1-3) ARJUNA032013: Starting transaction recovery manager
10:09:57,670 SEVERE [org.hornetq.core.server.impl.HornetQServerImpl] (MSC service thread 1-1) Failure in initialisation: java.lang.IllegalStateException: pageSize for address jms.queue.sendMailQueue >= maxSize. Normally pageSize should be significantly smaller than maxSize, ms: 10485760 ps 10485760
          at org.hornetq.core.paging.impl.PagingStoreImpl.<init>(PagingStoreImpl.java:166) [hornetq-core-2.2.11.Final.jar:]
          at org.hornetq.core.paging.impl.PagingStoreFactoryNIO.newStore(PagingStoreFactoryNIO.java:119) [hornetq-core-2.2.11.Final.jar:]
          at org.hornetq.core.paging.impl.PagingManagerImpl.newStore(PagingManagerImpl.java:272) [hornetq-core-2.2.11.Final.jar:]
          at org.hornetq.core.paging.impl.PagingManagerImpl.createPageStore(PagingManagerImpl.java:138) [hornetq-core-2.2.11.Final.jar:]
          at org.hornetq.core.paging.impl.PagingManagerImpl.getPageStore(PagingManagerImpl.java:164) [hornetq-core-2.2.11.Final.jar:]
          at org.hornetq.core.server.impl.HornetQServerImpl.loadJournals(HornetQServerImpl.java:1565) [hornetq-core-2.2.11.Final.jar:]
          at org.hornetq.core.server.impl.HornetQServerImpl.initialisePart2(HornetQServerImpl.java:1445) [hornetq-core-2.2.11.Final.jar:]
          at org.hornetq.core.server.impl.HornetQServerImpl.access$1200(HornetQServerImpl.java:138) [hornetq-core-2.2.11.Final.jar:]
          at org.hornetq.core.server.impl.HornetQServerImpl$SharedStoreLiveActivation.run(HornetQServerImpl.java:1900) [hornetq-core-2.2.11.Final.jar:]
          at org.hornetq.core.server.impl.HornetQServerImpl.start(HornetQServerImpl.java:366) [hornetq-core-2.2.11.Final.jar:]
          at org.hornetq.jms.server.impl.JMSServerManagerImpl.start(JMSServerManagerImpl.java:269) [hornetq-jms-2.2.11.Final.jar:]
          at org.jboss.as.messaging.jms.JMSService.start(JMSService.java:73) [jboss-as-messaging-7.1.0.Final.jar:7.1.0.Final]
          at org.jboss.msc.service.ServiceControllerImpl$StartTask.startService(ServiceControllerImpl.java:1811) [jboss-msc-1.0.2.GA.jar:1.0.2.GA]
          at org.jboss.msc.service.ServiceControllerImpl$StartTask.run(ServiceControllerImpl.java:1746) [jboss-msc-1.0.2.GA.jar:1.0.2.GA]
          at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) [rt.jar:1.6.0_24]
          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) [rt.jar:1.6.0_24]
          at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_24]


10:09:57,674 INFO  [org.hornetq.core.server.impl.HornetQServerImpl] (MSC service thread 1-1) HornetQ Server version 2.2.11.Final (HQ_2_2_11_FINAL_AS7, 122) [51aeccfd-606c-11e1-be13-0010189e36c0]) started
10:09:57,676 INFO  [org.hornetq.jms.server.impl.JMSServerManagerImpl] (MSC service thread 1-7) Caching command for createTopic for testTopic since the JMS Server is not active yet
10:09:57,676 INFO  [org.hornetq.jms.server.impl.JMSServerManagerImpl] (MSC service thread 1-5) Caching command for createQueue for sendMailQueue since the JMS Server is not active yet
10:09:57,677 INFO  [org.hornetq.jms.server.impl.JMSServerManagerImpl] (MSC service thread 1-2) Caching command for createConnectionFactory for InVmConnectionFactory since the JMS Server is not active yet
10:09:57,677 INFO  [org.hornetq.jms.server.impl.JMSServerManagerImpl] (MSC service thread 1-1) Caching command for createConnectionFactory for RemoteConnectionFactory since the JMS Server is not active yet
10:09:57,678 INFO  [org.hornetq.jms.server.impl.JMSServerManagerImpl] (MSC service thread 1-8) Caching command for createQueue for testQueue since the JMS Server is not active yet

Since this clearly complains about the address-setting max-size-bytes (10 Mb), which now is equal to the journal-file-size (10 Mb), it won't start up my sendMailQueue correctly. So, now I've deleted ./data/messaging* folders and see how it behaves with PAGE address policy.

I suspect the Consumer in HornetQ to not clean up messages after itself, when they are picked up from the queue.

This issue definitely causes deadlocks, which is not good for production use.

[clebert.suconic]

@Ove Ranheim your case is a different case.. You can't have the pageSize >= MaxSize on Page.

You should set the Pagesize to something like 10M and MaxSize to something like 100M (it all depends on the use case)

But you can't have pageSize >= MaxSize, otherwise you won't receive messages.

[clebert.suconic]

Please, try again with PageSize < 10M.

And BTW: Why are you setting the MaxSize to 10M? What does it have to do with the journal-size?

It seems you are making some mess there.

[oranheim]

Clebert,

Just to be clear here. Page size wasn't set because of the address policy of type BLOCK. Should page size be set anyway?

As Justin pointed out, it's worth checking out address policy of PAGE. So, I have run through my tests again with a configartion of page-size=1Mb and kept the max-size and jounal to 10Mb limits. I keep limits low, so if the configration is totally wrong, errors would show up. The good news is that PAGE works just fine.

So, does this mean that default BLOCK policy is not recommended?

[clebert.suconic]

Paging is better, however Blocking should work.

I believe the wrong configuration broke something on the code. It shouldn't matter Page-size on blocking, but the code it verifying for it when it starts, so can you try page-size < max-size as a test?

Page should work for your setup.

[clebert.suconic]

So, the original question the XA recovery will only happen after block-max-size has been achieved. or it will happen regardless of that?

[oranheim]

The original XA recovery post only occurs if address policy is of type BLOCK.

With PAGE set, it seems to works fine. In this case I off course set page-size < max-size to configuriation.

The jira issue raised, only realtes to BLOCK. So, I still think that is a valid issue.

[clebert.suconic]

As I said earlier, can you do a test with page-size < page-max-size. It seems this is a configuration issue caused by an inapropriate error message. I'm just looking for information and a way to replicate this issue.

[clebert.suconic]

I mean... pageSize==maxSize && blocking

[clebert.suconic]

Were you able to test blocking with a lower pageSize?

[oranheim]

Just switch to block policy.

journal-size: 10Mb

max-size: 10Mb

page-size: 1Mb.

So, after testing for next 3-4 hours we should know.