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
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)--
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
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