java.lang.IllegalStateException: Destination queue.ISXO_AuditLogQueue_01 not active after MessagingClusterHealthMBean restart JMS service ----------------------------------------------------------------------------------------------------------------------------------------- Key: JBMESSAGING-1948 URL: https://issues.jboss.org/browse/JBMESSAGING-1948 Project: JBoss Messaging Issue Type: Bug Components: JMS Clustering Affects Versions: 1.4.8.SP9 Reporter: Flemming Harms Attachments: ConnectionFactory-diff.patch, postoffice-patch.diff I get this error “java.lang.IllegalStateException: Destination queue.ISXO_AuditLogQueue_01 not active” after MessagingClusterHealthMBean restarts the JMS service with JBoss Messaging 1.4.8.SP9. I have 2 node JBoss5 cluster with JBoss Messaging and I have enabled the new failover model and setup the MessagingClusterHealthMBean to monitor split brain. I disconnect the cable from one of the servers MessagingClusterHealthMBean discover it’s alone and shut down the JMS service as expected. After a while I connect the server again and the server discover the other server and MessagingClusterHealthMBean starts the JMS service also as expected. But when I connect a client it fails with “java.lang.IllegalStateException: Destination queue.ISXO_AuditLogQueue_01 not active” and what I can see in the debugger ServerConnectionEndpoint have reference to the old post office where the queue is still exits in the inactiveConditions Set. Log from the server when it discover it’s alone and it restart the service again 2013-09-07 21:29:06,381 ERROR [org.jboss.messaging.core.impl.postoffice.MessagingPostOffice] (Thread-32) I'm orphaned and now I can't tell others that I'm alive. Shutdown node: 102 2013-09-07 21:29:09,728 INFO [org.jboss.jms.server.MessagingClusterHealthMBean] (Thread-32) Stopping JBM node on DB failure... 2013-09-07 21:29:09,731 INFO [org.jboss.jms.server.destination.QueueService] (Thread-32) Queue[/queue/ExpiryQueue] stopped 2013-09-07 21:29:09,732 INFO [org.jboss.jms.server.destination.QueueService] (Thread-32) Queue[/queue/DLQ] stopped 2013-09-07 21:29:09,733 INFO [org.jboss.jms.server.destination.QueueService] (Thread-32) Queue[/ISXO/AuditLogQueue, name=ISXO_AuditLogQueue_01] stopped 2013-09-07 21:29:09,733 INFO [org.jboss.jms.server.destination.QueueService] (Thread-32) Queue[/ISXO/CiscoUCSEventQueue, name=ISXO_CiscoUCSEventQueue_01] stopped 2013-09-07 21:29:09,738 INFO [org.jboss.jms.server.destination.TopicService] (Thread-32) Topic[/ISXO/RemoteEventTopic, name=ISXO_RemoteEventQueue_01] stopped 2013-09-07 21:29:09,739 INFO [org.jboss.jms.server.destination.QueueService] (Thread-32) Queue[/ISXO/ScheduledJobQueue, name=ISXO_ScheduledJobQueue_01] stopped 2013-09-07 21:29:11,210 INFO [org.jboss.jms.server.connectionfactory.ConnectionFactory] (Thread-32) org.jboss.jms.server.connectionfactory.ConnectionFactory@366480d7 undeployed 2013-09-07 21:29:11,216 INFO [org.jboss.jms.server.connectionfactory.ConnectionFactory] (Thread-32) org.jboss.jms.server.connectionfactory.ConnectionFactory@467463b3 undeployed 2013-09-07 21:29:11,216 INFO [org.jboss.jms.server.connectionfactory.ConnectionFactory] (Thread-32) org.jboss.jms.server.connectionfactory.ConnectionFactory@21fdb35f undeployed 2013-09-07 21:29:11,216 INFO [org.jboss.jms.server.connectionfactory.ConnectionFactory] (Thread-32) org.jboss.jms.server.connectionfactory.ConnectionFactory@443578f2 undeployed 2013-09-07 21:29:11,235 INFO [org.jboss.jms.server.connectionfactory.ConnectionFactory] (Thread-32) org.jboss.jms.server.connectionfactory.ConnectionFactory@ecdede5 undeployed 2013-09-07 21:29:11,298 ERROR [org.jgroups.blocks.ConnectionTable] (OOB-43,192.168.56.102:7900) failed sending data to 192.168.56.101:7900: java.net.SocketException: Socket closed 2013-09-07 21:29:14,413 WARN [org.jgroups.protocols.pbcast.NAKACK] (OOB-19,192.168.56.102:55200) 192.168.56.102:55200] discarded message from non-member 192.168.56.101:55200, my view is [192.168.56.102 2013-09-07 21:29:14,863 WARN [org.jgroups.protocols.pbcast.NAKACK] (OOB-19,192.168.56.102:55200) 192.168.56.102:55200] discarded message from non-member 192.168.56.101:55200, my view is [192.168.56.102 2013-09-07 21:29:21,080 INFO [org.jboss.jms.server.ServerPeer] (Thread-32) JMS ServerPeer[102] stopped 2013-09-07 21:29:21,090 INFO [org.jboss.jms.server.MessagingClusterHealthMBean] (Thread-32) JBM node is stopped. 2013-09-07 21:29:21,090 INFO [org.jboss.messaging.core.impl.postoffice.GroupMember] (Incoming-2,192.168.56.102:55200) Dead members: 1 ([192.168.56.101:55200]) 2013-09-07 21:29:21,090 INFO [org.jboss.messaging.core.impl.postoffice.GroupMember] (Incoming-2,192.168.56.102:55200) All Members : 1 ([192.168.56.102:55200]) 2013-09-07 21:30:24,666 INFO [org.jboss.jms.server.MessagingClusterHealthMBean] (Thread-75) Restarting JBM node... 2013-09-07 21:30:33,369 INFO [org.jboss.jms.server.ServerPeer] (Thread-75) JBoss Messaging 1.4.8.SP9 server [102] started 2013-09-07 21:30:33,459 INFO [STDOUT] (Thread-75) --------------------------------------------------------- GMS: address is 192.168.56.102:55200 (cluster=DefaultPartition-JMS-CTRL) --------------------------------------------------------- 2013-09-07 21:30:33,524 INFO [org.jboss.messaging.core.impl.postoffice.GroupMember] (Thread-75) org.jboss.messaging.core.impl.postoffice.GroupMember$ControlMembershipListener@6a500238 got new view [192 2013-09-07 21:30:33,525 INFO [org.jboss.messaging.core.impl.postoffice.GroupMember] (Thread-75) I am (192.168.56.102:55200) 2013-09-07 21:30:33,525 INFO [org.jboss.messaging.core.impl.postoffice.GroupMember] (Thread-75) New Members : 2 ([192.168.56.101:55200, 192.168.56.102:55200]) 2013-09-07 21:30:33,525 INFO [org.jboss.messaging.core.impl.postoffice.GroupMember] (Thread-75) All Members : 2 ([192.168.56.101:55200, 192.168.56.102:55200]) 2013-09-07 21:30:33,570 INFO [STDOUT] (pool-151-thread-1) --------------------------------------------------------- GMS: address is 192.168.56.102:7900 (cluster=DefaultPartition-JMS-DATA) --------------------------------------------------------- 2013-09-07 21:30:33,779 INFO [org.jboss.messaging.core.impl.postoffice.MessagingPostOffice] (Thread-75) Waiting for JGroups... 2013-09-07 21:30:33,784 INFO [org.jboss.messaging.core.impl.postoffice.MessagingPostOffice] (Thread-75) JGroups starts to work again, initializing state 2013-09-07 21:30:33,785 INFO [org.jboss.messaging.core.impl.postoffice.MessagingPostOffice] (Thread-75) Now node is ready for work. 2013-09-07 21:30:34,896 INFO [org.jboss.jms.server.connectionfactory.ConnectionFactory] (Thread-75) Connector sslbisocket://192.168.56.102:4459 has leasing enabled, lease period 25000 milliseconds 2013-09-07 21:30:34,896 INFO [org.jboss.jms.server.MessagingClusterHealthMBean] (Thread-75) Registered connection factory jboss.messaging.connectionfactory:service=SSLConnectionFactory 2013-09-07 21:30:34,896 INFO [org.jboss.jms.server.connectionfactory.ConnectionFactory] (Thread-75) org.jboss.jms.server.connectionfactory.ConnectionFactory@366480d7 started 2013-09-07 21:30:36,797 INFO [org.jboss.jms.server.connectionfactory.ConnectionFactory] (Thread-75) Connector bisocket://192.168.56.102:4457 has leasing enabled, lease period 25000 milliseconds 2013-09-07 21:30:36,797 INFO [org.jboss.jms.server.MessagingClusterHealthMBean] (Thread-75) Registered connection factory jboss.messaging.connectionfactory:service=ConnectionFactory 2013-09-07 21:30:36,797 INFO [org.jboss.jms.server.connectionfactory.ConnectionFactory] (Thread-75) org.jboss.jms.server.connectionfactory.ConnectionFactory@467463b3 started 2013-09-07 21:30:37,207 INFO [org.jboss.jms.server.connectionfactory.ConnectionFactory] (Thread-75) Connector servlet://192.168.56.102:8080 has leasing enabled, lease period 25000 milliseconds 2013-09-07 21:30:37,207 INFO [org.jboss.jms.server.MessagingClusterHealthMBean] (Thread-75) Registered connection factory jboss.messaging.connectionfactory:service=ServletConnectionFactory 2013-09-07 21:30:37,207 INFO [org.jboss.jms.server.connectionfactory.ConnectionFactory] (Thread-75) org.jboss.jms.server.connectionfactory.ConnectionFactory@21fdb35f started 2013-09-07 21:30:37,440 INFO [org.jboss.jms.server.connectionfactory.ConnectionFactory] (Thread-75) Connector bisocket://192.168.56.102:4457 has leasing enabled, lease period 25000 milliseconds 2013-09-07 21:30:37,441 INFO [org.jboss.jms.server.MessagingClusterHealthMBean] (Thread-75) Registered connection factory jboss.messaging.connectionfactory:service=ClusteredConnectionFactory 2013-09-07 21:30:37,441 INFO [org.jboss.jms.server.connectionfactory.ConnectionFactory] (Thread-75) org.jboss.jms.server.connectionfactory.ConnectionFactory@443578f2 started 2013-09-07 21:30:41,483 INFO [org.jboss.jms.server.connectionfactory.ConnectionFactory] (Thread-75) Connector bisocket://192.168.56.102:4457 has leasing enabled, lease period 25000 milliseconds 2013-09-07 21:30:41,483 INFO [org.jboss.jms.server.MessagingClusterHealthMBean] (Thread-75) Registered connection factory jboss.messaging.connectionfactory:service=ClusterPullConnectionFactory 2013-09-07 21:30:41,483 INFO [org.jboss.jms.server.connectionfactory.ConnectionFactory] (Thread-75) org.jboss.jms.server.connectionfactory.ConnectionFactory@ecdede5 started 2013-09-07 21:30:41,483 INFO [org.jboss.jms.server.MessagingClusterHealthMBean] (Thread-75) Registered destination jboss.messaging.destination:service=Queue,name=ExpiryQueue 2013-09-07 21:30:41,715 INFO [org.jboss.jms.server.destination.QueueService] (Thread-75) Queue[/queue/ExpiryQueue] started, fullSize=200000, pageSize=2000, downCacheSize=2000 2013-09-07 21:30:41,715 INFO [org.jboss.jms.server.MessagingClusterHealthMBean] (Thread-75) Registered destination jboss.messaging.destination:service=Queue,name=DLQ 2013-09-07 21:30:42,259 INFO [org.jboss.jms.server.destination.QueueService] (Thread-75) Queue[/queue/DLQ] started, fullSize=200000, pageSize=2000, downCacheSize=2000 2013-09-07 21:30:42,259 INFO [org.jboss.jms.server.MessagingClusterHealthMBean] (Thread-75) Registered destination jboss.messaging.destination:service=Queue,name=ISXO_AuditLogQueue_01 2013-09-07 21:30:42,495 INFO [org.jboss.jms.server.destination.QueueService] (Thread-75) Queue[/ISXO/AuditLogQueue, name=ISXO_AuditLogQueue_01] started, fullSize=200000, pageSize=2000, downCacheSize=20 2013-09-07 21:30:42,495 INFO [org.jboss.jms.server.MessagingClusterHealthMBean] (Thread-75) Registered destination jboss.messaging.destination:service=Queue,name=ISXO_CiscoUCSEventQueue_01 2013-09-07 21:30:42,923 INFO [org.jboss.jms.server.destination.QueueService] (Thread-75) Queue[/ISXO/CiscoUCSEventQueue, name=ISXO_CiscoUCSEventQueue_01] started, fullSize=200000, pageSize=2000, downCa 2013-09-07 21:30:42,923 INFO [org.jboss.jms.server.MessagingClusterHealthMBean] (Thread-75) Registered destination jboss.messaging.destination:service=Topic,name=ISXO_RemoteEventQueue_01 2013-09-07 21:30:43,122 INFO [org.jboss.jms.server.destination.TopicService] (Thread-75) Topic[/ISXO/RemoteEventTopic, name=ISXO_RemoteEventQueue_01] started, fullSize=200000, pageSize=2000, downCacheS 2013-09-07 21:30:43,122 INFO [org.jboss.jms.server.MessagingClusterHealthMBean] (Thread-75) Registered destination jboss.messaging.destination:service=Queue,name=ISXO_ScheduledJobQueue_01 2013-09-07 21:30:43,559 INFO [org.jboss.jms.server.destination.QueueService] (Thread-75) Queue[/ISXO/ScheduledJobQueue, name=ISXO_ScheduledJobQueue_01] started, fullSize=200000, pageSize=2000, downCach 2013-09-07 21:30:43,559 INFO [org.jboss.jms.server.MessagingClusterHealthMBean] (Thread-75) JBM node restarted. Stack trace the “java.lang.IllegalStateException: Destination queue.ISXO_AuditLogQueue_01 not active” Daemon Thread [ISXOSchedulerPrioritized_Worker-1] (Suspended (breakpoint at line 3046 in MessagingPostOffice)) owns: AtomicAction (id=519) MessagingPostOffice.routeInternal(MessageReference, Condition, Transaction, boolean, Set) line: 3046 MessagingPostOffice.route(MessageReference, Condition, Transaction) line: 983 ServerConnectionEndpoint.sendMessage(JBossMessage, Transaction, boolean) line: 796 ServerConnectionEndpoint.processTransaction(ClientTransaction, Transaction, boolean) line: 852 ServerConnectionEndpoint.sendTransaction(TransactionRequest, boolean) line: 516 ConnectionAdvised.org$jboss$jms$server$endpoint$advised$ConnectionAdvised$sendTransaction$aop(TransactionRequest, boolean) line: 106 ConnectionAdvised$sendTransaction_N3268650789275322226.invokeTarget() line: not available ConnectionAdvised$sendTransaction_N3268650789275322226(MethodInvocation).invokeNext() line: 111 SecurityAspect.handleSendTransaction(Invocation) line: 200 NativeMethodAccessorImpl.invoke0(Method, Object, Object[]) line: not available [native method] NativeMethodAccessorImpl.invoke(Object, Object[]) line: 39 DelegatingMethodAccessorImpl.invoke(Object, Object[]) line: 25 Method.invoke(Object, Object...) line: 597 PerInstanceAdvice.invoke(Invocation) line: 122 ConnectionAdvised$sendTransaction_N3268650789275322226(MethodInvocation).invokeNext() line: 102 ServerLogInterceptor.invoke(Invocation) line: 105 ConnectionAdvised$sendTransaction_N3268650789275322226(MethodInvocation).invokeNext() line: 102 ConnectionAdvised.sendTransaction(TransactionRequest, boolean) line: not available ConnectionSendTransactionRequest.serverInvoke() line: 86 JMSServerInvocationHandler.invoke(InvocationRequest) line: 165 BisocketServerInvoker(ServerInvoker).invoke(InvocationRequest) line: 930 LocalClientInvoker.invoke(InvocationRequest) line: 106 Client.invoke(Object, Map, InvokerLocator) line: 2034 Client.invoke(Object, Map) line: 877 Client.invoke(Object) line: 865 ClientConnectionDelegate(DelegateSupport).doInvoke(Client, RequestSupport, boolean) line: 189 ClientConnectionDelegate(DelegateSupport).doInvoke(Client, RequestSupport) line: 160 ClientConnectionDelegate.org$jboss$jms$client$delegate$ClientConnectionDelegate$sendTransaction$aop(TransactionRequest, boolean) line: 241 ClientConnectionDelegate$sendTransaction_N3268650789275322226.invokeTarget() line: not available ClientConnectionDelegate$sendTransaction_N3268650789275322226(MethodInvocation).invokeNext() line: 111 FailoverValveInterceptor.invoke(Invocation) line: 92 PerInstanceInterceptor.invoke(Invocation) line: 86 ClientConnectionDelegate$sendTransaction_N3268650789275322226(MethodInvocation).invokeNext() line: 102 ClosedInterceptor.invoke(Invocation) line: 172 PerInstanceInterceptor.invoke(Invocation) line: 86 ClientConnectionDelegate$sendTransaction_N3268650789275322226(MethodInvocation).invokeNext() line: 102 ClientConnectionDelegate.sendTransaction(TransactionRequest, boolean) line: not available ResourceManager.sendTransactionXA(TransactionRequest, ConnectionDelegate) line: 712 ResourceManager.commit(Xid, boolean, ConnectionDelegate) line: 392 MessagingXAResource.commit(Xid, boolean) line: 275 JmsXAResource.commit(Xid, boolean) line: 98 XAResourceRecord.topLevelOnePhaseCommit() line: 811 AtomicAction(BasicAction).onePhaseCommit(boolean) line: 2656 AtomicAction(BasicAction).End(boolean) line: 1784 AtomicAction(TwoPhaseCoordinator).end(boolean) line: 94 AtomicAction(AtomicAction).commit(boolean) line: 160 TransactionImple.commitAndDisassociate() line: 1431 TransactionManagerImple(BaseTransaction).commit() line: 137 TransactionManagerDelegate(BaseTransactionManagerDelegate).commit() line: 75 Ejb3TxPolicy(TxPolicy).endTransaction(TransactionManager, Transaction) line: 170 Ejb3TxPolicy(TxPolicy).invokeInOurTx(Invocation, TransactionManager) line: 87 TxInterceptor$Required.invoke(Invocation) line: 190 StatefulContainerInvocation(MethodInvocation).invokeNext() line: 102 TxPropagationInterceptor.invoke(Invocation) line: 76 StatefulContainerInvocation(MethodInvocation).invokeNext() line: 102 NullInterceptor.invoke(Invocation) line: 42 StatefulContainerInvocation(MethodInvocation).invokeNext() line: 102 Ejb3AuthenticationInterceptorv2.invoke(Invocation) line: 182 StatefulContainerInvocation(MethodInvocation).invokeNext() line: 102 ENCPropagationInterceptor.invoke(Invocation) line: 41 StatefulContainerInvocation(MethodInvocation).invokeNext() line: 102 BlockContainerShutdownInterceptor.invoke(Invocation) line: 67 StatefulContainerInvocation(MethodInvocation).invokeNext() line: 102 CurrentInvocationContextInterceptor.invoke(Invocation) line: 47 StatefulContainerInvocation(MethodInvocation).invokeNext() line: 102 CurrentInvocationInterceptor.invoke(Invocation) line: 67 StatefulContainerInvocation(MethodInvocation).invokeNext() line: 102 EJB3TCCLInterceptor.invoke(Invocation) line: 86 StatefulContainerInvocation(MethodInvocation).invokeNext() line: 102 StatelessContainer(SessionSpecContainer).invoke(Serializable, SerializableMethod, Object[]) line: 193 StatelessContainer(SessionSpecContainer).invoke(Object, SerializableMethod, Object[]) line: 250 SessionLocalProxyInvocationHandler(SessionProxyInvocationHandlerBase).invoke(Object, Method, Object[]) line: 188 $Proxy702.publishMessages(EventSet) line: not available NativeMethodAccessorImpl.invoke0(Method, Object, Object[]) line: not available [native method] NativeMethodAccessorImpl.invoke(Object, Object[]) line: 39 DelegatingMethodAccessorImpl.invoke(Object, Object[]) line: 25 Method.invoke(Object, Object...) line: 597 ClusteredEJB3InvokerJob(EJB3InvokerJob).invokeEjb(Object, JobExecutionContext) line: 196 ClusteredEJB3InvokerJob(EJB3InvokerJob).doExecute(JobExecutionContext) line: 141 ClusteredEJB3InvokerJob(EJB3InvokerJob).execute(JobExecutionContext) line: 78 JobRunShell.run() line: 203 SimpleThreadPool$WorkerThread.run() line: 520 Update ======== After debugging the code to understand what is going on I'm pretty sure we have situation where it use an old ServerConnectionEndpoint with a old postoffice instance. In our case we have a bean(stateless) that inject the TopicConnectionFactory and and Topic as resource this could possible reuse an old connection? I can see that sometimes it get an instance of ServerConnectionEndpoint which contains a reference to the current server peer and to the old post office. The server peer instance actual holde the reference to the new post office, but because the postoffice variable is only set on constructor level this is never changed. Furthermore I can see the start method in ConnectionFactory was creating a listener that listens for failed connections, but this was not removed when the service stopped. After I removed the listener when the ConnectionFactory is stopped, and restarted i'm able to receive updates again and it does not fail with a "java.lang.IllegalStateException: Destination queue.MyQueue not active"