Upgrade issue (1.9.3->1.9.5): Error During JGroups Cluster Setup, failed to start protocol stack

141 views
Skip to first unread message

Chris McCracken

unread,
Mar 28, 2012, 2:45:35 PM3/28/12
to dot...@googlegroups.com

I just upgraded our development system from 1.9.3 to 1.9.5 and am attempting to set up the new Jgroups clustered cache. During server startup, its throwing an error (and more continued errors after startup) and the java process never binds a port for the cache. Iptables is currently off for testing purposes (same error either way), and the error is the same if I have the cache set for IPv4 or IPv6 (our servers are only using IPv4, however). I have not yet tested using TCP, as UDP multicast seems to be lighter-weight and preferred.  I’m not sure if log4j is causing the problem, or just unable to log the trace correctly (log4j is completely out-of-the-box config, no customizations from our end).

 

Thanks in advance for any help!

 

Here’s the pertinent data:

 

Cache config from dotmarketing-config-ext.properties:

CACHE_CLUSTER_THROUGH_DB=false

CACHE_FORCE_IPV4=true

CACHE_BINDPORT=7800

CACHE_BINDADDRESS=192.168.1.52

CACHE_PROTOCOL=udp

CACHE_MULTICAST_PORT=45588

CACHE_MULTICAST_ADDRESS=228.10.10.10

DIST_INDEXATION_ENABLED=true

DIST_INDEXATION_SERVER_ID=2

DIST_INDEXATION_SERVERS_IDS=1,2

 

 

# lsof –I –nP:

java      15230    root   46u  IPv6  33598      0t0  TCP 127.0.0.1:8080 (LISTEN)

java      15230    root   48u  IPv6  33599      0t0  TCP 127.0.0.1:8081 (LISTEN)

java      15230    root   52r  IPv6  33938      0t0  TCP 127.0.0.1:8005 (LISTEN)

java      15230    root  207u  IPv6  33605      0t0  TCP 192.168.1.52:54533->10.5.1.40:1433 (ESTABLISHED)

java      15230    root  228u  IPv6  33626      0t0  TCP 192.168.1.52:54534->10.5.1.40:1433 (ESTABLISHED)

java      15230    root  231u  IPv6  33628      0t0  TCP 192.168.1.52:54535->10.5.1.40:1433 (ESTABLISHED)

java      15230    root  232u  IPv6  33629      0t0  TCP 192.168.1.52:54536->10.5.1.40:1433 (ESTABLISHED)

java      15230    root  272u  IPv6  34370      0t0  TCP 192.168.1.52:39570->10.5.1.40:1433 (ESTABLISHED)

 

…and of course catalina.out:

 

2012-03-28 13:05:47,611 INFO  com.dotmarketing.business.DotGuavaCacheAdministratorImpl - ***     Starting JGroups Cluster Setup

2012-03-28 13:05:47,611 INFO  com.dotmarketing.business.DotGuavaCacheAdministratorImpl - ***     Going to load JGroups with this Classpath file cache-jgroups-udp.xml

2012-03-28 13:05:47,611 INFO  com.dotmarketing.business.DotGuavaCacheAdministratorImpl - ***     Using 192.168.1.52 as the bindaddress

2012-03-28 13:05:47,611 INFO  com.dotmarketing.business.DotGuavaCacheAdministratorImpl - ***     Using 7800 as the bindport

2012-03-28 13:05:47,611 INFO  com.dotmarketing.business.DotGuavaCacheAdministratorImpl - ***     Setting up UDP Prperties

2012-03-28 13:05:47,611 INFO  com.dotmarketing.business.DotGuavaCacheAdministratorImpl - ***     Setting up JCannel

2012-03-28 13:05:47,746 INFO  org.jgroups.JChannel - JGroups version: 2.12.2.Final

2012-03-28 13:05:48,050 INFO  com.dotmarketing.business.DotGuavaCacheAdministratorImpl - Error During JGroups Cluster Setup

2012-03-28 13:05:48,051 FATAL com.dotmarketing.business.DotGuavaCacheAdministratorImpl - failed to start protocol stack

org.jgroups.ChannelException: failed to start protocol stack

        at org.jgroups.JChannel.startStack(JChannel.java:1787)

        at org.jgroups.JChannel.connect(JChannel.java:413)

        at org.jgroups.JChannel.connect(JChannel.java:388)

        at com.dotmarketing.business.DotGuavaCacheAdministratorImpl.<init>(DotGuavaCacheAdministratorImpl.java:195)

        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)

        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)

        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)

        at java.lang.reflect.Constructor.newInstance(Constructor.java:513)

        at java.lang.Class.newInstance0(Class.java:355)

        at java.lang.Class.newInstance(Class.java:308)

        at com.dotmarketing.business.CacheLocator.init(CacheLocator.java:62)

        at com.dotmarketing.business.CacheLocator.getInstance(CacheLocator.java:164)

        at com.dotmarketing.business.CacheLocator.getContentletCache(CacheLocator.java:87)

        at com.dotmarketing.portlets.contentlet.business.ContentletFactoryDBImpl.<init>(ContentletFactoryDBImpl.java:71)

        at com.dotmarketing.business.FactoryIndex.create(FactoryLocator.java:223)

        at com.dotmarketing.business.FactoryLocator.createService(FactoryLocator.java:179)

        at com.dotmarketing.business.FactoryLocator.createService(FactoryLocator.java:51)

        at com.dotmarketing.business.Locator.getServiceInstance(Locator.java:41)

        at com.dotmarketing.business.FactoryLocator.getInstance(FactoryLocator.java:169)

        at com.dotmarketing.business.FactoryLocator.getContentletFactory(FactoryLocator.java:78)

        at com.dotmarketing.portlets.contentlet.business.ContentletAPIImpl.<init>(ContentletAPIImpl.java:129)

        at com.dotmarketing.business.APIIndex.create(APILocator.java:318)

        at com.dotmarketing.business.APILocator.createService(APILocator.java:263)

        at com.dotmarketing.business.APILocator.createService(APILocator.java:69)

        at com.dotmarketing.business.Locator.getServiceInstance(Locator.java:41)

        at com.dotmarketing.business.APILocator.getInstance(APILocator.java:251)

        at com.dotmarketing.business.APILocator.getContentletAPIImpl(APILocator.java:124)

        at com.dotmarketing.portlets.contentlet.business.ContentletAPIInterceptor.<init>(ContentletAPIInterceptor.java:51)

        at com.dotmarketing.business.APIIndex.create(APILocator.java:319)

        at com.dotmarketing.business.APILocator.createService(APILocator.java:263)

        at com.dotmarketing.business.APILocator.createService(APILocator.java:69)

        at com.dotmarketing.business.Locator.getServiceInstance(Locator.java:41)

        at com.dotmarketing.business.APILocator.getInstance(APILocator.java:251)

        at com.dotmarketing.business.APILocator.getContentletAPI(APILocator.java:133)

        at com.dotmarketing.cms.urlmap.filters.URLMapFilter.init(URLMapFilter.java:318)

        at org.apache.catalina.core.ApplicationFilterConfig.getFilter(ApplicationFilterConfig.java:295)

        at org.apache.catalina.core.ApplicationFilterConfig.setFilterDef(ApplicationFilterConfig.java:422)

        at org.apache.catalina.core.ApplicationFilterConfig.<init>(ApplicationFilterConfig.java:115)

        at org.apache.catalina.core.StandardContext.filterStart(StandardContext.java:3838)

        at org.apache.catalina.core.StandardContext.start(StandardContext.java:4488)

        at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:791)

        at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:771)

        at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:546)

        at org.apache.catalina.startup.HostConfig.deployDescriptor(HostConfig.java:637)

        at org.apache.catalina.startup.HostConfig.deployDescriptors(HostConfig.java:563)

        at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:498)

        at org.apache.catalina.startup.HostConfig.start(HostConfig.java:1277)

        at org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:321)

        at org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:119)

        at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1053)

        at org.apache.catalina.core.StandardHost.start(StandardHost.java:785)

        at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1045)

        at org.apache.catalina.core.StandardEngine.start(StandardEngine.java:443)

        at org.apache.catalina.core.StandardService.start(StandardService.java:519)

        at org.apache.catalina.core.StandardServer.start(StandardServer.java:710)

        at org.apache.catalina.startup.Catalina.start(Catalina.java:581)

        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)

        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)

        at java.lang.reflect.Method.invoke(Method.java:597)

        at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:289)

        at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:414)

Caused by: java.lang.NoSuchMethodError: org.apache.log4j.Logger.isTraceEnabled()Z

        at org.jgroups.logging.Log4JLogImpl.isTraceEnabled(Log4JLogImpl.java:48)

        at org.jgroups.protocols.pbcast.STABLE.startStableTask(STABLE.java:462)

        at org.jgroups.protocols.pbcast.STABLE.start(STABLE.java:226)

        at org.jgroups.stack.ProtocolStack.startStack(ProtocolStack.java:990)

        at org.jgroups.JChannel.startStack(JChannel.java:1784)

        ... 61 more

 

….

 

2012-03-28 13:05:58,052 ERROR org.jgroups.util.TimeScheduler2 - failed running task org.jgroups.protocols.pbcast.STABLE$StableTask@3b4d82e1

java.lang.NoSuchMethodError: org.apache.log4j.Logger.isTraceEnabled()Z

        at org.jgroups.logging.Log4JLogImpl.isTraceEnabled(Log4JLogImpl.java:48)

        at org.jgroups.protocols.pbcast.STABLE$StableTask.run(STABLE.java:806)

        at org.jgroups.util.TimeScheduler2$RecurringTask.run(TimeScheduler2.java:592)

        at org.jgroups.util.TimeScheduler2$MyTask.run(TimeScheduler2.java:524)

        at org.jgroups.util.TimeScheduler2$Entry.execute(TimeScheduler2.java:429)

        at org.jgroups.util.TimeScheduler2$1.run(TimeScheduler2.java:295)

        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)

        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)

        at java.lang.Thread.run(Thread.java:662)

 

 

 

\ Chris McCracken
/ Internet Services Administrator
\ St Charles Community College
/ (636) 922-8456
\ cmccr...@stchas.edu

 

Jorge Urdaneta

unread,
Mar 28, 2012, 2:53:42 PM3/28/12
to dot...@googlegroups.com
I think the problem is

Caused by: java.lang.NoSuchMethodError: org.apache.log4j.Logger.isTraceEnabled()Z

        at org.jgroups.logging.Log4JLogImpl.isTraceEnabled(Log4JLogImpl.java:48)

        at org.jgroups.protocols.pbcast.STABLE.startStableTask(STABLE.java:462)

        at org.jgroups.protocols.pbcast.STABLE.start(STABLE.java:226)

        at org.jgroups.stack.ProtocolStack.startStack(ProtocolStack.java:990)

        at org.jgroups.JChannel.startStack(JChannel.java:1784)

And it looks like you have log4j versions conflict. Make sure you only have the log4j-1.2.16.jar we provide on tomcat/lib. And no other comming to the classpath.

The method isTraceEnabled() were introduced in Log4j 1.2.12
--
You received this message because you are subscribed to the Google Groups "dotCMS User Group" group.
To post to this group, send email to dot...@googlegroups.com.
To unsubscribe from this group, send email to dotcms+un...@googlegroups.com.
For more options, visit this group at http://groups.google.com/group/dotcms?hl=en.

-- 
Jorge Urdaneta
dotCMS developer

Chris McCracken

unread,
Mar 28, 2012, 4:41:49 PM3/28/12
to dot...@googlegroups.com

Thanks a lot, that helped. I had another log4j.jar in the tomcat/lib directory that looks like it came from our initial 1.9 install and was never removed by the update that dropped 1.2.16 in there. After removing that, I ran into a new error (which follows) that was resolved by adding “-Djava.net.preferIPv4Stack=true” to the JAVA_OPTS in the startup script (in case someone else runs into the same problem). Now on to re-enabling iptables and nailing down some rules for the Jgroups multicast….

 

Error during startup:

2012-03-28 15:18:32,604 ERROR org.jgroups.protocols.UDP - failed sending message to cluster (115 bytes): java.lang.Exception: dest=/228.10.10.10:45588 (118 bytes), cause: java.io.IOException: Invalid argument

 

…with recurring instances of:

2012-03-28 15:18:37,491 ERROR org.jgroups.protocols.TP$TransferQueueBundler - exception sending bundled msgs: java.lang.Exception: dest=/228.10.10.10:45588 (760 bytes):, cause: java.io.IOException: Invalid argument

 

 

 

\ Chris McCracken
/ Internet Services Administrator
\ St Charles Community College
/ (636) 922-8456
\ cmccr...@stchas.edu

 

Reply all
Reply to author
Forward
0 new messages