Cluster Replication issues in CF10 on RHEL6

Report · Nov 24, 2014

We recently updated our four physical servers to CF10 update 14, and gave them all a reboot to let the latest Kernel and RHEL6 security updates take effect. Each server has two worker instances, cfusion1 and cfusion2, in a round robin cluster.

The servers came back fine after the reboot until the following day. Upon restarting any CF instance, it seems the instance locks up. If I bring both CF instances down, then both back up, the cluster *USUALLY* comes back fine, although sometimes it does not, and I have to reboot the box. To make matteres even weirder, sometimes I can restart an instance, regardless if both are up or down, if I remove the secondary IP address on em1:1. Weird. This issue exists across all four physical servers. I have pulled one out of our web cluster to try to troubleshoot, while the other three limp along.

The major issue is that when one of the instances hang, they do so in a zombie state, where they are half dead, but not dead enough for the tomcate cluster to expire the instance. That means half my requests are processed by the working instance, and the other half my requests queue up indefinitely, eventually bringing my webserver down completely. While it seems that shutting down both instances then bringing both up again usually works, its not something I like to do on production machines. And occasionally, the instance wont come back. These machines have become painfully unstable.

When I attempt to restart cfusion2, heres what I see in the coldfusion-error.log

Nov 24, 2014 6:02:58 PM org.apache.catalina.core.AprLifecycleListener init

INFO: The APR based Apache Tomcat Native library which allows optimal performance in production environments was not found on the java.library.path: /opt/coldfusion10/jre/lib/amd64/server:/opt/coldfusion10/jre/lib/amd64:/opt/coldfusion10/jre/../lib/amd64:/opt/coldfusion10/cfusion2/lib:/opt/coldfusion10/cfusion2/lib/_ilnx21/bin:/opt/coldfusion10/cfusion2/lib/international::/usr/java/packages/lib/amd64:/usr/lib64:/lib64:/lib:/usr/lib

Nov 24, 2014 6:02:59 PM org.apache.coyote.AbstractProtocol init

INFO: Initializing ProtocolHandler ["http-bio-8502"]

Nov 24, 2014 6:02:59 PM org.apache.coyote.AbstractProtocol init

INFO: Initializing ProtocolHandler ["http-bio-8447"]

Nov 24, 2014 6:03:00 PM org.apache.coyote.AbstractProtocol init

INFO: Initializing ProtocolHandler ["ajp-bio-8014"]

Nov 24, 2014 6:03:00 PM org.apache.catalina.core.StandardService startInternal

INFO: Starting service Catalina

Nov 24, 2014 6:03:00 PM org.apache.catalina.core.StandardEngine startInternal

INFO: Starting Servlet Engine: Apache Tomcat/7.0.54

Nov 24, 2014 6:03:00 PM org.apache.catalina.ha.tcp.SimpleTcpCluster startInternal

INFO: Cluster is about to start

Nov 24, 2014 6:03:00 PM org.apache.catalina.tribes.transport.ReceiverBase bind

INFO: Receiver Server Socket bound to:/10.10.240.104:4002

Nov 24, 2014 6:03:00 PM org.apache.catalina.tribes.membership.McastServiceImpl setupSocket

INFO: Setting cluster mcast soTimeout to 500

Nov 24, 2014 6:03:00 PM org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers

INFO: Sleeping for 1000 milliseconds to establish cluster membership, start level:4

Nov 24, 2014 6:03:00 PM org.apache.catalina.ha.tcp.SimpleTcpCluster memberAdded

INFO: Replication member added:org.apache.catalina.tribes.membership.MemberImpl[tcp://{10, 10, 240, 104}:4001,{10, 10, 240, 104},4001, alive=416205, securePort=-1, UDP Port=-1, id={-40 103 -88 33 -118 2 70 76 -125 -43 102 49 -86 -103 123 -42 }, payload={}, command={}, domain={}, ]

Nov 24, 2014 6:03:01 PM org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers

INFO: Done sleeping, membership established, start level:4

Nov 24, 2014 6:03:01 PM org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers

INFO: Sleeping for 1000 milliseconds to establish cluster membership, start level:8

Nov 24, 2014 6:03:01 PM org.apache.catalina.tribes.io.BufferPool getBufferPool

INFO: Created a buffer pool with max size:104857600 bytes of type:org.apache.catalina.tribes.io.BufferPool15Impl

Nov 24, 2014 6:03:02 PM org.apache.catalina.tribes.membership.McastServiceImpl waitForMembers

INFO: Done sleeping, membership established, start level:8

Nov 24, 2014 6:03:04 PM org.apache.catalina.ha.session.ClusterSessionListener messageReceived

WARNING: Context manager doesn't exist:localhost#/

Nov 24, 2014 6:03:05 PM org.apache.catalina.ha.session.ClusterSessionListener messageReceived

WARNING: Context manager doesn't exist:localhost#/

Nov 24, 2014 6:03:06 PM org.apache.catalina.ha.session.DeltaManager startInternal

INFO: Register manager localhost#/ to cluster element Engine with name Catalina

Nov 24, 2014 6:03:06 PM org.apache.catalina.ha.session.DeltaManager startInternal

INFO: Starting clustering manager at localhost#/

Nov 24, 2014 6:03:36 PM org.apache.catalina.tribes.group.interceptors.TcpFailureDetector memberDisappeared

INFO: Received memberDisappeared[org.apache.catalina.tribes.membership.MemberImpl[tcp://{10, 10, 240, 104}:4001,{10, 10, 240, 104},4001, alive=451725, securePort=-1, UDP Port=-1, id={-40 103 -88 33 -118 2 70 76 -125 -43 102 49 -86 -103 123 -42 }, payload={}, command={}, domain={}, ]] message. Will verify.

Nov 24, 2014 6:03:36 PM org.apache.catalina.tribes.group.interceptors.TcpFailureDetector memberDisappeared

INFO: Verification complete. Member still alive[org.apache.catalina.tribes.membership.MemberImpl[tcp://{10, 10, 240, 104}:4001,{10, 10, 240, 104},4001, alive=451725, securePort=-1, UDP Port=-1, id={-40 103 -88 33 -118 2 70 76 -125 -43 102 49 -86 -103 123 -42 }, payload={}, command={}, domain={}, ]]

Nov 24, 2014 6:03:36 PM org.apache.catalina.ha.tcp.SimpleTcpCluster send

SEVERE: Unable to send message through cluster sender.

org.apache.catalina.tribes.ChannelException: Operation has timed out(30000 ms.).; Faulty members:tcp://{10, 10, 240, 104}:4001;

at org.apache.catalina.tribes.transport.nio.ParallelNioSender.sendMessage(ParallelNioSender.java:109)

at org.apache.catalina.tribes.transport.nio.PooledParallelSender.sendMessage(PooledParallelSender.java:54)

at org.apache.catalina.tribes.transport.ReplicationTransmitter.sendMessage(ReplicationTransmitter.java:78)

at org.apache.catalina.tribes.group.ChannelCoordinator.sendMessage(ChannelCoordinator.java:77)

at org.apache.catalina.tribes.group.ChannelInterceptorBase.sendMessage(ChannelInterceptorBase.java:77)

at org.apache.catalina.tribes.group.interceptors.MessageDispatchInterceptor.sendMessage(MessageDispatchInterceptor.java:77)

at org.apache.catalina.tribes.group.ChannelInterceptorBase.sendMessage(ChannelInterceptorBase.java:77)

at org.apache.catalina.tribes.group.interceptors.TcpFailureDetector.sendMessage(TcpFailureDetector.java:93)

at org.apache.catalina.tribes.group.ChannelInterceptorBase.sendMessage(ChannelInterceptorBase.java:77)

at org.apache.catalina.tribes.group.GroupChannel.send(GroupChannel.java:224)

at org.apache.catalina.tribes.group.GroupChannel.send(GroupChannel.java:182)

at org.apache.catalina.ha.tcp.SimpleTcpCluster.send(SimpleTcpCluster.java:837)

at org.apache.catalina.ha.session.DeltaManager.getAllClusterSessions(DeltaManager.java:789)

at org.apache.catalina.ha.session.DeltaManager.startInternal(DeltaManager.java:756)

at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)

at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5476)

at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)

at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1559)

at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1549)

at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)

at java.util.concurrent.FutureTask.run(FutureTask.java:138)

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)

Nov 24, 2014 6:03:36 PM org.apache.catalina.ha.session.DeltaManager getAllClusterSessions

INFO: Manager [localhost#/], requesting session state from org.apache.catalina.tribes.membership.MemberImpl[tcp://{10, 10, 240, 104}:4001,{10, 10, 240, 104},4001, alive=451725, securePort=-1, UDP Port=-1, id={-40 103 -88 33 -118 2 70 76 -125 -43 102 49 -86 -103 123 -42 }, payload={}, command={}, domain={}, ]. This operation will timeout if no session state has been received within 60 seconds.

Nov 24, 2014 6:03:36 PM org.apache.catalina.ha.session.DeltaManager waitForSendAllSessions

INFO: Manager [localhost#/]; session state send at 11/24/14 6:03 PM received in 30,264 ms.

Nov 24, 2014 6:03:36 PM org.apache.catalina.session.StandardSession tellNew

SEVERE: Session event listener threw exception

java.lang.NullPointerException

at coldfusion.bootstrap.HttpFlexSessionBootstrap.getListener(HttpFlexSessionBootstrap.java:154)

at coldfusion.bootstrap.HttpFlexSessionBootstrap.sessionCreated(HttpFlexSessionBootstrap.java:69)

at org.apache.catalina.session.StandardSession.tellNew(StandardSession.java:422)

at org.apache.catalina.session.StandardSession.setId(StandardSession.java:394)

at org.apache.catalina.ha.session.DeltaSession.setId(DeltaSession.java:275)

at org.apache.catalina.ha.session.DeltaManager.handleSESSION_CREATED(DeltaManager.java:1336)

at org.apache.catalina.ha.session.DeltaManager.messageReceived(DeltaManager.java:1214)

at org.apache.catalina.ha.session.DeltaManager.getAllClusterSessions(DeltaManager.java:803)

at org.apache.catalina.ha.session.DeltaManager.startInternal(DeltaManager.java:756)

at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)

at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5476)

at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)

at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1559)

at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1549)

at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)

at java.util.concurrent.FutureTask.run(FutureTask.java:138)

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)

Then when I try to stop the instance, I get this indication of a half dead process:

#/opt/coldfusion10/cfusion2/bin/coldfusion stop

Stopping ColdFusion 10 server instance named cfusion2, please wait

Nov 24, 2014 6:06:03 PM com.adobe.coldfusion.launcher.Launcher stopServer

SEVERE: Shutdown Port 8009is not active. Stop the server only after it is started.

ColdFusion 10 server instance named cfusion2 has been stopped

The working cluster instance cfusion1 shows this in the coldfusion-error.log

Nov 24, 2014 6:06:17 PM org.apache.catalina.tribes.transport.nio.ParallelNioSender doLoop

WARNING: Not retrying send for:tcp://{10, 10, 240, 104}:4002; Sender is disconnected.

Nov 24, 2014 6:06:17 PM org.apache.catalina.tribes.group.interceptors.TcpFailureDetector memberDisappeared

INFO: Received memberDisappeared[org.apache.catalina.tribes.membership.MemberImpl[tcp://{10, 10, 240, 104}:4002,{10, 10, 240, 104},4002, alive=192591, securePort=-1, UDP Port=-1, id={-96 126 -95 87 -79 5 76 -125 -101 -68 -56 -60 90 -22 -1 7 }, payload={}, command={}, domain={}, ]] message. Will verify.

Nov 24, 2014 6:06:17 PM org.apache.catalina.tribes.group.interceptors.TcpFailureDetector memberDisappeared

INFO: Verification complete. Member already disappeared[org.apache.catalina.tribes.membership.MemberImpl[tcp://{10, 10, 240, 104}:4002,{10, 10, 240, 104},4002, alive=192591, securePort=-1, UDP Port=-1, id={-96 126 -95 87 -79 5 76 -125 -101 -68 -56 -60 90 -22 -1 7 }, payload={}, command={}, domain={}, ]]

Nov 24, 2014 6:06:17 PM org.apache.catalina.ha.tcp.SimpleTcpCluster send

SEVERE: Unable to send message through cluster sender.

org.apache.catalina.tribes.ChannelException: Send failed, and sender is disconnected. Not retrying.; Faulty members:tcp://{10, 10, 240, 104}:4002;

at org.apache.catalina.tribes.transport.nio.ParallelNioSender.doLoop(ParallelNioSender.java:171)

at org.apache.catalina.tribes.transport.nio.ParallelNioSender.sendMessage(ParallelNioSender.java:89)