[jboss-dev-forums] [Design of Messaging on JBoss (Messaging/JBoss)] - Re: Changes on the JBM stack on JBoss5
clebert.suconic@jboss.com
do-not-reply at jboss.com
Fri Nov 7 12:33:07 EST 2008
We just got this log on hudson, after adding DEBUG on JGroups:
11:52:15,344 DEBUG @RMI TCP Connection(2)-10.18.1.111 [GMS] changed role to org.jgroups.protocols.pbcast.ClientGmsImpl
| 11:52:15,351 DEBUG @RMI TCP Connection(2)-10.18.1.111 [FRAG2] frag_size=60000, overhead=200, new frag_size=59800
| 11:52:15,367 DEBUG @RMI TCP Connection(2)-10.18.1.111 [FRAG2] received CONFIG event: {bind_addr=soa8.qa.atl2.redhat.com/10.18.1.111}
| 11:52:15,367 DEBUG @RMI TCP Connection(2)-10.18.1.111 [UDP] received CONFIG event: {bind_addr=soa8.qa.atl2.redhat.com/10.18.1.111}
| 11:52:15,369 INFO @RMI TCP Connection(2)-10.18.1.111 [JChannel] JGroups version: 2.6.5.GA
| 11:52:15,379 DEBUG @RMI TCP Connection(2)-10.18.1.111 [GMS] changed role to org.jgroups.protocols.pbcast.ClientGmsImpl
| 11:52:15,379 DEBUG @RMI TCP Connection(2)-10.18.1.111 [TCP] received CONFIG event: {bind_addr=soa8.qa.atl2.redhat.com/10.18.1.111}
| 11:52:15,394 DEBUG @RMI TCP Connection(2)-10.18.1.111 [ThreadPool] created a pool of 128 threads
| 11:52:15,395 DEBUG @RMI TCP Connection(2)-10.18.1.111 [UDP] received CONFIG event: {flush_supported=true}
| 11:52:15,395 DEBUG @RMI TCP Connection(2)-10.18.1.111 [FRAG2] received CONFIG event: {flush_supported=true}
| 11:52:15,399 DEBUG @RMI TCP Connection(2)-10.18.1.111 [UDP] creating sockets and starting threads
| 11:52:15,399 DEBUG @RMI TCP Connection(2)-10.18.1.111 [UDP] sockets will use interface 10.18.1.111
| 11:52:15,401 DEBUG @RMI TCP Connection(2)-10.18.1.111 [UDP] socket information:
| local_addr=10.18.1.111:38938, mcast_addr=228.11.11.11:45688, bind_addr=soa8.qa.atl2.redhat.com/10.18.1.111, ttl=2
| sock: bound to 10.18.1.111:38938, receive buffer size=131071, send buffer size=131071
| mcast_sock: bound to 10.18.1.111:45688, send buffer size=131071, receive buffer size=131071
| 11:52:15,406 DEBUG @RMI TCP Connection(2)-10.18.1.111 [UDP] created unicast receiver thread Thread[UDP ucast,10.18.1.111:38938,5,JGroups]
| 11:52:15,412 DEBUG @RMI TCP Connection(2)-10.18.1.111 [UDP] created multicast receiver thread Thread[UDP mcast,10.18.1.111:38938,10,JGroups]
| 11:52:15,420 DEBUG @RMI TCP Connection(2)-10.18.1.111 [GMS] initial_mbrs are [[own_addr=10.18.1.111:38936, coord_addr=10.18.1.111:38936, is_server=true]]
| 11:52:15,420 DEBUG @RMI TCP Connection(2)-10.18.1.111 [GMS] election results: {10.18.1.111:38936=1}
| 11:52:15,420 DEBUG @RMI TCP Connection(2)-10.18.1.111 [GMS] sending handleJoin(10.18.1.111:38938) to 10.18.1.111:38936
| 11:52:15,493 DEBUG @RMI TCP Connection(2)-10.18.1.111 [GMS] [10.18.1.111:38938]: JoinRsp=[10.18.1.111:38936|2] [10.18.1.111:38936, 10.18.1.111:38937, 10.18.1.111:38938]
|
|
| 11:52:15,494 DEBUG @RMI TCP Connection(2)-10.18.1.111 [GMS] new_view=[10.18.1.111:38936|2] [10.18.1.111:38936, 10.18.1.111:38937, 10.18.1.111:38938]
| 11:52:15,494 DEBUG @RMI TCP Connection(2)-10.18.1.111 [GMS] [local_addr=10.18.1.111:38938] view is [10.18.1.111:38936|2] [10.18.1.111:38936, 10.18.1.111:38937, 10.18.1.111:38938]
| 11:52:15,497 DEBUG @Timer-1,10.18.1.111:38938 [FD_SOCK] VIEW_CHANGE received: [10.18.1.111:38936, 10.18.1.111:38937, 10.18.1.111:38938]
| 11:52:15,499 DEBUG @FD_SOCK pinger,JBM_GRP1-CTRL,10.18.1.111:38938 [FD_SOCK] determinePingDest()=10.18.1.111:38936
| 11:52:15,500 DEBUG @FD_SOCK pinger,JBM_GRP1-CTRL,10.18.1.111:38938 [FD_SOCK] ping_dest=10.18.1.111:38936, ping_sock=Socket[addr=/10.18.1.111,port=51107,localport=37613], cache={10.18.1.111:38937=10.18.1.111:59241, 10.18.1.111:38938=10.18.1.111:55796, 10.18.1.111:38936=10.18.1.111:51107}
| 11:52:15,500 INFO @RMI TCP Connection(2)-10.18.1.111 [GroupMember] org.jboss.messaging.core.impl.postoffice.GroupMember$ControlMembershipListener at 425eb9 got new view [10.18.1.111:38936|2] [10.18.1.111:38936, 10.18.1.111:38937, 10.18.1.111:38938], old view is null
| 11:52:15,500 INFO @RMI TCP Connection(2)-10.18.1.111 [GroupMember] I am (10.18.1.111:38938)
| 11:52:15,500 DEBUG @RMI TCP Connection(2)-10.18.1.111 [MessagingPostOffice] org.jboss.messaging.core.impl.postoffice.MessagingPostOffice at e5f46e: 10.18.1.111:38936 joined
| 11:52:15,500 DEBUG @RMI TCP Connection(2)-10.18.1.111 [MessagingPostOffice] org.jboss.messaging.core.impl.postoffice.MessagingPostOffice at e5f46e: 10.18.1.111:38937 joined
| 11:52:15,501 DEBUG @RMI TCP Connection(2)-10.18.1.111 [MessagingPostOffice] org.jboss.messaging.core.impl.postoffice.MessagingPostOffice at e5f46e: 10.18.1.111:38938 joined
| 11:52:15,501 INFO @RMI TCP Connection(2)-10.18.1.111 [GroupMember] New Members : 3 ([10.18.1.111:38936, 10.18.1.111:38937, 10.18.1.111:38938])
| 11:52:15,501 INFO @RMI TCP Connection(2)-10.18.1.111 [GroupMember] All Members : 3 ([10.18.1.111:38936, 10.18.1.111:38937, 10.18.1.111:38938])
| 11:52:15,501 DEBUG @RMI TCP Connection(2)-10.18.1.111 [FLUSH] Installing view at 10.18.1.111:38938 view is [10.18.1.111:38936|2] [10.18.1.111:38936, 10.18.1.111:38937, 10.18.1.111:38938]
| 11:52:15,502 DEBUG @RMI TCP Connection(2)-10.18.1.111 [GMS] 10.18.1.111:38938 changed role to org.jgroups.protocols.pbcast.ParticipantGmsImpl
| 11:52:15,503 DEBUG @Incoming-4,10.18.1.111:38938 [FLUSH] At 10.18.1.111:38938 received STOP_FLUSH, unblocking FLUSH.down() and sending UNBLOCK up
| 11:52:15,504 DEBUG @RMI TCP Connection(2)-10.18.1.111 [FLUSH] Received Event[type=SUSPEND, arg=null] at 10.18.1.111:38938. Running FLUSH...
| 11:52:15,505 DEBUG @RMI TCP Connection(2)-10.18.1.111 [FLUSH] Flush coordinator 10.18.1.111:38938 is starting FLUSH with participants [10.18.1.111:38936, 10.18.1.111:38937, 10.18.1.111:38938]
| 11:52:15,506 DEBUG @Incoming-5,10.18.1.111:38938 [FLUSH] Received START_FLUSH at 10.18.1.111:38938 responded with FLUSH_COMPLETED to 10.18.1.111:38938
| 11:52:15,506 DEBUG @Incoming-7,10.18.1.111:38938 [FLUSH] At 10.18.1.111:38938 FLUSH_COMPLETED from 10.18.1.111:38938,completed false,flushCompleted [10.18.1.111:38938]
| 11:52:15,508 DEBUG @Incoming-8,10.18.1.111:38938 [FLUSH] At 10.18.1.111:38938 FLUSH_COMPLETED from 10.18.1.111:38936,completed false,flushCompleted [10.18.1.111:38936]
| 11:52:18,568 DEBUG @RMI TCP Connection(2)-10.18.1.111 [FLUSH] Retrying FLUSH at 10.18.1.111:38938. Attempts left 4
| 11:52:18,569 DEBUG @RMI TCP Connection(2)-10.18.1.111 [FLUSH] Flush coordinator 10.18.1.111:38938 is starting FLUSH with participants [10.18.1.111:38936, 10.18.1.111:38937, 10.18.1.111:38938]
| 11:52:18,569 DEBUG @Incoming-10,10.18.1.111:38938 [FLUSH] Rejecting flush at 10.18.1.111:38938, previous flush has to finish first
| 11:52:18,570 DEBUG @Incoming-10,10.18.1.111:38938 [FLUSH] Rejecting flush at 10.18.1.111:38938 to flush requester 10.18.1.111:38938 coordinator is null
| 11:52:18,572 DEBUG @Incoming-14,10.18.1.111:38938 [FLUSH] At 10.18.1.111:38938 FLUSH_COMPLETED from 10.18.1.111:38937,completed false,flushCompleted [10.18.1.111:38937]
| 11:52:21,501 DEBUG @Timer-7,10.18.1.111:38938 [FD] sending are-you-alive msg to 10.18.1.111:38936 (own address=10.18.1.111:38938)
| 11:52:21,631 DEBUG @RMI TCP Connection(2)-10.18.1.111 [FLUSH] Retrying FLUSH at 10.18.1.111:38938. Attempts left 3
| 11:52:21,632 DEBUG @RMI TCP Connection(2)-10.18.1.111 [FLUSH] Flush coordinator 10.18.1.111:38938 is starting FLUSH with participants [10.18.1.111:38936, 10.18.1.111:38937, 10.18.1.111:38938]
| 11:52:21,632 DEBUG @Incoming-15,10.18.1.111:38938 [FLUSH] Rejecting flush at 10.18.1.111:38938, previous flush has to finish first
| 11:52:21,632 DEBUG @Incoming-15,10.18.1.111:38938 [FLUSH] Rejecting flush at 10.18.1.111:38938 to flush requester 10.18.1.111:38938 coordinator is null
| 11:52:24,694 DEBUG @RMI TCP Connection(2)-10.18.1.111 [FLUSH] Retrying FLUSH at 10.18.1.111:38938. Attempts left 2
| 11:52:24,695 DEBUG @RMI TCP Connection(2)-10.18.1.111 [FLUSH] Flush coordinator 10.18.1.111:38938 is starting FLUSH with participants [10.18.1.111:38936, 10.18.1.111:38937, 10.18.1.111:38938]
| 11:52:24,695 DEBUG @Incoming-20,10.18.1.111:38938 [FLUSH] Rejecting flush at 10.18.1.111:38938, previous flush has to finish first
| 11:52:24,695 DEBUG @Incoming-20,10.18.1.111:38938 [FLUSH] Rejecting flush at 10.18.1.111:38938 to flush requester 10.18.1.111:38938 coordinator is null
| 11:52:27,504 DEBUG @Timer-12,10.18.1.111:38938 [FD] sending are-you-alive msg to 10.18.1.111:38936 (own address=10.18.1.111:38938)
| 11:52:27,758 DEBUG @RMI TCP Connection(2)-10.18.1.111 [FLUSH] Retrying FLUSH at 10.18.1.111:38938. Attempts left 1
| 11:52:27,758 DEBUG @RMI TCP Connection(2)-10.18.1.111 [FLUSH] Flush coordinator 10.18.1.111:38938 is starting FLUSH with participants [10.18.1.111:38936, 10.18.1.111:38937, 10.18.1.111:38938]
| 11:52:27,759 DEBUG @Incoming-6,10.18.1.111:38938 [FLUSH] Rejecting flush at 10.18.1.111:38938, previous flush has to finish first
| 11:52:27,759 DEBUG @Incoming-6,10.18.1.111:38938 [FLUSH] Rejecting flush at 10.18.1.111:38938 to flush requester 10.18.1.111:38938 coordinator is null
| 11:52:27,761 ERROR @RMI TCP Connection(2)-10.18.1.111 [ExceptionUtil] org.jboss.messaging.core.jmx.MessagingPostOfficeService at 2d59a3 startService
| java.lang.IllegalStateException: Could not flush the cluster and proceed with state retrieaval
| at org.jgroups.JChannel.getState(JChannel.java:1041)
| at org.jgroups.JChannel.getState(JChannel.java:973)
| at org.jgroups.JChannel.getState(JChannel.java:927)
| at org.jboss.messaging.core.impl.postoffice.GroupMember.start(GroupMember.java:152)
| at org.jboss.messaging.core.impl.postoffice.MessagingPostOffice.start(MessagingPostOffice.java:357)
| at org.jboss.messaging.core.jmx.MessagingPostOfficeService.startService(MessagingPostOfficeService.java:456)
| at org.jboss.system.ServiceMBeanSupport.jbossInternalStart(ServiceMBeanSupport.java:289)
| at org.jboss.system.ServiceMBeanSupport.start(ServiceMBeanSupport.java:196)
| at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
| at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
| at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
| at java.lang.reflect.Method.invoke(Method.java:585)
| at org.jboss.mx.interceptor.ReflectedDispatcher.invoke(ReflectedDispatcher.java:155)
| at org.jboss.mx.server.Invocation.dispatch(Invocation.java:94)
| at org.jboss.mx.interceptor.AbstractInterceptor.invoke(AbstractInterceptor.java:133)
| at org.jboss.mx.server.Invocation.invoke(Invocation.java:88)
| at org.jboss.mx.interceptor.ModelMBeanOperationInterceptor.invoke(ModelMBeanOperationInterceptor.java:142)
| at org.jboss.mx.server.Invocation.invoke(Invocation.java:88)
| at org.jboss.mx.server.AbstractMBeanInvoker.invoke(AbstractMBeanInvoker.java:264)
| at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:659)
| at org.jboss.test.messaging.tools.container.ServiceContainer.invoke(ServiceContainer.java:712)
| at org.jboss.test.messaging.tools.container.LocalTestServer.startServerPeer(LocalTestServer.java:349)
| at org.jboss.test.messaging.tools.container.LocalTestServer.start(LocalTestServer.java:137)
| at org.jboss.test.messaging.tools.container.RMITestServer.start(RMITestServer.java:146)
| at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
| at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
| at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
| at java.lang.reflect.Method.invoke(Method.java:585)
| at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:294)
| at sun.rmi.transport.Transport$1.run(Transport.java:153)
| at java.security.AccessController.doPrivileged(Native Method)
| at sun.rmi.transport.Transport.serviceCall(Transport.java:149)
| at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:466)
| at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:707)
| at java.lang.Thread.run(Thread.java:595)
View the original post : http://www.jboss.com/index.html?module=bb&op=viewtopic&p=4187788#4187788
Reply to the post : http://www.jboss.com/index.html?module=bb&op=posting&mode=reply&p=4187788
More information about the jboss-dev-forums
mailing list