5 Replies Latest reply on Apr 14, 2008 8:43 PM by Jian Fang

    Need helps with initial state transfer in production

    Jian Fang Newbie

      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.

        • 1. Re: Need helps with initial state transfer in production
          Manik Surtani Master

          Hmm, I don't see the part where

          org.jboss.cache.CacheException: Initial state transfer failed: Channel.getState() returned false
          


          appears in your debug log?

          • 2. Re: Need helps with initial state transfer in production
            Jian Fang Newbie

            We use different log files. Exceptions are logged in catalina.out. And Jboss and jgroup debug inform are in a separate log file, jbosscache.log. The error message I shown in my post came from catalina.out and the reset were from jbosscache.log.

            • 3. Re: Need helps with initial state transfer in production
              Jian Fang Newbie

              The detailed exception looks like,

              Apr 8, 2008 4:59:15 PM org.apache.coyote.http11.Http11AprProtocol init
              INFO: Initializing Coyote HTTP/1.1 on http-9080
              Apr 8, 2008 4:59:15 PM org.apache.coyote.ajp.AjpAprProtocol init
              INFO: Initializing Coyote AJP/1.3 on ajp-9009
              Apr 8, 2008 4:59:15 PM org.apache.catalina.startup.Catalina load
              INFO: Initialization processed in 1096 ms
              Apr 8, 2008 4:59:15 PM org.apache.catalina.core.StandardService start
              INFO: Starting service Catalina
              Apr 8, 2008 4:59:15 PM org.apache.catalina.core.StandardEngine start
              INFO: Starting Servlet Engine: Apache Tomcat/5.5.17
              Apr 8, 2008 4:59:15 PM org.apache.catalina.core.StandardHost start
              INFO: XML validation disabled
              Apr 8, 2008 4:59:15 PM org.apache.catalina.startup.HostConfig deployWAR
              INFO: Deploying web application archive catalyst_server.war
              
              -------------------------------------------------------
              GMS: address is 10.128.0.114:32783
              -------------------------------------------------------
              Apr 8, 2008 5:00:28 PM com.sun.xml.ws.transport.http.servlet.WSServletContextListener contextInitialized
              INFO: WSSERVLET12: JAX-WS context listener initializing
              Apr 8, 2008 5:00:28 PM com.sun.xml.ws.transport.http.servlet.RuntimeEndpointInfoParser processWsdlLocation
              INFO: wsdl cannot be found from DD or annotation. Will generate and publish a new WSDL for SEI endpoints.
              Apr 8, 2008 5:00:28 PM com.sun.xml.ws.transport.http.servlet.RuntimeEndpointInfoParser processWsdlLocation
              INFO: wsdl cannot be found from DD or annotation. Will generate and publish a new WSDL for SEI endpoints.
              Apr 8, 2008 5:00:30 PM org.apache.catalina.core.StandardContext start
              SEVERE: Error listenerStart
              Apr 8, 2008 5:00:30 PM org.apache.catalina.core.StandardContext start
              SEVERE: Context [/catalyst_server] startup failed due to previous errors
              Apr 8, 2008 5:00:30 PM com.sun.xml.ws.transport.http.servlet.WSServletContextListener contextDestroyed
              INFO: WSSERVLET13: JAX-WS context listener destroyed
              


              • 4. Re: Need helps with initial state transfer in production
                Jian Fang Newbie

                Sorry, the exception is in another log file stderr.log,

                2008-04-08 17:00:28,314 (main) [org.springframework.web.context.ContextLoader.initWebApplicationContext]
                 ERROR - Context initialization failed
                
                org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'authenticationDelegate' defined in class path resource [com/jtv/core/config/wiring/crosscut/security.xml]:
                
                ...
                

                Followed by a lot of Spring bean wiring and the last piece is

                
                 Invocation of init method failed; nested exception is org.jboss.cache.CacheException: Initial state transfer failed: Channel.getState() returned false
                Caused by:
                org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'jbCacheManager' defined in class path resource [com/jtv/core/config/wiring/coordinator/authentication-coordinator.xml]: Invocation of init method failed; nested exception 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(JBossCacheManagerFactoryBean.java:112)
                 at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1198)
                 at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1167)
                 at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:427)
                 at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:249)
                 at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:155)
                 at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:246)
                 at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:160)
                 at org.springframework.beans.factory.support.BeanDefinitionValueResolver.resolveReference(BeanDefinitionValueResolver.java:267)
                


                • 5. Re: Need helps with initial state transfer in production
                  Jian Fang Newbie

                  The wired thing is that when the exception was thrown in stderr.log, the jbosscache.log did not have any exceptions and seems the node was still involved in replication actions.

                  I am totally confused here,

                  1) Why did the new node react to replication requests at all before the initial state transfer finishes?

                  2) Why did it react to the replication requests after the web-app has already thrown exceptions? (Actually the error was from JBoss cache, right?. That is to say Jboss cache "start service" failed.)

                  2008-04-08 17:00:27,981 (UDP mcast receiver) org.jgroups.protocols.UDP.handleIncomingMessage
                   DEBUG: message is [dst: 239.0.0.101:45567, src: 10.128.0.113:32837 (3 headers), size = 2082 bytes], headers are {NAKACK=[MSG, seqno=31112], MessageDispatcher=[Header: name=MessageDispatcher, type=REQ, id=1207688427993, rsp_expected=true], dest_mbrs=[10.128.0.111:32777, 10.128.0.112:32821, 10.128.0.114:32783], UDP=[channel_name=JTVCORE-Cluster]}
                  
                  2008-04-08 17:00:27,982 (UpHandler (NAKACK)) org.jgroups.protocols.pbcast.NAKACK.handleMessage
                   DEBUG: 10.128.0.114:32783] received 10.128.0.113:32837#31112
                  
                  2008-04-08 17:00:27,982 (UpHandler (STATE_TRANSFER)) org.jgroups.blocks.RequestCorrelator.handleRequest
                   DEBUG: calling (org.jgroups.blocks.RpcDispatcher) with request 1207688427993
                  
                  2008-04-08 17:00:27,983 (UpHandler (STATE_TRANSFER)) org.jgroups.blocks.RpcDispatcher.handle
                   DEBUG: [sender=10.128.0.113:32837], method_call: _replicate(_put(null, /com/jtv/core/st/ST-181818-8J4Bzfnc0t08yd1X9TMMmsIEuGJdSHmY-JTV, ST-181818-8J4Bzfnc0t08yd1X9TMMmsIEuGJdSHmY-JTV, com.jtv.core.crosscut.impl.spring.security.ticket.ApplicationServiceTicket@e31bc86d, true))
                  
                  2008-04-08 17:00:27,983 (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-181818-8J4Bzfnc0t08yd1X9TMMmsIEuGJdSHmY-JTV, ST-181818-8J4Bzfnc0t08yd1X9TMMmsIEuGJdSHmY-JTV, com.jtv.core.crosscut.impl.spring.security.ticket.ApplicationServiceTicket@e31bc86d, true)]
                  
                  2008-04-08 17:00:27,983 (UpHandler (STATE_TRANSFER)) org.jboss.cache.interceptors.PessimisticLockInterceptor.invoke
                   DEBUG: PessimisticLockInterceptor invoked for method _put(null, /com/jtv/core/st/ST-181818-8J4Bzfnc0t08yd1X9TMMmsIEuGJdSHmY-JTV, ST-181818-8J4Bzfnc0t08yd1X9TMMmsIEuGJdSHmY-JTV, com.jtv.core.crosscut.impl.spring.security.ticket.ApplicationServiceTicket@e31bc86d, true)
                  
                  2008-04-08 17:00:27,984 (UpHandler (STATE_TRANSFER)) org.jboss.cache.interceptors.PessimisticLockInterceptor.lock
                   DEBUG: Attempting to lock node /com/jtv/core/st/ST-181818-8J4Bzfnc0t08yd1X9TMMmsIEuGJdSHmY-JTV for owner Thread[UpHandler (STATE_TRANSFER),5,main]
                  
                  2008-04-08 17:00:27,984 (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 17:00:27,984 (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 17:00:27,984 (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 17:00:27,985 (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 17:00:27,985 (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 17:00:27,985 (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 17:00:27,986 (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 17:00:27,986 (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 17:00:27,986 (UpHandler (STATE_TRANSFER)) org.jboss.cache.Node.acquireWriteLock
                   DEBUG: acquiring WL: fqn=/com/jtv/core/st/ST-181818-8J4Bzfnc0t08yd1X9TMMmsIEuGJdSHmY-JTV, caller=Thread[UpHandler (STATE_TRANSFER),5,main], lock=<unlocked>
                  
                  2008-04-08 17:00:27,986 (UpHandler (STATE_TRANSFER)) org.jboss.cache.Node.acquireWriteLock
                   DEBUG: acquired WL: fqn=/com/jtv/core/st/ST-181818-8J4Bzfnc0t08yd1X9TMMmsIEuGJdSHmY-JTV, caller=Thread[UpHandler (STATE_TRANSFER),5,main], lock=write owner=Thread[UpHandler (STATE_TRANSFER),5,main]
                  
                  2008-04-08 17:00:27,987 (UpHandler (STATE_TRANSFER)) org.jboss.cache.interceptors.CallInterceptor.invoke
                   DEBUG: Invoking method _put(null, /com/jtv/core/st/ST-181818-8J4Bzfnc0t08yd1X9TMMmsIEuGJdSHmY-JTV, ST-181818-8J4Bzfnc0t08yd1X9TMMmsIEuGJdSHmY-JTV, com.jtv.core.crosscut.impl.spring.security.ticket.ApplicationServiceTicket@e31bc86d, true) on cache.
                  
                  2008-04-08 17:00:27,987 (UpHandler (STATE_TRANSFER)) org.jboss.cache.TreeCache._put
                   DEBUG: _put(null, "/com/jtv/core/st/ST-181818-8J4Bzfnc0t08yd1X9TMMmsIEuGJdSHmY-JTV", ST-181818-8J4Bzfnc0t08yd1X9TMMmsIEuGJdSHmY-JTV, com.jtv.core.crosscut.impl.spring.security.ticket.ApplicationServiceTicket@e31bc86d)
                  
                  2008-04-08 17:00:27,987 (UpHandler (STATE_TRANSFER)) org.jboss.cache.interceptors.EvictionInterceptor.invoke
                   DEBUG: Invoking EvictionInterceptor
                  
                  2008-04-08 17:00:27,988 (UpHandler (STATE_TRANSFER)) org.jboss.cache.interceptors.EvictionInterceptor.updateNode
                   DEBUG: Updating node/element events with no tx
                  
                  2008-04-08 17:00:27,988 (UpHandler (STATE_TRANSFER)) org.jboss.cache.interceptors.EvictionInterceptor.doEventUpdatesOnRegionManager
                   DEBUG: Adding event EvictedEN[fqn=/com/jtv/core/st/ST-181818-8J4Bzfnc0t08yd1X9TMMmsIEuGJdSHmY-JTV event=3 diff=1] to region at /com/jtv/core/st/
                  
                  2008-04-08 17:00:27,988 (UpHandler (STATE_TRANSFER)) org.jboss.cache.interceptors.EvictionInterceptor.updateNode
                   DEBUG: Finished updating node
                  
                  2008-04-08 17:00:27,989 (UpHandler (STATE_TRANSFER)) org.jboss.cache.interceptors.EvictionInterceptor.invoke
                   DEBUG: Finished invoking EvictionInterceptor
                  
                  2008-04-08 17:00:27,989 (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 17:00:27,989 (UpHandler (STATE_TRANSFER)) org.jboss.cache.interceptors.UnlockInterceptor.releaseLocks
                   DEBUG: releasing lock for /com/jtv/core/st/ST-181818-8J4Bzfnc0t08yd1X9TMMmsIEuGJdSHmY-JTV: write owner=Thread[UpHandler (STATE_TRANSFER),5,main]
                  
                  2008-04-08 17:00:27,990 (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 17:00:27,990 (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 17:00:27,990 (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 17:00:27,990 (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 17:00:27,991 (UpHandler (STATE_TRANSFER)) org.jboss.cache.interceptors.ReplicationInterceptor.invoke
                   DEBUG: Non-tx crud meth
                  
                  2008-04-08 17:00:27,991 (UpHandler (STATE_TRANSFER)) org.jgroups.blocks.RequestCorrelator.handleRequest
                   DEBUG: sending rsp for 1207688427993 to 10.128.0.113:32837
                  
                  2008-04-08 17:00:27,992 (DownHandler (UNICAST)) org.jgroups.protocols.UNICAST.down
                   DEBUG: 10.128.0.114:32783 --> DATA(10.128.0.113:32837: #22
                  
                  2008-04-08 17:00:27,992 (DownHandler (UDP)) org.jgroups.protocols.UDP.down
                   DEBUG: sending msg to 10.128.0.113:32837 (src=10.128.0.114:32783), headers are {MessageDispatcher=[Header: name=MessageDispatcher, type=RSP, id=1207688427993, rsp_expected=false], UDP=[channel_name=JTVCORE-Cluster], UNICAST=[UNICAST: DATA, seqno=22]}
                  
                  2008-04-08 17:00:27,993 (UDP.UcastReceiverThread) org.jgroups.protocols.UDP.receive
                   DEBUG: received (ucast) 67 bytes from 10.128.0.113:32837
                  
                  2008-04-08 17:00:27,994 (UDP.UcastReceiverThread) org.jgroups.protocols.UDP.handleIncomingMessage
                   DEBUG: message is [dst: 10.128.0.114:32783, src: 10.128.0.113:32837 (2 headers), size = 0 bytes], headers are {UNICAST=[UNICAST: ACK, seqno=22], UDP=[channel_name=JTVCORE-Cluster]}
                  
                  2008-04-08 17:00:27,994 (UpHandler (UNICAST)) org.jgroups.protocols.UNICAST.handleAckReceived
                   DEBUG: 10.128.0.114:32783 <-- ACK(10.128.0.113:32837: #22)
                  2008-04-08 17:00:28,341 (TimeScheduler.Thread) org.jgroups.protocols.FD.run
                   DEBUG: sending are-you-alive msg to 10.128.0.111:32777 (own address=10.128.0.114:32783)
                  
                  2008-04-08 17:00:28,342 (DownHandler (UDP)) org.jgroups.protocols.UDP.down
                   DEBUG: sending msg to 10.128.0.111:32777 (src=10.128.0.114:32783), headers are {FD=[FD: heartbeat], UDP=[channel_name=JTVCORE-Cluster]}
                  
                  2008-04-08 17:00:28,343 (UDP.UcastReceiverThread) org.jgroups.protocols.UDP.receive
                   DEBUG: received (ucast) 69 bytes from 10.128.0.111:32777
                  
                  2008-04-08 17:00:28,343 (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 {UDP=[channel_name=JTVCORE-Cluster], FD=[FD: heartbeat ack]}
                  
                  2008-04-08 17:00:28,344 (UpHandler (FD)) org.jgroups.protocols.FD.up
                   DEBUG: received ack from 10.128.0.111:32777
                  
                  2008-04-08 17:00:28,347 (UDP.UcastReceiverThread) org.jgroups.protocols.UDP.receive
                   DEBUG: received (ucast) 57 bytes from 10.128.0.113:32837
                  
                  2008-04-08 17:00:28,348 (UDP.UcastReceiverThread) org.jgroups.protocols.UDP.handleIncomingMessage
                   DEBUG: message is [dst: 10.128.0.114:32783, src: 10.128.0.113:32837 (2 headers), size = 0 bytes], headers are {UDP=[channel_name=JTVCORE-Cluster], FD=[FD: heartbeat]}
                  
                  2008-04-08 17:00:28,348 (UpHandler (FD)) org.jgroups.protocols.FD.up
                   DEBUG: received are-you-alive from 10.128.0.113:32837, sending response
                  2008-04-08 17:00:28,348 (DownHandler (UDP)) org.jgroups.protocols.UDP.down
                   DEBUG: sending msg to 10.128.0.113:32837 (src=10.128.0.114:32783), headers are {FD=[FD: heartbeat ack], UDP=[channel_name=JTVCORE-Cluster]}
                  
                  2008-04-08 17:00:28,395 (UDP mcast receiver) org.jgroups.protocols.UDP.receive
                   DEBUG: received (mcast)2250 bytes from 10.128.0.112:32822
                  
                  2008-04-08 17:00:28,395 (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=123817], MessageDispatcher=[Header: name=MessageDispatcher, type=REQ, id=1207688428406, 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 17:00:28,396 (UpHandler (NAKACK)) org.jgroups.protocols.pbcast.NAKACK.handleMessage
                   DEBUG: 10.128.0.114:32783] received 10.128.0.112:32821#123817
                  
                  2008-04-08 17:00:28,397 (UpHandler (STATE_TRANSFER)) org.jgroups.blocks.RequestCorrelator.handleRequest
                   DEBUG: calling (org.jgroups.blocks.RpcDispatcher) with request 1207688428406
                  
                  2008-04-08 17:00:28,398 (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-236922-4nakwXPVFHwF2RK1oLVDTMvmNmFdJyBj-JTV, ST-236922-4nakwXPVFHwF2RK1oLVDTMvmNmFdJyBj-JTV, com.jtv.core.crosscut.impl.spring.security.ticket.ApplicationServiceTicket@7ba38be2, true))
                  
                  2008-04-08 17:00:28,398 (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-236922-4nakwXPVFHwF2RK1oLVDTMvmNmFdJyBj-JTV, ST-236922-4nakwXPVFHwF2RK1oLVDTMvmNmFdJyBj-JTV, com.jtv.core.crosscut.impl.spring.security.ticket.ApplicationServiceTicket@7ba38be2, true)]
                  
                  2008-04-08 17:00:28,399 (UpHandler (STATE_TRANSFER)) org.jboss.cache.interceptors.PessimisticLockInterceptor.invoke
                   DEBUG: PessimisticLockInterceptor invoked for method _put(null, /com/jtv/core/st/ST-236922-4nakwXPVFHwF2RK1oLVDTMvmNmFdJyBj-JTV, ST-236922-4nakwXPVFHwF2RK1oLVDTMvmNmFdJyBj-JTV, com.jtv.core.crosscut.impl.spring.security.ticket.ApplicationServiceTicket@7ba38be2, true)
                  
                  2008-04-08 17:00:28,399 (UpHandler (STATE_TRANSFER)) org.jboss.cache.interceptors.PessimisticLockInterceptor.lock
                   DEBUG: Attempting to lock node /com/jtv/core/st/ST-236922-4nakwXPVFHwF2RK1oLVDTMvmNmFdJyBj-JTV for owner Thread[UpHandler (STATE_TRANSFER),5,main]
                  
                  2008-04-08 17:00:28,400 (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 17:00:28,400 (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 17:00:28,401 (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 17:00:28,401 (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 17:00:28,402 (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 17:00:28,402 (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 17:00:28,403 (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 17:00:28,403 (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 17:00:28,404 (UpHandler (STATE_TRANSFER)) org.jboss.cache.Node.acquireWriteLock
                   DEBUG: acquiring WL: fqn=/com/jtv/core/st/ST-236922-4nakwXPVFHwF2RK1oLVDTMvmNmFdJyBj-JTV, caller=Thread[UpHandler (STATE_TRANSFER),5,main], lock=<unlocked>
                  
                  2008-04-08 17:00:28,404 (UpHandler (STATE_TRANSFER)) org.jboss.cache.Node.acquireWriteLock
                   DEBUG: acquired WL: fqn=/com/jtv/core/st/ST-236922-4nakwXPVFHwF2RK1oLVDTMvmNmFdJyBj-JTV, caller=Thread[UpHandler (STATE_TRANSFER),5,main], lock=write owner=Thread[UpHandler (STATE_TRANSFER),5,main]
                  2008-04-08 17:00:28,405 (UpHandler (STATE_TRANSFER)) org.jboss.cache.interceptors.CallInterceptor.invoke
                   DEBUG: Invoking method _put(null, /com/jtv/core/st/ST-236922-4nakwXPVFHwF2RK1oLVDTMvmNmFdJyBj-JTV, ST-236922-4nakwXPVFHwF2RK1oLVDTMvmNmFdJyBj-JTV, com.jtv.core.crosscut.impl.spring.security.ticket.ApplicationServiceTicket@7ba38be2, true) on cache.
                  
                  2008-04-08 17:00:28,405 (UpHandler (STATE_TRANSFER)) org.jboss.cache.TreeCache._put
                   DEBUG: _put(null, "/com/jtv/core/st/ST-236922-4nakwXPVFHwF2RK1oLVDTMvmNmFdJyBj-JTV", ST-236922-4nakwXPVFHwF2RK1oLVDTMvmNmFdJyBj-JTV, com.jtv.core.crosscut.impl.spring.security.ticket.ApplicationServiceTicket@7ba38be2)
                  
                  2008-04-08 17:00:28,406 (UpHandler (STATE_TRANSFER)) org.jboss.cache.interceptors.EvictionInterceptor.invoke
                   DEBUG: Invoking EvictionInterceptor
                  
                  2008-04-08 17:00:28,406 (UpHandler (STATE_TRANSFER)) org.jboss.cache.interceptors.EvictionInterceptor.updateNode
                   DEBUG: Updating node/element events with no tx
                  
                  2008-04-08 17:00:28,407 (UpHandler (STATE_TRANSFER)) org.jboss.cache.interceptors.EvictionInterceptor.doEventUpdatesOnRegionManager
                   DEBUG: Adding event EvictedEN[fqn=/com/jtv/core/st/ST-236922-4nakwXPVFHwF2RK1oLVDTMvmNmFdJyBj-JTV event=3 diff=1] to region at /com/jtv/core/st/
                  
                  2008-04-08 17:00:28,407 (UpHandler (STATE_TRANSFER)) org.jboss.cache.interceptors.EvictionInterceptor.updateNode
                   DEBUG: Finished updating node
                  
                  2008-04-08 17:00:28,408 (UpHandler (STATE_TRANSFER)) org.jboss.cache.interceptors.EvictionInterceptor.invoke
                   DEBUG: Finished invoking EvictionInterceptor
                  
                  2008-04-08 17:00:28,408 (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 17:00:28,409 (UpHandler (STATE_TRANSFER)) org.jboss.cache.interceptors.UnlockInterceptor.releaseLocks
                   DEBUG: releasing lock for /com/jtv/core/st/ST-236922-4nakwXPVFHwF2RK1oLVDTMvmNmFdJyBj-JTV: write owner=Thread[UpHandler (STATE_TRANSFER),5,main]
                  
                  2008-04-08 17:00:28,409 (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 17:00:28,410 (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 17:00:28,410 (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 17:00:28,411 (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 17:00:28,411 (UpHandler (STATE_TRANSFER)) org.jboss.cache.interceptors.ReplicationInterceptor.invoke
                   DEBUG: Non-tx crud meth
                  
                  2008-04-08 17:00:28,412 (UpHandler (STATE_TRANSFER)) org.jgroups.blocks.RequestCorrelator.handleRequest
                   DEBUG: sending rsp for 1207688428406 to 10.128.0.112:32821
                  
                  2008-04-08 17:00:28,413 (DownHandler (UNICAST)) org.jgroups.protocols.UNICAST.down
                   DEBUG: 10.128.0.114:32783 --> DATA(10.128.0.112:32821: #198
                  
                  2008-04-08 17:00:28,413 (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=1207688428406, rsp_expected=false], UDP=[channel_name=JTVCORE-Cluster], UNICAST=[UNICAST: DATA, seqno=198]}
                  
                  2008-04-08 17:00:28,415 (UDP.UcastReceiverThread) org.jgroups.protocols.UDP.receive
                   DEBUG: received (ucast) 67 bytes from 10.128.0.112:32821
                  
                  2008-04-08 17:00:28,415 (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=198], UDP=[channel_name=JTVCORE-Cluster]}
                  
                  2008-04-08 17:00:28,416 (UpHandler (UNICAST)) org.jgroups.protocols.UNICAST.handleAckReceived
                   DEBUG: 10.128.0.114:32783 <-- ACK(10.128.0.112:32821: #198)