1:20 p.m.
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@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"
--
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