mod_cluster slows the JBoss EAP 5 start up process by trying to connect to down Apache httpd servers

Environment

• JBoss Enterprise Application Platform (EAP) 5
• JBoss Enterprise Web Server (EWS)
  • Apache httpd
  • mod_cluster 1.0.10.GA_CP02

Issue

• JBoss is slow to start and it looks like the delay is due to the main thread taking a long time to time out in its connections to down/unavailable Apache httpd servers through mod_cluster:

12:32:04,345 TRACE [org.jboss.modcluster.mcmp.impl.DefaultMCMPHandler] (main) Sending command [org.jboss.modcluster.mcmp.impl.DefaultMCMPRequest{requestType=INFO,wildcard=false,jvmRoute=null,parameters={}}] to proxy [<apacheip>:6666]
12:38:22,371 INFO  [org.jboss.modcluster.mcmp.impl.DefaultMCMPHandler] (main) IO error sending command INFO to proxy <apacheip>:6666
java.net.ConnectException: Connection timed out
	at java.net.PlainSocketImpl.socketConnect(Native Method)
	at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:333)
	at java.net.PlainSocketImpl.connectToAddress(PlainSocketImpl.java:195)
	at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:182)
	at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:366)
	at java.net.Socket.connect(Socket.java:529)
	at java.net.Socket.connect(Socket.java:478)
	at java.net.Socket.<init>(Socket.java:375)
	at java.net.Socket.<init>(Socket.java:218)
	at javax.net.DefaultSocketFactory.createSocket(SocketFactory.java:212)
	at org.jboss.modcluster.mcmp.impl.DefaultMCMPHandler$Proxy.getConnection(DefaultMCMPHandler.java:1141)

• Thread dumps show the main thread stalled in the following call:

"main" prio=10 tid=0x000000004318d800 nid=0x4085 runnable [0x0000000041822000]
   java.lang.Thread.State: RUNNABLE
	at java.net.PlainSocketImpl.socketConnect(Native Method)
	at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:333)
	- locked <0x00000000f093e6a8> (a java.net.SocksSocketImpl)
	at java.net.PlainSocketImpl.connectToAddress(PlainSocketImpl.java:195)
	at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:182)
	at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:366)
	at java.net.Socket.connect(Socket.java:529)
	at java.net.Socket.connect(Socket.java:478)
	at java.net.Socket.<init>(Socket.java:375)
	at java.net.Socket.<init>(Socket.java:218)
	at javax.net.DefaultSocketFactory.createSocket(SocketFactory.java:212)
	at org.jboss.modcluster.mcmp.impl.DefaultMCMPHandler$Proxy.getConnection(DefaultMCMPHandler.java:1141)
	- locked <0x00000000f08aa980> (a org.jboss.modcluster.mcmp.impl.DefaultMCMPHandler$Proxy)
	at org.jboss.modcluster.mcmp.impl.DefaultMCMPHandler$Proxy.getConnectionWriter(DefaultMCMPHandler.java:1166)
	- locked <0x00000000f08aa980> (a org.jboss.modcluster.mcmp.impl.DefaultMCMPHandler$Proxy)
	at org.jboss.modcluster.mcmp.impl.DefaultMCMPHandler.sendRequest(DefaultMCMPHandler.java:776)
	at org.jboss.modcluster.mcmp.impl.DefaultMCMPHandler.sendRequest(DefaultMCMPHandler.java:875)
	- locked <0x00000000f08aa980> (a org.jboss.modcluster.mcmp.impl.DefaultMCMPHandler$Proxy)
	at org.jboss.modcluster.mcmp.impl.DefaultMCMPHandler.status(DefaultMCMPHandler.java:465)
	at org.jboss.modcluster.mcmp.impl.DefaultMCMPHandler.init(DefaultMCMPHandler.java:140)
	at org.jboss.modcluster.CatalinaEventHandler.init(CatalinaEventHandler.java:113)
	- locked <0x00000000ffdbaac0> (a org.jboss.modcluster.CatalinaEventHandler)
	at org.jboss.modcluster.CatalinaEventHandler.init(CatalinaEventHandler.java:56)
	at org.jboss.modcluster.CatalinaEventHandlerAdapter.lifecycleEvent(CatalinaEventHandlerAdapter.java:127)
	at org.jboss.modcluster.AbstractModClusterService.lifecycleEvent(AbstractModClusterService.java:90)
	at org.jboss.web.tomcat.service.deployers.MicrocontainerIntegrationLifecycleListener.lifecycleEvent(MicrocontainerIntegrationLifecycleListener.java:102)
	at org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:117)
	at org.apache.catalina.core.StandardServer.start(StandardServer.java:741)
	at org.apache.catalina.startup.Catalina.start(Catalina.java:575)

Resolution

• Acquire a Content from issues.jboss.org is not included.fix for this in 1.0.10.GA_CP04 so that this connection is attempted with a proper timeout.
• Acquire a Content from issues.jboss.org is not included.one-off fix for 1.0.10.GA_CP02.
• On EAP 6/7, this timeout defaults to 20 seconds. Lower this timeout as needed through the socket-timeout parameter in your mod-cluster-config, see further details in JBoss EAP 6 or 7 starts slowly when one of the mod_cluster proxies is down.

Root Cause

• Content from issues.jboss.org is not included.MODCLUSTER-321
• DefaultMCMPHandler$Proxy.getConnection hands the address/port straight to the socket factory and so Socket.connect is called without any timeout:

      private synchronized Socket getConnection() throws IOException
      {
         if ((this.socket == null) || this.socket.isClosed())
         {
            this.socket = this.socketFactory.createSocket(this.address, this.port);
            this.socket.setSoTimeout(this.socketTimeout);
         }
         return this.socket;
      }

Diagnostic Steps

• Troubleshoot with TRACE logging and thread dumps as desribed in JBoss is slow to start.

This solution is part of Red Hat’s fast-track publication program, providing a huge library of solutions that Red Hat engineers have created while supporting our customers. To give you the knowledge you need the instant it becomes available, these articles may be presented in a raw and unedited form.