[jboss-jira] [JBoss JIRA] (JBMESSAGING-1948) java.lang.IllegalStateException: Destination queue.ISXO_AuditLogQueue_01 not active after MessagingClusterHealthMBean restart JMS service
Flemming Harms (JIRA)
jira-events at lists.jboss.org
Thu Oct 3 07:20:03 EDT 2013
Flemming Harms created JBMESSAGING-1948:
-------------------------------------------
Summary: 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
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 at 366480d7 undeployed
2013-09-07 21:29:11,216 INFO [org.jboss.jms.server.connectionfactory.ConnectionFactory] (Thread-32) org.jboss.jms.server.connectionfactory.ConnectionFactory at 467463b3 undeployed
2013-09-07 21:29:11,216 INFO [org.jboss.jms.server.connectionfactory.ConnectionFactory] (Thread-32) org.jboss.jms.server.connectionfactory.ConnectionFactory at 21fdb35f undeployed
2013-09-07 21:29:11,216 INFO [org.jboss.jms.server.connectionfactory.ConnectionFactory] (Thread-32) org.jboss.jms.server.connectionfactory.ConnectionFactory at 443578f2 undeployed
2013-09-07 21:29:11,235 INFO [org.jboss.jms.server.connectionfactory.ConnectionFactory] (Thread-32) org.jboss.jms.server.connectionfactory.ConnectionFactory at 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 at 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 at 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 at 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 at 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 at 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 at 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"
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
More information about the jboss-jira
mailing list