2 Replies Latest reply on May 15, 2007 1:00 PM by lasitha

    jboss shutdown problems

      hi,

      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

        • 1. Re: jboss shutdown problems
          raist_majere

          Is there any user connected to the webpage your server is hostnig when you shutdown? If any user has an Internet Explorer opened with your page, that may be the cause I've seen many times happening to me...

          • 2. Re: jboss shutdown problems
            lasitha

            I have experienced the same problem in a redhat server, and problem was that the /etc/hosts file contained a mapping to server name(localhost name) to an ip address which could not be resolved from the server. This ip was used as a public ip, which provided the facility to connect external users through a firewall. Adding the server name to 127.0.0.1 mapping resolved the issue.

            if this wont help, try shutting down the server using shutdown.sh -S cause u can at least get an idea why the server couldn't be shutdown at once.