10:20 a.m.
On Tue, 2007-10-23 at 09:58 -0500, Brian Stansberry wrote:
Adrian wrote:
> When I look at this code, it looks like it is doing an infinte wait,
> shouldn't this have a timeout?
>
>
http://fisheye.jboss.org/browse/JBossCache/core/tags/2.0.0.GA/src/org/jbo...
>
Arguably yes, although only as a second line of defense against a bug.
Which there appears to be here. You only get to the wait call if
channel.getState() returns true (line 1270 in the above linked rev.)
The getState call has a timeout. In your case it should *not* have
returned true, as your node is the only cluster member.
Vladimir/Manik, does anything here ring a bell? E.g. was there any
change in the Channel.getState() behavior in JG 2.5.0? Adrian's seeing
this in AS trunk, which is using JBC 2.0.0.GA and JG 2.5.0.GA.
Make sure you do an rm -rf thirdparty or use a clean checkout
so you can be sure you have all the latest jars.
Adrian, has some kind of parallelization of deployment been
introduced?
No. But each service is free to do some startup asynch by forking
a thread.
Your logging seems to show JBoss Messaging deployment proceeding in
parallel with deployment of cluster-beans.xml. When I run "./run.sh -b
localhost -c all" I don't see this problem (and the JBM logging occurs
after the cluster-beans.xml stuff.)
So you think this could be a race? I don't see anything in the
DEBUG messages (or the thread dump) that suggests both are
active at the same time.
Here's the DEBUG from the last JBoss Messaging logging:
2007-10-23 14:28:34,335 DEBUG
[org.jboss.jms.server.connectionfactory.ConnectionFactory] Started
jboss.messaging.connectionfactory:service=ConnectionFactory
2007-10-23 14:28:34,336 DEBUG
[org.jboss.system.microcontainer.jmx.ServiceControllerLifecycleCallback]
Registered MBean jboss.jgroups:service=MultiplexerChannelFactory
2007-10-23 14:28:34,337 DEBUG
[org.jboss.ha.framework.server.JChannelFactory] Ignoring create call;
current state is Started
2007-10-23 14:28:34,337 DEBUG
[org.jboss.ha.framework.server.JChannelFactory] Ignoring start call;
current state is Started
2007-10-23 14:28:34,362 DEBUG [org.jboss.cache.jmx.CacheJmxWrapper]
Registered in JMX under jboss.cache:service=EJB3SFSBClusteredCache
2007-10-23 14:28:34,362 DEBUG [org.jboss.system.ServiceController]
starting service jboss.cache:service=EJB3SFSBClusteredCache
2007-10-23 14:28:34,362 DEBUG [org.jboss.system.ServiceController]
Registering service jboss.cache:service=EJB3SFSBClusteredCache
2007-10-23 14:28:34,373 DEBUG [org.jboss.cache.jmx.CacheJmxWrapper]
Registered in JMX under
jboss.cache:partitionName=DefaultPartition,service=HAPartitionCache
2007-10-23 14:28:34,374 DEBUG [org.jboss.system.ServiceController]
starting service
jboss.cache:service=HAPartitionCache,partitionName=DefaultPartition
2007-10-23 14:28:34,374 DEBUG [org.jboss.system.ServiceController]
Registering service
jboss.cache:service=HAPartitionCache,partitionName=DefaultPartition
2007-10-23 14:28:34,384 DEBUG [org.jboss.cache.jmx.CacheJmxWrapper]
Registered in JMX under jboss.cache:service=ClusteredSSOCache
2007-10-23 14:28:34,384 DEBUG [org.jboss.system.ServiceController]
starting service jboss.cache:service=ClusteredSSOCache
2007-10-23 14:28:34,384 DEBUG [org.jboss.system.ServiceController]
Registering service jboss.cache:service=ClusteredSSOCache
2007-10-23 14:28:34,390 DEBUG [org.jboss.cache.jmx.CacheJmxWrapper]
Constructing Cache
2007-10-23 14:28:34,797 DEBUG
[org.jboss.cache.factories.InterceptorChainFactory] interceptor chain
is:
class org.jboss.cache.interceptors.CallInterceptor
class org.jboss.cache.interceptors.UnlockInterceptor
class org.jboss.cache.interceptors.PessimisticLockInterceptor
class org.jboss.cache.interceptors.ReplicationInterceptor
class org.jboss.cache.interceptors.NotificationInterceptor
class org.jboss.cache.interceptors.TxInterceptor
class org.jboss.cache.interceptors.CacheMgmtInterceptor
class org.jboss.cache.interceptors.InvocationContextInterceptor
2007-10-23 14:28:34,806 DEBUG
[org.jboss.cache.CacheImpl.DefaultPartition-ClusteredSSOCache] Not using
an EvictionPolicy
2007-10-23 14:28:34,815 DEBUG
[org.jboss.cache.CacheImpl.DefaultPartition-ClusteredSSOCache] cache
mode is REPL_ASYNC
2007-10-23 14:28:34,815 DEBUG
[org.jboss.cache.CacheImpl.DefaultPartition-ClusteredSSOCache] Created
Multiplexer Channel for cache cluster DefaultPartition-ClusteredSS
OCache using stack udp
2007-10-23 14:28:34,844 DEBUG
[org.jboss.cache.marshall.VersionAwareMarshaller] Initialised with
version 2.0.0 and versionInt 20
2007-10-23 14:28:34,844 DEBUG
[org.jboss.cache.marshall.VersionAwareMarshaller] Using default
marshaller class org.jboss.cache.marshall.CacheMarshaller200
2007-10-23 14:28:34,844 DEBUG
[org.jboss.cache.CacheImpl.DefaultPartition-ClusteredSSOCache] Using
marshaller org.jboss.cache.marshall.VersionAwareMarshaller
2007-10-23 14:28:34,845 DEBUG
[org.jboss.cache.CacheImpl.DefaultPartition-ClusteredSSOCache] Block
received at 127.0.0.1:32787
2007-10-23 14:28:34,899 DEBUG
[org.jboss.cache.interceptors.InvocationContextInterceptor] Invoked on
cache instance [127.0.0.1:32787] and InvocationContext [Invocation
Context{methodCall=MethodName: _block; MethodIdInteger: 43; Args:
()transaction=null, globalTransaction=null,
optionOverrides=Option{failSilently=false, cacheModeLocal
=false, dataVersion=null, suppressLocking=false,
forceDataGravitation=false, skipDataGravitation=false},
originLocal=true, txHasMods=false}]
2007-10-23 14:28:34,899 DEBUG
[org.jboss.cache.interceptors.InvocationContextInterceptor] Setting up
transactional context.
2007-10-23 14:28:34,899 DEBUG
[org.jboss.cache.interceptors.InvocationContextInterceptor] Setting tx
as null and gtx as null
2007-10-23 14:28:34,900 DEBUG
[org.jboss.cache.interceptors.ReplicationInterceptor]
isLocalCommitOrRollback? false; gtx = null
2007-10-23 14:28:34,900 DEBUG
[org.jboss.cache.interceptors.PessimisticLockInterceptor]
PessimisticLockInterceptor invoked for method MethodName: _block;
MethodIdInteg
er: 43; Args: ()
2007-10-23 14:28:34,900 DEBUG
[org.jboss.cache.interceptors.PessimisticLockInterceptor] bypassed
locking as method _block() doesn't require locking
2007-10-23 14:28:34,900 DEBUG
[org.jboss.cache.interceptors.CallInterceptor] Passing up method
MethodName: _block; MethodIdInteger: 43; Args: () so it gets invoked on
cache.
2007-10-23 14:28:34,900 DEBUG
[org.jboss.cache.interceptors.UnlockInterceptor] Attempting to release
locks on current thread. Lock table is {}
2007-10-23 14:28:34,900 DEBUG
[org.jboss.cache.interceptors.ReplicationInterceptor] Non-tx and non
crud meth
2007-10-23 14:28:34,900 DEBUG
[org.jboss.cache.interceptors.InvocationContextInterceptor] Resetting
invocation-scope options
2007-10-23 14:28:34,900 DEBUG
[org.jboss.cache.CacheImpl.DefaultPartition-ClusteredSSOCache] Block
processed at 127.0.0.1:32787
2007-10-23 14:28:34,902 INFO
[org.jboss.cache.CacheImpl.DefaultPartition-ClusteredSSOCache]
viewAccepted(): [127.0.0.1:32787|0] [127.0.0.1:32787]
2007-10-23 14:28:34,902 DEBUG
[org.jboss.cache.CacheImpl.DefaultPartition-ClusteredSSOCache] UnBlock
received at 127.0.0.1:32787
2007-10-23 14:28:34,903 DEBUG
[org.jboss.cache.interceptors.InvocationContextInterceptor] Invoked on
cache instance [127.0.0.1:32787] and InvocationContext [Invocation
Context{methodCall=MethodName: _unblock; MethodIdInteger: 44; Args:
()transaction=null, globalTransaction=null,
optionOverrides=Option{failSilently=false, cacheModeLoc
al=false, dataVersion=null, suppressLocking=false,
forceDataGravitation=false, skipDataGravitation=false},
originLocal=true, txHasMods=false}]
2007-10-23 14:28:34,903 DEBUG
[org.jboss.cache.interceptors.InvocationContextInterceptor] Setting up
transactional context.
2007-10-23 14:28:34,903 DEBUG
[org.jboss.cache.interceptors.InvocationContextInterceptor] Setting tx
as null and gtx as null
2007-10-23 14:28:34,903 DEBUG
[org.jboss.cache.interceptors.ReplicationInterceptor]
isLocalCommitOrRollback? false; gtx = null
2007-10-23 14:28:34,903 DEBUG
[org.jboss.cache.interceptors.PessimisticLockInterceptor]
PessimisticLockInterceptor invoked for method MethodName: _unblock;
MethodIdInt
eger: 44; Args: ()
2007-10-23 14:28:34,903 DEBUG
[org.jboss.cache.interceptors.PessimisticLockInterceptor] bypassed
locking as method _unblock() doesn't require locking
2007-10-23 14:28:34,903 DEBUG
[org.jboss.cache.interceptors.CallInterceptor] Passing up method
MethodName: _unblock; MethodIdInteger: 44; Args: () so it gets invoked o
n cache.
2007-10-23 14:28:34,903 DEBUG
[org.jboss.cache.interceptors.UnlockInterceptor] Attempting to release
locks on current thread. Lock table is {}
2007-10-23 14:28:34,903 DEBUG
[org.jboss.cache.interceptors.ReplicationInterceptor] Non-tx and non
crud meth
2007-10-23 14:28:34,903 DEBUG
[org.jboss.cache.interceptors.InvocationContextInterceptor] Resetting
invocation-scope options
2007-10-23 14:28:34,903 DEBUG
[org.jboss.cache.CacheImpl.DefaultPartition-ClusteredSSOCache] UnBlock
processed at 127.0.0.1:32787
2007-10-23 14:28:34,903 INFO
[org.jboss.cache.CacheImpl.DefaultPartition-ClusteredSSOCache] CacheImpl
local address is 127.0.0.1:32787
Got bored waiting here. ;-)
2007-10-23 14:32:30,094 INFO
[org.jboss.bootstrap.microcontainer.ServerImpl] JBoss SHUTDOWN
There's no JBoss Cache logging before this, only some generic
clustering logging (I've included where jms is using clustering
but otherwise stripped its logging):
2007-10-23 14:28:27,360 DEBUG [org.jboss.system.ServiceController]
starting service jboss.jgroups:service=MultiplexerChannelFactory
2007-10-23 14:28:27,360 DEBUG [org.jboss.system.ServiceController]
Registering service jboss.jgroups:service=MultiplexerChannelFactory
2007-10-23 14:28:27,364 DEBUG
[org.jboss.ha.framework.server.JChannelFactory] Ignoring create call;
current state is Stopped
...
2007-10-23 14:28:27,367 DEBUG
[org.jboss.ha.framework.server.JChannelFactory] Starting JChannelFactory
2007-10-23 14:28:27,367 DEBUG
[org.jboss.ha.framework.server.JChannelFactory] Started JChannelFactory
2007-10-23 14:28:27,368 DEBUG
[org.jboss.messaging.core.jmx.MessagingPostOfficeService] Starting
jboss.messaging:service=PostOffice
2007-10-23 14:28:27,378 DEBUG
[org.jboss.messaging.core.jmx.MessagingPostOfficeService]
org.jboss.messaging.core.jmx.MessagingPostOfficeService@14b7042 uses
Multiplexe
rJChannelFactory
2007-10-23 14:28:28,110 DEBUG
[org.jboss.ha.framework.server.JChannelFactory] Passing unique node id
127.0.0.1:1099 to the channel as additional data
2007-10-23 14:28:28,121 DEBUG
[org.jboss.ha.framework.server.JChannelFactory] Passing unique node id
127.0.0.1:1099 to the channel as additional data
2007-10-23 14:28:28,214 INFO [STDOUT]
-------------------------------------------------------
GMS: address is 127.0.0.1:32786
-------------------------------------------------------
2007-10-23 14:28:30,306 DEBUG
[org.jboss.messaging.core.impl.postoffice.GroupMember]
org.jboss.messaging.core.impl.postoffice.GroupMember
$ControlMembershipListener@334
cb9 got new view [127.0.0.1:32786|0] [127.0.0.1:32786], old view is null
2007-10-23 14:28:30,386 DEBUG
[org.jboss.messaging.core.impl.postoffice.MessagingPostOffice]
org.jboss.messaging.core.impl.postoffice.MessagingPostOffice@1c86116:
127.
0.0.1:32786 joined
2007-10-23 14:28:30,386 DEBUG
[org.jboss.messaging.core.impl.postoffice.GroupMember] First view
arrived
2007-10-23 14:28:30,387 DEBUG
[org.jboss.messaging.core.impl.postoffice.GroupMember] We are the first
member of the group so no need to wait for state
2007-10-23 14:28:30,391 INFO [STDOUT]
-------------------------------------------------------
GMS: address is 127.0.0.1:32787
-------------------------------------------------------
2007-10-23 14:28:32,412 DEBUG
[org.jboss.messaging.core.impl.postoffice.MessagingPostOffice] Updated
failover map:
0->0
2007-10-23 14:28:32,427 DEBUG
[org.jboss.messaging.core.impl.postoffice.MessagingPostOffice]
org.jboss.messaging.core.impl.postoffice.MessagingPostOffice@1c86116
puts
replicant locally: JVMID->6-fnu8e48f-1-yvy7e48f-0gpx6x-d24o4c5
...
2007-10-23 14:28:32,872 DEBUG
[org.jboss.jms.server.endpoint.ServerConnectionFactoryEndpoint]
updateClusteredClients being called!!! clientFactoriesToUpdate.size = 0
,,,
2007-10-23 14:28:34,335 DEBUG
[org.jboss.jms.server.connectionfactory.ConnectionFactory] Started
jboss.messaging.connectionfactory:service=ConnectionFactory
2007-10-23 14:28:34,336 DEBUG
[org.jboss.system.microcontainer.jmx.ServiceControllerLifecycleCallback]
Registered MBean jboss.jgroups:service=MultiplexerChannelFactory
2007-10-23 14:28:34,337 DEBUG
[org.jboss.ha.framework.server.JChannelFactory] Ignoring create call;
current state is Started
2007-10-23 14:28:34,337 DEBUG
[org.jboss.ha.framework.server.JChannelFactory] Ignoring start call;
current state is Started
--
xxxxxxxxxxxxxxxxxxxxxxxxxxxx
Adrian Brock
Chief Scientist
JBoss, a division of Red Hat
xxxxxxxxxxxxxxxxxxxxxxxxxxxx