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, [EMAIL PROTECTED], 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, [EMAIL PROTECTED], 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, [EMAIL PROTECTED], 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, [EMAIL PROTECTED], 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, [EMAIL PROTECTED])
|
| 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
_______________________________________________
jboss-user mailing list
jboss-user@lists.jboss.org
https://lists.jboss.org/mailman/listinfo/jboss-user
