[ http://issues.apache.org/jira/browse/GERONIMO-1422?page=comments#action_12362648 ]
Kevan Miller commented on GERONIMO-1422: ---------------------------------------- I've also seen these messages on my Mac (but server still stopped). This reconnect problem looks pretty basic. It seems that the server has shutdown, but the client is trying to reconnect. Geonimo is trying to shutdown the "client", but an ActiveMQ bug is preventing this. reconnect() is synchronized and is using Thread.sleep() to wait for some interval before retrying to reconnect (that's a pretty bad idea). This is preventing any other synchronized methods on the ActiveMQAsfEndpointWorker from running. Note that there is a "Geronimo shutdown thread" which is waiting to call ActiveMQAsfEndpointWorker.close() in the stack traces which John collected. Using Thread.wait() and appropriate "state" coordination between reconnect() and close() would seem to clear up this problem. I can generate a patch, if need be... Once the reconnect() lockout problem is fixed, I think we'll notice another problem... The geronimo.log posted to http://issues.apache.org/jira/browse/GERONIMO-1372 shows evidence of infinite loop in ActiveMQ shutdown processing. The log entry from the 1372 log is excerpted below: 17:30:34,325 WARN [TransportChannelSupport] Caught exception dispatching message and no ExceptionListener registered: javax.jms.JMSException: asyncSend failed: java.io.EOFException: Cannot write to the stream any more it has already been closed javax.jms.JMSException: asyncSend failed: java.io.EOFException: Cannot write to the stream any more it has already been closed at org.activemq.util.JMSExceptionHelper.newJMSException(JMSExceptionHelper.java:49) at org.activemq.transport.tcp.TcpTransportChannel.doAsyncSend(TcpTransportChannel.java:483) at org.activemq.transport.TransportChannelSupport.asyncSendWithReceipt(TransportChannelSupport.java:160) at org.activemq.transport.TransportChannelSupport.send(TransportChannelSupport.java:145) at org.activemq.ActiveMQConnection.syncSendPacket(ActiveMQConnection.java:1377) at org.activemq.ActiveMQConnection.sendConnectionInfoToBroker(ActiveMQConnection.java:1617) at org.activemq.ActiveMQConnection.close(ActiveMQConnection.java:762) at org.activemq.ra.ActiveMQBaseEndpointWorker.safeClose(ActiveMQBaseEndpointWorker.java:78) at org.activemq.ra.ActiveMQAsfEndpointWorker.disconnect(ActiveMQAsfEndpointWorker.java:164) at org.activemq.ra.ActiveMQAsfEndpointWorker.reconnect(ActiveMQAsfEndpointWorker.java:176) at org.activemq.ra.ActiveMQAsfEndpointWorker.access$200(ActiveMQAsfEndpointWorker.java:40) at org.activemq.ra.ActiveMQAsfEndpointWorker$1$1.onException(ActiveMQAsfEndpointWorker.java:83) at org.activemq.transport.TransportChannelSupport.onAsyncException(TransportChannelSupport.java:445) at org.activemq.transport.tcp.TcpTransportChannel.doAsyncSend(TcpTransportChannel.java:484) at org.activemq.transport.TransportChannelSupport.asyncSendWithReceipt(TransportChannelSupport.java:160) at org.activemq.transport.TransportChannelSupport.send(TransportChannelSupport.java:145) at org.activemq.ActiveMQConnection.syncSendPacket(ActiveMQConnection.java:1377) at org.activemq.ActiveMQConnection.sendConnectionInfoToBroker(ActiveMQConnection.java:1617) at org.activemq.ActiveMQConnection.close(ActiveMQConnection.java:762) at org.activemq.ra.ActiveMQBaseEndpointWorker.safeClose(ActiveMQBaseEndpointWorker.java:78) at org.activemq.ra.ActiveMQAsfEndpointWorker.disconnect(ActiveMQAsfEndpointWorker.java:164) at org.activemq.ra.ActiveMQAsfEndpointWorker.reconnect(ActiveMQAsfEndpointWorker.java:176) at org.activemq.ra.ActiveMQAsfEndpointWorker.access$200(ActiveMQAsfEndpointWorker.java:40) at org.activemq.ra.ActiveMQAsfEndpointWorker$1$1.onException(ActiveMQAsfEndpointWorker.java:83) at org.activemq.transport.TransportChannelSupport.onAsyncException(TransportChannelSupport.java:445) at org.activemq.transport.tcp.TcpTransportChannel.doAsyncSend(TcpTransportChannel.java:484) at org.activemq.transport.TransportChannelSupport.asyncSendWithReceipt(TransportChannelSupport.java:160) at org.activemq.transport.TransportChannelSupport.send(TransportChannelSupport.java:145) at org.activemq.ActiveMQConnection.syncSendPacket(ActiveMQConnection.java:1377) at org.activemq.ActiveMQConnection.sendConnectionInfoToBroker(ActiveMQConnection.java:1617) at org.activemq.ActiveMQConnection.close(ActiveMQConnection.java:762) ... (you get the picture) at org.activemq.ActiveMQConnection.close(ActiveMQConnection.java:762) at org.activemq.ra.ActiveMQBaseEndpointWorker.safeClose(ActiveMQBaseEndpointWorker.java:78) at org.activemq.ra.ActiveMQAsfEndpointWorker.disconnect(ActiveMQAsfEndpointWorker.java:164) at org.activemq.ra.ActiveMQAsfEndpointWorker.stop(ActiveMQAsfEndpointWorker.java:139) at org.activemq.ra.ActiveMQResourceAdapter.endpointDeactivation(ActiveMQResourceAdapter.java:261) at org.apache.geronimo.connector.ResourceAdapterWrapper.endpointDeactivation(ResourceAdapterWrapper.java:92) at org.apache.geronimo.connector.ResourceAdapterWrapper$$FastClassByCGLIB$$4ab28e73.invoke(<generated>) at net.sf.cglib.reflect.FastMethod.invoke(FastMethod.java:53) at org.apache.geronimo.gbean.runtime.FastMethodInvoker.invoke(FastMethodInvoker.java:38) at org.apache.geronimo.gbean.runtime.GBeanOperation.invoke(GBeanOperation.java:118) at org.apache.geronimo.gbean.runtime.GBeanInstance.invoke(GBeanInstance.java:800) at org.apache.geronimo.gbean.runtime.RawInvoker.invoke(RawInvoker.java:57) at org.apache.geronimo.kernel.basic.RawOperationInvoker.invoke(RawOperationInvoker.java:36) at org.apache.geronimo.kernel.basic.ProxyMethodInterceptor.intercept(ProxyMethodInterceptor.java:96) at org.apache.geronimo.connector.ResourceAdapterWrapper$$EnhancerByCGLIB$$74512a94.endpointDeactivation(<generated>) at org.apache.geronimo.connector.ActivationSpecWrapper.deactivate(ActivationSpecWrapper.java:109) at org.apache.geronimo.connector.ActivationSpecWrapper$$FastClassByCGLIB$$aaa078c1.invoke(<generated>) at net.sf.cglib.reflect.FastMethod.invoke(FastMethod.java:53) at org.apache.geronimo.gbean.runtime.FastMethodInvoker.invoke(FastMethodInvoker.java:38) at org.apache.geronimo.gbean.runtime.GBeanOperation.invoke(GBeanOperation.java:118) at org.apache.geronimo.gbean.runtime.GBeanInstance.invoke(GBeanInstance.java:800) at org.apache.geronimo.gbean.runtime.RawInvoker.invoke(RawInvoker.java:57) at org.apache.geronimo.kernel.basic.RawOperationInvoker.invoke(RawOperationInvoker.java:36) at org.apache.geronimo.kernel.basic.ProxyMethodInterceptor.intercept(ProxyMethodInterceptor.java:96) at org.apache.geronimo.connector.ActivationSpecWrapper$$EnhancerByCGLIB$$7598abd2.deactivate(<generated>) at org.openejb.mdb.MDBContainer.doStop(MDBContainer.java:223) at org.apache.geronimo.gbean.runtime.GBeanInstance.destroyInstance(GBeanInstance.java:1079) at org.apache.geronimo.gbean.runtime.GBeanInstanceState.attemptFullStop(GBeanInstanceState.java:395) at org.apache.geronimo.gbean.runtime.GBeanInstanceState.stop(GBeanInstanceState.java:200) at org.apache.geronimo.gbean.runtime.GBeanInstance.stop(GBeanInstance.java:545) at org.apache.geronimo.kernel.basic.BasicKernel.stopGBean(BasicKernel.java:213) at org.apache.geronimo.gbean.runtime.GBeanInstanceState.stop(GBeanInstanceState.java:192) at org.apache.geronimo.gbean.runtime.GBeanInstance.stop(GBeanInstance.java:545) at org.apache.geronimo.kernel.basic.BasicKernel.stopGBean(BasicKernel.java:213) at org.apache.geronimo.gbean.runtime.GBeanInstanceState.stop(GBeanInstanceState.java:192) at org.apache.geronimo.gbean.runtime.GBeanInstance.stop(GBeanInstance.java:545) at org.apache.geronimo.kernel.basic.BasicKernel.stopGBean(BasicKernel.java:213) at org.apache.geronimo.gbean.runtime.GBeanInstanceState.stop(GBeanInstanceState.java:192) at org.apache.geronimo.gbean.runtime.GBeanInstance.stop(GBeanInstance.java:545) at org.apache.geronimo.kernel.basic.BasicKernel.stopGBean(BasicKernel.java:213) at org.apache.geronimo.kernel.config.ConfigurationManagerImpl$ShutdownHook.run(ConfigurationManagerImpl.java:287) at org.apache.geronimo.kernel.basic.BasicKernel.notifyShutdownHooks(BasicKernel.java:406) at org.apache.geronimo.kernel.basic.BasicKernel.shutdown(BasicKernel.java:383) at org.apache.geronimo.system.main.Daemon$1.run(Daemon.java:272) Caused by: java.io.EOFException: Cannot write to the stream any more it has already been closed at org.activemq.transport.tcp.TcpBufferedOutputStream.checkClosed(TcpBufferedOutputStream.java:132) at org.activemq.transport.tcp.TcpBufferedOutputStream.write(TcpBufferedOutputStream.java:70) at java.io.DataOutputStream.writeByte(DataOutputStream.java:131) at org.activemq.io.impl.DefaultWireFormat.writePacket(DefaultWireFormat.java:112) at org.activemq.transport.tcp.TcpTransportChannel.doAsyncSend(TcpTransportChannel.java:474) ... 864 more I haven't looked at svn history (or older src versions), but I see evidence of changes in ActiveMQ close processing in TcpTransportChannel (i.e. code that's been commented out). You could break the loop at many different levels: 1) at the outer(API)-level you could add a "pendingClose" in ActiveMQConnection.close() with a pendingClose boolean. 2) somewhere in between. perhaps using sendConnectionInfotoBroker(sendCloseTimeout, false, true); would do the trick... Personally, I'd use 1) but ActiveMQ may have their own preference... > Geronimo shutdown does not complete due to ActiveMQ attempting to reconnect > endpoints to broker every 30 seconds > ---------------------------------------------------------------------------------------------------------------- > > Key: GERONIMO-1422 > URL: http://issues.apache.org/jira/browse/GERONIMO-1422 > Project: Geronimo > Type: Bug > Components: ActiveMQ > Versions: 1.0 > Environment: Solaris 10 x86 under VMWare player 1.01 > Java 1.4.2_10 > tomcat build of geronimo > Reporter: John Sisson > Fix For: 1.0.1 > Attachments: geronimo_shutdown_stdout.txt, shutdown.txt > > Can anyone reproduce this problem on other platforms? > If I start the tomcat build of the release candidate and then shut it down > once the startup has completed it shuts down almost cleanly: > Server shutdown begun > 11:25:47,951 INFO [Http11Protocol] Stopping Coyote HTTP/1.1 on > http-0.0.0.0-8443 > 11:25:48,986 INFO [Http11Protocol] Stopping Coyote HTTP/1.1 on > http-0.0.0.0-8080 > 11:25:49,001 INFO [StandardContext] Container > org.apache.catalina.core.ContainerBase.[Geronimo].[localhost].[/] has not > been started > Server shutdown completed > I have shutdown issues If I do the following: > * start the tomcat build of release candidate using geronimo.sh run --long > * connect to the daytrader web app > * populate the daytrader database via the daytrader configuration page > * log into daytrader and view account, portfolio etc. > * press ctrl-C in the window that geronimo was started in to shut it down. > * You will see ActiveMQAsfEndpointWorker messages every 30 seconds. > 10:46:56,356 WARN [BrokerContainerImpl] Got duplicate deregisterConnection > for client: ID:unknown-34799-1136504488185-10:0 > 10:46:56,358 WARN [TransportChannelSupport] Caught exception dispatching > message and no ExceptionListener registered: javax.jms.JMSException: Error > reading socket: java.io.EOFException > javax.jms.JMSException: Error reading socket: java.io.EOFException > at > org.activemq.util.JMSExceptionHelper.newJMSException(JMSExceptionHelper.java:49) > at > org.activemq.transport.tcp.TcpTransportChannel.doClose(TcpTransportChannel.java:509) > at > org.activemq.transport.tcp.TcpTransportChannel.run(TcpTransportChannel.java:330) > at java.lang.Thread.run(Thread.java:534) > Caused by: java.io.EOFException > at java.io.DataInputStream.readByte(DataInputStream.java:333) > at > org.activemq.io.AbstractWireFormat.readPacket(AbstractWireFormat.java:230) > at > org.activemq.transport.tcp.TcpTransportChannel.run(TcpTransportChannel.java:313) > ... 1 more > 10:47:27,401 INFO [ActiveMQAsfEndpointWorker] Endpoint connection to JMS > broker failed: Initialization of TcpTransportChannel failed. URI was: > tcp://localhost:61616 Reason: java.net.ConnectException: Connection refused > 10:47:27,402 INFO [ActiveMQAsfEndpointWorker] Endpoint will try to reconnect > to the JMS broker in 30 seconds > 10:47:27,403 INFO [ActiveMQAsfEndpointWorker] Endpoint connection to JMS > broker failed: Initialization of TcpTransportChannel failed. URI was: > tcp://localhost:61616 Reason: java.net.ConnectException: Connection refused > 10:47:27,403 INFO [ActiveMQAsfEndpointWorker] Endpoint will try to reconnect > to the JMS broker in 30 seconds > I will have attached a capture of stdout also including a thread dump to this > issue. -- This message is automatically generated by JIRA. - If you think it was sent incorrectly contact one of the administrators: http://issues.apache.org/jira/secure/Administrators.jspa - For more information on JIRA, see: http://www.atlassian.com/software/jira
