geronimo-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Kevan Miller (JIRA)" <...@geronimo.apache.org>
Subject [jira] Commented: (GERONIMO-1422) Geronimo shutdown does not complete due to ActiveMQ attempting to reconnect endpoints to broker every 30 seconds
Date Fri, 13 Jan 2006 14:46:22 GMT
    [ 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


Mime
View raw message