Need helps with initial state transfer in production
Hi,
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.
