7 Replies Latest reply on Feb 16, 2006 10:48 AM by belaban

Listener ignored => ChannelException: unable to setup the pr

svenschauwvliege Feb 15, 2006 12:55 PM

When trying to enable clustered caching we ran into this problem:
Setup:
We have 2 servers on one of the servers (server2) we receve no errors

configuration on server 1 ip: 192.168.100.51

#cache.memory=true
#cache.capacity=100
#gdp.cache.debug=false
gdp.cache.lifetime=1800
#cache.cluster.multicast.ip=231.12.21.100
cache.cluster.properties=UDP(mcast_addr=231.12.21.100;mcast_port=30210;bind_addr=192.168.100.51:1509;ip_ttl=32;\
mcast_send_buf_size=150000;mcast_recv_buf_size=80000):\
PING(timeout=2000;num_initial_members=10):\
MERGE2(min_interval=5000;max_interval=10000):\
FD_SOCK:VERIFY_SUSPECT(timeout=2000):\
pbcast.NAKACK(gc_lag=50;retransmit_timeout=300,600,1200,2400,4800;max_xmit_size=8192):\
UNICAST(timeout=300,600,1200,2400):\
pbcast.STABLE(desired_avg_gossip=20000):\
FRAG(frag_size=8096;down_thread=false;up_thread=false):\
pbcast.GMS(join_timeout=10000;join_retry_timeout=4000;shun=true;print_local_addr=true)

configuration on server2 ip: 192.168.100.45

#cache.memory=true
#cache.capacity=100
#gdp.cache.debug=false
gdp.cache.lifetime=1800
#cache.cluster.multicast.ip=231.12.21.100
cache.cluster.properties=UDP(mcast_addr=231.12.21.100;mcast_port=30210;bind_addr=192.168.100.45;ip_ttl=32;\
mcast_send_buf_size=150000;mcast_recv_buf_size=80000):\
PING(timeout=2000;num_initial_members=10):\
MERGE2(min_interval=5000;max_interval=10000):\
FD_SOCK:VERIFY_SUSPECT(timeout=2000):\
pbcast.NAKACK(gc_lag=50;retransmit_timeout=300,600,1200,2400,4800;max_xmit_size=8192):\
UNICAST(timeout=300,600,1200,2400):\
pbcast.STABLE(desired_avg_gossip=20000):\
FRAG(frag_size=8096;down_thread=false;up_thread=false):\
pbcast.GMS(join_timeout=10000;join_retry_timeout=4000;shun=true;print_local_addr=true)

oscache.properties (on both servers)

cache.memory=true
cache.capacity=2000
cache.algorithm=com.opensymphony.oscache.base.algorithm.LRUCache
gdp.cache.debug=false
gdp.cache.lifetime=3600
#for development purposes
#gdp.cache.lifetime=60
cache.event.listeners=com.opensymphony.oscache.plugins.clustersupport.JavaGroupsBroadcastingListener

Error:

2006-02-15 18:01:31,109 [AloneScheduler_Worker-0] ERROR com.opensymphony.oscache.base.AbstractCacheAdministrator (AbstractCacheAdministrator.java:332) - Could not initialize listener 'com.opensymphony.oscache.plugins.clustersupport.JavaGroupsBroadcastingListener'. Listener ignored. - configureStandardListeners
com.opensymphony.oscache.base.InitializationException: Initialization failed: ChannelException: unable to setup the protocol stack
 at com.opensymphony.oscache.plugins.clustersupport.JavaGroupsBroadcastingListener.initialize(JavaGroupsBroadcastingListener.java:119)
 at com.opensymphony.oscache.base.AbstractCacheAdministrator.configureStandardListeners(AbstractCacheAdministrator.java:330)
 at com.opensymphony.oscache.general.GeneralCacheAdministrator.createCache(GeneralCacheAdministrator.java:297)
 at com.opensymphony.oscache.general.GeneralCacheAdministrator.<init>(GeneralCacheAdministrator.java:99)
 at com.gdp3000.permission.PermissionDataManager.getCacheAdmin(Unknown Source)
 at com.gdp3000.permission.PermissionDataManager.getUserWithFilter(Unknown Source)
 at com.gdp3000.permission.PermissionDataManager.getUserByUid(Unknown Source)
 at com.gdp3000.permission.PermissionManager.checkUserIdPassword(Unknown Source)
 at com.gdp3000.permission.PermissionManager.authenticate(Unknown Source)
 at com.gudrun.scheduler.GdpStatefulJob.execute(Unknown Source)
 at com.gdp3000.communication.email.EMailListener.execute(Unknown Source)
 at org.quartz.core.JobRunShell.run(JobRunShell.java:188)
 at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:511)
2006-02-15 18:01:31,156 [AloneScheduler_Worker-2] ERROR com.opensymphony.oscache.base.AbstractCacheAdministrator (AbstractCacheAdministrator.java:332) - Could not initialize listener 'com.opensymphony.oscache.plugins.clustersupport.JavaGroupsBroadcastingListener'. Listener ignored. - configureStandardListeners
com.opensymphony.oscache.base.InitializationException: Initialization failed: ChannelException: unable to setup the protocol stack
 at com.opensymphony.oscache.plugins.clustersupport.JavaGroupsBroadcastingListener.initialize(JavaGroupsBroadcastingListener.java:119)
 at com.opensymphony.oscache.base.AbstractCacheAdministrator.configureStandardListeners(AbstractCacheAdministrator.java:330)
 at com.opensymphony.oscache.general.GeneralCacheAdministrator.createCache(GeneralCacheAdministrator.java:297)
 at com.opensymphony.oscache.general.GeneralCacheAdministrator.<init>(GeneralCacheAdministrator.java:99)
 at com.gdp3000.permission.PermissionDataManager.getCacheAdmin(Unknown Source)
 at com.gdp3000.permission.PermissionDataManager.getUserWithFilter(Unknown Source)
 at com.gdp3000.permission.PermissionDataManager.getUserByUid(Unknown Source)
 at com.gdp3000.permission.PermissionManager.checkUserIdPassword(Unknown Source)
 at com.gdp3000.permission.PermissionManager.authenticate(Unknown Source)
 at com.gudrun.scheduler.GdpStatefulJob.execute(Unknown Source)
 at com.gdp3000.communication.email.EMailListener.execute(Unknown Source)
 at org.quartz.core.JobRunShell.run(JobRunShell.java:188)
 at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:511)

What are we missing here ?

1. Re: Listener ignored => ChannelException: unable to setup th

belaban Feb 15, 2006 3:08 PM (in response to svenschauwvliege)

You should add a TRACE or DEBUG category for org.jgroups to see what caused the channel to not start.
Actions

2. Re: Listener ignored => ChannelException: unable to setup th

svenschauwvliege Feb 16, 2006 3:55 AM (in response to svenschauwvliege)

Hi, thanks for the help

this is what comes from the log files:

2006-02-16 09:46:02,875 [AloneScheduler_Worker-2] DEBUG org.jgroups.conf.ClassConfigurator (ClassConfigurator.java:84) - 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.FRAG$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
50: class org.jgroups.service.lease.LeaseRequestHeader
51: class org.jgroups.service.lease.LeaseResponseHeader
52: class org.jgroups.service.lease.DenyResponseHeader
53: class org.jgroups.protocols.COMPRESS$CompressHeader
 - <init>
2006-02-16 09:46:02,875 [AloneScheduler_Worker-3] ERROR com.opensymphony.oscache.base.AbstractCacheAdministrator (AbstractCacheAdministrator.java:332) - Could not initialize listener 'com.opensymphony.oscache.plugins.clustersupport.JavaGroupsBroadcastingListener'. Listener ignored. - configureStandardListeners
com.opensymphony.oscache.base.InitializationException: Initialization failed: ChannelException: unable to setup the protocol stack
 at com.opensymphony.oscache.plugins.clustersupport.JavaGroupsBroadcastingListener.initialize(JavaGroupsBroadcastingListener.java:119)
 at com.opensymphony.oscache.base.AbstractCacheAdministrator.configureStandardListeners(AbstractCacheAdministrator.java:330)
 at com.opensymphony.oscache.general.GeneralCacheAdministrator.createCache(GeneralCacheAdministrator.java:297)
 at com.opensymphony.oscache.general.GeneralCacheAdministrator.<init>(GeneralCacheAdministrator.java:99)
 at com.gdp3000.permission.PermissionDataManager.getCacheAdmin(Unknown Source)
 at com.gdp3000.permission.PermissionDataManager.getUserWithFilter(Unknown Source)
 at com.gdp3000.permission.PermissionDataManager.getUserByUid(Unknown Source)
 at com.gdp3000.permission.PermissionManager.checkUserIdPassword(Unknown Source)
 at com.gdp3000.permission.PermissionManager.authenticate(Unknown Source)
 at com.gudrun.scheduler.GdpStatefulJob.execute(Unknown Source)
 at com.gdp3000.communication.email.EMailListener.execute(Unknown Source)
 at org.quartz.core.JobRunShell.run(JobRunShell.java:188)
 at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:511)

3. Re: Listener ignored => ChannelException: unable to setup th

belaban Feb 16, 2006 4:00 AM (in response to svenschauwvliege)

OSCache might eat the exception at:
com.opensymphony.oscache.plugins.clustersupport.JavaGroupsBroadcastingListener.initialize(JavaGr
oupsBroadcastingListener.java:119)

I suggest you debug this to get the exception. It should say exactly where the configuration is incorrect.
Actions

4. Re: Listener ignored => ChannelException: unable to setup th

svenschauwvliege Feb 16, 2006 9:30 AM (in response to svenschauwvliege)

I have managed to set the properties right (no more errors) but the clustered cache doesnt work

here is a part of the log file:

2006-02-16 15:00:38,046 [DownHandler (STABLE)] DEBUG org.jgroups.protocols.pbcast.STABLE (STABLE.java:322) - stable task started; num_gossip_runs=3, max_gossip_runs=3 - startStableTask
2006-02-16 15:00:38,046 [DownHandler (STABLE)] DEBUG org.jgroups.protocols.pbcast.STABLE (STABLE.java:322) - stable task started; num_gossip_runs=3, max_gossip_runs=3 - startStableTask
2006-02-16 15:00:38,046 [DownHandler (GMS)] DEBUG org.jgroups.protocols.pbcast.GMS (GMS.java:92) - newweb1-staging:3853 changed role to org.jgroups.protocols.pbcast.CoordGmsImpl - setImpl
2006-02-16 15:00:38,046 [thread-pool-24] INFO com.opensymphony.oscache.plugins.clustersupport.JavaGroupsBroadcastingListener (JavaGroupsBroadcastingListener.java:117) - JavaGroups clustering support started successfully - initialize
2006-02-16 15:00:38,046 [DownHandler (GMS)] DEBUG org.jgroups.protocols.pbcast.GMS (GMS.java:92) - newweb1-staging:3853 changed role to org.jgroups.protocols.pbcast.CoordGmsImpl - setImpl
2006-02-16 15:00:38,046 [DownHandler (FD_SOCK)] DEBUG org.jgroups.protocols.FD_SOCK (FD_SOCK.java:251) - VIEW_CHANGE received: [newweb1-staging:3853] - down
2006-02-16 15:00:38,046 [PullPushAdapterThread] INFO com.opensymphony.oscache.plugins.clustersupport.JavaGroupsBroadcastingListener (JavaGroupsBroadcastingListener.java:184) - A new member at address 'newweb1-staging:3853' has joined the cluster - memberJoined
2006-02-16 15:00:38,046 [thread-pool-24] INFO com.opensymphony.oscache.plugins.clustersupport.JavaGroupsBroadcastingListener (JavaGroupsBroadcastingListener.java:117) - JavaGroups clustering support started successfully - initialize
2006-02-16 15:00:38,046 [MERGE2.FindSubgroups thread] DEBUG org.jgroups.protocols.MERGE2 (MERGE2.java:230) - merge task started - run
2006-02-16 15:00:38,046 [DownHandler (FD_SOCK)] DEBUG org.jgroups.protocols.FD_SOCK (FD_SOCK.java:251) - VIEW_CHANGE received: [newweb1-staging:3853] - down
2006-02-16 15:00:38,046 [DownHandler (GMS)] DEBUG org.jgroups.protocols.pbcast.GMS (GMS.java:92) - newweb1-staging:3853 changed role to org.jgroups.protocols.pbcast.CoordGmsImpl - setImpl
2006-02-16 15:00:38,046 [PullPushAdapterThread] INFO com.opensymphony.oscache.plugins.clustersupport.JavaGroupsBroadcastingListener (JavaGroupsBroadcastingListener.java:184) - A new member at address 'newweb1-staging:3853' has joined the cluster - memberJoined
2006-02-16 15:00:38,046 [DownHandler (FD_SOCK)] DEBUG org.jgroups.protocols.FD_SOCK (FD_SOCK.java:490) - first member; cache is empty - getCacheFromCoordinator
2006-02-16 15:00:38,046 [MERGE2.FindSubgroups thread] DEBUG org.jgroups.protocols.MERGE2 (MERGE2.java:230) - merge task started - run
2006-02-16 15:00:38,046 [DownHandler (GMS)] DEBUG org.jgroups.protocols.pbcast.GMS (GMS.java:92) - newweb1-staging:3853 changed role to org.jgroups.protocols.pbcast.CoordGmsImpl - setImpl
2006-02-16 15:00:38,046 [DownHandler (FD_SOCK)] DEBUG org.jgroups.protocols.FD_SOCK (FD_SOCK.java:490) - first member; cache is empty - getCacheFromCoordinator
2006-02-16 15:00:38,046 [DownHandler (GMS)] DEBUG org.jgroups.protocols.pbcast.ClientGmsImpl (ClientGmsImpl.java:340) - created group (first member). My view is [newweb1-staging:3853|0], impl is org.jgroups.protocols.pbcast.CoordGmsImpl - becomeSingletonMember
2006-02-16 15:00:38,046 [DownHandler (GMS)] DEBUG org.jgroups.protocols.pbcast.ClientGmsImpl (ClientGmsImpl.java:340) - created group (first member). My view is [newweb1-staging:3853|0], impl is org.jgroups.protocols.pbcast.CoordGmsImpl - becomeSingletonMember
2006-02-16 15:00:38,046 [DownHandler (FD_SOCK)] DEBUG org.jgroups.protocols.FD_SOCK (FD_SOCK.java:577) - hdr=I_HAVE_SOCK, mbr=newweb1-staging:3853, sock_addr=newweb1-staging:49153 - sendIHaveSockMessage
2006-02-16 15:00:38,046 [DownHandler (FD_SOCK)] DEBUG org.jgroups.protocols.FD_SOCK (FD_SOCK.java:577) - hdr=I_HAVE_SOCK, mbr=newweb1-staging:3853, sock_addr=newweb1-staging:49153 - sendIHaveSockMessage
2006-02-16 15:00:38,046 [DownHandler (UDP)] DEBUG org.jgroups.protocols.UDP (UDP.java:756) - sending message to 231.12.21.101:30211 (src=newweb1-staging:3853), headers are {FD_SOCK=I_HAVE_SOCK, mbr=newweb1-staging:3853, sock_addr=newweb1-staging:49153, UDP=[UDP:group_addr=OSCacheBus]} - sendUdpMessage
2006-02-16 15:00:38,046 [DownHandler (UDP)] DEBUG org.jgroups.protocols.UDP (UDP.java:756) - sending message to 231.12.21.101:30211 (src=newweb1-staging:3853), headers are {FD_SOCK=I_HAVE_SOCK, mbr=newweb1-staging:3853, sock_addr=newweb1-staging:49153, UDP=[UDP:group_addr=OSCacheBus]} - sendUdpMessage
2006-02-16 15:00:38,046 [DownHandler (UDP)] DEBUG org.jgroups.protocols.UDP (UDP.java:773) - looped back local message [dst: 231.12.21.101:30211, src: newweb1-staging:3853 (2 headers), size = 0 bytes] - sendUdpMessage
2006-02-16 15:00:38,046 [DownHandler (UDP)] DEBUG org.jgroups.protocols.UDP (UDP.java:773) - looped back local message [dst: 231.12.21.101:30211, src: newweb1-staging:3853 (2 headers), size = 0 bytes] - sendUdpMessage
2006-02-16 15:00:38,046 [UpHandler (FD_SOCK)] DEBUG org.jgroups.protocols.FD_SOCK (FD_SOCK.java:186) - i-have-sock: newweb1-staging:3853 --> newweb1-staging:49153 (cache is {newweb1-staging:3853=newweb1-staging:49153}) - up
2006-02-16 15:00:38,046 [UpHandler (FD_SOCK)] DEBUG org.jgroups.protocols.FD_SOCK (FD_SOCK.java:186) - i-have-sock: newweb1-staging:3853 --> newweb1-staging:49153 (cache is {newweb1-staging:3853=newweb1-staging:49153}) - up
2006-02-16 15:00:38,046 [UDP mcast receiver] DEBUG org.jgroups.protocols.UDP (UDP.java:219) - received (mcast) 182 bytes from /192.168.100.45:3854 (size=182 bytes) - run
2006-02-16 15:00:38,046 [UDP mcast receiver] DEBUG org.jgroups.protocols.UDP (UDP.java:219) - received (mcast) 182 bytes from /192.168.100.45:3854 (size=182 bytes) - run
2006-02-16 15:00:38,046 [UDP mcast receiver] DEBUG org.jgroups.protocols.UDP (UDP.java:707) - discarded own loopback multicast packet - handleMessage
2006-02-16 15:00:38,046 [UDP mcast receiver] DEBUG org.jgroups.protocols.UDP (UDP.java:707) - discarded own loopback multicast packet - handleMessage
2006-02-16 15:00:38,046 [thread-pool-24] INFO com.opensymphony.oscache.plugins.clustersupport.JavaGroupsBroadcastingListener (JavaGroupsBroadcastingListener.java:109) - Starting a new JavaGroups broadcasting listener with properties=UDP(mcast_addr=231.12.21.106;mcast_port=30216;bind_addr=192.168.100.45;ip_ttl=32;mcast_send_buf_size=150000;mcast_recv_buf_size=80000):PING(timeout=2000;num_initial_members=10):MERGE2(min_interval=5000;max_interval=10000):FD_SOCK:VERIFY_SUSPECT(timeout=2000):pbcast.NAKACK(gc_lag=50;retransmit_timeout=300,600,1200,2400,4800;max_xmit_size=8192):UNICAST(timeout=300,600,1200,2400):pbcast.STABLE(desired_avg_gossip=20000):FRAG(frag_size=8096;down_thread=false;up_thread=false):pbcast.GMS(join_timeout=10000;join_retry_timeout=4000;shun=true;print_local_addr=true) - initialize
2006-02-16 15:00:38,046 [thread-pool-24] INFO com.opensymphony.oscache.plugins.clustersupport.JavaGroupsBroadcastingListener (JavaGroupsBroadcastingListener.java:109) - Starting a new JavaGroups broadcasting listener with properties=UDP(mcast_addr=231.12.21.106;mcast_port=30216;bind_addr=192.168.100.45;ip_ttl=32;mcast_send_buf_size=150000;mcast_recv_buf_size=80000):PING(timeout=2000;num_initial_members=10):MERGE2(min_interval=5000;max_interval=10000):FD_SOCK:VERIFY_SUSPECT(timeout=2000):pbcast.NAKACK(gc_lag=50;retransmit_timeout=300,600,1200,2400,4800;max_xmit_size=8192):UNICAST(timeout=300,600,1200,2400):pbcast.STABLE(desired_avg_gossip=20000):FRAG(frag_size=8096;down_thread=false;up_thread=false):pbcast.GMS(join_timeout=10000;join_retry_timeout=4000;shun=true;print_local_addr=true) - initialize
2006-02-16 15:00:38,062 [thread-pool-24] DEBUG org.jgroups.protocols.AUTOCONF (AUTOCONF.java:165) - frag_size=64000 - senseMaxFragSize
2006-02-16 15:00:38,062 [thread-pool-24] DEBUG org.jgroups.protocols.AUTOCONF (AUTOCONF.java:165) - frag_size=64000 - senseMaxFragSize
2006-02-16 15:00:38,062 [thread-pool-24] DEBUG org.jgroups.protocols.pbcast.GMS (GMS.java:92) - changed role to org.jgroups.protocols.pbcast.ClientGmsImpl - setImpl
2006-02-16 15:00:38,062 [thread-pool-24] DEBUG org.jgroups.protocols.pbcast.GMS (GMS.java:92) - changed role to org.jgroups.protocols.pbcast.ClientGmsImpl - setImpl
2006-02-16 15:00:38,062 [DownHandler (UDP)] DEBUG org.jgroups.protocols.UDP (UDP.java:324) - creating sockets and starting threads - start
2006-02-16 15:00:38,062 [DownHandler (UDP)] DEBUG org.jgroups.protocols.UDP (UDP.java:324) - creating sockets and starting threads - start
2006-02-16 15:00:38,078 [DownHandler (UDP)] INFO org.jgroups.protocols.UDP (UDP.java:866) - unicast sockets will use interface 192.168.100.45 - createSockets
2006-02-16 15:00:38,078 [DownHandler (UDP)] INFO org.jgroups.protocols.UDP (UDP.java:866) - unicast sockets will use interface 192.168.100.45 - createSockets
2006-02-16 15:00:38,078 [DownHandler (UDP)] INFO org.jgroups.protocols.UDP (UDP.java:922) - socket information:
local_addr=newweb1-staging:3858, mcast_addr=231.12.21.106:30216, bind_addr=/192.168.100.45, ttl=32
sock: bound to 192.168.100.45:3858, receive buffer size=64000, send buffer size=32000
mcast_recv_sock: bound to 192.168.100.45:30216, send buffer size=150000, receive buffer size=80000
mcast_send_sock: bound to 192.168.100.45:3859, send buffer size=150000, receive buffer size=80000 - createSockets
2006-02-16 15:00:38,078 [DownHandler (UDP)] INFO org.jgroups.protocols.UDP (UDP.java:922) - socket information:
local_addr=newweb1-staging:3858, mcast_addr=231.12.21.106:30216, bind_addr=/192.168.100.45, ttl=32
sock: bound to 192.168.100.45:3858, receive buffer size=64000, send buffer size=32000
mcast_recv_sock: bound to 192.168.100.45:30216, send buffer size=150000, receive buffer size=80000
mcast_send_sock: bound to 192.168.100.45:3859, send buffer size=150000, receive buffer size=80000 - createSockets
2006-02-16 15:00:38,078 [DownHandler (UDP)] DEBUG org.jgroups.protocols.UDP (UDP.java:1103) - created unicast receiver thread - startThreads
2006-02-16 15:00:38,078 [DownHandler (UDP)] DEBUG org.jgroups.protocols.UDP (UDP.java:1103) - created unicast receiver thread - startThreads
2006-02-16 15:00:38,078 [ServerSocketHandler thread] DEBUG org.jgroups.protocols.FD_SOCK (FD_SOCK.java:780) - waiting for client connections on port 49154 - run
2006-02-16 15:00:38,078 [ServerSocketHandler thread] DEBUG org.jgroups.protocols.FD_SOCK (FD_SOCK.java:780) - waiting for client connections on port 49154 - run
2006-02-16 15:00:38,078 [DownHandler (PING)] DEBUG org.jgroups.protocols.PING (PING.java:352) - FIND_INITIAL_MBRS - down
2006-02-16 15:00:38,078 [DownHandler (PING)] DEBUG org.jgroups.protocols.PING (PING.java:352) - FIND_INITIAL_MBRS - down
2006-02-16 15:00:38,078 [FD_SOCK Ping thread] DEBUG org.jgroups.protocols.FD_SOCK (FD_SOCK.java:315) - pinger_thread started - run
2006-02-16 15:00:38,078 [FD_SOCK Ping thread] DEBUG org.jgroups.protocols.FD_SOCK (FD_SOCK.java:315) - pinger_thread started - run
2006-02-16 15:00:38,078 [DownHandler (PING)] DEBUG org.jgroups.protocols.PING (PING.java:369) - waiting for initial members: time_to_wait=2000, got 0 rsps - down
2006-02-16 15:00:38,078 [DownHandler (PING)] DEBUG org.jgroups.protocols.PING (PING.java:369) - waiting for initial members: time_to_wait=2000, got 0 rsps - down
2006-02-16 15:00:38,078 [DownHandler (UDP)] DEBUG org.jgroups.protocols.UDP (UDP.java:756) - sending message to 231.12.21.106:30216 (src=newweb1-staging:3858), headers are {PING=[PING: type=GET_MBRS_REQ, arg=null], UDP=[UDP:group_addr=OSCacheBus]} - sendUdpMessage
2006-02-16 15:00:38,078 [DownHandler (UDP)] DEBUG org.jgroups.protocols.UDP (UDP.java:756) - sending message to 231.12.21.106:30216 (src=newweb1-staging:3858), headers are {PING=[PING: type=GET_MBRS_REQ, arg=null], UDP=[UDP:group_addr=OSCacheBus]} - sendUdpMessage
2006-02-16 15:00:38,078 [FD_SOCK Ping thread] DEBUG org.jgroups.protocols.FD_SOCK (FD_SOCK.java:320) - determinePingDest()=null, pingable_mbrs=[] - run
2006-02-16 15:00:38,078 [FD_SOCK Ping thread] DEBUG org.jgroups.protocols.FD_SOCK (FD_SOCK.java:320) - determinePingDest()=null, pingable_mbrs=[] - run
2006-02-16 15:00:38,078 [DownHandler (UDP)] DEBUG org.jgroups.protocols.UDP (UDP.java:773) - looped back local message [dst: 231.12.21.106:30216, src: newweb1-staging:3858 (2 headers), size = 0 bytes] - sendUdpMessage
2006-02-16 15:00:38,078 [DownHandler (UDP)] DEBUG org.jgroups.protocols.UDP (UDP.java:773) - looped back local message [dst: 231.12.21.106:30216, src: newweb1-staging:3858 (2 headers), size = 0 bytes] - sendUdpMessage
2006-02-16 15:00:38,078 [FD_SOCK Ping thread] DEBUG org.jgroups.protocols.FD_SOCK (FD_SOCK.java:359) - pinger thread terminated - run
2006-02-16 15:00:38,078 [FD_SOCK Ping thread] DEBUG org.jgroups.protocols.FD_SOCK (FD_SOCK.java:359) - pinger thread terminated - run
2006-02-16 15:00:38,078 [UDP mcast receiver] DEBUG org.jgroups.protocols.UDP (UDP.java:219) - received (mcast) 98 bytes from /192.168.100.45:3859 (size=98 bytes) - run
2006-02-16 15:00:38,078 [UDP mcast receiver] DEBUG org.jgroups.protocols.UDP (UDP.java:219) - received (mcast) 98 bytes from /192.168.100.45:3859 (size=98 bytes) - run
2006-02-16 15:00:38,078 [UDP mcast receiver] DEBUG org.jgroups.protocols.UDP (UDP.java:707) - discarded own loopback multicast packet - handleMessage
2006-02-16 15:00:38,078 [UDP mcast receiver] DEBUG org.jgroups.protocols.UDP (UDP.java:707) - discarded own loopback multicast packet - handleMessage
2006-02-16 15:00:40,078 [DownHandler (PING)] DEBUG org.jgroups.protocols.PING (PING.java:384) - initial mbrs are [] - down
2006-02-16 15:00:40,078 [DownHandler (PING)] DEBUG org.jgroups.protocols.PING (PING.java:384) - initial mbrs are [] - down
2006-02-16 15:00:40,078 [DownHandler (GMS)] DEBUG org.jgroups.protocols.pbcast.ClientGmsImpl (ClientGmsImpl.java:60) - initial_mbrs are [] - join
2006-02-16 15:00:40,078 [DownHandler (GMS)] DEBUG org.jgroups.protocols.pbcast.ClientGmsImpl (ClientGmsImpl.java:60) - initial_mbrs are [] - join
2006-02-16 15:00:40,078 [DownHandler (GMS)] DEBUG org.jgroups.protocols.pbcast.ClientGmsImpl (ClientGmsImpl.java:69) - no initial members discovered: creating group as first member - join
2006-02-16 15:00:40,078 [DownHandler (GMS)] DEBUG org.jgroups.protocols.pbcast.ClientGmsImpl (ClientGmsImpl.java:69) - no initial members discovered: creating group as first member - join
2006-02-16 15:00:40,078 [DownHandler (GMS)] DEBUG org.jgroups.protocols.pbcast.GMS (GMS.java:306) - [local_addr=newweb1-staging:3858] view is [newweb1-staging:3858|0] [newweb1-staging:3858] - installView
2006-02-16 15:00:40,078 [DownHandler (GMS)] DEBUG org.jgroups.protocols.pbcast.GMS (GMS.java:306) - [local_addr=newweb1-staging:3858] view is [newweb1-staging:3858|0] [newweb1-staging:3858] - installView
2006-02-16 15:00:40,078 [DownHandler (GMS)] DEBUG org.jgroups.protocols.pbcast.GMS (GMS.java:92) - newweb1-staging:3858 changed role to org.jgroups.protocols.pbcast.CoordGmsImpl - setImpl
2006-02-16 15:00:40,078 [thread-pool-24] INFO com.opensymphony.oscache.plugins.clustersupport.JavaGroupsBroadcastingListener (JavaGroupsBroadcastingListener.java:117) - JavaGroups clustering support started successfully - initialize
2006-02-16 15:00:40,078 [DownHandler (GMS)] DEBUG org.jgroups.protocols.pbcast.GMS (GMS.java:92) - newweb1-staging:3858 changed role to org.jgroups.protocols.pbcast.CoordGmsImpl - setImpl
2006-02-16 15:00:40,078 [DownHandler (STABLE)] DEBUG org.jgroups.protocols.pbcast.STABLE (STABLE.java:322) - stable task started; num_gossip_runs=3, max_gossip_runs=3 - startStableTask
2006-02-16 15:00:40,078 [PullPushAdapterThread] INFO com.opensymphony.oscache.plugins.clustersupport.JavaGroupsBroadcastingListener (JavaGroupsBroadcastingListener.java:184) - A new member at address 'newweb1-staging:3858' has joined the cluster - memberJoined
2006-02-16 15:00:40,078 [thread-pool-24] INFO com.opensymphony.oscache.plugins.clustersupport.JavaGroupsBroadcastingListener (JavaGroupsBroadcastingListener.java:117) - JavaGroups clustering support started successfully - initialize
2006-02-16 15:00:40,093 [DownHandler (GMS)] DEBUG org.jgroups.protocols.pbcast.GMS (GMS.java:92) - newweb1-staging:3858 changed role to org.jgroups.protocols.pbcast.CoordGmsImpl - setImpl
2006-02-16 15:00:40,078 [DownHandler (STABLE)] DEBUG org.jgroups.protocols.pbcast.STABLE (STABLE.java:322) - stable task started; num_gossip_runs=3, max_gossip_runs=3 - startStableTask
2006-02-16 15:00:40,078 [PullPushAdapterThread] INFO com.opensymphony.oscache.plugins.clustersupport.JavaGroupsBroadcastingListener (JavaGroupsBroadcastingListener.java:184) - A new member at address 'newweb1-staging:3858' has joined the cluster - memberJoined
2006-02-16 15:00:40,093 [DownHandler (FD_SOCK)] DEBUG org.jgroups.protocols.FD_SOCK (FD_SOCK.java:251) - VIEW_CHANGE received: [newweb1-staging:3858] - down
2006-02-16 15:00:40,093 [DownHandler (FD_SOCK)] DEBUG org.jgroups.protocols.FD_SOCK (FD_SOCK.java:251) - VIEW_CHANGE received: [newweb1-staging:3858] - down
2006-02-16 15:00:40,093 [DownHandler (FD_SOCK)] DEBUG org.jgroups.protocols.FD_SOCK (FD_SOCK.java:490) - first member; cache is empty - getCacheFromCoordinator
2006-02-16 15:00:40,093 [DownHandler (FD_SOCK)] DEBUG org.jgroups.protocols.FD_SOCK (FD_SOCK.java:490) - first member; cache is empty - getCacheFromCoordinator
2006-02-16 15:00:40,093 [DownHandler (FD_SOCK)] DEBUG org.jgroups.protocols.FD_SOCK (FD_SOCK.java:577) - hdr=I_HAVE_SOCK, mbr=newweb1-staging:3858, sock_addr=newweb1-staging:49154 - sendIHaveSockMessage
2006-02-16 15:00:40,093 [DownHandler (FD_SOCK)] DEBUG org.jgroups.protocols.FD_SOCK (FD_SOCK.java:577) - hdr=I_HAVE_SOCK, mbr=newweb1-staging:3858, sock_addr=newweb1-staging:49154 - sendIHaveSockMessage
2006-02-16 15:00:40,093 [DownHandler (UDP)] DEBUG org.jgroups.protocols.UDP (UDP.java:756) - sending message to 231.12.21.106:30216 (src=newweb1-staging:3858), headers are {FD_SOCK=I_HAVE_SOCK, mbr=newweb1-staging:3858, sock_addr=newweb1-staging:49154, UDP=[UDP:group_addr=OSCacheBus]} - sendUdpMessage
2006-02-16 15:00:40,093 [DownHandler (UDP)] DEBUG org.jgroups.protocols.UDP (UDP.java:756) - sending message to 231.12.21.106:30216 (src=newweb1-staging:3858), headers are {FD_SOCK=I_HAVE_SOCK, mbr=newweb1-staging:3858, sock_addr=newweb1-staging:49154, UDP=[UDP:group_addr=OSCacheBus]} - sendUdpMessage
2006-02-16 15:00:40,093 [DownHandler (UDP)] DEBUG org.jgroups.protocols.UDP (UDP.java:773) - looped back local message [dst: 231.12.21.106:30216, src: newweb1-staging:3858 (2 headers), size = 0 bytes] - sendUdpMessage
2006-02-16 15:00:40,093 [DownHandler (UDP)] DEBUG org.jgroups.protocols.UDP (UDP.java:773) - looped back local message [dst: 231.12.21.106:30216, src: newweb1-staging:3858 (2 headers), size = 0 bytes] - sendUdpMessage
2006-02-16 15:00:40,093 [UDP mcast receiver] DEBUG org.jgroups.protocols.UDP (UDP.java:219) - received (mcast) 182 bytes from /192.168.100.45:3859 (size=182 bytes) - run
2006-02-16 15:00:40,093 [UDP mcast receiver] DEBUG org.jgroups.protocols.UDP (UDP.java:219) - received (mcast) 182 bytes from /192.168.100.45:3859 (size=182 bytes) - run
2006-02-16 15:00:40,093 [UDP mcast receiver] DEBUG org.jgroups.protocols.UDP (UDP.java:707) - discarded own loopback multicast packet - handleMessage
2006-02-16 15:00:40,093 [UDP mcast receiver] DEBUG org.jgroups.protocols.UDP (UDP.java:707) - discarded own loopback multicast packet - handleMessage
2006-02-16 15:00:40,093 [DownHandler (GMS)] DEBUG org.jgroups.protocols.pbcast.GMS (GMS.java:92) - newweb1-staging:3858 changed role to org.jgroups.protocols.pbcast.CoordGmsImpl - setImpl
2006-02-16 15:00:40,093 [DownHandler (GMS)] DEBUG org.jgroups.protocols.pbcast.ClientGmsImpl (ClientGmsImpl.java:340) - created group (first member). My view is [newweb1-staging:3858|0], impl is org.jgroups.protocols.pbcast.CoordGmsImpl - becomeSingletonMember
2006-02-16 15:00:40,093 [DownHandler (GMS)] DEBUG org.jgroups.protocols.pbcast.ClientGmsImpl (ClientGmsImpl.java:340) - created group (first member). My view is [newweb1-staging:3858|0], impl is org.jgroups.protocols.pbcast.CoordGmsImpl - becomeSingletonMember
2006-02-16 15:00:40,093 [UpHandler (FD_SOCK)] DEBUG org.jgroups.protocols.FD_SOCK (FD_SOCK.java:186) - i-have-sock: newweb1-staging:3858 --> newweb1-staging:49154 (cache is {newweb1-staging:3858=newweb1-staging:49154}) - up
2006-02-16 15:00:40,093 [UpHandler (FD_SOCK)] DEBUG org.jgroups.protocols.FD_SOCK (FD_SOCK.java:186) - i-have-sock: newweb1-staging:3858 --> newweb1-staging:49154 (cache is {newweb1-staging:3858=newweb1-staging:49154}) - up
2006-02-16 15:00:40,093 [MERGE2.FindSubgroups thread] DEBUG org.jgroups.protocols.MERGE2 (MERGE2.java:230) - merge task started - run
2006-02-16 15:00:40,093 [MERGE2.FindSubgroups thread] DEBUG org.jgroups.protocols.MERGE2 (MERGE2.java:230) - merge task started - run
2006-02-16 15:00:40,093 [thread-pool-24] WARN com.inno.factory.XMLFileConfigurationManager (?:?) - XML file validation not supported by XML parser. - getDocument
2006-02-16 15:00:41,953 [thread-pool-24] INFO com.opensymphony.oscache.plugins.clustersupport.JavaGroupsBroadcastingListener (JavaGroupsBroadcastingListener.java:109) - Starting a new JavaGroups broadcasting listener with properties=UDP(mcast_addr=231.12.21.105;mcast_port=30215;bind_addr=192.168.100.45;ip_ttl=32;mcast_send_buf_size=150000;mcast_recv_buf_size=80000):PING(timeout=2000;num_initial_members=10):MERGE2(min_interval=5000;max_interval=10000):FD_SOCK:VERIFY_SUSPECT(timeout=2000):pbcast.NAKACK(gc_lag=50;retransmit_timeout=300,600,1200,2400,4800;max_xmit_size=8192):UNICAST(timeout=300,600,1200,2400):pbcast.STABLE(desired_avg_gossip=20000):FRAG(frag_size=8096;down_thread=false;up_thread=false):pbcast.GMS(join_timeout=10000;join_retry_timeout=4000;shun=true;print_local_addr=true) - initialize
2006-02-16 15:00:41,953 [thread-pool-24] INFO com.opensymphony.oscache.plugins.clustersupport.JavaGroupsBroadcastingListener (JavaGroupsBroadcastingListener.java:109) - Starting a new JavaGroups broadcasting listener with properties=UDP(mcast_addr=231.12.21.105;mcast_port=30215;bind_addr=192.168.100.45;ip_ttl=32;mcast_send_buf_size=150000;mcast_recv_buf_size=80000):PING(timeout=2000;num_initial_members=10):MERGE2(min_interval=5000;max_interval=10000):FD_SOCK:VERIFY_SUSPECT(timeout=2000):pbcast.NAKACK(gc_lag=50;retransmit_timeout=300,600,1200,2400,4800;max_xmit_size=8192):UNICAST(timeout=300,600,1200,2400):pbcast.STABLE(desired_avg_gossip=20000):FRAG(frag_size=8096;down_thread=false;up_thread=false):pbcast.GMS(join_timeout=10000;join_retry_timeout=4000;shun=true;print_local_addr=true) - initialize
2006-02-16 15:00:41,968 [thread-pool-24] DEBUG org.jgroups.protocols.AUTOCONF (AUTOCONF.java:165) - frag_size=64000 - senseMaxFragSize
2006-02-16 15:00:41,968 [thread-pool-24] DEBUG org.jgroups.protocols.AUTOCONF (AUTOCONF.java:165) - frag_size=64000 - senseMaxFragSize
2006-02-16 15:00:41,968 [thread-pool-24] DEBUG org.jgroups.protocols.pbcast.GMS (GMS.java:92) - changed role to org.jgroups.protocols.pbcast.ClientGmsImpl - setImpl
2006-02-16 15:00:41,968 [thread-pool-24] DEBUG org.jgroups.protocols.pbcast.GMS (GMS.java:92) - changed role to org.jgroups.protocols.pbcast.ClientGmsImpl - setImpl
2006-02-16 15:00:41,968 [DownHandler (UDP)] DEBUG org.jgroups.protocols.UDP (UDP.java:324) - creating sockets and starting threads - start
2006-02-16 15:00:41,968 [DownHandler (UDP)] DEBUG org.jgroups.protocols.UDP (UDP.java:324) - creating sockets and starting threads - start
2006-02-16 15:00:41,968 [DownHandler (UDP)] INFO org.jgroups.protocols.UDP (UDP.java:866) - unicast sockets will use interface 192.168.100.45 - createSockets
2006-02-16 15:00:41,968 [DownHandler (UDP)] INFO org.jgroups.protocols.UDP (UDP.java:866) - unicast sockets will use interface 192.168.100.45 - createSockets
2006-02-16 15:00:41,984 [DownHandler (UDP)] INFO org.jgroups.protocols.UDP (UDP.java:922) - socket information:
local_addr=newweb1-staging:3863, mcast_addr=231.12.21.105:30215, bind_addr=/192.168.100.45, ttl=32
sock: bound to 192.168.100.45:3863, receive buffer size=64000, send buffer size=32000
mcast_recv_sock: bound to 192.168.100.45:30215, send buffer size=150000, receive buffer size=80000
mcast_send_sock: bound to 192.168.100.45:3864, send buffer size=150000, receive buffer size=80000 - createSockets
2006-02-16 15:00:41,984 [DownHandler (UDP)] INFO org.jgroups.protocols.UDP (UDP.java:922) - socket information:
local_addr=newweb1-staging:3863, mcast_addr=231.12.21.105:30215, bind_addr=/192.168.100.45, ttl=32
sock: bound to 192.168.100.45:3863, receive buffer size=64000, send buffer size=32000
mcast_recv_sock: bound to 192.168.100.45:30215, send buffer size=150000, receive buffer size=80000
mcast_send_sock: bound to 192.168.100.45:3864, send buffer size=150000, receive buffer size=80000 - createSockets
2006-02-16 15:00:41,984 [DownHandler (UDP)] DEBUG org.jgroups.protocols.UDP (UDP.java:1103) - created unicast receiver thread - startThreads
2006-02-16 15:00:41,984 [DownHandler (UDP)] DEBUG org.jgroups.protocols.UDP (UDP.java:1103) - created unicast receiver thread - startThreads
2006-02-16 15:00:41,984 [ServerSocketHandler thread] DEBUG org.jgroups.protocols.FD_SOCK (FD_SOCK.java:780) - waiting for client connections on port 49155 - run
2006-02-16 15:00:41,984 [ServerSocketHandler thread] DEBUG org.jgroups.protocols.FD_SOCK (FD_SOCK.java:780) - waiting for client connections on port 49155 - run
2006-02-16 15:00:41,984 [DownHandler (PING)] DEBUG org.jgroups.protocols.PING (PING.java:352) - FIND_INITIAL_MBRS - down
2006-02-16 15:00:41,984 [DownHandler (PING)] DEBUG org.jgroups.protocols.PING (PING.java:352) - FIND_INITIAL_MBRS - down
2006-02-16 15:00:41,984 [FD_SOCK Ping thread] DEBUG org.jgroups.protocols.FD_SOCK (FD_SOCK.java:315) - pinger_thread started - run
2006-02-16 15:00:41,984 [FD_SOCK Ping thread] DEBUG org.jgroups.protocols.FD_SOCK (FD_SOCK.java:315) - pinger_thread started - run
2006-02-16 15:00:41,984 [DownHandler (PING)] DEBUG org.jgroups.protocols.PING (PING.java:369) - waiting for initial members: time_to_wait=2000, got 0 rsps - down
2006-02-16 15:00:41,984 [DownHandler (PING)] DEBUG org.jgroups.protocols.PING (PING.java:369) - waiting for initial members: time_to_wait=2000, got 0 rsps - down
2006-02-16 15:00:41,984 [DownHandler (UDP)] DEBUG org.jgroups.protocols.UDP (UDP.java:756) - sending message to 231.12.21.105:30215 (src=newweb1-staging:3863), headers are {PING=[PING: type=GET_MBRS_REQ, arg=null], UDP=[UDP:group_addr=OSCacheBus]} - sendUdpMessage
20

While debugging i find these props in the GeneralCacheAdministrator

{cache.cluster.properties=UDP(mcast_addr=231.12.21.106;mcast_port=30216;bind_addr=192.168.100.51;ip_ttl=32;mcast_send_buf_size=150000;mcast_recv_buf_size=80000):PING(timeout=2000;num_initial_members=10):MERGE2(min_interval=5000;max_interval=10000):FD_SOCK:VERIFY_SUSPECT(timeout=2000):pbcast.NAKACK(gc_lag=50;retransmit_timeout=300,600,1200,2400,4800;max_xmit_size=8192):UNICAST(timeout=300,600,1200,2400):pbcast.STABLE(desired_avg_gossip=20000):FRAG(frag_size=8096;down_thread=false;up_thread=false):pbcast.GMS(join_timeout=10000;join_retry_timeout=4000;shun=true;print_local_addr=true), cache.algorithm=com.opensymphony.oscache.base.algorithm.LRUCache, cache.cluster.use.jgroups=true, gdp.cache.debug=false, gdp.cache.lifetime=900, cache.capacity=100, cache.memory=true, cache.event.listeners=com.opensymphony.oscache.plugins.clustersupport.JavaGroupsBroadcastingListener}

To flush we use flushEntry method by id of the to flush object

thanks

5. Re: Listener ignored => ChannelException: unable to setup th

belaban Feb 16, 2006 10:05 AM (in response to svenschauwvliege)

What exactly doesn't work ? If you can reproduce it, it would be good if you could create a JIRA bug report (http://jira.jboss.com/jira/browse/JGRP) and attach the logs to that case.
Actions
6. Re: Listener ignored => ChannelException: unable to setup th

svenschauwvliege Feb 16, 2006 10:31 AM (in response to svenschauwvliege)

the clustering doesnt work.
is there a way to see in the logs if jgroups sends the "flush command" out to the other nodes? if so where do i look for?
Actions
7. Re: Listener ignored => ChannelException: unable to setup th

belaban Feb 16, 2006 10:48 AM (in response to svenschauwvliege)

I assume flush() is an OSCache method ? Then it is probably sent out using RpcDispatcher.callRemoteMethods("flush", ..). I'd either debug that part and set a breakpoint at flush(), or enable TRACE log for org.jgroups.blocks to see debug info for RpcDispatcher
Actions

Go to original post