[jboss-jira] [JBoss JIRA] (JBMESSAGING-1782) on cluster hiccup jbossmessaging dies

on cluster hiccup jbossmessaging dies ------------------------------------- Key: JBMESSAGING-1782 URL: https://issues.jboss.org/browse/JBMESSAGING-1782 Project: JBoss Messaging Issue Type: Bug Affects Versions: 1.4.3.GA, 1.4.6.GA Environment: jboss 5.1 jboss groups 2.6.13 GA Reporter: Armin Haaf Assignee: Yong Hao Gao Fix For: 1.4.8.SP8 Attachments: ejbtest.tgz sometimes we have a problem with our cluster loosing a socket connection. Groups come up again, but messaging dies and is no longer usable on this node. Node 1 gots suspected by node 2 (i'm not sure why). Node 1 gets removed from the cluster and trys to reconnect. Reconnect seems to work, but messaging is now dead output from node1: 2010-01-11 04:24:17,070 ERROR [org.jgroups.blocks.ConnectionTable] [T:169] failed sending data to 10.199.12.135:7900: java.net.SocketException: Broken pipe 2010-01-11 04:24:17,072 WARN [org.jgroups.protocols.FD] [T:48734] I was suspected by 10.199.12.135:32792; ignoring the SUSPECT message and sending back a HEARTBEAT_ACK 2010-01-11 04:24:17,072 WARN [org.jgroups.protocols.FD] [T:48717] I was suspected by 10.199.12.135:32792; ignoring the SUSPECT message and sending back a HEARTBEAT_ACK 2010-01-11 04:24:17,073 WARN [org.jgroups.protocols.FD] [T:48720] I was suspected by 10.199.12.135:32792; ignoring the SUSPECT message and sending back a HEARTBEAT_ACK 2010-01-11 04:24:17,073 WARN [org.jgroups.protocols.pbcast.GMS] [T:67] I (10.199.12.134:32797) am not a member of view [10.199.12.135:32792|12] [10.199.12.135:32792], shunning myself and leaving the group (prev_members are [10.199.12.135:32792, 10.199.12.134:32797], current view is [10.199.12.135:32792|11] [10.199.12.135:32792, 10.199.12.134:32797]) 2010-01-11 04:24:17,073 WARN [org.jgroups.protocols.pbcast.GMS] [T:48721] I (10.199.12.134:32797) am not a member of view [10.199.12.135:32792|10] [10.199.12.135:32792], shunning myse lf and leaving the group (prev_members are [10.199.12.135:32792, 10.199.12.134:32797], current view is [10.199.12.135:32792|9] [10.199.12.135:32792, 10.199.12.134:32797]) 2010-01-11 04:24:17,074 WARN [org.jgroups.protocols.pbcast.GMS] [T:48719] I (10.199.12.134:32797) am not a member of view [10.199.12.135:32792|12] [10.199.12.135:32792], shunning myse lf and leaving the group (prev_members are [10.199.12.135:32792, 10.199.12.134:32797], current view is [10.199.12.135:32792|11] [10.199.12.135:32792, 10.199.12.134:32797]) 2010-01-11 04:24:17,075 ERROR [org.jgroups.protocols.UNICAST] [T:48718] 10.199.12.134:32797: sender window for 10.199.12.135:32792 not found 2010-01-11 04:24:17,585 INFO [STDOUT] [T:48741] --------------------------------------------------------- GMS: address is 10.199.12.134:32799 (cluster=lisa2000) --------------------------------------------------------- 2010-01-11 04:24:17,591 INFO [org.jboss.ha.framework.interfaces.HAPartition.lisa2000] [T:48741] New cluster view for partition lisa2000: 11 ([10.199.12.135:1099, 10.199.12.134:1099] d elta: 0) 2010-01-11 04:24:17,593 INFO [STDOUT] [T:48742] --------------------------------------------------------- GMS: address is 10.199.12.134:32799 (cluster=MessagingPostOffice-CTRL) --------------------------------------------------------- 2010-01-11 04:24:17,594 INFO [org.jboss.ha.framework.server.DistributedReplicantManagerImpl.lisa2000] [T:101] I am (10.199.12.134:1099) received membershipChanged event: 2010-01-11 04:24:17,594 INFO [org.jboss.ha.framework.server.DistributedReplicantManagerImpl.lisa2000] [T:101] Dead members: 0 ([]) 2010-01-11 04:24:17,594 INFO [org.jboss.ha.framework.server.DistributedReplicantManagerImpl.lisa2000] [T:101] New Members : 0 ([]) 2010-01-11 04:24:17,594 INFO [org.jboss.ha.framework.server.DistributedReplicantManagerImpl.lisa2000] [T:101] All Members : 2 ([10.199.12.135:1099, 10.199.12.134:1099]) 2010-01-11 04:24:17,601 INFO [STDOUT] [T:48740] --------------------------------------------------------- GMS: address is 10.199.12.134:32799 (cluster=lisa2000-HAPartitionCache) --------------------------------------------------------- 2010-01-11 04:24:17,601 INFO [org.jboss.messaging.core.impl.postoffice.GroupMember] [T:48742] org.jboss.messaging.core.impl.postoffice.GroupMember$ControlMembershipListener@429c429c g ot new view [10.199.12.135:32792|13] [10.199.12.135:32792, 10.199.12.134:32799], old view is [10.199.12.135:32792|11] [10.199.12.135:32792, 10.199.12.134:32797] 2010-01-11 04:24:17,601 INFO [org.jboss.messaging.core.impl.postoffice.GroupMember] [T:48742] I am (10.199.12.134:32799) 2010-01-11 04:24:17,609 INFO [org.jboss.cache.RPCManagerImpl] [T:48740] Received new cluster view: [10.199.12.135:32792|13] [10.199.12.135:32792, 10.199.12.134:32799] 2010-01-11 04:24:17,617 INFO [org.jboss.cache.statetransfer.LegacyStateTransferIntegrator] [T:48753] Using version 4096 2010-01-11 04:24:19,686 INFO [org.jboss.messaging.core.impl.postoffice.GroupMember] [T:48742] Dead members: 1 ([10.199.12.134:32797]) 2010-01-11 04:24:19,686 INFO [org.jboss.messaging.core.impl.postoffice.GroupMember] [T:48742] New Members : 1 ([10.199.12.134:32799]) 2010-01-11 04:24:19,686 INFO [org.jboss.messaging.core.impl.postoffice.GroupMember] [T:48742] All Members : 2 ([10.199.12.135:32792, 10.199.12.134:32799]) 2010-01-11 04:24:25,437 INFO [lisa.logistics.core.ejb.CommandExecutionBean] [T:782] Execute of ping takes 10 ms. 2010-01-11 04:24:28,705 ERROR [org.jboss.messaging.util.ExceptionUtil] [T:194] ConnectionEndpoint[l26-sy0xoa4g-1-qtygu64g-qp6dlm-q3cj5a] createSessionDelegate [t26-d91xoa4g-1-qtygu64g- qp6dlm-q3cj5a] java.lang.IllegalStateException: Cannot find binding for queue DLQ at org.jboss.jms.server.ServerPeer.getDefaultDLQInstance(ServerPeer.java:1254) at org.jboss.jms.server.endpoint.ServerSessionEndpoint.<init>(ServerSessionEndpoint.java:228) at org.jboss.jms.server.endpoint.ServerConnectionEndpoint.createSessionDelegate(ServerConnectionEndpoint.java:249) at org.jboss.jms.server.endpoint.advised.ConnectionAdvised.org$jboss$jms$server$endpoint$advised$ConnectionAdvised$createSessionDelegate$aop(ConnectionAdvised.java:75) at org.jboss.jms.server.endpoint.advised.ConnectionAdvised$createSessionDelegate_6052335267724906805.invokeTarget(ConnectionAdvised$createSessionDelegate_6052335267724906805.ja va) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:111) at org.jboss.jms.server.container.ServerLogInterceptor.invoke(ServerLogInterceptor.java:105) at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102) at org.jboss.jms.server.endpoint.advised.ConnectionAdvised.createSessionDelegate(ConnectionAdvised.java) at org.jboss.jms.wireformat.ConnectionCreateSessionDelegateRequest.serverInvoke(ConnectionCreateSessionDelegateRequest.java:87) at org.jboss.jms.server.remoting.JMSServerInvocationHandler.invoke(JMSServerInvocationHandler.java:143) at org.jboss.remoting.ServerInvoker.invoke(ServerInvoker.java:891) at org.jboss.remoting.transport.socket.ServerThread.completeInvocation(ServerThread.java:744) at org.jboss.remoting.transport.socket.ServerThread.processInvocation(ServerThread.java:697) at org.jboss.remoting.transport.socket.ServerThread.dorun(ServerThread.java:551) at org.jboss.remoting.transport.socket.ServerThread.run(ServerThread.java:232) output from node 2: 2010-01-11 04:24:15,618 INFO [org.jboss.ha.framework.interfaces.HAPartition.lifecycle.lisa2000] [T:46047] Suspected member: 10.199.12.134:32797 2010-01-11 04:24:15,680 INFO [org.jboss.ha.framework.interfaces.HAPartition.lifecycle.lisa2000] [T:89] New cluster view for partition lisa2000 (id: 10, delta: -1) : [10.199.1 2.135:1099] 2010-01-11 04:24:15,681 INFO [org.jboss.cache.RPCManagerImpl] [T:89] Received new cluster view: [10.199.12.135:32792|12] [10.199.12.135:32792] 2010-01-11 04:24:15,682 INFO [org.jboss.ha.framework.server.DistributedReplicantManagerImpl.lisa2000] [T:106] I am (10.199.12.135:1099) received membershipChanged event: 2010-01-11 04:24:15,682 INFO [org.jboss.ha.framework.server.DistributedReplicantManagerImpl.lisa2000] [T:106] Dead members: 1 ([10.199.12.134:1099]) 2010-01-11 04:24:15,682 INFO [org.jboss.messaging.core.impl.postoffice.GroupMember] [T:108] org.jboss.messaging.core.impl.postoffice.GroupMember$ControlMembershipListener@443 24432 got new view [10.199.12.135:32792|12] [10.199.12.135:32792], old view is [10.199.12.135:32792|11] [10.199.12.135:32792, 10.199.12.134:32797] 2010-01-11 04:24:15,682 INFO [org.jboss.messaging.core.impl.postoffice.GroupMember] [T:108] I am (10.199.12.135:32792) 2010-01-11 04:24:15,683 ERROR [org.jboss.messaging.core.impl.postoffice.GroupMember] [T:108] Caught Exception in MembershipListener java.lang.IllegalStateException: org.jboss.messaging.core.impl.postoffice.MessagingPostOffice@2b4e2b4e cannot find node ID for address 10.199.12.134:32797 at org.jboss.messaging.core.impl.postoffice.MessagingPostOffice.nodesLeft(MessagingPostOffice.java:942) at org.jboss.messaging.core.impl.postoffice.GroupMember$ControlMembershipListener.viewAccepted(GroupMember.java:508) at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.handleUpEvent(MessageDispatcher.java:733) at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:776) at org.jgroups.JChannel.up(JChannel.java:1336) at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:454) at org.jgroups.protocols.pbcast.FLUSH.up(FLUSH.java:435) at org.jgroups.protocols.pbcast.STATE_TRANSFER.up(STATE_TRANSFER.java:153) at org.jgroups.protocols.FRAG2.up(FRAG2.java:188) at org.jgroups.protocols.FC.up(FC.java:493) at org.jgroups.protocols.pbcast.GMS.installView(GMS.java:543) at org.jgroups.protocols.pbcast.CoordGmsImpl.handleViewChange(CoordGmsImpl.java:463) at org.jgroups.protocols.pbcast.GMS.up(GMS.java:749) at org.jgroups.protocols.VIEW_SYNC.up(VIEW_SYNC.java:192) at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:233) at org.jgroups.protocols.UNICAST.up(UNICAST.java:328) at org.jgroups.protocols.pbcast.NAKACK.handleMessage(NAKACK.java:895) at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:708) at org.jgroups.protocols.BARRIER.up(BARRIER.java:136) at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:167) at org.jgroups.protocols.FD.up(FD.java:284) at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:307) at org.jgroups.protocols.MERGE2.up(MERGE2.java:144) at org.jgroups.protocols.Discovery.up(Discovery.java:262) at org.jgroups.protocols.PING.up(PING.java:273) at org.jgroups.protocols.TP$ProtocolAdapter.up(TP.java:2315) at org.jgroups.protocols.TP.passMessageUp(TP.java:1249) at org.jgroups.protocols.TP.access$100(TP.java:49) at org.jgroups.protocols.TP$1.run(TP.java:1176) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:736) 2010-01-11 04:24:15,682 INFO [org.jboss.ha.framework.server.DistributedReplicantManagerImpl.lisa2000] [T:106] New Members : 0 ([]) 2010-01-11 04:24:15,683 INFO [org.jboss.ha.framework.server.DistributedReplicantManagerImpl.lisa2000] [T:106] All Members : 1 ([10.199.12.135:1099]) 2010-01-11 04:24:17,033 WARN [org.jgroups.protocols.pbcast.NAKACK] [T:46042] 10.199.12.135:32792] discarded message from non-member 10.199.12.134:32797, my view is [10.199.12 .135:32792|12] [10.199.12.135:32792] 2010-01-11 04:24:17,033 WARN [org.jgroups.protocols.pbcast.NAKACK] [T:46041] 10.199.12.135:32792] discarded message from non-member 10.199.12.134:32797, my view is [10.199.12 .135:32792|10] [10.199.12.135:32792] 2010-01-11 04:24:17,069 WARN [org.jgroups.protocols.pbcast.NAKACK] [T:46041] 10.199.12.135:32792] discarded message from non-member 10.199.12.134:32797, my view is [10.199.12 .135:32792|10] [10.199.12.135:32792] 2010-01-11 04:24:17,072 WARN [org.jgroups.protocols.pbcast.NAKACK] [T:45905] 10.199.12.135:7900] discarded message from non-member 10.199.12.134:7900, my view is [10.199.12.1 35:7900|10] [10.199.12.135:7900] 2010-01-11 04:24:17,589 INFO [org.jboss.ha.framework.interfaces.HAPartition.lifecycle.lisa2000] [T:103] New cluster view for partition lisa2000 (id: 11, delta: 1) : [10.199.1 2.135:1099, 10.199.12.134:1099] 2010-01-11 04:24:17,589 INFO [org.jboss.ha.framework.server.DistributedReplicantManagerImpl.lisa2000] [T:106] I am (10.199.12.135:1099) received membershipChanged event: 2010-01-11 04:24:17,589 INFO [org.jboss.ha.framework.server.DistributedReplicantManagerImpl.lisa2000] [T:106] Dead members: 0 ([]) 2010-01-11 04:24:17,589 INFO [org.jboss.ha.framework.server.DistributedReplicantManagerImpl.lisa2000] [T:106] New Members : 1 ([10.199.12.134:1099]) 2010-01-11 04:24:17,589 INFO [org.jboss.ha.framework.server.DistributedReplicantManagerImpl.lisa2000] [T:106] All Members : 2 ([10.199.12.135:1099, 10.199.12.134:1099]) 2010-01-11 04:24:17,597 INFO [org.jboss.messaging.core.impl.postoffice.GroupMember] [T:113] org.jboss.messaging.core.impl.postoffice.GroupMember$ControlMembershipListener@443 24432 got new view [10.199.12.135:32792|13] [10.199.12.135:32792, 10.199.12.134:32799], old view is [10.199.12.135:32792|12] [10.199.12.135:32792] 2010-01-11 04:24:17,597 INFO [org.jboss.messaging.core.impl.postoffice.GroupMember] [T:113] I am (10.199.12.135:32792) 2010-01-11 04:24:17,597 INFO [org.jboss.messaging.core.impl.postoffice.GroupMember] [T:113] New Members : 1 ([10.199.12.134:32799]) 2010-01-11 04:24:17,597 INFO [org.jboss.messaging.core.impl.postoffice.GroupMember] [T:113] All Members : 2 ([10.199.12.135:32792, 10.199.12.134:32799]) 2010-01-11 04:24:17,607 INFO [org.jboss.cache.RPCManagerImpl] [T:99] Received new cluster view: [10.199.12.135:32792|13] [10.199.12.135:32792, 10.199.12.134:32799] 2010-01-11 04:24:19,609 WARN [org.jgroups.protocols.pbcast.GMS] [T:46052] 10.199.12.135:32792 failed to collect all ACKs (1) for unicasted view [10.199.12.135:32792|13] [10.1 99.12.135:32792, 10.199.12.134:32799] after 2000ms, missing ACKs from [10.199.12.134:32799], local_addr=10.199.12.135:32792 2010-01-11 04:24:19,611 ERROR [org.jboss.messaging.core.impl.postoffice.UnbindRequest] [T:875] Failed to remove binding java.lang.IllegalStateException: Don't know about node id: 1 at org.jboss.messaging.core.impl.postoffice.MessagingPostOffice.removeBindingFromCluster(MessagingPostOffice.java:1079) at org.jboss.messaging.core.impl.postoffice.UnbindRequest.execute(UnbindRequest.java:61) at org.jboss.messaging.core.impl.postoffice.GroupMember$ControlRequestHandler.handle(GroupMember.java:622) at org.jgroups.blocks.MessageDispatcher.handle(MessageDispatcher.java:616) at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:637) at org.jgroups.blocks.RequestCorrelator$Request.run(RequestCorrelator.java:944) at org.jgroups.util.ReusableThread.run(ReusableThread.java:220) at java.lang.Thread.run(Thread.java:736) 2010-01-11 04:24:19,611 ERROR [org.jboss.messaging.core.impl.postoffice.GroupMember] [T:875] Caught Exception in RequestHandler java.lang.Exception: Failed to remove binding at org.jboss.messaging.core.impl.postoffice.UnbindRequest.execute(UnbindRequest.java:67) at org.jboss.messaging.core.impl.postoffice.GroupMember$ControlRequestHandler.handle(GroupMember.java:622) at org.jgroups.blocks.MessageDispatcher.handle(MessageDispatcher.java:616) at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:637) at org.jgroups.blocks.RequestCorrelator$Request.run(RequestCorrelator.java:944) at org.jgroups.util.ReusableThread.run(ReusableThread.java:220) at java.lang.Thread.run(Thread.java:736) Caused by: java.lang.IllegalStateException: Don't know about node id: 1 at org.jboss.messaging.core.impl.postoffice.MessagingPostOffice.removeBindingFromCluster(MessagingPostOffice.java:1079) at org.jboss.messaging.core.impl.postoffice.UnbindRequest.execute(UnbindRequest.java:61) ... 6 more 2010-01-11 04:24:19,611 ERROR [org.jgroups.blocks.RequestCorrelator] [T:875] error invoking method java.lang.IllegalStateException: Failed to remove binding at org.jboss.messaging.core.impl.postoffice.UnbindRequest.execute(UnbindRequest.java:67) at org.jboss.messaging.core.impl.postoffice.GroupMember$ControlRequestHandler.handle(GroupMember.java:622) at org.jgroups.blocks.MessageDispatcher.handle(MessageDispatcher.java:616) at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:637) at org.jgroups.blocks.RequestCorrelator$Request.run(RequestCorrelator.java:944) at org.jgroups.util.ReusableThread.run(ReusableThread.java:220) at java.lang.Thread.run(Thread.java:736) 2010-01-11 04:24:19,622 ERROR [org.jboss.messaging.core.impl.postoffice.UnbindRequest] [T:875] Failed to remove binding java.lang.IllegalStateException: Don't know about node id: 1 at org.jboss.messaging.core.impl.postoffice.MessagingPostOffice.removeBindingFromCluster(MessagingPostOffice.java:1079) at org.jboss.messaging.core.impl.postoffice.UnbindRequest.execute(UnbindRequest.java:61) at org.jboss.messaging.core.impl.postoffice.GroupMember$ControlRequestHandler.handle(GroupMember.java:622) at org.jgroups.blocks.MessageDispatcher.handle(MessageDispatcher.java:616) at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:637) at org.jgroups.blocks.RequestCorrelator$Request.run(RequestCorrelator.java:944) at org.jgroups.util.ReusableThread.run(ReusableThread.java:220) at java.lang.Thread.run(Thread.java:736) 2010-01-11 04:24:19,623 ERROR [org.jboss.messaging.core.impl.postoffice.GroupMember] [T:875] Caught Exception in RequestHandler java.lang.Exception: Failed to remove binding at org.jboss.messaging.core.impl.postoffice.UnbindRequest.execute(UnbindRequest.java:67) at org.jboss.messaging.core.impl.postoffice.GroupMember$ControlRequestHandler.handle(GroupMember.java:622) at org.jgroups.blocks.MessageDispatcher.handle(MessageDispatcher.java:616) at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:637) at org.jgroups.blocks.RequestCorrelator$Request.run(RequestCorrelator.java:944) at org.jgroups.util.ReusableThread.run(ReusableThread.java:220) at java.lang.Thread.run(Thread.java:736) Caused by: java.lang.IllegalStateException: Don't know about node id: 1 at org.jboss.messaging.core.impl.postoffice.MessagingPostOffice.removeBindingFromCluster(MessagingPostOffice.java:1079) at org.jboss.messaging.core.impl.postoffice.UnbindRequest.execute(UnbindRequest.java:61) ... 6 more 2010-01-11 04:24:19,623 ERROR [org.jgroups.blocks.RequestCorrelator] [T:875] error invoking method java.lang.IllegalStateException: Failed to remove binding at org.jboss.messaging.core.impl.postoffice.UnbindRequest.execute(UnbindRequest.java:67) at org.jboss.messaging.core.impl.postoffice.GroupMember$ControlRequestHandler.handle(GroupMember.java:622) at org.jgroups.blocks.MessageDispatcher.handle(MessageDispatcher.java:616) at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:637) at org.jgroups.blocks.RequestCorrelator$Request.run(RequestCorrelator.java:944) at org.jgroups.util.ReusableThread.run(ReusableThread.java:220) at java.lang.Thread.run(Thread.java:736) 2010-01-11 04:24:23,881 WARN [org.jgroups.protocols.pbcast.NAKACK] [T:46065] 10.199.12.135:7900] discarded message from non-member 10.199.12.134:7900, my view is [10.199.12.1 35:7900|10] [10.199.12.135:7900] 2010-01-11 04:24:32,813 WARN [org.jgroups.protocols.pbcast.NAKACK] [T:46065] 10.199.12.135:7900] discarded message from non-member 10.199.12.134:7900, my view is [10.199.12.1 35:7900|10] [10.199.12.135:7900] 2010-01-11 04:24:33,501 WARN [org.jgroups.protocols.pbcast.NAKACK] [T:46065] 10.199.12.135:7900] discarded message from non-member 10.199.12.134:7900, my view is [10.199.12.1 35:7900|10] [10.199.12.135:7900] 2010-01-11 04:24:45,201 WARN [org.jgroups.protocols.pbcast.NAKACK] [T:46069] 10.199.12.135:7900] discarded message from non-member 10.199.12.134:7900, my view is [10.199.12.1 35:7900|10] [10.199.12.135:7900] 2010-01-11 04:24:53,645 ERROR [org.jgroups.blocks.ConnectionTable] [T:171] failed sending data to 10.199.12.134:7900: java.net.SocketException: Socket closed