[jboss-user] [JBoss Cache: Core Edition] - Need helps with initial state transfer in production
jiafan1
do-not-reply at jboss.com
Fri Apr 11 15:28:47 EDT 2008
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 at 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 at 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 at 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 at 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 at 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.
View the original post : http://www.jboss.com/index.html?module=bb&op=viewtopic&p=4143522#4143522
Reply to the post : http://www.jboss.com/index.html?module=bb&op=posting&mode=reply&p=4143522
More information about the jboss-user
mailing list