3 Replies Latest reply on Sep 25, 2008 9:07 PM by niefeng

    Initial state transfer failed: Channel.getState() returned f

    niefeng
    niefeng Sep 25, 2008 8:28 PM

      We have a cluster with two nodes (JBOSS4.0.5 CP10) deployed in Solaris 10 with JRE150_10 Sparc edition. We found the following error when the second node being started up. Below is the console msg we found in the 2nd node. We are puzzle why the cluster initial can form properly, however when the 2nd node tryng to get the state from the Main node, it failed to do that and leave the group "StgGtasPartition4"

      2008-09-25 20:10:55,970 INFO [FRAG2] frag_size=60000, overhead=0, new frag_size=60000
2008-09-25 20:10:56,121 INFO [UDP] unicast sockets will use interface 150.105.49.84
2008-09-25 20:10:56,129 INFO [UDP] socket information:
local_addr=lsgridtalkp02:56637, mcast_addr=228.1.3.88:45577, bind_addr=/150.105.49.84, ttl=2
sock: bound to 150.105.49.84:56637, receive buffer size=2097152, send buffer size=640000
mcast_recv_sock: bound to 150.105.49.84:45577, send buffer size=640000, receive buffer size=2097152
mcast_send_sock: bound to 150.105.49.84:56638, send buffer size=640000, receive buffer size=2097152
2008-09-25 20:10:56,130 INFO [STDOUT]
-------------------------------------------------------
GMS: address is lsgridtalkp02:56637
-------------------------------------------------------
2008-09-25 20:10:58,447 INFO [TreeCache] viewAccepted(): [lsgridtalkp01:54552|3] [lsgridtalkp01:54552, lsgridtalkp02:56637]
2008-09-25 20:10:58,451 INFO [TreeCache] TreeCache local address is lsgridtalkp02:56637
2008-09-25 20:11:06,647 INFO [TreeCache] received the state (size=1024 bytes)
2008-09-25 20:11:06,708 INFO [TreeCache] state was retrieved successfully (in 8255 milliseconds)
2008-09-25 20:11:06,709 INFO [TreeCache] parseConfig(): PojoCacheConfig is empty
2008-09-25 20:11:07,815 INFO [StgGtasPartition4] Initializing
2008-09-25 20:11:07,986 INFO [UDP] unicast sockets will use interface 150.105.49.84
2008-09-25 20:11:07,990 INFO [UDP] socket information:
local_addr=lsgridtalkp02:56651 (additional data: 19 bytes), mcast_addr=228.1.3.88:45566, bind_addr=/150.105.49.84, ttl=8
sock: bound to 150.105.49.84:56651, receive buffer size=2000000, send buffer size=640000
mcast_recv_sock: bound to 150.105.49.84:45566, send buffer size=640000, receive buffer size=2000000
mcast_send_sock: bound to 150.105.49.84:56652, send buffer size=640000, receive buffer size=2000000
2008-09-25 20:11:07,992 INFO [STDOUT]
-------------------------------------------------------
GMS: address is lsgridtalkp02:56651 (additional data: 19 bytes)
-------------------------------------------------------
2008-09-25 20:11:10,493 INFO [StgGtasPartition4] Number of cluster members: 2
2008-09-25 20:11:10,494 INFO [StgGtasPartition4] New cluster view for partition StgGtasPartition4: 3 ([150.105.49.79:31099, 150.105.49.84:31099] delta: 0)
2008-09-25 20:11:10,494 INFO [StgGtasPartition4] Other members: 1
2008-09-25 20:11:10,495 INFO [StgGtasPartition4] Fetching state (will wait for 30000 milliseconds):
2008-09-25 20:11:56,732 WARN [ServiceController] Problem starting service jboss:service=StgGtasPartition4
java.lang.IllegalStateException: Initial state transfer failed: Channel.getState() returned false
 at org.jboss.ha.framework.server.HAPartitionImpl.fetchState(HAPartitionImpl.java:351)
 at org.jboss.ha.framework.server.HAPartitionImpl.startPartition(HAPartitionImpl.java:280)
 at org.jboss.ha.framework.server.ClusterPartition.startService(ClusterPartition.java:341)


      We have tried to increase the time for waiting to 60s, the same error still occured. The following show the "cluster-service.xml" 

      <mbean code="org.jboss.ha.framework.server.ClusterPartition"
 name="jboss:service=${jboss.partition.name:DefaultPartition}">

 <!-- Name of the partition being built -->
 <attribute name="PartitionName">${jboss.partition.name:DefaultPartition}</attribute>

 <!-- The address used to determine the node name -->
 <attribute name="NodeAddress">${jboss.bind.address}</attribute>

 <!-- Determine if deadlock detection is enabled -->
 <attribute name="DeadlockDetection">False</attribute>

 <!-- Max time (in ms) to wait for state transfer to complete. Increase for large states -->
 <attribute name="StateTransferTimeout">30000</attribute>

 <!-- The JGroups protocol configuration -->
 <attribute name="PartitionConfig">
 <!--
 The default UDP stack:
 - If you have a multihomed machine, set the UDP protocol's bind_addr attribute to the
 appropriate NIC IP address, e.g bind_addr="192.168.0.2".
 - On Windows machines, because of the media sense feature being broken with multicast
 (even after disabling media sense) set the UDP protocol's loopback attribute to true
 -->
 <Config>
 <UDP mcast_addr="${jboss.partition.udpGroup:228.1.2.3}" mcast_port="45566"
 ip_ttl="${jgroups.mcast.ip_ttl:8}" ip_mcast="true"
 mcast_recv_buf_size="2000000" mcast_send_buf_size="640000"
 ucast_recv_buf_size="2000000" ucast_send_buf_size="640000"
 loopback="false" bind_addr="150.105.49.79"/>
 <PING timeout="2000" num_initial_members="3"
 up_thread="true" down_thread="true"/>
 <MERGE2 min_interval="10000" max_interval="20000"/>
 <FD_SOCK down_thread="false" up_thread="false"/>
 <FD shun="true" up_thread="true" down_thread="true"
 timeout="10000" max_tries="5"/>
 <VERIFY_SUSPECT timeout="3000" num_msgs="3"
 up_thread="true" down_thread="true"/>
 <pbcast.NAKACK gc_lag="50" retransmit_timeout="300,600,1200,2400,4800"
 max_xmit_size="8192"
 up_thread="true" down_thread="true"/>
 <UNICAST timeout="300,600,1200,2400,4800" window_size="100" min_threshold="10"
 down_thread="true"/>
 <pbcast.STABLE desired_avg_gossip="20000" max_bytes="400000"
 up_thread="true" down_thread="true"/>
 <FRAG frag_size="8192"
 down_thread="true" up_thread="true"/>
 <pbcast.GMS join_timeout="5000" join_retry_timeout="2000"
 shun="true" print_local_addr="true"/>
 <pbcast.STATE_TRANSFER up_thread="true" down_thread="true"/>
 </Config>
 </attribute>
 <depends>jboss:service=Naming</depends>
 </mbean>


      the following post show the DEBUG stack trace from Main node and 2nd node when the 2nd node is being started up

      • 2988 Views
      • Tags:
        • 1. Re: Initial state transfer failed: Channel.getState() return
          niefeng
          niefeng Sep 25, 2008 8:48 PM (in response to niefeng)

          The following DEBUG message is from 2nd node. It has tried to send the "sending are-you-alive msg" to the Main node; however eventually it still not able to join the group. The complete stack trace can be viewed here http://myspace2020.googlepages.com/2ndNode.log

          [25:09:08-19:45:12,803] [DEBUG:org.jboss.system.ServiceController] [main] Creating service jboss:service=StgGtasPartition4
[25:09:08-19:45:12,804] [DEBUG:org.jboss.ha.framework.server.ClusterPartition] [main] Creating jboss:service=StgGtasPartition4
[25:09:08-19:45:12,804] [DEBUG:org.jboss.ha.framework.server.ClusterPartition] [main] Creating JGroups JChannel
[25:09:08-19:45:12,823] [DEBUG:org.jgroups.protocols.AUTOCONF] [main] frag_size=64000
[25:09:08-19:45:12,848] [DEBUG:org.jgroups.protocols.pbcast.GMS] [main] changed role to org.jgroups.protocols.pbcast.ClientGmsImpl
[25:09:08-19:45:12,869] [DEBUG:org.jboss.ha.framework.server.ClusterPartition] [main] Creating HAPartition
[25:09:08-19:45:12,914] [DEBUG:org.jboss.ha.framework.server.ClusterPartition] [main] Initing HAPartition: org.jboss.ha.framework.server.HAPartitionImpl@160ce61
[25:09:08-19:45:12,915] [ INFO:org.jboss.ha.framework.interfaces.HAPartition.StgGtasPartition4] [main] Initializing
[25:09:08-19:45:12,916] [DEBUG:org.jboss.ha.framework.interfaces.HAPartition.StgGtasPartition4] [main] setMembershipListener
[25:09:08-19:45:12,917] [DEBUG:org.jboss.ha.framework.interfaces.HAPartition.StgGtasPartition4] [main] setMessageListener
[25:09:08-19:45:12,917] [DEBUG:org.jboss.ha.framework.interfaces.HAPartition.StgGtasPartition4] [main] create replicant manager
[25:09:08-19:45:12,958] [DEBUG:org.jboss.ha.framework.interfaces.HAPartition.StgGtasPartition4] [main] init replicant manager
[25:09:08-19:45:12,959] [DEBUG:org.jboss.ha.framework.server.DistributedReplicantManagerImpl.StgGtasPartition4] [main] registerRPCHandler
[25:09:08-19:45:12,959] [DEBUG:org.jboss.ha.framework.server.DistributedReplicantManagerImpl.StgGtasPartition4] [main] subscribeToStateTransferEvents
[25:09:08-19:45:12,960] [DEBUG:org.jboss.ha.framework.server.DistributedReplicantManagerImpl.StgGtasPartition4] [main] registerMembershipListener
[25:09:08-19:45:12,969] [DEBUG:org.jboss.ha.framework.interfaces.HAPartition.StgGtasPartition4] [main] bind replicant manager
[25:09:08-19:45:12,969] [DEBUG:org.jboss.ha.framework.interfaces.HAPartition.StgGtasPartition4] [main] create distributed state
[25:09:08-19:45:12,988] [DEBUG:org.jboss.ha.framework.interfaces.HAPartition.StgGtasPartition4] [main] init distributed state service
[25:09:08-19:45:12,995] [DEBUG:org.jboss.ha.framework.interfaces.HAPartition.StgGtasPartition4] [main] bind distributed state service
[25:09:08-19:45:13,004] [DEBUG:org.jboss.ha.framework.interfaces.HAPartition.StgGtasPartition4] [main] done initing.
[25:09:08-19:45:13,005] [DEBUG:org.jboss.ha.framework.server.ClusterPartition] [main] HAPartition initialized
[25:09:08-19:45:13,005] [DEBUG:org.jboss.ha.framework.server.ClusterPartition] [main] Created jboss:service=StgGtasPartition4
[25:09:08-19:45:13,007] [DEBUG:org.jboss.system.ServiceController] [main] Creating dependent components for: jboss:service=StgGtasPartition4 dependents are: [ObjectName: jboss:service=HASessionState
 State: CONFIGURED
 I Depend On:
 jboss:service=Naming
 jboss:service=StgGtasPartition4
, ObjectName: jboss:service=HAJNDI
 State: CONFIGURED
 I Depend On:
 jboss:service=StgGtasPartition4
 jboss.system:service=ThreadPool
, ObjectName: jboss.cache:service=InvalidationBridge,type=JavaGroups
 State: CONFIGURED
 I Depend On:
 jboss:service=StgGtasPartition4
 jboss.cache:service=InvalidationManager
]
[25:09:08-19:45:13,007] [DEBUG:org.jboss.system.ServiceController] [main] Creating service jboss:service=HASessionState
[25:09:08-19:45:13,008] [DEBUG:org.jboss.ha.hasessionstate.server.HASessionStateService] [main] Creating jboss:service=HASessionState
[25:09:08-19:45:13,037] [DEBUG:org.jboss.ha.hasessionstate.server.HASessionStateService] [main] Created jboss:service=HASessionState
[25:09:08-19:45:13,038] [DEBUG:org.jboss.system.ServiceController] [main] Creating dependent components for: jboss:service=HASessionState dependents are: []
[25:09:08-19:45:13,038] [DEBUG:org.jboss.system.ServiceController] [main] Creating service jboss:service=HAJNDI
[25:09:08-19:45:13,039] [DEBUG:org.jboss.ha.jndi.HANamingService] [main] Creating jboss:service=HAJNDI
[25:09:08-19:45:13,040] [DEBUG:org.jboss.ha.jndi.HANamingService] [main] Initializing HAJNDI server on partition: StgGtasPartition4
[25:09:08-19:45:13,057] [DEBUG:org.jboss.ha.jndi.HANamingService] [main] initialize HAJNDI
[25:09:08-19:45:13,058] [DEBUG:org.jboss.ha.jndi.HAJNDI] [main] subscribeToStateTransferEvents
[25:09:08-19:45:13,058] [DEBUG:org.jboss.ha.jndi.TreeHead] [main] registerRPCHandler
[25:09:08-19:45:13,060] [DEBUG:org.jboss.ha.jndi.HANamingService] [main] Created jboss:service=HAJNDI
[25:09:08-19:45:13,061] [DEBUG:org.jboss.system.ServiceController] [main] Creating dependent components for: jboss:service=HAJNDI dependents are: []
[25:09:08-19:45:13,061] [DEBUG:org.jboss.system.ServiceController] [main] Creating service jboss.cache:service=InvalidationBridge,type=JavaGroups
[25:09:08-19:45:13,062] [DEBUG:org.jboss.cache.invalidation.bridges.JGCacheInvalidationBridge] [main] Creating jboss.cache:service=InvalidationBridge,type=JavaGroups
[25:09:08-19:45:13,062] [DEBUG:org.jboss.cache.invalidation.bridges.JGCacheInvalidationBridge] [main] Created jboss.cache:service=InvalidationBridge,type=JavaGroups
[25:09:08-19:45:13,063] [DEBUG:org.jboss.system.ServiceController] [main] Creating dependent components for: jboss.cache:service=InvalidationBridge,type=JavaGroups dependents are: []
[25:09:08-19:45:13,064] [DEBUG:org.jboss.system.ServiceController] [main] Creating service jboss:service=HASessionState
[25:09:08-19:45:13,064] [DEBUG:org.jboss.system.ServiceController] [main] Ignoring create request for service: jboss:service=HASessionState
[25:09:08-19:45:13,065] [DEBUG:org.jboss.system.ServiceController] [main] Creating service jboss:service=HAJNDI
[25:09:08-19:45:13,065] [DEBUG:org.jboss.system.ServiceController] [main] Ignoring create request for service: jboss:service=HAJNDI
[25:09:08-19:45:13,066] [DEBUG:org.jboss.system.ServiceController] [main] Creating service jboss:service=invoker,type=jrmpha
[25:09:08-19:45:13,067] [DEBUG:org.jboss.invocation.jrmp.server.JRMPInvokerHA] [main] Creating jboss:service=invoker,type=jrmpha
[25:09:08-19:45:13,067] [DEBUG:org.jboss.invocation.jrmp.server.JRMPInvokerHA] [main] Created jboss:service=invoker,type=jrmpha
[25:09:08-19:45:13,068] [DEBUG:org.jboss.system.ServiceController] [main] Creating dependent components for: jboss:service=invoker,type=jrmpha dependents are: []
[25:09:08-19:45:13,069] [DEBUG:org.jboss.system.ServiceController] [main] Creating service jboss:service=invoker,type=pooledha
[25:09:08-19:45:13,070] [DEBUG:org.jboss.invocation.pooled.server.PooledInvokerHA] [main] Creating jboss:service=invoker,type=pooledha
[25:09:08-19:45:13,070] [DEBUG:org.jboss.invocation.pooled.server.PooledInvokerHA] [main] Created jboss:service=invoker,type=pooledha
[25:09:08-19:45:13,071] [DEBUG:org.jboss.system.ServiceController] [main] Creating dependent components for: jboss:service=invoker,type=pooledha dependents are: []
[25:09:08-19:45:13,071] [DEBUG:org.jboss.system.ServiceController] [main] Creating service jboss.cache:service=InvalidationBridge,type=JavaGroups
[25:09:08-19:45:13,072] [DEBUG:org.jboss.system.ServiceController] [main] Ignoring create request for service: jboss.cache:service=InvalidationBridge,type=JavaGroups
[25:09:08-19:45:13,073] [DEBUG:org.jboss.deployment.MainDeployer] [main] Done with create step of deploying cluster-service.xml
[25:09:08-19:45:13,073] [DEBUG:org.jboss.deployment.MainDeployer] [main] Begin deployment start file:/opt/local/GridTalk/jboss-4.0.5.GA/server/default/deploy/cluster-service.xml
[25:09:08-19:45:13,074] [DEBUG:org.jboss.deployment.SARDeployer] [main] Deploying SAR, start step: url file:/opt/local/GridTalk/jboss-4.0.5.GA/server/default/deploy/cluster-service.xml
[25:09:08-19:45:13,075] [DEBUG:org.jboss.system.ServiceController] [main] starting service jboss:service=StgGtasPartition4
[25:09:08-19:45:13,076] [DEBUG:org.jboss.ha.framework.server.ClusterPartition] [main] Starting jboss:service=StgGtasPartition4
[25:09:08-19:45:13,079] [DEBUG:org.jgroups.protocols.FRAG] [DownHandler (FRAG)] received CONFIG event: {additional_data=[B@155e0bc}
[25:09:08-19:45:13,080] [DEBUG:org.jgroups.protocols.UDP] [DownHandler (UDP)] received CONFIG event: {additional_data=[B@155e0bc}
[25:09:08-19:45:13,079] [DEBUG:org.jgroups.protocols.pbcast.NAKACK] [DownHandler (NAKACK)] received CONFIG event: {additional_data=[B@155e0bc}
[25:09:08-19:45:13,082] [DEBUG:org.jgroups.stack.ProtocolStack] [main] flushing took 3 msecs
[25:09:08-19:45:13,083] [DEBUG:org.jboss.ha.framework.server.ClusterPartition] [main] Starting ClusterPartition: StgGtasPartition4
[25:09:08-19:45:13,084] [DEBUG:org.jgroups.protocols.UDP] [DownHandler (UDP)] creating sockets and starting threads
[25:09:08-19:45:13,085] [ INFO:org.jgroups.protocols.UDP] [DownHandler (UDP)] unicast sockets will use interface 150.105.49.84
[25:09:08-19:45:13,088] [ INFO:org.jgroups.protocols.UDP] [DownHandler (UDP)] socket information:
local_addr=lsgridtalkp02:56070 (additional data: 19 bytes), mcast_addr=228.1.3.88:45566, bind_addr=/150.105.49.84, ttl=8
sock: bound to 150.105.49.84:56070, receive buffer size=2000000, send buffer size=640000
mcast_recv_sock: bound to 150.105.49.84:45566, send buffer size=640000, receive buffer size=2000000
mcast_send_sock: bound to 150.105.49.84:56071, send buffer size=640000, receive buffer size=2000000
[25:09:08-19:45:13,089] [DEBUG:org.jgroups.protocols.UDP] [DownHandler (UDP)] created unicast receiver thread
[25:09:08-19:45:13,094] [DEBUG:org.jgroups.protocols.FD_SOCK] [FD_SOCK Ping thread] determinePingDest()=null, pingable_mbrs=[]
[25:09:08-19:45:13,095] [DEBUG:org.jgroups.protocols.FD_SOCK] [FD_SOCK Ping thread] pinger thread terminated
[25:09:08-19:45:13,921] [DEBUG:org.jgroups.protocols.pbcast.STABLE] [UDP.IncomingPacketHandler thread] received digest lsgridtalkp01:54552#6 (6), lsgridtalkp02:56067#0 (-1) from lsgridtalkp01:54552
[25:09:08-19:45:13,922] [DEBUG:org.jgroups.protocols.pbcast.STABLE] [UDP.IncomingPacketHandler thread] already received gossip from lsgridtalkp01:54552
[25:09:08-19:45:15,096] [DEBUG:org.jgroups.protocols.PING] [DownHandler (PING)] initial mbrs are [[own_addr=lsgridtalkp01:54555 (additional data: 19 bytes), coord_addr=lsgridtalkp01:54555 (additional data: 19 bytes)]]
[25:09:08-19:45:15,097] [DEBUG:org.jgroups.protocols.pbcast.ClientGmsImpl] [DownHandler (GMS)] initial_mbrs are [[own_addr=lsgridtalkp01:54555 (additional data: 19 bytes), coord_addr=lsgridtalkp01:54555 (additional data: 19 bytes)]]
[25:09:08-19:45:15,097] [DEBUG:org.jgroups.protocols.pbcast.ClientGmsImpl] [DownHandler (GMS)] sending handleJoin(lsgridtalkp02:56070 (additional data: 19 bytes)) to lsgridtalkp01:54555 (additional data: 19 bytes)
[25:09:08-19:45:15,098] [DEBUG:org.jgroups.protocols.pbcast.STABLE] [DownHandler (STABLE)] stable task started; num_gossip_runs=3, max_gossip_runs=3
[25:09:08-19:45:15,099] [DEBUG:org.jgroups.stack.AckSenderWindow] [DownHandler (UNICAST)] window_size=100, min_threshold=10
[25:09:08-19:45:15,110] [DEBUG:org.jgroups.protocols.pbcast.NAKACK] [UpHandler (NAKACK)] message was discarded (not yet server)
[25:09:08-19:45:15,111] [DEBUG:org.jgroups.protocols.pbcast.ClientGmsImpl] [DownHandler (GMS)] digest is [lsgridtalkp01:54555 (additional data: 19 bytes): [0 : 7, lsgridtalkp02:56070 (additional data: 19 bytes): [0 : 0]
[25:09:08-19:45:15,112] [DEBUG:org.jgroups.protocols.pbcast.ClientGmsImpl] [DownHandler (GMS)] [lsgridtalkp02:56070 (additional data: 19 bytes)]: JoinRsp=[lsgridtalkp01:54555 (additional data: 19 bytes)|1] [lsgridtalkp01:54555 (additional data: 19 bytes), lsgridtalkp02:56070 (additional data: 19 bytes)] 


[25:09:08-19:45:15,113] [DEBUG:org.jgroups.protocols.pbcast.ClientGmsImpl] [DownHandler (GMS)] new_view=[lsgridtalkp01:54555 (additional data: 19 bytes)|1] [lsgridtalkp01:54555 (additional data: 19 bytes), lsgridtalkp02:56070 (additional data: 19 bytes)]
 [25:09:08-19:45:15,113] [DEBUG:org.jgroups.protocols.pbcast.GMS] [DownHandler (GMS)] [local_addr=lsgridtalkp02:56070 (additional data: 19 bytes)] view is [lsgridtalkp01:54555 (additional data: 19 bytes)|1] [lsgridtalkp01:54555 (additional data: 19 bytes), lsgridtalkp02:56070 (additional data: 19 bytes)]
 [25:09:08-19:45:15,114] [DEBUG:org.jboss.ha.framework.server.ClusterPartition] [main] Starting channel
 [25:09:08-19:45:15,114] [DEBUG:org.jgroups.protocols.pbcast.STABLE] [DownHandler (STABLE)] stable task started; num_gossip_runs=3, max_gossip_runs=3
 [25:09:08-19:45:15,115] [DEBUG:org.jgroups.protocols.pbcast.GMS] [DownHandler (GMS)] lsgridtalkp02:56070 (additional data: 19 bytes) changed role to org.jgroups.protocols.pbcast.ParticipantGmsImpl
 [25:09:08-19:45:15,115] [DEBUG:org.jgroups.protocols.FD] [DownHandler (FD)] suspected_mbrs: [], after adjustment: [], stopped: true
 [25:09:08-19:45:15,115] [DEBUG:org.jboss.ha.framework.interfaces.HAPartition.StgGtasPartition4] [main] get nodeName
 [25:09:08-19:45:15,117] [DEBUG:org.jgroups.protocols.FD_SOCK] [DownHandler (FD)] VIEW_CHANGE received: [lsgridtalkp01:54555 (additional data: 19 bytes), lsgridtalkp02:56070 (additional data: 19 bytes)]
 [25:09:08-19:45:15,120] [DEBUG:org.jboss.ha.framework.interfaces.HAPartition.StgGtasPartition4] [main] Get current members
 [25:09:08-19:45:15,121] [ INFO:org.jboss.ha.framework.interfaces.HAPartition.StgGtasPartition4] [main] Number of cluster members: 2
 [25:09:08-19:45:15,122] [ INFO:org.jboss.ha.framework.interfaces.HAPartition.StgGtasPartition4] [MessageDispatcher up processing thread] New cluster view for partition StgGtasPartition4: 1 ([150.105.49.79:31099, 150.105.49.84:31099] delta: 0)
 [25:09:08-19:45:15,122] [ INFO:org.jboss.ha.framework.interfaces.HAPartition.StgGtasPartition4] [main] Other members: 1
 [25:09:08-19:45:15,123] [DEBUG:org.jgroups.protocols.FD_SOCK] [DownHandler (FD)] got cache from lsgridtalkp01:54555 (additional data: 19 bytes): cache is {lsgridtalkp01:54555 (additional data: 19 bytes)=lsgridtalkp01:49153}
 [25:09:08-19:45:15,123] [ INFO:org.jboss.ha.framework.interfaces.HAPartition.StgGtasPartition4] [main] Fetching state (will wait for 30000 milliseconds):
 [25:09:08-19:45:15,124] [DEBUG:org.jgroups.protocols.FD_SOCK] [FD_SOCK Ping thread] determinePingDest()=lsgridtalkp01:54555 (additional data: 19 bytes), pingable_mbrs=[lsgridtalkp01:54555 (additional data: 19 bytes), lsgridtalkp02:56070 (additional data: 19 bytes)]
 [25:09:08-19:45:15,125] [DEBUG:org.jgroups.protocols.pbcast.STATE_TRANSFER] [DownHandler (STATE_TRANSFER)] GET_STATE: asking lsgridtalkp01:54555 (additional data: 19 bytes) for state
 [25:09:08-19:45:15,125] [DEBUG:org.jgroups.protocols.FD_SOCK] [UpHandler (PING)] i-have-sock: lsgridtalkp02:56070 (additional data: 19 bytes) --> lsgridtalkp02:49153 (cache is {lsgridtalkp02:56070 (additional data: 19 bytes)=lsgridtalkp02:49153, lsgridtalkp01:54555 (additional data: 19 bytes)=lsgridtalkp01:49153})
 [25:09:08-19:45:15,126] [DEBUG:org.jgroups.protocols.pbcast.STATE_TRANSFER] [DownHandler (STATE_TRANSFER)] passing down a SUSPEND_STABLE event
 [25:09:08-19:45:15,127] [DEBUG:org.jgroups.protocols.pbcast.STABLE] [DownHandler (STABLE)] suspending message garbage collection
 [25:09:08-19:45:15,128] [DEBUG:org.jgroups.protocols.FD_SOCK] [FD_SOCK Ping thread] ping_dest=lsgridtalkp01:54555 (additional data: 19 bytes), ping_sock=Socket[addr=lsgridtalkp01.itlogon.com/150.105.49.79,port=49153,localport=55359], cache={lsgridtalkp02:56070 (additional data: 19 bytes)=lsgridtalkp02:49153, lsgridtalkp01:54555 (additional data: 19 bytes)=lsgridtalkp01:49153}
 [25:09:08-19:45:15,128] [DEBUG:org.jboss.ha.framework.interfaces.HAPartition.StgGtasPartition4] [MessageDispatcher up processing thread] membership changed from 2 to 2
 [25:09:08-19:45:15,128] [DEBUG:org.jgroups.protocols.pbcast.STABLE] [DownHandler (STABLE)] stable task started; num_gossip_runs=3, max_gossip_runs=3
 [25:09:08-19:45:25,125] [DEBUG:org.jgroups.protocols.FD] [TimeScheduler.Thread] sending are-you-alive msg to lsgridtalkp01:54555 (additional data: 19 bytes) (own address=lsgridtalkp02:56070 (additional data: 19 bytes))
 [25:09:08-19:45:25,128] [DEBUG:org.jgroups.protocols.FD] [UpHandler (FD)] received ack from lsgridtalkp01:54555 (additional data: 19 bytes)
 [25:09:08-19:45:31,692] [DEBUG:org.jgroups.protocols.UDP] [TimeScheduler.Thread]
 sending msgs:
 lsgridtalkp01:54552: 1 msgs

 [25:09:08-19:45:31,693] [DEBUG:org.jgroups.protocols.FD] [TimeScheduler.Thread] sending are-you-alive msg to lsgridtalkp01:54552 (own address=lsgridtalkp02:56067)
 [25:09:08-19:45:31,732] [DEBUG:org.jgroups.protocols.UDP] [TimeScheduler.Thread]
 sending msgs:
 lsgridtalkp01:54552: 1 msgs

 [25:09:08-19:45:31,775] [DEBUG:org.jgroups.protocols.FD] [UDP.IncomingPacketHandler thread] received ack from lsgridtalkp01:54552
 [25:09:08-19:45:35,126] [DEBUG:org.jgroups.protocols.FD] [TimeScheduler.Thread] sending are-you-alive msg to lsgridtalkp01:54555 (additional data: 19 bytes) (own address=lsgridtalkp02:56070 (additional data: 19 bytes))
 [25:09:08-19:45:35,130] [DEBUG:org.jgroups.protocols.FD] [UpHandler (FD)] received ack from lsgridtalkp01:54555 (additional data: 19 bytes)
 [25:09:08-19:45:45,127] [DEBUG:org.jgroups.protocols.FD] [TimeScheduler.Thread] sending are-you-alive msg to lsgridtalkp01:54555 (additional data: 19 bytes) (own address=lsgridtalkp02:56070 (additional data: 19 bytes))
 [25:09:08-19:45:45,127] [DEBUG:org.jboss.ha.framework.server.ClusterPartition] [main] Caught exception after channel connected; closing channel -- Initial state transfer failed: Channel.getState() returned false
 [25:09:08-19:45:45,129] [DEBUG:org.jgroups.protocols.pbcast.ParticipantGmsImpl] [DownHandler (GMS)] sending LEAVE request to lsgridtalkp01:54555 (additional data: 19 bytes)
 [25:09:08-19:45:45,130] [DEBUG:org.jgroups.protocols.FD] [UpHandler (FD)] received ack from lsgridtalkp01:54555 (additional data: 19 bytes)
 [25:09:08-19:45:45,138] [DEBUG:org.jgroups.protocols.pbcast.ParticipantGmsImpl] [UpHandler (GMS)] view=[lsgridtalkp01:54555 (additional data: 19 bytes)|2] [lsgridtalkp01:54555 (additional data: 19 bytes)]
 [25:09:08-19:45:50,132] [DEBUG:org.jgroups.protocols.pbcast.ParticipantGmsImpl] [DownHandler (GMS)] sending LEAVE request to lsgridtalkp01:54555 (additional data: 19 bytes)
 [25:09:08-19:45:51,693] [DEBUG:org.jgroups.protocols.FD] [TimeScheduler.Thread] sending are-you-alive msg to lsgridtalkp01:54552 (own address=lsgridtalkp02:56067)
 [25:09:08-19:45:51,713] [DEBUG:org.jgroups.protocols.UDP] [TimeScheduler.Thread]
 sending msgs:
 lsgridtalkp01:54552: 2 msgs

 [25:09:08-19:45:51,756] [DEBUG:org.jgroups.protocols.FD] [UDP.IncomingPacketHandler thread] received ack from lsgridtalkp01:54552
 [25:09:08-19:45:54,026] [DEBUG:org.jgroups.protocols.pbcast.STABLE] [TimeScheduler.Thread] stable task will not run as suspended=true
 [25:09:08-19:45:55,127] [DEBUG:org.jgroups.protocols.FD] [TimeScheduler.Thread] sending are-you-alive msg to lsgridtalkp01:54555 (additional data: 19 bytes) (own address=lsgridtalkp02:56070 (additional data: 19 bytes))
 [25:09:08-19:45:55,131] [DEBUG:org.jgroups.protocols.FD] [UpHandler (FD)] received ack from lsgridtalkp01:54555 (additional data: 19 bytes)
 [25:09:08-19:45:55,137] [DEBUG:org.jgroups.protocols.pbcast.ParticipantGmsImpl] [DownHandler (GMS)] sending LEAVE request to lsgridtalkp01:54555 (additional data: 19 bytes)
 [25:09:08-19:45:55,762] [DEBUG:org.jgroups.protocols.pbcast.STABLE] [TimeScheduler.Thread] mcasting digest [lsgridtalkp01:54552: [7 : 7 (7)], lsgridtalkp02:56067: [0 : 0] (num_gossip_runs=3, max_gossip_runs=3)
 [25:09:08-19:45:55,797] [DEBUG:org.jgroups.protocols.UDP] [TimeScheduler.Thread]
 sending msgs:
 228.1.3.88:45577: 1 msgs

 [25:09:08-19:45:55,801] [DEBUG:org.jgroups.protocols.pbcast.STABLE] [UDP.IncomingPacketHandler thread] received digest lsgridtalkp01:54552#7 (7), lsgridtalkp02:56067#0 (-1) from lsgridtalkp02:56067
 [25:09:08-19:45:56,555] [DEBUG:org.jgroups.protocols.pbcast.STABLE] [UDP.IncomingPacketHandler thread] stability vector is [lsgridtalkp01:54552#6, lsgridtalkp02:56067#0]
 [25:09:08-19:45:56,556] [DEBUG:org.jgroups.protocols.pbcast.NAKACK] [UDP.IncomingPacketHandler thread] received digest [lsgridtalkp01:54552: [-1 : 6 (7)], lsgridtalkp02:56067: [-1 : 0]
 [25:09:08-19:46:00,142] [DEBUG:org.jgroups.protocols.pbcast.GMS] [DownHandler (GMS)] lsgridtalkp02:56070 (additional data: 19 bytes) changed role to org.jgroups.protocols.pbcast.ClientGmsImpl
 [25:09:08-19:46:00,143] [DEBUG:org.jgroups.protocols.pbcast.GMS] [DownHandler (GMS)] lsgridtalkp02:56070 (additional data: 19 bytes) changed role to org.jgroups.protocols.pbcast.ClientGmsImpl
 [25:09:08-19:46:00,145] [DEBUG:org.jgroups.protocols.FD_SOCK] [FD_SOCK Ping thread] socket to lsgridtalkp01:54555 (additional data: 19 bytes) was reset
 [25:09:08-19:46:00,148] [DEBUG:org.jgroups.protocols.FD_SOCK] [FD_SOCK Ping thread] pinger thread terminated
 [25:09:08-19:46:00,148] [DEBUG:org.jgroups.protocols.UDP] [DownHandler (UDP)] closing sockets and stopping threads
 [25:09:08-19:46:00,149] [DEBUG:org.jgroups.protocols.UDP] [UDP mcast receiver] multicast thread terminated
 [25:09:08-19:46:00,454] [DEBUG:org.jgroups.protocols.UDP] [DownHandler (UDP)] multicast receive socket closed
 [25:09:08-19:46:00,454] [DEBUG:org.jgroups.protocols.UDP] [DownHandler (UDP)] multicast send socket closed
 [25:09:08-19:46:00,455] [DEBUG:org.jgroups.protocols.UDP] [DownHandler (UDP)] socket closed


            • Actions
          • 2. Re: Initial state transfer failed: Channel.getState() return
            niefeng
            niefeng Sep 25, 2008 9:01 PM (in response to niefeng)

            The following showed the DEBUG log message from Main node when the second node is being started up. Look at those highlighted in Bold (starting from time [25:09:08-19:45:15,121] till [25:09:08-19:45:15,132], it look like the Main node is receiving the state request from 2nd node, and preparing it and return to 2nd node; However 2nd node never receive such state info. We are wondering could it due to the configuration setting problem?

            The complete stack trace can be viewed under http://myspace2020.googlepages.com/MainNode.log

            [25:09:08-19:45:11,483] [DEBUG:org.jgroups.protocols.pbcast.GMS] [UDP.IncomingPacketHandler thread] mbr=lsgridtalkp02:56067
[25:09:08-19:45:11,483] [DEBUG:org.jgroups.protocols.pbcast.CoordGmsImpl] [UDP.IncomingPacketHandler thread] mbr=lsgridtalkp02:56067
[25:09:08-19:45:11,484] [DEBUG:org.jgroups.protocols.pbcast.CoordGmsImpl] [UDP.IncomingPacketHandler thread] got digest=[lsgridtalkp01:54552: [5 : 6]
[25:09:08-19:45:11,485] [DEBUG:org.jgroups.protocols.pbcast.GMS] [UDP.IncomingPacketHandler thread] VID=1, current members=(lsgridtalkp01:54552), new_mbrs=(lsgridtalkp02:56067), old_mbrs=(), suspected_mbrs=()
[25:09:08-19:45:11,485] [DEBUG:org.jgroups.protocols.pbcast.GMS] [UDP.IncomingPacketHandler thread] new view is [lsgridtalkp01:54552|1] [lsgridtalkp01:54552, lsgridtalkp02:56067]
[25:09:08-19:45:11,486] [DEBUG:org.jgroups.protocols.pbcast.CoordGmsImpl] [UDP.IncomingPacketHandler thread] joined member lsgridtalkp02:56067, view is [lsgridtalkp01:54552|1] [lsgridtalkp01:54552, lsgridtalkp02:56067]
[25:09:08-19:45:11,487] [DEBUG:org.jgroups.protocols.pbcast.STABLE] [UDP.IncomingPacketHandler thread] stable task started; num_gossip_runs=3, max_gossip_runs=3
[25:09:08-19:45:11,510] [DEBUG:org.jgroups.protocols.UDP] [TimeScheduler.Thread]
sending msgs:
lsgridtalkp02:56067: 2 msgs

[25:09:08-19:45:11,513] [DEBUG:org.jgroups.protocols.pbcast.GMS] [UDP.IncomingPacketHandler thread] mcasting view {[lsgridtalkp01:54552|1] [lsgridtalkp01:54552, lsgridtalkp02:56067]} (2 mbrs)

[25:09:08-19:45:11,595] [DEBUG:org.jgroups.protocols.UDP] [TimeScheduler.Thread]
sending msgs:
228.1.3.88:45577: 1 msgs

[25:09:08-19:45:11,598] [DEBUG:org.jgroups.protocols.pbcast.CoordGmsImpl] [UDP.IncomingPacketHandler thread] view=[lsgridtalkp01:54552|1] [lsgridtalkp01:54552, lsgridtalkp02:56067]
[25:09:08-19:45:11,598] [DEBUG:org.jgroups.protocols.pbcast.GMS] [UDP.IncomingPacketHandler thread] [local_addr=lsgridtalkp01:54552] view is [lsgridtalkp01:54552|1] [lsgridtalkp01:54552, lsgridtalkp02:56067]
[25:09:08-19:45:11,598] [DEBUG:org.jgroups.protocols.pbcast.STABLE] [UDP.IncomingPacketHandler thread] stable task started; num_gossip_runs=3, max_gossip_runs=3
[25:09:08-19:45:11,599] [DEBUG:org.jgroups.protocols.FD] [UDP.IncomingPacketHandler thread] suspected_mbrs: [], after adjustment: [], stopped: true
[25:09:08-19:45:11,599] [DEBUG:org.jgroups.protocols.FD_SOCK] [UDP.IncomingPacketHandler thread] VIEW_CHANGE received: [lsgridtalkp01:54552, lsgridtalkp02:56067]
[25:09:08-19:45:11,600] [DEBUG:org.jgroups.protocols.FD_SOCK] [FD_SOCK Ping thread] determinePingDest()=lsgridtalkp02:56067, pingable_mbrs=[lsgridtalkp01:54552, lsgridtalkp02:56067]
[25:09:08-19:45:11,607] [ INFO:org.jboss.cache.TreeCache] [MessageDispatcher up processing thread] viewAccepted(): [lsgridtalkp01:54552|1] [lsgridtalkp01:54552, lsgridtalkp02:56067]
[25:09:08-19:45:11,670] [DEBUG:org.jgroups.protocols.UDP] [TimeScheduler.Thread]
sending msgs:
228.1.3.88:45577: 1 msgs

[25:09:08-19:45:11,713] [DEBUG:org.jgroups.protocols.FD_SOCK] [UDP.IncomingPacketHandler thread] i-have-sock: lsgridtalkp02:56067 --> lsgridtalkp02:49152 (cache is {lsgridtalkp02:56067=lsgridtalkp02:49152, lsgridtalkp01:54552=lsgridtalkp01:49152})
[25:09:08-19:45:11,716] [DEBUG:org.jgroups.protocols.pbcast.STATE_TRANSFER] [UDP.IncomingPacketHandler thread] passing down GET_DIGEST_STATE
[25:09:08-19:45:11,716] [DEBUG:org.jgroups.protocols.pbcast.STATE_TRANSFER] [UDP.IncomingPacketHandler thread] GET_DIGEST_STATE_OK: digest is [lsgridtalkp01:54552: [6 : 7, lsgridtalkp02:56067: [0 : 0]
passUp(GET_APPLSTATE)
[25:09:08-19:45:11,717] [ INFO:org.jboss.cache.TreeCache] [MessageDispatcher up processing thread] locking the subtree at / to transfer state
[25:09:08-19:45:11,750] [DEBUG:org.jgroups.protocols.UDP] [TimeScheduler.Thread]
sending msgs:
lsgridtalkp02:56067: 1 msgs

[25:09:08-19:45:11,751] [DEBUG:org.jboss.cache.statetransfer.StateTransferGenerator_140] [MessageDispatcher up processing thread] generated the in-memory state (97 bytes)
[25:09:08-19:45:11,752] [DEBUG:org.jboss.cache.statetransfer.StateTransferGenerator_140] [MessageDispatcher up processing thread] returning the associated state (4 bytes)
[25:09:08-19:45:11,752] [ INFO:org.jboss.cache.statetransfer.StateTransferGenerator_140] [MessageDispatcher up processing thread] returning the state for tree rooted in /(1024 bytes)
[25:09:08-19:45:11,790] [DEBUG:org.jgroups.protocols.UDP] [TimeScheduler.Thread]
sending msgs:
lsgridtalkp02:56067: 1 msgs

[25:09:08-19:45:11,919] [DEBUG:org.jgroups.protocols.FD_SOCK] [FD_SOCK Ping thread] ping_dest=lsgridtalkp02:56067, ping_sock=Socket[addr=lsgridtalkp02.itlogon.com/150.105.49.84,port=49152,localport=39719], cache={lsgridtalkp02:56067=lsgridtalkp02:49152, lsgridtalkp01:54552=lsgridtalkp01:49152}
[25:09:08-19:45:12,401] [DEBUG:org.jgroups.protocols.PING] [DownHandler (PING)] initial mbrs are [[own_addr=lsgridtalkp01:54555 (additional data: 19 bytes), coord_addr=lsgridtalkp01:54555 (additional data: 19 bytes)]]
[25:09:08-19:45:12,401] [DEBUG:org.jgroups.protocols.MERGE2] [MERGE2.FindSubgroups thread] initial_mbrs=[[own_addr=lsgridtalkp01:54555 (additional data: 19 bytes), coord_addr=lsgridtalkp01:54555 (additional data: 19 bytes)]]
[25:09:08-19:45:13,873] [DEBUG:org.jgroups.protocols.pbcast.STABLE] [TimeScheduler.Thread] mcasting digest [lsgridtalkp01:54552: [6 : 6 (6)], lsgridtalkp02:56067: [0 : 0] (num_gossip_runs=3, max_gossip_runs=3)
[25:09:08-19:45:13,912] [DEBUG:org.jgroups.protocols.UDP] [TimeScheduler.Thread]
sending msgs:
228.1.3.88:45577: 1 msgs

[25:09:08-19:45:13,914] [DEBUG:org.jgroups.protocols.pbcast.STABLE] [UDP.IncomingPacketHandler thread] received digest lsgridtalkp01:54552#6 (6), lsgridtalkp02:56067#0 (-1) from lsgridtalkp01:54552
[25:09:08-19:45:15,099] [DEBUG:org.jgroups.protocols.pbcast.GMS] [UpHandler (GMS)] mbr=lsgridtalkp02:56070 (additional data: 19 bytes)
[25:09:08-19:45:15,099] [DEBUG:org.jgroups.protocols.pbcast.STABLE] [UpHandler (STABLE)] stable task started; num_gossip_runs=3, max_gossip_runs=3
[25:09:08-19:45:15,099] [DEBUG:org.jgroups.protocols.pbcast.CoordGmsImpl] [UpHandler (GMS)] mbr=lsgridtalkp02:56070 (additional data: 19 bytes)
[25:09:08-19:45:15,100] [DEBUG:org.jgroups.protocols.pbcast.CoordGmsImpl] [UpHandler (GMS)] got digest=[lsgridtalkp01:54555 (additional data: 19 bytes): [0 : 6]
[25:09:08-19:45:15,101] [DEBUG:org.jgroups.protocols.pbcast.GMS] [UpHandler (GMS)] VID=1, current members=(lsgridtalkp01:54555 (additional data: 19 bytes)), new_mbrs=(lsgridtalkp02:56070 (additional data: 19 bytes)), old_mbrs=(), suspected_mbrs=()
[25:09:08-19:45:15,101] [DEBUG:org.jgroups.protocols.pbcast.GMS] [UpHandler (GMS)] new view is [lsgridtalkp01:54555 (additional data: 19 bytes)|1] [lsgridtalkp01:54555 (additional data: 19 bytes), lsgridtalkp02:56070 (additional data: 19 bytes)]
[25:09:08-19:45:15,102] [DEBUG:org.jgroups.protocols.pbcast.CoordGmsImpl] [UpHandler (GMS)] joined member lsgridtalkp02:56070 (additional data: 19 bytes), view is [lsgridtalkp01:54555 (additional data: 19 bytes)|1] [lsgridtalkp01:54555 (additional data: 19 bytes), lsgridtalkp02:56070 (additional data: 19 bytes)]
[25:09:08-19:45:15,102] [DEBUG:org.jgroups.protocols.pbcast.GMS] [UpHandler (GMS)] mcasting view {[lsgridtalkp01:54555 (additional data: 19 bytes)|1] [lsgridtalkp01:54555 (additional data: 19 bytes), lsgridtalkp02:56070 (additional data: 19 bytes)]} (2 mbrs)

[25:09:08-19:45:15,102] [DEBUG:org.jgroups.stack.AckSenderWindow] [DownHandler (UNICAST)] window_size=100, min_threshold=10
[25:09:08-19:45:15,105] [DEBUG:org.jgroups.protocols.pbcast.CoordGmsImpl] [UpHandler (GMS)] view=[lsgridtalkp01:54555 (additional data: 19 bytes)|1] [lsgridtalkp01:54555 (additional data: 19 bytes), lsgridtalkp02:56070 (additional data: 19 bytes)]
[25:09:08-19:45:15,106] [DEBUG:org.jgroups.protocols.pbcast.GMS] [UpHandler (GMS)] [local_addr=lsgridtalkp01:54555 (additional data: 19 bytes)] view is [lsgridtalkp01:54555 (additional data: 19 bytes)|1] [lsgridtalkp01:54555 (additional data: 19 bytes), lsgridtalkp02:56070 (additional data: 19 bytes)]
[25:09:08-19:45:15,106] [DEBUG:org.jgroups.protocols.pbcast.STABLE] [DownHandler (STABLE)] stable task started; num_gossip_runs=3, max_gossip_runs=3
[25:09:08-19:45:15,107] [DEBUG:org.jgroups.protocols.FD] [DownHandler (FD)] suspected_mbrs: [], after adjustment: [], stopped: true
[25:09:08-19:45:15,107] [DEBUG:org.jgroups.protocols.FD_SOCK] [DownHandler (FD)] VIEW_CHANGE received: [lsgridtalkp01:54555 (additional data: 19 bytes), lsgridtalkp02:56070 (additional data: 19 bytes)]
[25:09:08-19:45:15,107] [ INFO:org.jboss.ha.framework.interfaces.HAPartition.lifecycle.StgGtasPartition4] [MessageDispatcher up processing thread] New cluster view for partition StgGtasPartition4 (id: 1, delta: 1) : [150.105.49.79:31099, 150.105.49.84:31099]
[25:09:08-19:45:15,108] [DEBUG:org.jboss.ha.framework.interfaces.HAPartition.StgGtasPartition4] [MessageDispatcher up processing thread] membership changed from 2 to 2
[25:09:08-19:45:15,108] [DEBUG:org.jgroups.protocols.FD_SOCK] [FD_SOCK Ping thread] determinePingDest()=lsgridtalkp02:56070 (additional data: 19 bytes), pingable_mbrs=[lsgridtalkp01:54555 (additional data: 19 bytes), lsgridtalkp02:56070 (additional data: 19 bytes)]
[25:09:08-19:45:15,108] [DEBUG:org.jboss.ha.framework.interfaces.HAPartition.StgGtasPartition4] [AsynchViewChangeHandler Thread] Begin notifyListeners, viewID: 1
[25:09:08-19:45:15,109] [ INFO:org.jboss.ha.framework.server.DistributedReplicantManagerImpl.StgGtasPartition4] [AsynchViewChangeHandler Thread] I am (150.105.49.79:31099) received membershipChanged event:
[25:09:08-19:45:15,109] [ INFO:org.jboss.ha.framework.server.DistributedReplicantManagerImpl.StgGtasPartition4] [AsynchViewChangeHandler Thread] Dead members: 0 ([])
[25:09:08-19:45:15,109] [ INFO:org.jboss.ha.framework.server.DistributedReplicantManagerImpl.StgGtasPartition4] [AsynchViewChangeHandler Thread] New Members : 1 ([150.105.49.84:31099])
[25:09:08-19:45:15,110] [ INFO:org.jboss.ha.framework.server.DistributedReplicantManagerImpl.StgGtasPartition4] [AsynchViewChangeHandler Thread] All Members : 2 ([150.105.49.79:31099, 150.105.49.84:31099])
[25:09:08-19:45:15,110] [DEBUG:org.jboss.ha.framework.interfaces.HAPartition.StgGtasPartition4] [AsynchViewChangeHandler Thread] End notifyListeners, viewID: 1
[25:09:08-19:45:15,121] [DEBUG:org.jgroups.protocols.FD_SOCK] [UpHandler (PING)] i-have-sock: lsgridtalkp02:56070 (additional data: 19 bytes) --> lsgridtalkp02:49153 (cache is {lsgridtalkp02:56070 (additional data: 19 bytes)=lsgridtalkp02:49153, lsgridtalkp01:54555 (additional data: 19 bytes)=lsgridtalkp01:49153})
 [25:09:08-19:45:15,128] [DEBUG:org.jgroups.protocols.pbcast.STATE_TRANSFER] [UpHandler (STATE_TRANSFER)] passing down GET_DIGEST_STATE
 [25:09:08-19:45:15,129] [DEBUG:org.jgroups.protocols.pbcast.STATE_TRANSFER] [UpHandler (STATE_TRANSFER)] GET_DIGEST_STATE_OK: digest is [lsgridtalkp01:54555 (additional data: 19 bytes): [0 : 7, lsgridtalkp02:56070 (additional data: 19 bytes): [0 : 0]
 passUp(GET_APPLSTATE)
 [25:09:08-19:45:15,130] [DEBUG:org.jboss.ha.framework.interfaces.HAPartition.StgGtasPartition4] [MessageDispatcher up processing thread] getState called.
 [25:09:08-19:45:15,130] [DEBUG:org.jboss.ha.framework.interfaces.HAPartition.StgGtasPartition4] [MessageDispatcher up processing thread] getState for DistributedReplicantManager
 [25:09:08-19:45:15,131] [DEBUG:org.jboss.ha.framework.interfaces.HAPartition.StgGtasPartition4] [MessageDispatcher up processing thread] getState for HASessionStateTransfer
 [25:09:08-19:45:15,132] [DEBUG:org.jboss.ha.hasessionstate.server.HASessionStateImpl./HASessionState/Default] [MessageDispatcher up processing thread] Building and returning state of HASessionState
 [25:09:08-19:45:15,135] [DEBUG:org.jboss.ha.framework.interfaces.HAPartition.StgGtasPartition4] [MessageDispatcher up processing thread] getState for HAJNDI
 [25:09:08-19:45:15,135] [DEBUG:org.jboss.ha.framework.interfaces.HAPartition.StgGtasPartition4] [MessageDispatcher up processing thread] getState for DistributedState
 [25:09:08-19:45:15,423] [DEBUG:org.jgroups.protocols.FD_SOCK] [FD_SOCK Ping thread] ping_dest=lsgridtalkp02:56070 (additional data: 19 bytes), ping_sock=Socket[addr=lsgridtalkp02.itlogon.com/150.105.49.84,port=49153,localport=39720], cache={lsgridtalkp02:56070 (additional data: 19 bytes)=lsgridtalkp02:49153, lsgridtalkp01:54555 (additional data: 19 bytes)=lsgridtalkp01:49153}
[25:09:08-19:45:18,669] [DEBUG:org.jboss.web.tomcat.tc5.session.JBossCacheManager] [ContainerBackgroundProcessor[StandardEngine[jboss.web]]] Looking for sessions that have expired ...
[25:09:08-19:45:18,670] [DEBUG:org.jboss.web.tomcat.tc5.session.JBossCacheManager] [ContainerBackgroundProcessor[StandardEngine[jboss.web]]] Looking for sessions that have expired ...
[25:09:08-19:45:18,671] [DEBUG:org.jboss.web.tomcat.tc5.session.JBossCacheManager] [ContainerBackgroundProcessor[StandardEngine[jboss.web]]] Looking for sessions that have expired ...
[25:09:08-19:45:19,999] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] MBeanListener.handleNotification(), notification: javax.management.timer.TimerNotification[source=jboss:service=Timer][type=Schedule][message=Scheduler Notification]
[25:09:08-19:45:19,999] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] Scheduler is started: true
[25:09:08-19:45:20,000] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] MBean Arguments are: [Thu Sep 25 19:45:19 EDT 2008]
[25:09:08-19:45:20,000] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] MBean Arguments Types are: [java.util.Date]
[25:09:08-19:45:20,000] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] invoke(gtvan.httpbc:service=TxDeliveryService, processInTx
[25:09:08-19:45:20,036] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] Remaining Repititions: -1, wait for next call to stop: false
[25:09:08-19:45:20,036] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] MBeanListener.handleNotification(), notification: javax.management.timer.TimerNotification[source=jboss:service=Timer][type=Schedule][message=Scheduler Notification]
[25:09:08-19:45:20,037] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] Scheduler is started: true
[25:09:08-19:45:20,037] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] MBean Arguments are: [Thu Sep 25 19:45:19 EDT 2008]
[25:09:08-19:45:20,037] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] MBean Arguments Types are: [java.util.Date]
[25:09:08-19:45:20,037] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] invoke(gtvan.httpbc:service=TxDeliveryService, processOutTx
[25:09:08-19:45:20,071] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] Remaining Repititions: -1, wait for next call to stop: false
[25:09:08-19:45:24,874] [DEBUG:org.jgroups.protocols.PING] [DownHandler (PING)] initial mbrs are [[own_addr=lsgridtalkp01:54555 (additional data: 19 bytes), coord_addr=lsgridtalkp01:54555 (additional data: 19 bytes)], [own_addr=lsgridtalkp02:56070 (additional data: 19 bytes), coord_addr=lsgridtalkp01:54555 (additional data: 19 bytes)]]
[25:09:08-19:45:24,874] [DEBUG:org.jgroups.protocols.MERGE2] [MERGE2.FindSubgroups thread] initial_mbrs=[[own_addr=lsgridtalkp01:54555 (additional data: 19 bytes), coord_addr=lsgridtalkp01:54555 (additional data: 19 bytes)], [own_addr=lsgridtalkp02:56070 (additional data: 19 bytes), coord_addr=lsgridtalkp01:54555 (additional data: 19 bytes)]]
[25:09:08-19:45:25,116] [DEBUG:org.jgroups.protocols.FD] [TimeScheduler.Thread] sending are-you-alive msg to lsgridtalkp02:56070 (additional data: 19 bytes) (own address=lsgridtalkp01:54555 (additional data: 19 bytes))
[25:09:08-19:45:25,121] [DEBUG:org.jgroups.protocols.FD] [UpHandler (FD)] received ack from lsgridtalkp02:56070 (additional data: 19 bytes)
[25:09:08-19:45:27,697] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] MBeanListener.handleNotification(), notification: javax.management.timer.TimerNotification[source=jboss:service=Timer][type=Schedule][message=Scheduler Notification]
[25:09:08-19:45:27,697] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] Scheduler is started: true
[25:09:08-19:45:27,698] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] MBean Arguments are: [Thu Sep 25 19:45:27 EDT 2008]
[25:09:08-19:45:27,698] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] MBean Arguments Types are: [java.util.Date]
[25:09:08-19:45:27,698] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] invoke(gtvan.isat:service=ArchiveSchedulerService, invokeArchiveScheduler
[25:09:08-19:45:27,733] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] Remaining Repititions: -1, wait for next call to stop: false
[25:09:08-19:45:27,747] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] MBeanListener.handleNotification(), notification: javax.management.timer.TimerNotification[source=jboss:service=Timer][type=Schedule][message=Scheduler Notification]
[25:09:08-19:45:27,747] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] Scheduler is started: true
[25:09:08-19:45:27,747] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] MBean Arguments are: []
[25:09:08-19:45:27,747] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] MBean Arguments Types are: []
[25:09:08-19:45:27,748] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] invoke(gtvan.isat:service=ArchiveService, checkArchiveStatus
[25:09:08-19:45:27,854] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] Remaining Repititions: -1, wait for next call to stop: false
[25:09:08-19:45:28,679] [DEBUG:org.jboss.web.tomcat.tc5.session.JBossCacheManager] [ContainerBackgroundProcessor[StandardEngine[jboss.web]]] Looking for sessions that have expired ...
[25:09:08-19:45:28,680] [DEBUG:org.jboss.web.tomcat.tc5.session.JBossCacheManager] [ContainerBackgroundProcessor[StandardEngine[jboss.web]]] Looking for sessions that have expired ...
[25:09:08-19:45:28,682] [DEBUG:org.jboss.web.tomcat.tc5.session.JBossCacheManager] [ContainerBackgroundProcessor[StandardEngine[jboss.web]]] Looking for sessions that have expired ...
[25:09:08-19:45:29,999] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] MBeanListener.handleNotification(), notification: javax.management.timer.TimerNotification[source=jboss:service=Timer][type=Schedule][message=Scheduler Notification]
[25:09:08-19:45:29,999] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] Scheduler is started: true
[25:09:08-19:45:30,000] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] MBean Arguments are: [Thu Sep 25 19:45:29 EDT 2008]
[25:09:08-19:45:30,000] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] MBean Arguments Types are: [java.util.Date]
[25:09:08-19:45:30,000] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] invoke(gtvan.httpbc:service=TxDeliveryService, processInTx
[25:09:08-19:45:30,034] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] Remaining Repititions: -1, wait for next call to stop: false
[25:09:08-19:45:30,034] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] MBeanListener.handleNotification(), notification: javax.management.timer.TimerNotification[source=jboss:service=Timer][type=Schedule][message=Scheduler Notification]
[25:09:08-19:45:30,034] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] Scheduler is started: true
[25:09:08-19:45:30,035] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] MBean Arguments are: [Thu Sep 25 19:45:29 EDT 2008]
[25:09:08-19:45:30,035] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] MBean Arguments Types are: [java.util.Date]
[25:09:08-19:45:30,035] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] invoke(gtvan.httpbc:service=TxDeliveryService, processOutTx
[25:09:08-19:45:30,067] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] Remaining Repititions: -1, wait for next call to stop: false
[25:09:08-19:45:31,611] [DEBUG:org.jgroups.protocols.FD] [TimeScheduler.Thread] sending are-you-alive msg to lsgridtalkp02:56067 (own address=lsgridtalkp01:54552)
[25:09:08-19:45:31,651] [DEBUG:org.jgroups.protocols.UDP] [TimeScheduler.Thread]
sending msgs:
lsgridtalkp02:56067: 1 msgs

[25:09:08-19:45:31,691] [DEBUG:org.jgroups.protocols.FD] [UDP.IncomingPacketHandler thread] received ack from lsgridtalkp02:56067
[25:09:08-19:45:31,771] [DEBUG:org.jgroups.protocols.UDP] [TimeScheduler.Thread]
sending msgs:
lsgridtalkp02:56067: 1 msgs

[25:09:08-19:45:35,124] [DEBUG:org.jgroups.protocols.FD] [TimeScheduler.Thread] sending are-you-alive msg to lsgridtalkp02:56070 (additional data: 19 bytes) (own address=lsgridtalkp01:54555 (additional data: 19 bytes))
[25:09:08-19:45:35,127] [DEBUG:org.jgroups.protocols.FD] [UpHandler (FD)] received ack from lsgridtalkp02:56070 (additional data: 19 bytes)
[25:09:08-19:45:38,690] [DEBUG:org.jboss.web.tomcat.tc5.session.JBossCacheManager] [ContainerBackgroundProcessor[StandardEngine[jboss.web]]] Looking for sessions that have expired ...
[25:09:08-19:45:38,690] [DEBUG:org.jboss.web.tomcat.tc5.session.JBossCacheManager] [ContainerBackgroundProcessor[StandardEngine[jboss.web]]] Looking for sessions that have expired ...
[25:09:08-19:45:38,692] [DEBUG:org.jboss.web.tomcat.tc5.session.JBossCacheManager] [ContainerBackgroundProcessor[StandardEngine[jboss.web]]] Looking for sessions that have expired ...
[25:09:08-19:45:39,999] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] MBeanListener.handleNotification(), notification: javax.management.timer.TimerNotification[source=jboss:service=Timer][type=Schedule][message=Scheduler Notification]
[25:09:08-19:45:40,000] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] Scheduler is started: true
[25:09:08-19:45:40,000] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] MBean Arguments are: [Thu Sep 25 19:45:39 EDT 2008]
[25:09:08-19:45:40,001] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] MBean Arguments Types are: [java.util.Date]
[25:09:08-19:45:40,001] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] invoke(gtvan.httpbc:service=TxDeliveryService, processInTx
[25:09:08-19:45:40,036] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] Remaining Repititions: -1, wait for next call to stop: false
[25:09:08-19:45:40,037] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] MBeanListener.handleNotification(), notification: javax.management.timer.TimerNotification[source=jboss:service=Timer][type=Schedule][message=Scheduler Notification]
[25:09:08-19:45:40,037] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] Scheduler is started: true
[25:09:08-19:45:40,038] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] MBean Arguments are: [Thu Sep 25 19:45:39 EDT 2008]
[25:09:08-19:45:40,038] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] MBean Arguments Types are: [java.util.Date]
[25:09:08-19:45:40,038] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] invoke(gtvan.httpbc:service=TxDeliveryService, processOutTx
[25:09:08-19:45:40,071] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] Remaining Repititions: -1, wait for next call to stop: false
[25:09:08-19:45:40,870] [DEBUG:org.jgroups.protocols.PING] [DownHandler (PING)] initial mbrs are [[own_addr=lsgridtalkp01:54555 (additional data: 19 bytes), coord_addr=lsgridtalkp01:54555 (additional data: 19 bytes)], [own_addr=lsgridtalkp02:56070 (additional data: 19 bytes), coord_addr=lsgridtalkp01:54555 (additional data: 19 bytes)]]
[25:09:08-19:45:40,871] [DEBUG:org.jgroups.protocols.MERGE2] [MERGE2.FindSubgroups thread] initial_mbrs=[[own_addr=lsgridtalkp01:54555 (additional data: 19 bytes), coord_addr=lsgridtalkp01:54555 (additional data: 19 bytes)], [own_addr=lsgridtalkp02:56070 (additional data: 19 bytes), coord_addr=lsgridtalkp01:54555 (additional data: 19 bytes)]]
[25:09:08-19:45:45,125] [DEBUG:org.jgroups.protocols.FD] [TimeScheduler.Thread] sending are-you-alive msg to lsgridtalkp02:56070 (additional data: 19 bytes) (own address=lsgridtalkp01:54555 (additional data: 19 bytes))
[25:09:08-19:45:45,128] [DEBUG:org.jgroups.protocols.FD] [UpHandler (FD)] received ack from lsgridtalkp02:56070 (additional data: 19 bytes)
[25:09:08-19:45:45,129] [DEBUG:org.jgroups.protocols.pbcast.GMS] [UpHandler (GMS)] received LEAVE_REQ GmsHeader[LEAVE_REQ]: mbr=lsgridtalkp02:56070 (additional data: 19 bytes)
 from lsgridtalkp02:56070 (additional data: 19 bytes)
[25:09:08-19:45:45,129] [DEBUG:org.jgroups.protocols.pbcast.CoordGmsImpl] [UpHandler (GMS)] mbr=lsgridtalkp02:56070 (additional data: 19 bytes)
[25:09:08-19:45:45,129] [DEBUG:org.jgroups.protocols.pbcast.GMS] [UpHandler (GMS)] VID=2, current members=(lsgridtalkp01:54555 (additional data: 19 bytes), lsgridtalkp02:56070 (additional data: 19 bytes)), new_mbrs=(), old_mbrs=(lsgridtalkp02:56070 (additional data: 19 bytes)), suspected_mbrs=()
[25:09:08-19:45:45,130] [DEBUG:org.jgroups.protocols.pbcast.GMS] [UpHandler (GMS)] new view is [lsgridtalkp01:54555 (additional data: 19 bytes)|2] [lsgridtalkp01:54555 (additional data: 19 bytes)]
[25:09:08-19:45:45,130] [DEBUG:org.jgroups.protocols.pbcast.GMS] [UpHandler (GMS)] mcasting view {[lsgridtalkp01:54555 (additional data: 19 bytes)|2] [lsgridtalkp01:54555 (additional data: 19 bytes)]} (1 mbrs)

[25:09:08-19:45:45,134] [DEBUG:org.jgroups.protocols.pbcast.CoordGmsImpl] [UpHandler (GMS)] view=[lsgridtalkp01:54555 (additional data: 19 bytes)|2] [lsgridtalkp01:54555 (additional data: 19 bytes)]
[25:09:08-19:45:45,135] [DEBUG:org.jgroups.protocols.pbcast.GMS] [UpHandler (GMS)] [local_addr=lsgridtalkp01:54555 (additional data: 19 bytes)] view is [lsgridtalkp01:54555 (additional data: 19 bytes)|2] [lsgridtalkp01:54555 (additional data: 19 bytes)]
[25:09:08-19:45:45,136] [DEBUG:org.jgroups.protocols.FRAG] [DownHandler (FRAG)] [VIEW_CHANGE] removed lsgridtalkp02:56070 (additional data: 19 bytes) from fragmentation table
[25:09:08-19:45:45,136] [DEBUG:org.jgroups.protocols.pbcast.STABLE] [DownHandler (STABLE)] stable task started; num_gossip_runs=3, max_gossip_runs=3
[25:09:08-19:45:45,136] [ INFO:org.jboss.ha.framework.interfaces.HAPartition.lifecycle.StgGtasPartition4] [MessageDispatcher up processing thread] New cluster view for partition StgGtasPartition4 (id: 2, delta: -1) : [150.105.49.79:31099]
[25:09:08-19:45:45,137] [DEBUG:org.jgroups.protocols.UNICAST] [DownHandler (UNICAST)] removed lsgridtalkp02:56070 (additional data: 19 bytes) from connection table
[25:09:08-19:45:45,137] [DEBUG:org.jboss.ha.framework.interfaces.HAPartition.StgGtasPartition4] [MessageDispatcher up processing thread] dead members: [150.105.49.84:31099]
[25:09:08-19:45:45,137] [DEBUG:org.jgroups.protocols.pbcast.NAKACK] [DownHandler (NAKACK)] removing lsgridtalkp02:56070 (additional data: 19 bytes) from received_msgs (not member anymore)
[25:09:08-19:45:45,137] [DEBUG:org.jboss.ha.framework.interfaces.HAPartition.StgGtasPartition4] [MessageDispatcher up processing thread] membership changed from 1 to 1
[25:09:08-19:45:45,138] [DEBUG:org.jgroups.protocols.FD] [DownHandler (FD)] suspected_mbrs: [], after adjustment: [], stopped: true
[25:09:08-19:45:45,138] [DEBUG:org.jboss.ha.framework.interfaces.HAPartition.StgGtasPartition4] [AsynchViewChangeHandler Thread] Begin notifyListeners, viewID: 2
[25:09:08-19:45:45,138] [DEBUG:org.jgroups.protocols.FD_SOCK] [DownHandler (FD)] VIEW_CHANGE received: [lsgridtalkp01:54555 (additional data: 19 bytes)]
[25:09:08-19:45:45,139] [ INFO:org.jboss.ha.framework.server.DistributedReplicantManagerImpl.StgGtasPartition4] [AsynchViewChangeHandler Thread] I am (150.105.49.79:31099) received membershipChanged event:
[25:09:08-19:45:45,139] [ INFO:org.jboss.ha.framework.server.DistributedReplicantManagerImpl.StgGtasPartition4] [AsynchViewChangeHandler Thread] Dead members: 1 ([150.105.49.84:31099])
[25:09:08-19:45:45,140] [ INFO:org.jboss.ha.framework.server.DistributedReplicantManagerImpl.StgGtasPartition4] [AsynchViewChangeHandler Thread] New Members : 0 ([])
[25:09:08-19:45:45,140] [ INFO:org.jboss.ha.framework.server.DistributedReplicantManagerImpl.StgGtasPartition4] [AsynchViewChangeHandler Thread] All Members : 1 ([150.105.49.79:31099])
[25:09:08-19:45:45,140] [DEBUG:org.jgroups.protocols.FD_SOCK] [FD_SOCK Ping thread] socket to null was reset
[25:09:08-19:45:45,140] [DEBUG:org.jboss.ha.framework.server.DistributedReplicantManagerImpl.StgGtasPartition4] [AsynchViewChangeHandler Thread] purgeDeadMembers, [150.105.49.84:31099]
[25:09:08-19:45:45,140] [DEBUG:org.jgroups.protocols.FD_SOCK] [FD_SOCK Ping thread] pinger thread terminated
[25:09:08-19:45:45,141] [DEBUG:org.jboss.ha.framework.interfaces.HAPartition.StgGtasPartition4] [AsynchViewChangeHandler Thread] End notifyListeners, viewID: 2
[25:09:08-19:45:46,016] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] MBeanListener.handleNotification(), notification: javax.management.timer.TimerNotification[source=jboss:service=Timer][type=Schedule][message=Scheduler Notification]
[25:09:08-19:45:46,016] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] Scheduler is started: true
[25:09:08-19:45:46,017] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] MBean Arguments are: [Thu Sep 25 19:45:46 EDT 2008]
[25:09:08-19:45:46,017] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] MBean Arguments Types are: [java.util.Date]
[25:09:08-19:45:46,017] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] invoke(gtvan.genreport:service=ScheduleReportService, generateReport
[25:09:08-19:45:46,056] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] Remaining Repititions: -1, wait for next call to stop: false
[25:09:08-19:45:46,056] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] MBeanListener.handleNotification(), notification: javax.management.timer.TimerNotification[source=jboss:service=Timer][type=Schedule][message=Scheduler Notification]
[25:09:08-19:45:46,056] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] Scheduler is started: true
[25:09:08-19:45:46,057] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] MBean Arguments are: []
[25:09:08-19:45:46,057] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] MBean Arguments Types are: []
[25:09:08-19:45:46,057] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] invoke(gtvan.genreport:service=ScheduleReportService, deleteReport
[25:09:08-19:45:46,094] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] Remaining Repititions: -1, wait for next call to stop: false
[25:09:08-19:45:48,700] [DEBUG:org.jboss.web.tomcat.tc5.session.JBossCacheManager] [ContainerBackgroundProcessor[StandardEngine[jboss.web]]] Looking for sessions that have expired ...
[25:09:08-19:45:48,701] [DEBUG:org.jboss.web.tomcat.tc5.session.JBossCacheManager] [ContainerBackgroundProcessor[StandardEngine[jboss.web]]] Looking for sessions that have expired ...
[25:09:08-19:45:48,702] [DEBUG:org.jboss.web.tomcat.tc5.session.JBossCacheManager] [ContainerBackgroundProcessor[StandardEngine[jboss.web]]] Looking for sessions that have expired ...
[25:09:08-19:45:49,999] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] MBeanListener.handleNotification(), notification: javax.management.timer.TimerNotification[source=jboss:service=Timer][type=Schedule][message=Scheduler Notification]
[25:09:08-19:45:50,000] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] Scheduler is started: true
[25:09:08-19:45:50,000] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] MBean Arguments are: [Thu Sep 25 19:45:49 EDT 2008]
[25:09:08-19:45:50,001] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] MBean Arguments Types are: [java.util.Date]
[25:09:08-19:45:50,001] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] invoke(gtvan.httpbc:service=TxDeliveryService, processInTx
[25:09:08-19:45:50,035] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] Remaining Repititions: -1, wait for next call to stop: false
[25:09:08-19:45:50,035] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] MBeanListener.handleNotification(), notification: javax.management.timer.TimerNotification[source=jboss:service=Timer][type=Schedule][message=Scheduler Notification]
[25:09:08-19:45:50,036] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] Scheduler is started: true
[25:09:08-19:45:50,036] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] MBean Arguments are: [Thu Sep 25 19:45:49 EDT 2008]
[25:09:08-19:45:50,036] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] MBean Arguments Types are: [java.util.Date]
[25:09:08-19:45:50,037] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] invoke(gtvan.httpbc:service=TxDeliveryService, processOutTx
[25:09:08-19:45:50,070] [DEBUG:org.jboss.varia.scheduler.ScheduleManager$MBeanListener] [Timer-2] Remaining Repititions: -1, wait for next call to stop: false
[25:09:08-19:45:50,132] [ WARN:org.jgroups.protocols.UNICAST] [UpHandler (UNICAST)] [lsgridtalkp01:54555 (additional data: 19 bytes)] seqno 14 from lsgridtalkp02:56070 (additional data: 19 bytes) is not tagged as the first message sent by lsgridtalkp02:56070 (additional data: 19 bytes); however, the table for received messages from lsgridtalkp02:56070 (additional data: 19 bytes) is still null ! We probably haven't received the first message from lsgridtalkp02:56070 (additional data: 19 bytes) ! Discarding message (operational=true)
[25:09:08-19:45:51,621] [DEBUG:org.jgroups.protocols.FD] [TimeScheduler.Thread] sending are-you-alive msg to lsgridtalkp02:56067 (own address=lsgridtalkp01:54552)
[25:09:08-19:45:51,661] [DEBUG:org.jgroups.protocols.UDP] [TimeScheduler.Thread]
sending msgs:
lsgridtalkp02:56067: 1 msgs

[25:09:08-19:45:51,712] [DEBUG:org.jgroups.protocols.FD] [UDP.IncomingPacketHandler thread] received ack from lsgridtalkp02:56067
[25:09:08-19:45:51,751] [DEBUG:org.jgroups.protocols.UDP] [TimeScheduler.Thread]
sending msgs:
lsgridtalkp02:56067: 1 msgs

[25:09:08-19:45:55,136] [ WARN:org.jgroups.protocols.UNICAST] [UpHandler (UNICAST)] [lsgridtalkp01:54555 (additional data: 19 bytes)] seqno 15 from lsgridtalkp02:56070 (additional data: 19 bytes) is not tagged as the first message sent by lsgridtalkp02:56070 (additional data: 19 bytes); however, the table for received messages from lsgridtalkp02:56070 (additional data: 19 bytes) is still null ! We probably haven't received the first message from lsgridtalkp02:56070 (additional data: 19 bytes) ! Discarding message (operational=true)
[25:09:08-19:45:55,797] [DEBUG:org.jgroups.protocols.pbcast.STABLE] [UDP.IncomingPacketHandler thread] received digest lsgridtalkp01:54552#7 (7), lsgridtalkp02:56067#0 (-1) from lsgridtalkp02:56067
[25:09:08-19:45:55,797] [DEBUG:org.jgroups.protocols.pbcast.STABLE] [UDP.IncomingPacketHandler thread] sending stability msg lsgridtalkp01:54552#6 (7), lsgridtalkp02:56067#0 (-1)
[25:09:08-19:45:55,798] [DEBUG:org.jgroups.protocols.pbcast.STABLE] [UDP.IncomingPacketHandler thread] stability_task=null, delay is 701
[25:09:08-19:45:56,546] [DEBUG:org.jgroups.protocols.UDP] [TimeScheduler.Thread]
sending msgs:
228.1.3.88:45577: 1 msgs

[25:09:08-19:45:56,548] [DEBUG:org.jgroups.protocols.pbcast.STABLE] [UDP.IncomingPacketHandler thread] stability vector is [lsgridtalkp01:54552#6, lsgridtalkp02:56067#0]
[25:09:08-19:45:56,548] [DEBUG:org.jgroups.protocols.pbcast.STABLE] [UDP.IncomingPacketHandler thread] cancelling stability task (running=false)
[25:09:08-19:45:56,548] [DEBUG:org.jgroups.protocols.pbcast.NAKACK] [UDP.IncomingPacketHandler thread] received digest [lsgridtalkp01:54552: [-1 : 6 (7)], lsgridtalkp02:56067: [-1 : 0]
[25:09:08-19:45:57,377] [DEBUG:org.jboss.resource.connectionmanager.IdleRemover] [IdleRemover] run: IdleRemover notifying pools, interval: 60000
[25:09:08-19:45:57,582] [DEBUG:org.jboss.mq.il.uil2.SocketManager] [UIL2.SocketManager.WriteTask#467 client=150.105.49.79:39704] End WriteTask.run
[25:09:08-19:45:58,447] [ INFO:org.apache.log4j.net.SocketNode] [Thread-3] Caught java.io.IOException: java.io.WriteAbortedException: writing aborted; java.io.InterruptedIOException
[25:09:08-19:45:58,447] [ INFO:org.apache.log4j.net.SocketNode] [Thread-3] Closing connection.


              • Actions
            • 3. Re: Initial state transfer failed: Channel.getState() return
              niefeng
              niefeng Sep 25, 2008 9:07 PM (in response to niefeng)

              We have also tried to ensure that the UDP packet can flow through properly within the network. Below output of the testing of multicast and UDP port. Both server can communicate to each other.

              Can someone enlighten me what happen to the setup, could it be due to the network structure or the jboss AS configuration? Thanks for your help.

              --- From sender ---
java -cp jgroups.jar org.jgroups.tests.McastSenderTest -bind_addr 150.105.49.84 -mcast_addr 228.1.3.88 -port 45566
Socket=0.0.0.0/0.0.0.0:45566, ttl=32, bind interface=/150.105.49.84
> eragdfsghsdf
> << Received response from 150.105.49.79:45566: Hello from Bela
dsfgfsdgh
> << Received response from 150.105.49.79:45566: Hello from Bela
dfsgfsdhfsd
> << Received response from 150.105.49.79:45566: Hello from Bela
dsfgfsdhgsdf
> << Received response from 150.105.49.79:45566: Hello from Bela
dfsgsdfh
> << Received response from 150.105.49.79:45566: Hello from Bela
sdgasdfgasdf
> << Received response from 150.105.49.79:45566: Hello from Bela
sdfgsdfgh
> << Received response from 150.105.49.79:45566: Hello from Bela
dfsgsdfh
> << Received response from 150.105.49.79:45566: Hello from Bela
sdfghsdfhsdf
> << Received response from 150.105.49.79:45566: Hello from Bela
sdfhsdfhsdf
> << Received response from 150.105.49.79:45566: Hello from Bela
dsfhsdfh
> << Received response from 150.105.49.79:45566: Hello from Bela
dfshsdfhsdf
> << Received response from 150.105.49.79:45566: Hello from Bela
sdhgsdfhsdf
> << Received response from 150.105.49.79:45566: Hello from Bela
dssfhsdfh
> << Received response from 150.105.49.79:45566: Hello from Bela
dfshfsdhsdf
> << Received response from 150.105.49.79:45566: Hello from Bela
dsfhsdfhsdfh
> << Received response from 150.105.49.79:45566: Hello from Bela
dfshsdfhhgfsdhfdshsdf
> << Received response from 150.105.49.79:45566: Hello from Bela
dfshsdfh
> << Received response from 150.105.49.79:45566: Hello from Bela
dfshsdfhfsd
> << Received response from 150.105.49.79:45566: Hello from Bela
sdfhsfdhdsh
> << Received response from 150.105.49.79:45566: Hello from Bela
dsfhsdfhsdfhsdf
> << Received response from 150.105.49.79:45566: Hello from Bela
sdfhsfdhsdfhsdf
> << Received response from 150.105.49.79:45566: Hello from Bela
^Cawang@lsgridtalkp02 #


java -cp jgroups.jar org.jgroups.tests.McastReceiverTest -bind_addr 150.105.49.79 -mcast_addr 228.1.3.88 -port 45566
Socket=0.0.0.0/0.0.0.0:45566, bind interface=/150.105.49.79
pw‑UDPStgGtasPartition5 [sender=150.105.49.79:52429]
pw‑UDPStgGtasPartition5 [sender=150.105.49.79:52429]
pw‑UDPStgGtasPartition5 [sender=150.105.49.79:52429]
pw‑UDPStgGtasPartition5 [sender=150.105.49.79:52429]
pw‑UDPStgGtasPartition5 [sender=150.105.49.79:52429]
eragdfsghsdf [sender=150.105.49.84:45566]
dsfgfsdgh [sender=150.105.49.84:45566]
dfsgfsdhfsd [sender=150.105.49.84:45566]
dsfgfsdhgsdf [sender=150.105.49.84:45566]
dfsgsdfh [sender=150.105.49.84:45566]
sdgasdfgasdf [sender=150.105.49.84:45566]
sdfgsdfgh [sender=150.105.49.84:45566]
dfsgsdfh [sender=150.105.49.84:45566]
pw‑UDPStgGtasPartition5 [sender=150.105.49.79:52429]
sdfghsdfhsdf [sender=150.105.49.84:45566]
sdfhsdfhsdf [sender=150.105.49.84:45566]
dsfhsdfh [sender=150.105.49.84:45566]
dfshsdfhsdf [sender=150.105.49.84:45566]
sdhgsdfhsdf [sender=150.105.49.84:45566]
dssfhsdfh [sender=150.105.49.84:45566]
dfshfsdhsdf [sender=150.105.49.84:45566]
dsfhsdfhsdfh [sender=150.105.49.84:45566]
dfshsdfhhgfsdhfdshsdf [sender=150.105.49.84:45566]
dfshsdfh [sender=150.105.49.84:45566]
dfshsdfhfsd [sender=150.105.49.84:45566]
sdfhsfdhdsh [sender=150.105.49.84:45566]
dsfhsdfhsdfhsdf [sender=150.105.49.84:45566]
pw‑UDPStgGtasPartition5 [sender=150.105.49.79:52429]
sdfhsfdhsdfhsdf [sender=150.105.49.84:45566]
pw‑UDPStgGtasPartition5 [sender=150.105.49.79:52429]
pw‑UDPStgGtasPartition5 [sender=150.105.49.79:52429]


                • Actions