Just a little update, sorry for the consecutive emails. Apparently sometimes we got the logs cited previously. In those cases, the connection and subscription seem to work afterwards. Problem comes that sometimes we got some "correlation problems" 1/26/2010 6:42:39 AM Debug: [Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Warn] [6] ActiveMQ.NMS.Warning: Transport failed to tcp://localhost:61616/, attempting to automatically reconnect due to: Unable to read beyond the end of the stream. 0 1/26/2010 6:42:39 AM Debug: [Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Debug] [26] ActiveMQ.NMS.Debug: Attempting connect to: tcp://localhost:61616/ 0 1/26/2010 6:42:39 AM Debug: [Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Debug] [6] ActiveMQ.NMS.Debug: Transport has been Interrupted. 0 1/26/2010 6:42:39 AM Debug: [Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Debug] [26] ActiveMQ.NMS.Debug: Attempting connect to: tcp://localhost:61616/ 0 1/26/2010 6:42:39 AM Debug: [Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Debug] [26] ActiveMQ.NMS.Debug: Opening socket to: localhost on port: 61616 0 1/26/2010 6:42:39 AM Debug: [Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Debug] [26] ActiveMQ.NMS.Debug: Connected to localhost:61616 using InterNetwork protocol. 0 1/26/2010 6:42:39 AM Debug: [ Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Info] [26] ActiveMQ.NMS.Info: Restoring previous transport connection. 0 1/26/2010 6:42:39 AM Debug: [Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Debug] [25] ActiveMQ.NMS.Debug: Parsing type: 1 with: Apache.NMS.ActiveMQ.OpenWire.V1.WireFormatInfoMarshaller 0 1/26/2010 6:42:39 AM Debug: [Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Debug] [25] ActiveMQ.NMS.Debug: Parsing type: 2 with: Apache.NMS.ActiveMQ.OpenWire.V3.BrokerInfoMarshaller 0 1/26/2010 6:42:39 AM Debug: [Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Debug] [25] ActiveMQ.NMS.Debug: Parsing type: 30 with: Apache.NMS.ActiveMQ.OpenWire.V3.ResponseMarshaller 0 1/26/2010 6:42:39 AM Debug: [Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Error] [25] ActiveMQ.NMS.Error: Unknown response ID: 0 for response: Response[CorrelationId=1] 0 1/26/2010 6:42:39 AM Debug: [Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Debug] [25] ActiveMQ.NMS.Debug: Parsing type: 30 with: Apache.NMS.ActiveMQ.OpenWire.V3.ResponseMarshaller 0 1/26/2010 6:42:39 AM Debug: [Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Error] [25] ActiveMQ.NMS.Error: Unknown response ID: 0 for response: Response[CorrelationId=2] 0 1/26/2010 6:42:39 AM Debug: [Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Debug] [25] ActiveMQ.NMS.Debug: Parsing type: 30 with: Apache.NMS.ActiveMQ.OpenWire.V3.ResponseMarshaller 0 1/26/2010 6:42:39 AM Debug: [Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Error] [25] ActiveMQ.NMS.Error: Unknown response ID: 0 for response: Response[CorrelationId=3] 0 1/26/2010 6:42:39 AM Debug: [ Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Info] [26] ActiveMQ.NMS.Info: Sending queued commands... 0 1/26/2010 6:42:39 AM Debug: [Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Debug] [26] ActiveMQ.NMS.Debug: Transport has resumed normal operation. 0 1/26/2010 6:42:39 AM Error: [Dummy.Framework.Notification.ActiveMQ.Tools.TopicConnection.OnConnectionResumedListener] [26] ACTIVEMQ: Connection with Broker Resumed 0 1/26/2010 6:42:39 AM Debug: [Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Debug] [26] ActiveMQ.NMS.Debug: Connection established 0 1/26/2010 6:42:39 AM Debug: [ Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Info] [26] ActiveMQ.NMS.Info: Successfully reconnected to: tcp://localhost:61616/ 0
It seems this "Unknown response ID: 0 for response: Response[CorrelationId=1]" comes from the transport filter ResponseCorrelator. Can this be the cause of the lost subscriptions? Basically after this the messages start to stack in the embedded broker but they are not dequeued. Any help or comment on the issue would be greatly appreciated :) Thank you very much for your help, Sebastian 2010/1/26 Sebastian Rodriguez <srodrig...@gmail.com> > Another piece of information: the exact exception stack is as follow: > > [Dummy.Framework.Notification.ActiveMQ.Tools.TopicConnection.OnExceptionListener] > [5] System.IO.EndOfStreamException: Unable to read beyond the end of > the stream. > > at System.IO.__Error.EndOfFile() > > at System.IO.BinaryReader.FillBuffer(Int32 numBytes) > > at System.IO.BinaryReader.ReadInt32() > > at Apache.NMS.Util.EndianBinaryReader.ReadInt32() > > at Apache.NMS.ActiveMQ.OpenWire.OpenWireFormat.Unmarshal(BinaryReader > dis) > > at Apache.NMS.ActiveMQ.Transport.Tcp.TcpTransport.ReadLoop() 0 > > > 2010/1/26 Sebastian Rodriguez <srodrig...@gmail.com> > > From the log messages I can see: >> >> 1/25/2010 9:49:09 AM Debug: >> [Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Warn] >> [6] ActiveMQ.NMS.Warning: Transport failed to >> tcp://localhost:61616/, attempting to automatically reconnect due to: Unable >> to read beyond the end of the stream. 0 >> >> 1/25/2010 9:49:09 AM Debug: >> [Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Debug] >> [6] ActiveMQ.NMS.Debug: Transport has been >> Interrupted. 0 >> >> 1/25/2010 9:49:09 AM Debug: >> [Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Debug] >> [7] ActiveMQ.NMS.Debug: Attempting connect to: >> tcp://localhost:61616/ 0 >> >> 1/25/2010 9:49:09 AM Debug: >> [Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Debug] >> [7] ActiveMQ.NMS.Debug: Attempting connect to: >> tcp://localhost:61616/ 0 >> >> 1/25/2010 9:49:09 AM Debug: >> [Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Debug] >> [7] ActiveMQ.NMS.Debug: Opening socket to: localhost on port: >> 61616 0 >> >> 1/25/2010 9:49:10 AM Debug: >> [Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Debug] >> [7] ActiveMQ.NMS.Debug: Connect fail to: >> tcp://localhost:61616/, reason: Error connecting to localhost:61616. >> 0 >> >> 1/25/2010 9:49:10 AM Debug: >> [Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Debug] >> [7] ActiveMQ.NMS.Debug: Waiting 10ms before attempting >> connection. 0 >> >> 1/25/2010 9:49:10 AM Debug: >> [Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Debug] >> [7] ActiveMQ.NMS.Debug: Attempting connect to: >> tcp://localhost:61616/ 0 >> >> 1/25/2010 9:49:10 AM Debug: >> [Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Debug] >> [7] ActiveMQ.NMS.Debug: Attempting connect to: >> tcp://localhost:61616/ 0 >> >> 1/25/2010 9:49:10 AM Debug: >> [Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Debug] >> [7] ActiveMQ.NMS.Debug: Opening socket to: localhost on port: >> 61616 0 >> >> 1/25/2010 9:49:12 AM Debug: >> [Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Debug] >> [7] ActiveMQ.NMS.Debug: Connect fail to: >> tcp://localhost:61616/, reason: Error connecting to localhost:61616. >> 0 >> >> 1/25/2010 9:49:12 AM Debug: >> [Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Debug] >> [7] ActiveMQ.NMS.Debug: Waiting 20ms before attempting >> connection. 0 >> >> 1/25/2010 9:49:12 AM Debug: >> [Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Debug] >> [7] ActiveMQ.NMS.Debug: Attempting connect to: >> tcp://localhost:61616/ 0 >> >> 1/25/2010 9:49:12 AM Debug: >> [Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Debug] >> [7] ActiveMQ.NMS.Debug: Attempting connect to: >> tcp://localhost:61616/ 0 >> >> 1/25/2010 9:49:12 AM Debug: >> [Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Debug] >> [7] ActiveMQ.NMS.Debug: Opening socket to: localhost on port: >> 61616 0 >> >> 1/25/2010 9:49:12 AM Debug: >> [Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Debug] >> [7] ActiveMQ.NMS.Debug: Connected to localhost:61616 using >> InterNetwork protocol. 0 >> >> 1/25/2010 9:49:12 AM Debug: [ >> Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Info] >> [7] ActiveMQ.NMS.Info: Restoring previous transport >> connection. 0 >> >> 1/25/2010 9:49:12 AM Debug: >> [Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Debug] >> [6] ActiveMQ.NMS.Debug: Parsing type: 1 with: >> Apache.NMS.ActiveMQ.OpenWire.V1.WireFormatInfoMarshaller 0 >> >> 1/25/2010 9:49:12 AM Debug: [ >> Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Info] >> [7] ActiveMQ.NMS.Info: Sending queued commands... 0 >> >> 1/25/2010 9:49:12 AM Debug: >> [Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Debug] >> [7] ActiveMQ.NMS.Debug: Transport has resumed normal >> operation. 0 >> >> 1/25/2010 9:49:12 AM Error: >> [Dummy.Framework.Notification.ActiveMQ.Tools.TopicConnection.OnConnectionResumedListener] >> [7] ACTIVEMQ: Connection with Broker Resumed 0 >> >> 1/25/2010 9:49:12 AM Debug: >> [Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Debug] >> [7] ActiveMQ.NMS.Debug: Connection established >> 0 >> >> 1/25/2010 9:49:12 AM Debug: [ >> Dummy.Framework.Notification.ActiveMQ.Tools.ActiveMQTracer.Info] >> [7] ActiveMQ.NMS.Info: Successfully reconnected to: >> tcp://localhost:61616/ 0 >> Is it the normal behavior that we do not receive a ConnectionInterrupted >> event? >> >> What can be the causes to receive the exception Unable to read beyond the >> end of the stream? I've seen a jira speaking about it ( >> http://issues.apache.org/activemq/browse/AMQNET-196) but i do not receive >> this exception in a regular basis. It seems that this exception occurs more >> often in slow or old machines. Can it be related? >> >> Thank you very much for your help on the subject, >> >> Sebastien >> 2010/1/25 Sebastian Rodriguez <srodrig...@gmail.com> >> >> I've enabled the logging and left the client running during the night. >>> Hopefully I'll be able to come back to you tomorrow with more details. >>> The "funny" thing, is that there is no connection lost, we "only" looses >>> the subscriptions. >>> I'll try to make a sample tomorrow see if i can reproduce the error >>> >>> 2010/1/25 Timothy Bish <tabish...@gmail.com> >>> >>>> On Mon, 2010-01-25 at 12:18 +0800, Sebastian Rodriguez wrote: >>>> >>>> > Dear all, >>>> > I'm encountering a very strange problem. >>>> > I have a client that uses an embedded broker to connect to a network >>>> of >>>> > brokers. >>>> > The connection between my client and the embedded broker is done >>>> through the >>>> > Apache.NMS.ActiveMQ client. >>>> > I'm connecting to the embedded broker through a failover uri as I want >>>> to >>>> > recover from possible exception raised. >>>> > The version of the NMS client is 1.2.0.1794 and we are using the >>>> latest >>>> > version from 5.3.1 branch. This was also happening with the stable >>>> release >>>> > 5.3.0. >>>> > >>>> > Everything works perfectly until I receive the event >>>> > ConnectionResumedListener. >>>> > The weird part is that: >>>> > >>>> > - why do I receive a connection resume event without a previous >>>> > connection interrupted event? >>>> > - the connection is recovered properly, but not my subscription. >>>> > Basically my client doesnt receive anything anymore from the >>>> embedded broker >>>> > although the broker still receives the messages incoming from the >>>> network of >>>> > brokers. >>>> > >>>> > Do you have any ideas why I would receive a connection resumed alone >>>> > (without a connection interrupted?), and why the failover transport >>>> > correctly recovers the connection but not subscriptions? >>>> > Thank you very much for your advice on the matter, >>>> > >>>> >>>> Can you enable logging and capture some logs around the time the event >>>> is fired? I have not seen any spurious disconnects as yet from NMS. If >>>> you have a sample app that can demonstrate the problem that would be >>>> helpful. >>>> >>>> Regards >>>> Tim. >>>> >>>> >>>> >>>> >>>> >>>> >>>> -- >>>> Tim Bish >>>> http://fusesource.com >>>> http://timbish.blogspot.com/ >>>> >>>> >>>> >>>> >>> >>> >>> -- >>> Sebastien Rodriguez >>> >> >> >> >> -- >> Sebastien Rodriguez >> > > > > -- > Sebastien Rodriguez > -- Sebastien Rodriguez
