2:28 p.m.
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.
View the original post :
http://www.jboss.com/index.html?module=bb&op=viewtopic&p=4143522#...
Reply to the post :
http://www.jboss.com/index.html?module=bb&op=posting&mode=reply&a...