jboss shutdown problems
petrkalina Feb 27, 2006 4:07 PMhi,
I'm experiencing strange problems with the server shutdown. Everything worked fine, until something happened in my system and problems started to appear. Maybe some of you experienced something simillar or is more experienced, so you might give me a clue. It is very unfortunate, that I fear the behaviour cannot be easily reproduced, so you just have to get the picture from the content of this post..
The symptoms are:
The server starts normally.
When I try to shut the server down by ctrl+c, I get this output:
20:52:58,574 INFO [Server] Runtime shutdown hook called, forceHalt: true 20:52:58,725 INFO [Server] JBoss SHUTDOWN: Undeploying all packages 20:52:58,750 INFO [TomcatDeployer] undeploy, ctxPath=/jmx-console, warUrl=.../deploy/jmx-console.war/ 20:52:58,940 INFO [ConnectionFactoryBindingService] Unbound ConnectionManager 'jboss.jca:service=ConnectionFactoryBinding,name=JmsXA' from JNDI name 'java:JmsXA' 20:52:59,131 INFO [testTopic] Unbinding JNDI name: topic/testTopic 20:52:59,133 INFO [securedTopic] Unbinding JNDI name: topic/securedTopic 20:52:59,272 INFO [testDurableTopic] Unbinding JNDI name: topic/testDurableTopic 20:52:59,273 INFO [testQueue] Unbinding JNDI name: queue/testQueue 20:52:59,419 INFO [A] Unbinding JNDI name: queue/A 20:52:59,421 INFO [B] Unbinding JNDI name: queue/B 20:52:59,692 INFO [C] Unbinding JNDI name: queue/C 20:52:59,693 INFO [D] Unbinding JNDI name: queue/D 20:52:59,830 INFO [ex] Unbinding JNDI name: queue/ex 20:52:59,974 INFO [DLQ] Unbinding JNDI name: queue/DLQ 20:52:59,977 INFO [ConnectionFactoryBindingService] Unbound ConnectionManager 'jboss.jca:service=DataSourceBinding,name=DefaultDS' from JNDI name 'java:DefaultDS' 20:53:01,464 INFO [HypersonicDatabase] Database standalone closed clean 20:53:01,493 INFO [ConnectionFactoryBindingService] Unbound ConnectionManager 'jboss.jca:service=ConnectionFactoryBinding,name=FirebirdDS' from JNDI name 'java:FirebirdDS' 20:53:01,746 INFO [MailService] Mail service 'java:/Mail' removed from JNDI 20:53:01,809 INFO [TomcatDeployer] undeploy, ctxPath=/web-console, warUrl=.../deploy/management/console-mgr.sar/web-console.war/ 20:53:02,180 INFO [TomcatDeployer] undeploy, ctxPath=/jbossmq-httpil, warUrl=.../deploy/jms/jbossmq-httpil.sar/jbossmq-httpil.war/ 20:53:02,234 INFO [TomcatDeployer] undeploy, ctxPath=/, warUrl=.../deploy/jbossweb-tomcat55.sar/ROOT.war/ 20:56:11,370 INFO [Http11Protocol] Pausing Coyote HTTP/1.1 on http-0.0.0.0-8080 20:59:20,668 ERROR [Connector] Protocol handler pause failed 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:507) at java.net.Socket.connect(Socket.java:457) at java.net.Socket.<init>(Socket.java:365) at java.net.Socket.<init>(Socket.java:207) at org.apache.jk.common.ChannelSocket.unLockSocket(ChannelSocket.java:463) at org.apache.jk.common.ChannelSocket.pause(ChannelSocket.java:272) at org.apache.jk.server.JkMain.pause(JkMain.java:677) at org.apache.jk.server.JkCoyoteHandler.pause(JkCoyoteHandler.java:209) at org.apache.catalina.connector.Connector.pause(Connector.java:943) at org.jboss.web.tomcat.tc5.StandardService.stop(StandardService.java:583) at org.apache.catalina.core.StandardServer.stop(StandardServer.java:717) at org.apache.catalina.startup.Catalina.stop(Catalina.java:586) 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:585) at org.apache.commons.modeler.BaseModelMBean.invoke(BaseModelMBean.java:503) at org.jboss.mx.server.RawDynamicInvoker.invoke(RawDynamicInvoker.java:150) at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:644) at org.jboss.web.tomcat.tc5.Tomcat5.stopService(Tomcat5.java:458) at org.jboss.system.ServiceMBeanSupport.jbossInternalStop(ServiceMBeanSupport.java:300) at org.jboss.system.ServiceMBeanSupport.jbossInternalLifecycle(ServiceMBeanSupport.java:232) at sun.reflect.GeneratedMethodAccessor2.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:585) at org.jboss.mx.interceptor.ReflectedDispatcher.invoke(ReflectedDispatcher.java:141) at org.jboss.mx.server.Invocation.dispatch(Invocation.java:80) at org.jboss.mx.interceptor.AbstractInterceptor.invoke(AbstractInterceptor.java:118) at org.jboss.mx.server.Invocation.invoke(Invocation.java:74) at org.jboss.mx.interceptor.ModelMBeanOperationInterceptor.invoke(ModelMBeanOperationInterceptor.java:127) at org.jboss.mx.interceptor.DynamicInterceptor.invoke(DynamicInterceptor.java:80) at org.jboss.mx.server.Invocation.invoke(Invocation.java:74) at org.jboss.mx.server.AbstractMBeanInvoker.invoke(AbstractMBeanInvoker.java:245) at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:644) at org.jboss.system.ServiceController$ServiceProxy.invoke(ServiceController.java:943) at $Proxy0.stop(Unknown Source) at org.jboss.system.ServiceController.stop(ServiceController.java:519) at sun.reflect.GeneratedMethodAccessor71.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:585) at org.jboss.mx.interceptor.ReflectedDispatcher.invoke(ReflectedDispatcher.java:141) at org.jboss.mx.server.Invocation.dispatch(Invocation.java:80) at org.jboss.mx.server.Invocation.invoke(Invocation.java:72) at org.jboss.mx.server.AbstractMBeanInvoker.invoke(AbstractMBeanInvoker.java:245) at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:644) at org.jboss.mx.util.MBeanProxyExt.invoke(MBeanProxyExt.java:176) at $Proxy4.stop(Unknown Source) at org.jboss.deployment.SARDeployer.stop(SARDeployer.java:319) at org.jboss.deployment.MainDeployer.stop(MainDeployer.java:640) at org.jboss.deployment.MainDeployer.undeploy(MainDeployer.java:613) at org.jboss.deployment.MainDeployer.shutdown(MainDeployer.java:500) 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:585) at org.jboss.mx.interceptor.ReflectedDispatcher.invoke(ReflectedDispatcher.java:141) at org.jboss.mx.server.Invocation.dispatch(Invocation.java:80) at org.jboss.mx.interceptor.AbstractInterceptor.invoke(AbstractInterceptor.java:118) at org.jboss.mx.server.Invocation.invoke(Invocation.java:74) at org.jboss.mx.interceptor.ModelMBeanOperationInterceptor.invoke(ModelMBeanOperationInterceptor.java:127) at org.jboss.mx.server.Invocation.invoke(Invocation.java:74) at org.jboss.mx.server.AbstractMBeanInvoker.invoke(AbstractMBeanInvoker.java:245) at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:644) at org.jboss.system.server.ServerImpl$ShutdownHook.shutdownDeployments(ServerImpl.java:988) at org.jboss.system.server.ServerImpl$ShutdownHook.shutdown(ServerImpl.java:963) at org.jboss.system.server.ServerImpl$ShutdownHook.run(ServerImpl.java:941) 20:59:21,828 INFO [StandardService] Stopping service jboss.web 20:59:21,974 INFO [Http11Protocol] Stopping Coyote HTTP/1.1 on http-0.0.0.0-8080 20:59:22,095 INFO [TomcatDeployer] undeploy, ctxPath=/invoker, warUrl=.../deploy/http-invoker.sar/invoker.war/ 20:59:22,226 INFO [TomcatDeployer] undeploy, ctxPath=/ws4ee, warUrl=.../tmp/deploy/tmp63595jboss-ws4ee.war/ Shutting down 20:59:23,579 INFO [Server] Shutdown complete Shutdown complete Halting VM
note the 3 minutes spent on undeploying Tomcat and another three before the exception occurs.
Similar behaviour occurs with both 4.0.2 and 4.0.3_SP1 default instances in the "factory" configuration with no changes made by me - so it has to be some problem with my box.
I tried to get as verbose an output as possible from the server - so I set the org.apache logger level to DEBUG and checked what happens in the server.log:
2006-02-27 21:11:53,580 DEBUG [org.jboss.web.tomcat.tc5.Tomcat5] Stopping jboss.web:service=WebServer 2006-02-27 21:11:53,588 DEBUG [org.apache.commons.modeler.BaseModelMBean] Invoke stop 2006-02-27 21:12:03,405 DEBUG [org.apache.catalina.session.ManagerBase] Start expire sessions StandardManager at 1141071123405 sessioncount 0 2006-02-27 21:12:03,406 DEBUG [org.apache.catalina.session.ManagerBase] End expire sessions StandardManager processingTime 1 expired sessions: 0 2006-02-27 21:12:03,406 DEBUG [org.apache.catalina.session.ManagerBase] Start expire sessions StandardManager at 1141071123406 sessioncount 0 2006-02-27 21:12:03,406 DEBUG [org.apache.catalina.session.ManagerBase] End expire sessions StandardManager processingTime 0 expired sessions: 0 2006-02-27 21:13:03,455 DEBUG [org.apache.catalina.session.ManagerBase] Start expire sessions StandardManager at 1141071183455 sessioncount 0 2006-02-27 21:13:03,608 DEBUG [org.apache.catalina.session.ManagerBase] End expire sessions StandardManager processingTime 153 expired sessions: 0 2006-02-27 21:13:03,608 DEBUG [org.apache.catalina.session.ManagerBase] Start expire sessions StandardManager at 1141071183608 sessioncount 0 2006-02-27 21:13:03,608 DEBUG [org.apache.catalina.session.ManagerBase] End expire sessions StandardManager processingTime 0 expired sessions: 0 2006-02-27 21:14:03,690 DEBUG [org.apache.catalina.session.ManagerBase] Start expire sessions StandardManager at 1141071243690 sessioncount 0 2006-02-27 21:14:03,690 DEBUG [org.apache.catalina.session.ManagerBase] End expire sessions StandardManager processingTime 0 expired sessions: 0 2006-02-27 21:14:03,690 DEBUG [org.apache.catalina.session.ManagerBase] Start expire sessions StandardManager at 1141071243690 sessioncount 0 2006-02-27 21:14:03,690 DEBUG [org.apache.catalina.session.ManagerBase] End expire sessions StandardManager processingTime 0 expired sessions: 0 2006-02-27 21:15:02,668 DEBUG [org.apache.tomcat.util.net.PoolTcpEndpoint] Caught exception trying to unlock accept on port 8080 java.net.ConnectException: Connection timed out at java.net.PlainSocketImpl.socketConnect(Native Method) at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:333)
...
2006-02-27 21:15:02,899 INFO [org.apache.coyote.http11.Http11Protocol] Pausing Coyote HTTP/1.1 on http-0.0.0.0-8080 2006-02-27 21:15:04,067 DEBUG [org.apache.catalina.session.ManagerBase] Start expire sessions StandardManager at 1141071304067 sessioncount 0 2006-02-27 21:15:04,067 DEBUG [org.apache.catalina.session.ManagerBase] End expire sessions StandardManager processingTime 0 expired sessions: 0 2006-02-27 21:15:04,067 DEBUG [org.apache.catalina.session.ManagerBase] Start expire sessions StandardManager at 1141071304067 sessioncount 0 2006-02-27 21:15:04,067 DEBUG [org.apache.catalina.session.ManagerBase] End expire sessions StandardManager processingTime 0 expired sessions: 0 2006-02-27 21:16:04,521 DEBUG [org.apache.catalina.session.ManagerBase] Start expire sessions StandardManager at 1141071364521 sessioncount 0 2006-02-27 21:16:04,678 DEBUG [org.apache.catalina.session.ManagerBase] End expire sessions StandardManager processingTime 157 expired sessions: 0 2006-02-27 21:16:04,678 DEBUG [org.apache.catalina.session.ManagerBase] Start expire sessions StandardManager at 1141071364678 sessioncount 0 2006-02-27 21:16:04,715 DEBUG [org.apache.catalina.session.ManagerBase] End expire sessions StandardManager processingTime 37 expired sessions: 0 2006-02-27 21:17:04,847 DEBUG [org.apache.catalina.session.ManagerBase] Start expire sessions StandardManager at 1141071424847 sessioncount 0 2006-02-27 21:17:04,910 DEBUG [org.apache.catalina.session.ManagerBase] End expire sessions StandardManager processingTime 63 expired sessions: 0 2006-02-27 21:17:04,910 DEBUG [org.apache.catalina.session.ManagerBase] Start expire sessions StandardManager at 1141071424910 sessioncount 0 2006-02-27 21:17:04,910 DEBUG [org.apache.catalina.session.ManagerBase] End expire sessions StandardManager processingTime 0 expired sessions: 0 2006-02-27 21:18:05,317 DEBUG [org.apache.catalina.session.ManagerBase] Start expire sessions StandardManager at 1141071485317 sessioncount 0 2006-02-27 21:18:05,428 DEBUG [org.apache.catalina.session.ManagerBase] End expire sessions StandardManager processingTime 111 expired sessions: 0 2006-02-27 21:18:05,428 DEBUG [org.apache.catalina.session.ManagerBase] Start expire sessions StandardManager at 1141071485428 sessioncount 0 2006-02-27 21:18:05,428 DEBUG [org.apache.catalina.session.ManagerBase] End expire sessions StandardManager processingTime 0 expired sessions: 0 2006-02-27 21:18:12,213 ERROR [org.apache.catalina.connector.Connector] Protocol handler pause failed java.net.ConnectException: Connection timed out at java.net.PlainSocketImpl.socketConnect(Native Method) at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:333)
so it's obvious, that the problem is many retries of expiring http sessions. I'm not sure what might be the cause of this behaviour..
There are other strange symptoms: the Shutdown script is not working as intended - shutdown.sh -S doesn't affect the server. Also I found somewhere in the forum, that ivoking the stop() operation in jboss.jmx RMIadpter service should stop the server instance - this doesn't work as well (the author of the post however used 3.2.6, so this might not be relevant)
I tried to Google and search and found very little people experiencing this problem, and if, I didn't find any solution. My suspition is, that it might have something to do with some of the network/http configuration of my machine, but I'm not successful so far.
thanx a lot for any sugestions
-- peter kalina