Exception handling during context startup

[akarl]

I have a setup with 2 mod_cluster 1.0.0.GA load balancers and 2 JBoss 5.1 app servers.  The app servers know about the load balancers via configuration and advertisement/discovery is turned off.  My application is an EAR with 3 WARs and a JAR data-source inside it (pretty standard web services).  I deploy the application using the farm deployer.  All of this so far works fine.  I start the app servers up, they find each other (JGroups), they find the load balancers.  I deploy the app and all is fine.  Both app servers get the deployment and tell the load balancers about it.  Now at some point I need to restart one of the app servers.  It happens to be the non-master node in the cluster.  When I do this the app server starts up, deploys 2 out of the 3 WARs and then throws mod cluster errors at me which then fails the deployment of the entire EAR.  The EAR never tries to restart itself which is the expected JBoss behavior for failed deployments.  If I push a new EAR to either node after startup the app starts up correctly on both nodes.  If I shut down one of the load balancers no failures occur during app server restart and/or redeployment.

The exception below is troubling but I'm actually more worried that this mod_cluster communications error is causing my application deployment to fail when mod_cluster could handle the exception and try connecting to the load balancers at a later time.

{code}
java.lang.IllegalStateException: No valid response to RPC [sendRequest]
at org.jboss.modcluster.ha.ClusteredMCMPHandlerImpl$RpcStub.invokeRpc(ClusteredMCMPHandlerImpl.java:527)
at org.jboss.modcluster.ha.ClusteredMCMPHandlerImpl$RpcStub.invokeRpc(ClusteredMCMPHandlerImpl.java:483)
at org.jboss.modcluster.ha.ClusteredMCMPHandlerImpl$RpcStub.sendRequest(ClusteredMCMPHandlerImpl.java:463)
at org.jboss.modcluster.ha.ClusteredMCMPHandlerImpl.sendRequest(ClusteredMCMPHandlerImpl.java:331)
at org.jboss.modcluster.CatalinaEventHandler.startContext(CatalinaEventHandler.java:268)
at org.jboss.modcluster.CatalinaEventHandler.startContext(CatalinaEventHandler.java:55)
at org.jboss.modcluster.CatalinaEventHandlerAdapter.lifecycleEvent(CatalinaEventHandlerAdapter.java:121)
at org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:117)
at org.apache.catalina.core.StandardContext.start(StandardContext.java:4312)
at org.jboss.web.tomcat.service.deployers.TomcatDeployment.performDeployInternal(TomcatDeployment.java:310)
at org.jboss.web.tomcat.service.deployers.TomcatDeployment.performDeploy(TomcatDeployment.java:142)
at org.jboss.web.deployers.AbstractWarDeployment.start(AbstractWarDeployment.java:461)
at org.jboss.web.deployers.WebModule.startModule(WebModule.java:118)
at org.jboss.web.deployers.WebModule.start(WebModule.java:97)
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.jboss.mx.interceptor.ReflectedDispatcher.invoke(ReflectedDispatcher.java:157)
at org.jboss.mx.server.Invocation.dispatch(Invocation.java:96)
at org.jboss.mx.server.Invocation.invoke(Invocation.java:88)
at org.jboss.mx.server.AbstractMBeanInvoker.invoke(AbstractMBeanInvoker.java:264)
at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:668)
at org.jboss.system.microcontainer.ServiceProxy.invoke(ServiceProxy.java:206)
at $Proxy38.start(Unknown Source)
at org.jboss.system.microcontainer.StartStopLifecycleAction.installAction(StartStopLifecycleAction.java:42)
at org.jboss.system.microcontainer.StartStopLifecycleAction.installAction(StartStopLifecycleAction.java:37)
at org.jboss.dependency.plugins.action.SimpleControllerContextAction.secureInstallAction(SimpleControllerContextAction.java:67)
at org.jboss.dependency.plugins.action.AccessControllerContextAction$1.run(AccessControllerContextAction.java:80)
at java.security.AccessController.doPrivileged(Native Method)
at org.jboss.dependency.plugins.action.AccessControllerContextAction.install(AccessControllerContextAction.java:103)
at org.jboss.dependency.plugins.AbstractControllerContextActions.install(AbstractControllerContextActions.java:51)
at org.jboss.dependency.plugins.AbstractControllerContext.install(AbstractControllerContext.java:348)
at org.jboss.system.microcontainer.ServiceControllerContext.install(ServiceControllerContext.java:286)
at org.jboss.dependency.plugins.AbstractController.install(AbstractController.java:1631)
at org.jboss.dependency.plugins.AbstractController.incrementState(AbstractController.java:934)
at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:1082)
at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:984)
at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:822)
at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:553)
at org.jboss.system.ServiceController.doChange(ServiceController.java:688)
at org.jboss.system.ServiceController.start(ServiceController.java:460)
at org.jboss.system.deployers.ServiceDeployer.start(ServiceDeployer.java:163)
at org.jboss.system.deployers.ServiceDeployer.deploy(ServiceDeployer.java:99)
at org.jboss.system.deployers.ServiceDeployer.deploy(ServiceDeployer.java:46)
at org.jboss.deployers.spi.deployer.helpers.AbstractSimpleRealDeployer.internalDeploy(AbstractSimpleRealDeployer.java:62)
at org.jboss.deployers.spi.deployer.helpers.AbstractRealDeployer.deploy(AbstractRealDeployer.java:50)
at org.jboss.deployers.plugins.deployers.DeployerWrapper.deploy(DeployerWrapper.java:171)
at org.jboss.deployers.plugins.deployers.DeployersImpl.doDeploy(DeployersImpl.java:1439)
at org.jboss.deployers.plugins.deployers.DeployersImpl.doInstallParentFirst(DeployersImpl.java:1157)
at org.jboss.deployers.plugins.deployers.DeployersImpl.doInstallParentFirst(DeployersImpl.java:1178)
at org.jboss.deployers.plugins.deployers.DeployersImpl.doInstallParentFirst(DeployersImpl.java:1210)
at org.jboss.deployers.plugins.deployers.DeployersImpl.install(DeployersImpl.java:1098)
at org.jboss.dependency.plugins.AbstractControllerContext.install(AbstractControllerContext.java:348)
at org.jboss.dependency.plugins.AbstractController.install(AbstractController.java:1631)
at org.jboss.dependency.plugins.AbstractController.incrementState(AbstractController.java:934)
at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:1082)
at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:984)
at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:822)
at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:553)
at org.jboss.deployers.plugins.deployers.DeployersImpl.process(DeployersImpl.java:781)
at org.jboss.deployers.plugins.main.MainDeployerImpl.process(MainDeployerImpl.java:702)
at org.jboss.system.server.profileservice.repository.MainDeployerAdapter.process(MainDeployerAdapter.java:117)
at org.jboss.system.server.profileservice.repository.ProfileDeployAction.install(ProfileDeployAction.java:70)
at org.jboss.system.server.profileservice.repository.AbstractProfileAction.install(AbstractProfileAction.java:53)
at org.jboss.system.server.profileservice.repository.AbstractProfileService.install(AbstractProfileService.java:361)
at org.jboss.dependency.plugins.AbstractControllerContext.install(AbstractControllerContext.java:348)
at org.jboss.dependency.plugins.AbstractController.install(AbstractController.java:1631)
at org.jboss.dependency.plugins.AbstractController.incrementState(AbstractController.java:934)
at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:1082)
at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:984)
at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:822)
at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:553)
at org.jboss.system.server.profileservice.repository.AbstractProfileService.activateProfile(AbstractProfileService.java:306)
at org.jboss.system.server.profileservice.ProfileServiceBootstrap.start(ProfileServiceBootstrap.java:271)
at org.jboss.bootstrap.AbstractServerImpl.start(AbstractServerImpl.java:461)
at org.jboss.Main.boot(Main.java:221)
at org.jboss.Main$1.run(Main.java:556)
at java.lang.Thread.run(Thread.java:619)
2010-02-18 07:13:12,486 ERROR [org.apache.catalina.core.StandardContext] Context [/edge-test/version/20659] startup failed due to previous errors
{code}

The following errors are seen in the httpd error_log at the time when the exception above is thrown by the app server.

{code}
[error] ajp_cping_cpong: apr_socket_recv failed
{code}

I have also tried updating mod_cluster to 1.0.3.GA on one of the load balancers.  This had no effect on the results.

[akarl]

One more thing to note.  My load balancers are running 1.0.0 but my app servers are using the 1.0.3 jar.  As mentioned previously updating the load balancers to 1.0.3 had no effect on the outcome.

[akarl]

The communication errors were related to networking errors where both load balancers were trying to use the same IP address.  I am still concerned though that an error like this would fail my deployment.  I would have instead expected mod_cluster to spit errors into the log but allow the application to be deployed.  This jives with the behavior if I start the app servers when my load balancer is not started then start up my load balancer later.

[pferraro]

Sorry for the late response - I just saw that this thread had no response.

The IllegalStateException seen above is handled within mod_cluster and will not propagate back to the AS nor cause the deployment to fail.  mod_cluster handles this condition by marking the proxy in error state, and will attempt to reset it during the next status cycle (10 seconds by default).

[akarl]

Doesn't my stack trace directly conflict with what you just said?  My deployment is absolutely failing due to a timeout here. 

I walked the code involved in this stack trace and I do see one place where the error is caught but it is promptly re-thrown as an unchecked exception.  Remember that I am using the latest "released" version of the code 1.0.3.  I know that some major work has been done on the trunk and I have not looked into that yet.

[pferraro]

Not necessarily - the stack trace in the log just indicates the location at which the error was logged.

Is the context actually failing to deploy in the AS?  or is it just failing to register with the proxy?

If it's failing to deploy, then that's definitely a bug.  Do you recall the code path that could throw an unhandled unchecked exception?

We just released a 1.1.0.CR1 release off of trunk - you can give that a whirl if you'd like - though I don't recall any changes that would dramatically impact the rpc logic being stressed here.

[akarl]

Yes its failing my deployment.  Just follow the code trail in the stack trace and you see that the IllegalStateException is thrown by line 527 of ClusteredMCMPHandlerImpl which is then caught by line 485 but then re-thrown by line 492.  After that it is never caught and bubbles up to the "lifecycleEvent" method of CatalinaEventHandlerAdapter (line 121).

All of these line numbers are from branch 1.x.

[pferraro]

https://jira.jboss.org/jira/browse/MODCLUSTER-140