Need helps with initial state transfer in production
jiafan1 Apr 11, 2008 3:28 PMHi,
We have four production machines running as a cluster and we use JBoss Cache version 1.4.0 as data cache (In memory Tree cache only and no cache loader). The application worked fine. 2 days ago, our infrastructure people patched one of the production machine (10.128.0.114) for PCI compliance (The changes are basically securing the server by enforcing passwords of a certain length and changing the service accounts to only be suable and not logging in directly). After that, the JBoss Cache cannot join the existing cluster with the following exception:
Invocation of init method failed; nested e xception is org.jboss.cache.CacheException: Initial state transfer failed: Channel.getState() returned false Caused by: org.jboss.cache.CacheException: Initial state transfer failed: Channel.getState() returned false at org.jboss.cache.TreeCache.fetchStateOnStartup(TreeCache.java:3191) at org.jboss.cache.TreeCache.startService(TreeCache.java:1429) at com.jtv.core.resource.impl.spring.cache.JBossCacheManagerFactoryBean.createCache(JBossCacheManagerFactoryBean.java :102) at com.jtv.core.resource.impl.spring.cache.JBossCacheManagerFactoryBean.afterPropertiesSet(JBossCacheManagerFactoryBe an.java:112) at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCap ableBeanFactory.java:1198) at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapabl eBeanFactory.java:1167) at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBea nFactory.java:427)
The exception may not really related to the patch. We changed the log level to debug for JBoss Cache and JGroup and found the new node (10.128.0.114) responsed to replicate requests during the initial state transfer, which sounds really wired since the new node should not react to any replicate requests until the tree cache service starts. Also, not sure after the replication procedure, the node resumed state transfer or re-started state transfer and why the lock on the new node did not take effect. We doubled the initial start timeout limit but got the same result. Seems to us the new node lost the lock for the cache during the initial state transfer state and was interrupted by the replication requests and finally led to timeout and failed. Really appreciate any helps on this.
Thanks in advance,
Jian
The configuration is as:
<mbean code="org.jboss.cache.TreeCache" name="jboss.cache:service=TreeCache"> <depends>jboss:service=Naming</depends> <depends>jboss:service=TransactionManager</depends> <!-- Configure the TransactionManager --> <!-- org.jboss.cache.DummyTransactionManagerLookup--> <attribute name="TransactionManagerLookupClass">com.jtv.core.resource.impl.spring.cache.JBossCacheTransaction ManagerLookup</attribute> <!-- Node locking scheme: OPTIMISTIC PESSIMISTIC (default) --> <attribute name="NodeLockingScheme">PESSIMISTIC</attribute> <!-- Node locking level : SERIALIZABLE REPEATABLE_READ (default) READ_COMMITTED READ_UNCOMMITTED NONE --> <attribute name="IsolationLevel">REPEATABLE_READ</attribute> <!-- Valid modes are LOCAL REPL_ASYNC REPL_SYNC INVALIDATION_ASYNC INVALIDATION_SYNC --> <attribute name="CacheMode">REPL_SYNC</attribute> <!-- Name of cluster. Needs to be the same for all clusters, in order to find each other --> <attribute name="ClusterName">JTVCORE-Cluster</attribute> <!-- JGroups protocol stack properties. Can also be a URL, e.g. file:/home/bela/default.xml <attribute name="ClusterProperties"></attribute> --> <attribute name="ClusterConfig"> <config> <UDP mcast_send_buf_size="32000" mcast_port="&mcast-port;" ucast_recv_buf_size="64000" mcast_addr="&mcast-addr;" bind_addr="&mcast-listen-iface-addr;" loopback="false" mcast_recv_buf_size="64000" max_bundle_size="60000" max_bundle_timeout="30" use_incoming_packet_handler="false" use_outgoing_packet_handler="false" ucast_send_buf_size="32000" ip_ttl="32" enable_bundling="false"/> <PING timeout="&startup-group-join-wait-time;" num_initial_members="4" down_thread="true" up_thread="true"/> <MERGE2 max_interval="10000" min_interval="5000"/> <FD timeout="2000" max_tries="3" shun="true"/> <VERIFY_SUSPECT timeout="1500"/> <pbcast.NAKACK max_xmit_size="8192" use_mcast_xmit="false" gc_lag="50" retransmit_timeout="600,1200,2400,4800"/> <UNICAST timeout="1200,2400,3600"/> --> <pbcast.STABLE stability_delay="1000" desired_avg_gossip="20000" max_bytes="0"/> <FRAG frag_size="8192" down_thread="false" up_thread="false"/> <VIEW_SYNC avg_send_interval="60000" down_thread="false" up_thread="false" /> <pbcast.GMS print_local_addr="true" join_timeout="3000" join_retry_timeout="2000" shun="true"/><!--test what happens here --> <pbcast.STATE_TRANSFER down_thread="true" up_thread="true"/> </config> </attribute> <!-- Whether or not to fetch state on joining a cluster NOTE this used to be called FetchStateOnStartup and has been renamed to be more descriptive. --> <!-- --> <attribute name="FetchInMemoryState">true</attribute> <!-- --> <!-- The max amount of time (in milliseconds) we wait until the initial state (ie. the contents of the cache) are retrieved from existing members in a clustered environment --> <attribute name="InitialStateRetrievalTimeout">20000</attribute> <!-- Number of milliseconds to wait until all responses for a synchronous call have been received. --> <attribute name="SyncReplTimeout">20000</attribute> <!-- Max number of milliseconds to wait for a lock acquisition --> <attribute name="LockAcquisitionTimeout">15000</attribute> <!-- Name of the eviction policy class. --> <!--attribute name="EvictionPolicyClass"></attribute--> <!-- <attribute name="EvictionPolicyClass">org.jboss.cache.eviction.LRUPolicy</attribute> --> <!-- Specific eviction policy configurations. This is LRU --> <attribute name="EvictionPolicyConfig"> <config> <attribute name="wakeUpIntervalSeconds">5</attribute> <!-- Cache wide default /com/jtv/core--> <region name="_default_" policyClass= "org.jboss.cache.eviction.LRUPolicy"> <attribute name="maxNodes">0</attribute> <attribute name="timeToLiveSeconds">0</attribute> </region> <region name="/com/jtv/core/tgt" policyClass= "org.jboss.cache.eviction.LRUPolicy"> <attribute name="maxNodes">20000</attribute> <attribute name="timeToLiveSeconds">0</attribute> </region><!--org.jboss.cache.eviction.LFUPolicy--> <region name="/com/jtv/core/st" policyClass= "org.jboss.cache.eviction.LRUPolicy"> <attribute name="maxNodes">20000</attribute> <attribute name="timeToLiveSeconds">0</attribute> </region> </config> </attribute> <!-- Indicate whether to use region based marshalling or not. Set this to true if you are running under a scoped class loader, e.g., inside an application server. Default is "false". --> <attribute name="UseRegionBasedMarshalling">false</attribute>
and the debug info is as follows,
2008-04-08 16:59:27,848 (main) org.jboss.cache.factories.InterceptorChainFactory.createPessimisticInterceptorChain INFO : interceptor chain is: class org.jboss.cache.interceptors.CallInterceptor class org.jboss.cache.interceptors.EvictionInterceptor class org.jboss.cache.interceptors.PessimisticLockInterceptor class org.jboss.cache.interceptors.UnlockInterceptor class org.jboss.cache.interceptors.ReplicationInterceptor class org.jboss.cache.interceptors.TxInterceptor class org.jboss.cache.interceptors.CacheMgmtInterceptor 2008-04-08 16:59:27,869 (main) org.jboss.cache.TreeCache._createService DEBUG: cache mode is REPL_SYNC 2008-04-08 16:59:28,047 (main) org.jgroups.conf.ClassConfigurator.init DEBUG: mapping is: 1: class org.jgroups.stack.IpAddress 2: class org.jgroups.protocols.CAUSAL$CausalHeader 3: class org.jgroups.protocols.FD$FdHeader 4: class org.jgroups.protocols.FD_PID$FdHeader 5: class org.jgroups.protocols.FD_PROB$FdHeader 6: class org.jgroups.protocols.FD_SOCK$FdHeader 7: class org.jgroups.protocols.FragHeader 8: class org.jgroups.protocols.MERGE$MergeHeader 9: class org.jgroups.protocols.NakAckHeader 10: class org.jgroups.protocols.PARTITIONER$PartitionerHeader 11: class org.jgroups.protocols.PerfHeader 12: class org.jgroups.protocols.PIGGYBACK$PiggybackHeader 13: class org.jgroups.protocols.PingHeader 14: class org.jgroups.protocols.TcpHeader 15: class org.jgroups.protocols.TOTAL$Header 16: class org.jgroups.protocols.TOTAL_OLD$TotalHeader 17: class org.jgroups.protocols.TOTAL_TOKEN$TotalTokenHeader 18: class org.jgroups.protocols.TOTAL_TOKEN$RingTokenHeader 19: class org.jgroups.protocols.TunnelHeader 20: class org.jgroups.protocols.UdpHeader 21: class org.jgroups.protocols.UNICAST$UnicastHeader 22: class org.jgroups.protocols.VERIFY_SUSPECT$VerifyHeader 23: class org.jgroups.protocols.WANPIPE$WanPipeHeader 24: class org.jgroups.protocols.pbcast.GMS$GmsHeader 25: class org.jgroups.protocols.pbcast.NakAckHeader 26: class org.jgroups.protocols.pbcast.PbcastHeader 27: class org.jgroups.protocols.pbcast.STABLE$StableHeader 28: class org.jgroups.protocols.pbcast.STATE_TRANSFER$StateHeader 29: class org.jgroups.protocols.SMACK$SmackHeader 30: class org.jgroups.Message 31: class org.jgroups.View 32: class org.jgroups.ViewId 33: class org.jgroups.util.List 34: interface org.jgroups.Address 35: class org.jgroups.blocks.RequestCorrelator$Header 36: class org.jgroups.protocols.PingRsp 37: class [Ljava.lang.Object; 38: class java.util.Vector 39: class org.jgroups.protocols.pbcast.JoinRsp 40: class org.jgroups.protocols.pbcast.Digest 41: class java.util.Hashtable 53: class org.jgroups.protocols.COMPRESS$CompressHeader 54: class org.jgroups.protocols.FC$FcHeader 55: class org.jgroups.protocols.WanPipeAddress 56: class org.jgroups.protocols.TpHeader 57: class org.jgroups.protocols.ENCRYPT$EncryptHeader 2008-04-08 16:59:28,077 (main) org.jgroups.protocols.AUTOCONF.senseMaxFragSize DEBUG: frag_size=64000 2008-04-08 16:59:28,146 (main) org.jgroups.protocols.pbcast.GMS.setImpl DEBUG: changed role to org.jgroups.protocols.pbcast.ClientGmsImpl 2008-04-08 16:59:28,194 (main) org.jboss.cache.marshall.VersionAwareMarshaller.<init> DEBUG: Initialised with version 1.4.0 and versionInt 14 2008-04-08 16:59:28,195 (main) org.jboss.cache.marshall.VersionAwareMarshaller.<init> DEBUG: Using default marshaller class org.jboss.cache.marshall.TreeCacheMarshaller140 2008-04-08 16:59:28,205 (DownHandler (STABLE)) org.jgroups.protocols.pbcast.STABLE.startStableTask DEBUG: stable task started 2008-04-08 16:59:28,210 (DownHandler (UDP)) org.jgroups.protocols.UDP.start DEBUG: creating sockets and starting threads 2008-04-08 16:59:28,211 (DownHandler (UDP)) org.jgroups.protocols.UDP.createSockets INFO : sockets will use interface 10.128.0.114 2008-04-08 16:59:28,233 (DownHandler (UDP)) org.jgroups.protocols.UDP.createSockets INFO : socket information: local_addr=10.128.0.114:32783, mcast_addr=239.0.0.101:45567, bind_addr=/10.128.0.114, ttl=32 sock: bound to 10.128.0.114:32783, receive buffer size=64000, send buffer size=32000 mcast_recv_sock: bound to 10.128.0.114:45567, send buffer size=32000, receive buffer size=64000 mcast_send_sock: bound to 10.128.0.114:32784, send buffer size=32000, receive buffer size=64000 2008-04-08 16:59:28,237 (DownHandler (UDP)) org.jgroups.protocols.UDP.bindToInterfaces DEBUG: joined /224.0.0.75:7500 on eth0 2008-04-08 16:59:28,238 (DownHandler (UDP)) org.jgroups.protocols.UDP.bindToInterfaces DEBUG: joined /224.0.0.75:7500 on lo 2008-04-08 16:59:28,241 (DownHandler (UDP)) org.jgroups.protocols.UDP.startThreads DEBUG: created unicast receiver thread 2008-04-08 16:59:28,241 (UpHandler (STATE_TRANSFER)) org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.passUp DEBUG: setting local_addr (null) to 10.128.0.114:32783 2008-04-08 16:59:28,244 (PingWaiter) org.jgroups.protocols.PingWaiter.findInitialMembers DEBUG: waiting for initial members: time_to_wait=20000, got 0 rsps 2008-04-08 16:59:28,245 (PingSender) org.jgroups.protocols.PingSender.run DEBUG: sending GET_MBRS_REQ 2008-04-08 16:59:28,250 (DownHandler (UDP)) org.jgroups.protocols.UDP.down DEBUG: sending msg to null (src=10.128.0.114:32783), headers are {PING=[PING: type=GET_MBRS_REQ, arg=null], UDP=[channel_name=JTVCORE-Cluster]} 2008-04-08 16:59:28,253 (UDP mcast receiver) org.jgroups.protocols.UDP.receive DEBUG: received (mcast)57 bytes from 10.128.0.114:32784 2008-04-08 16:59:28,253 (UDP.UcastReceiverThread) org.jgroups.protocols.UDP.receive DEBUG: received (ucast) 84 bytes from 10.128.0.113:32837 2008-04-08 16:59:28,256 (UDP mcast receiver) org.jgroups.protocols.UDP.handleIncomingMessage DEBUG: message is [dst: 239.0.0.101:45567, src: 10.128.0.114:32783 (2 headers), size = 0 bytes], headers are {UDP=[channel_name=JTVCORE-Cluster], PING=[PING: type=GET_MBRS_REQ, arg=null]}
part omitted because too long and seems fine
2008-04-08 16:59:48,296 (DownHandler (UDP)) org.jgroups.protocols.UDP.down DEBUG: sending msg to 10.128.0.111:32777 (src=10.128.0.114:32783), headers are {UDP=[channel_name=JTVCORE-Cluster], UNICAST=[UNICAST: DATA, seqno=3], STATE_TRANSFER=[StateHeader: type=STATE_REQ, sender=10.128.0.114:32783 id=#1} 2008-04-08 16:59:48,297 (UDP.UcastReceiverThread) org.jgroups.protocols.UDP.receive DEBUG: received (ucast) 67 bytes from 10.128.0.111:32777 2008-04-08 16:59:48,297 (UDP.UcastReceiverThread) org.jgroups.protocols.UDP.handleIncomingMessage DEBUG: message is [dst: 10.128.0.114:32783, src: 10.128.0.111:32777 (2 headers), size = 0 bytes], headers are {UNICAST=[UNICAST: ACK, seqno=2], UDP=[channel_name=JTVCORE-Cluster]} 2008-04-08 16:59:48,298 (UDP.UcastReceiverThread) org.jgroups.protocols.UDP.receive DEBUG: received (ucast) 67 bytes from 10.128.0.111:32777 2008-04-08 16:59:48,298 (UpHandler (FD)) org.jgroups.protocols.FD.up DEBUG: received msg from 10.128.0.111:32777 (counts as ack) 2008-04-08 16:59:48,299 (UDP.UcastReceiverThread) org.jgroups.protocols.UDP.handleIncomingMessage DEBUG: message is [dst: 10.128.0.114:32783, src: 10.128.0.111:32777 (2 headers), size = 0 bytes], headers are {UNICAST=[UNICAST: ACK, seqno=3], UDP=[channel_name=JTVCORE-Cluster]} 2008-04-08 16:59:48,299 (UpHandler (UNICAST)) org.jgroups.protocols.UNICAST.handleAckReceived DEBUG: 10.128.0.114:32783 <-- ACK(10.128.0.111:32777: #2) 2008-04-08 16:59:48,299 (UpHandler (FD)) org.jgroups.protocols.FD.up DEBUG: received msg from 10.128.0.111:32777 (counts as ack) 2008-04-08 16:59:48,300 (UpHandler (UNICAST)) org.jgroups.protocols.UNICAST.handleAckReceived DEBUG: 10.128.0.114:32783 <-- ACK(10.128.0.111:32777: #3) 2008-04-08 16:59:48,329 (UDP mcast receiver) org.jgroups.protocols.UDP.receive DEBUG: received (mcast)2250 bytes from 10.128.0.112:32822 2008-04-08 16:59:48,330 (UDP mcast receiver) org.jgroups.protocols.UDP.handleIncomingMessage DEBUG: message is [dst: 239.0.0.101:45567, src: 10.128.0.112:32821 (3 headers), size = 2082 bytes], headers are {NAKACK=[MSG, seqno=123620], MessageDispatcher=[Header: name=MessageDispatcher, type=REQ, id=1207688388340, rsp_expected=true], dest_mbrs=[10.128.0.111:32777, 10.128.0.113:32837, 10.128.0.114:32783], UDP=[channel_name=JTVCORE-Cluster]} 2008-04-08 16:59:48,330 (UpHandler (NAKACK)) org.jgroups.protocols.pbcast.NAKACK.handleMessage DEBUG: 10.128.0.114:32783] received 10.128.0.112:32821#123620 2008-04-08 16:59:48,332 (UpHandler (STATE_TRANSFER)) org.jgroups.blocks.RequestCorrelator.handleRequest DEBUG: calling (org.jgroups.blocks.RpcDispatcher) with request 1207688388340 2008-04-08 16:59:48,463 (UpHandler (STATE_TRANSFER)) org.jgroups.blocks.RpcDispatcher.handle DEBUG: [sender=10.128.0.112:32821], method_call: _replicate(_put(null, /com/jtv/core/st/ST-173404-KOnokuekCK8YP47AWdSzotsQAOkFEO38-JTV, ST-173404-KOnokuekCK8YP47AWdSzotsQAOkFEO38-JTV, com.jtv.core.crosscut.impl.spring.security.ticket.ApplicationServiceTicket@a7f3234e, true)) 2008-04-08 16:59:48,464 (UpHandler (STATE_TRANSFER)) org.jboss.cache.interceptors.TxInterceptor.invoke DEBUG: (10.128.0.114:32783) call on method [_put(null, /com/jtv/core/st/ST-173404-KOnokuekCK8YP47AWdSzotsQAOkFEO38-JTV, ST-173404-KOnokuekCK8YP47AWdSzotsQAOkFEO38-JTV, com.jtv.core.crosscut.impl.spring.security.ticket.ApplicationServiceTicket@a7f3234e, true)] 2008-04-08 16:59:48,465 (UpHandler (STATE_TRANSFER)) org.jboss.cache.interceptors.PessimisticLockInterceptor.invoke DEBUG: PessimisticLockInterceptor invoked for method _put(null, /com/jtv/core/st/ST-173404-KOnokuekCK8YP47AWdSzotsQAOkFEO38-JTV, ST-173404-KOnokuekCK8YP47AWdSzotsQAOkFEO38-JTV, com.jtv.core.crosscut.impl.spring.security.ticket.ApplicationServiceTicket@a7f3234e, true) 2008-04-08 16:59:48,465 (UpHandler (STATE_TRANSFER)) org.jboss.cache.interceptors.PessimisticLockInterceptor.lock DEBUG: Attempting to lock node /com/jtv/core/st/ST-173404-KOnokuekCK8YP47AWdSzotsQAOkFEO38-JTV for owner Thread[UpHandler (STATE_TRANSFER),5,main] 2008-04-08 16:59:48,466 (UpHandler (STATE_TRANSFER)) org.jboss.cache.Node.getOrCreateChild DEBUG: created child: fqn=/com 2008-04-08 16:59:48,466 (UpHandler (STATE_TRANSFER)) org.jboss.cache.Node.acquireReadLock DEBUG: acquiring RL: fqn=/com, caller=Thread[UpHandler (STATE_TRANSFER),5,main], lock=<unlocked> 2008-04-08 16:59:48,467 (UpHandler (STATE_TRANSFER)) org.jboss.cache.Node.acquireReadLock DEBUG: acquired RL: fqn=/com, caller=Thread[UpHandler (STATE_TRANSFER),5,main], lock=read owners=[Thread[UpHandler (STATE_TRANSFER),5,main]] 2008-04-08 16:59:48,468 (UpHandler (STATE_TRANSFER)) org.jboss.cache.Node.getOrCreateChild DEBUG: created child: fqn=/com/jtv 2008-04-08 16:59:48,468 (UpHandler (STATE_TRANSFER)) org.jboss.cache.Node.acquireReadLock DEBUG: acquiring RL: fqn=/com/jtv, caller=Thread[UpHandler (STATE_TRANSFER),5,main], lock=<unlocked> 2008-04-08 16:59:48,469 (UpHandler (STATE_TRANSFER)) org.jboss.cache.Node.acquireReadLock DEBUG: acquired RL: fqn=/com/jtv, caller=Thread[UpHandler (STATE_TRANSFER),5,main], lock=read owners=[Thread[UpHandler (STATE_TRANSFER),5,main]] 2008-04-08 16:59:48,469 (UpHandler (STATE_TRANSFER)) org.jboss.cache.Node.getOrCreateChild DEBUG: created child: fqn=/com/jtv/core 2008-04-08 16:59:48,469 (UpHandler (STATE_TRANSFER)) org.jboss.cache.Node.acquireReadLock DEBUG: acquiring RL: fqn=/com/jtv/core, caller=Thread[UpHandler (STATE_TRANSFER),5,main], lock=<unlocked> 2008-04-08 16:59:48,470 (UpHandler (STATE_TRANSFER)) org.jboss.cache.Node.acquireReadLock DEBUG: acquired RL: fqn=/com/jtv/core, caller=Thread[UpHandler (STATE_TRANSFER),5,main], lock=read owners=[Thread[UpHandler (STATE_TRANSFER),5,main]] 2008-04-08 16:59:48,470 (UpHandler (STATE_TRANSFER)) org.jboss.cache.Node.getOrCreateChild DEBUG: created child: fqn=/com/jtv/core/st 2008-04-08 16:59:48,471 (UpHandler (STATE_TRANSFER)) org.jboss.cache.Node.acquireReadLock DEBUG: acquiring RL: fqn=/com/jtv/core/st, caller=Thread[UpHandler (STATE_TRANSFER),5,main], lock=<unlocked> 2008-04-08 16:59:48,471 (UpHandler (STATE_TRANSFER)) org.jboss.cache.Node.acquireReadLock DEBUG: acquired RL: fqn=/com/jtv/core/st, caller=Thread[UpHandler (STATE_TRANSFER),5,main], lock=read owners=[Thread[UpHandler (STATE_TRANSFER),5,main]] 2008-04-08 16:59:48,471 (UpHandler (STATE_TRANSFER)) org.jboss.cache.Node.getOrCreateChild DEBUG: created child: fqn=/com/jtv/core/st/ST-173404-KOnokuekCK8YP47AWdSzotsQAOkFEO38-JTV 2008-04-08 16:59:48,472 (UpHandler (STATE_TRANSFER)) org.jboss.cache.Node.acquireWriteLock DEBUG: acquiring WL: fqn=/com/jtv/core/st/ST-173404-KOnokuekCK8YP47AWdSzotsQAOkFEO38-JTV, caller=Thread[UpHandler (STATE_TRANSFER),5,main], lock=<unlocked> 2008-04-08 16:59:48,472 (UpHandler (STATE_TRANSFER)) org.jboss.cache.Node.acquireWriteLock DEBUG: acquired WL: fqn=/com/jtv/core/st/ST-173404-KOnokuekCK8YP47AWdSzotsQAOkFEO38-JTV, caller=Thread[UpHandler (STATE_TRANSFER),5,main], lock=write owner=Thread[UpHandler (STATE_TRANSFER),5,main] 2008-04-08 16:59:48,473 (UpHandler (STATE_TRANSFER)) org.jboss.cache.interceptors.CallInterceptor.invoke DEBUG: Invoking method _put(null, /com/jtv/core/st/ST-173404-KOnokuekCK8YP47AWdSzotsQAOkFEO38-JTV, ST-173404-KOnokuekCK8YP47AWdSzotsQAOkFEO38-JTV, com.jtv.core.crosscut.impl.spring.security.ticket.ApplicationServiceTicket@a7f3234e, true) on cache. 2008-04-08 16:59:48,474 (UpHandler (STATE_TRANSFER)) org.jboss.cache.TreeCache._put DEBUG: _put(null, "/com/jtv/core/st/ST-173404-KOnokuekCK8YP47AWdSzotsQAOkFEO38-JTV", ST-173404-KOnokuekCK8YP47AWdSzotsQAOkFEO38-JTV, com.jtv.core.crosscut.impl.spring.security.ticket.ApplicationServiceTicket@a7f3234e) 2008-04-08 16:59:48,474 (UpHandler (STATE_TRANSFER)) org.jboss.cache.interceptors.EvictionInterceptor.invoke DEBUG: Invoking EvictionInterceptor 2008-04-08 16:59:48,474 (UpHandler (STATE_TRANSFER)) org.jboss.cache.interceptors.EvictionInterceptor.updateNode DEBUG: Updating node/element events with no tx 2008-04-08 16:59:48,477 (UpHandler (STATE_TRANSFER)) org.jboss.cache.interceptors.EvictionInterceptor.doEventUpdatesOnRegionManager DEBUG: Adding event EvictedEN[fqn=/com/jtv/core/st/ST-173404-KOnokuekCK8YP47AWdSzotsQAOkFEO38-JTV event=3 diff=1] to region at /com/jtv/core/st/ 2008-04-08 16:59:48,478 (UpHandler (STATE_TRANSFER)) org.jboss.cache.interceptors.EvictionInterceptor.updateNode DEBUG: Finished updating node 2008-04-08 16:59:48,478 (UpHandler (STATE_TRANSFER)) org.jboss.cache.interceptors.EvictionInterceptor.invoke DEBUG: Finished invoking EvictionInterceptor 2008-04-08 16:59:48,479 (UpHandler (STATE_TRANSFER)) org.jboss.cache.interceptors.UnlockInterceptor.invoke DEBUG: Attempting to release locks on current thread. Lock table is {Thread[UpHandler (STATE_TRANSFER),5,main]=[read owners=[Thread[UpHandler (STATE_TRANSFER),5,main]], read owners=[Thread[UpHandler (STATE_TRANSFER),5,main]], read owners=[Thread[UpHandler (STATE_TRANSFER),5,main]], read owners=[Thread[UpHandler (STATE_TRANSFER),5,main]], write owner=Thread[UpHandler (STATE_TRANSFER),5,main]]} 2008-04-08 16:59:48,479 (UpHandler (STATE_TRANSFER)) org.jboss.cache.interceptors.UnlockInterceptor.releaseLocks DEBUG: releasing lock for /com/jtv/core/st/ST-173404-KOnokuekCK8YP47AWdSzotsQAOkFEO38-JTV: write owner=Thread[UpHandler (STATE_TRANSFER),5,main] 2008-04-08 16:59:48,480 (UpHandler (STATE_TRANSFER)) org.jboss.cache.interceptors.UnlockInterceptor.releaseLocks DEBUG: releasing lock for /com/jtv/core/st: read owners=[Thread[UpHandler (STATE_TRANSFER),5,main]] 2008-04-08 16:59:48,480 (UpHandler (STATE_TRANSFER)) org.jboss.cache.interceptors.UnlockInterceptor.releaseLocks DEBUG: releasing lock for /com/jtv/core: read owners=[Thread[UpHandler (STATE_TRANSFER),5,main]] 2008-04-08 16:59:48,481 (UpHandler (STATE_TRANSFER)) org.jboss.cache.interceptors.UnlockInterceptor.releaseLocks DEBUG: releasing lock for /com/jtv: read owners=[Thread[UpHandler (STATE_TRANSFER),5,main]] 2008-04-08 16:59:48,481 (UpHandler (STATE_TRANSFER)) org.jboss.cache.interceptors.UnlockInterceptor.releaseLocks DEBUG: releasing lock for /com: read owners=[Thread[UpHandler (STATE_TRANSFER),5,main]] 2008-04-08 16:59:48,481 (UpHandler (STATE_TRANSFER)) org.jboss.cache.interceptors.ReplicationInterceptor.invoke DEBUG: Non-tx crud meth 2008-04-08 16:59:48,482 (UpHandler (STATE_TRANSFER)) org.jgroups.blocks.RequestCorrelator.handleRequest DEBUG: sending rsp for 1207688388340 to 10.128.0.112:32821 2008-04-08 16:59:48,483 (DownHandler (UNICAST)) org.jgroups.protocols.UNICAST.down DEBUG: 10.128.0.114:32783: created new connection for dst 10.128.0.112:32821 2008-04-08 16:59:48,484 (DownHandler (UNICAST)) org.jgroups.protocols.UNICAST.down DEBUG: 10.128.0.114:32783 --> DATA(10.128.0.112:32821: #1 2008-04-08 16:59:48,485 (DownHandler (UDP)) org.jgroups.protocols.UDP.down DEBUG: sending msg to 10.128.0.112:32821 (src=10.128.0.114:32783), headers are {MessageDispatcher=[Header: name=MessageDispatcher, type=RSP, id=1207688388340, rsp_expected=false], UDP=[channel_name=JTVCORE-Cluster], UNICAST=[UNICAST: DATA, seqno=1]} 2008-04-08 16:59:48,486 (UDP.UcastReceiverThread) org.jgroups.protocols.UDP.receive DEBUG: received (ucast) 67 bytes from 10.128.0.112:32821 2008-04-08 16:59:48,486 (UDP.UcastReceiverThread) org.jgroups.protocols.UDP.handleIncomingMessage DEBUG: message is [dst: 10.128.0.114:32783, src: 10.128.0.112:32821 (2 headers), size = 0 bytes], headers are {UNICAST=[UNICAST: ACK, seqno=1], UDP=[channel_name=JTVCORE-Cluster]} 2008-04-08 16:59:48,487 (UpHandler (UNICAST)) org.jgroups.protocols.UNICAST.handleAckReceived DEBUG: 10.128.0.114:32783 <-- ACK(10.128.0.112:32821: #1) 2008-04-08 16:59:49,091 (UDP.UcastReceiverThread) org.jgroups.protocols.UDP.receive DEBUG: received (ucast) 8290 bytes from 10.128.0.111:32777 2008-04-08 16:59:49,092 (UDP.UcastReceiverThread) org.jgroups.protocols.UDP.handleIncomingMessage DEBUG: message is [dst: 10.128.0.114:32783, src: 10.128.0.111:32777 (3 headers), size = 8192 bytes], headers are {FRAG=[id=6, frag_id=0, num_frags=1025], UNICAST=[UNICAST: DATA, seqno=2], UDP=[channel_name=JTVCORE-Cluster]} 2008-04-08 16:59:49,092 (UDP.UcastReceiverThread) org.jgroups.protocols.UDP.receive DEBUG: received (ucast) 8290 bytes from 10.128.0.111:32777 2008-04-08 16:59:49,092 (UpHandler (FD)) org.jgroups.protocols.FD.up DEBUG: received msg from 10.128.0.111:32777 (counts as ack) 2008-04-08 16:59:49,093 (UpHandler (UNICAST)) org.jgroups.protocols.UNICAST.handleDataReceived DEBUG: 10.128.0.114:32783 <-- DATA(10.128.0.111:32777: #2 2008-04-08 16:59:49,093 (UDP.UcastReceiverThread) org.jgroups.protocols.UDP.handleIncomingMessage DEBUG: message is [dst: 10.128.0.114:32783, src: 10.128.0.111:32777 (3 headers), size = 8192 bytes], headers are {FRAG=[id=6, frag_id=1, num_frags=1025], UNICAST=[UNICAST: DATA, seqno=3], UDP=[channel_name=JTVCORE-Cluster]} 2008-04-08 16:59:49,093 (UpHandler (UNICAST)) org.jgroups.stack.AckReceiverWindow.remove DEBUG: removed seqno=2 2008-04-08 16:59:49,094 (UpHandler (FD)) org.jgroups.protocols.FD.up DEBUG: received msg from 10.128.0.111:32777 (counts as ack) 2008-04-08 16:59:49,094 (UpHandler (UNICAST)) org.jgroups.protocols.UNICAST.sendAck DEBUG: 10.128.0.114:32783 --> ACK(10.128.0.111:32777: #2) 2008-04-08 16:59:49,094 (UDP.UcastReceiverThread) org.jgroups.protocols.UDP.receive DEBUG: received (ucast) 8290 bytes from 10.128.0.111:32777 2008-04-08 16:59:49,097 (UpHandler (UNICAST)) org.jgroups.protocols.UNICAST.handleDataReceived DEBUG: 10.128.0.114:32783 <-- DATA(10.128.0.111:32777: #3 2008-04-08 16:59:49,097 (DownHandler (UDP)) org.jgroups.protocols.UDP.down DEBUG: sending msg to 10.128.0.111:32777 (src=10.128.0.114:32783), headers are {UDP=[channel_name=JTVCORE-Cluster], UNICAST=[UNICAST: ACK, seqno=2]} 2008-04-08 16:59:49,098 (UDP.UcastReceiverThread) org.jgroups.protocols.UDP.handleIncomingMessage DEBUG: message is [dst: 10.128.0.114:32783, src: 10.128.0.111:32777 (3 headers), size = 8192 bytes], headers are {FRAG=[id=6, frag_id=2, num_frags=1025], UNICAST=[UNICAST: DATA, seqno=4], UDP=[channel_name=JTVCORE-Cluster]} 2008-04-08 16:59:49,098 (UpHandler (UNICAST)) org.jgroups.stack.AckReceiverWindow.remove DEBUG: removed seqno=3
after a while, the replicate request came from 10.128.0.112 again, and the new node 10.128.0.114 started to react to that request again. This procedure repeated until the initial state transfer timed out and failed.
Thanks again.