You are viewing a plain text version of this content. The canonical link for it is here.

Posted to users@activemq.apache.org by Chris Robison <ch...@gmail.com> on 2012/04/07 19:56:03 UTC

Client consumer exception and disconnection

I'm running into an interesting issue. I have a client connecting to an
activemq server, trying to consume messages and reply to a temporary
destination set. The ActiveMQ server debug is showing the following:

2012-04-07 13:20:25,708 | DEBUG | Received WireFormat: WireFormatInfo {
version=6, properties={CacheSize=0, CacheEnabled=false,
MaxInactivityDurationInitialDelay=10000, SizePrefixDisabled=false,
TcpNoDelayEnabled=true, MaxInactivityDuration=30000,
TightEncodingEnabled=false, StackTraceEnabled=false},
magic=[A,c,t,i,v,e,M,Q]} |
org.apache.activemq.transport.WireFormatNegotiator | ActiveMQ Transport:
ssl:///172.17.5.16:52657
2012-04-07 13:20:25,708 | DEBUG | ssl:///172.17.5.16:52657 before
negotiation: OpenWireFormat{version=9, cacheEnabled=false,
stackTraceEnabled=false, tightEncodingEnabled=false,
sizePrefixDisabled=false, maxFrameSize=104857600} |
org.apache.activemq.transport.WireFormatNegotiator | ActiveMQ Transport:
ssl:///172.17.5.16:52657
2012-04-07 13:20:25,709 | DEBUG | ssl:///172.17.5.16:52657 after
negotiation: OpenWireFormat{version=6, cacheEnabled=false,
stackTraceEnabled=false, tightEncodingEnabled=false,
sizePrefixDisabled=false, maxFrameSize=104857600} |
org.apache.activemq.transport.WireFormatNegotiator | ActiveMQ Transport:
ssl:///172.17.5.16:52657
2012-04-07 13:20:25,725 | DEBUG | Setting up new connection id:
ID:WIIPAP101-52658-634694015719174302-1:0, address: tcp://172.17.5.16:52657,
info: ConnectionInfo {commandId = 1, responseRequired = true, connectionId
= ID:WIIPAP101-52658-634694015719174302-1:0, clientId =
ID:WIIPAP101-52658-634694015719174302-0:0, clientIp = null, userName =
mqipauser, password = *****, brokerPath = null, brokerMasterConnector =
false, manageable = false, clientMaster = false, faultTolerant = false,
failoverReconnect = false} | org.apache.activemq.broker.TransportConnection
| ActiveMQ Transport: ssl:///172.17.5.16:52657
2012-04-07 13:20:25,727 | DEBUG | Create the LDAP initial context. |
org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
172.17.5.16:52657
2012-04-07 13:20:25,739 | DEBUG | Get the user DN. |
org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
172.17.5.16:52657
2012-04-07 13:20:25,739 | DEBUG | Looking for the user in LDAP with  |
org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
172.17.5.16:52657
2012-04-07 13:20:25,740 | DEBUG |   base DN:
OU=Users,OU=ActiveMQ,DC=VOSH,DC=NET |
org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
172.17.5.16:52657
2012-04-07 13:20:25,740 | DEBUG |   filter: (sAMAccountName=mqipauser) |
org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
172.17.5.16:52657
2012-04-07 13:20:25,743 | DEBUG | Binding the user. |
org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
172.17.5.16:52657
2012-04-07 13:20:25,750 | DEBUG | User CN=MQ IPA
User,OU=Users,OU=ActiveMQ,DC=VOSH,DC=NET successfully bound. |
org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
172.17.5.16:52657
2012-04-07 13:20:25,751 | DEBUG | Get user roles. |
org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
172.17.5.16:52657
2012-04-07 13:20:25,751 | DEBUG | Looking for the user roles in LDAP with
 | org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
172.17.5.16:52657
2012-04-07 13:20:25,751 | DEBUG |   base DN:
OU=Groups,OU=ActiveMQ,DC=VOSH,DC=NET |
org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
172.17.5.16:52657
2012-04-07 13:20:25,751 | DEBUG |   filter: (member=CN=MQ IPA
User,OU=Users,OU=ActiveMQ,DC=VOSH,DC=NET) |
org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
172.17.5.16:52657
2012-04-07 13:20:25,762 | DEBUG | Roles [MQIPAUsers, MQUsers] for user
mqipauser | org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport:
ssl:///172.17.5.16:52657
2012-04-07 13:20:25,789 | DEBUG | msipap101.vosh.net adding consumer:
ID:WIIPAP101-52658-634694015719174302-1:0:1:1 for destination:
queue://SolidCloud.Requests.Desktops.IPA |
org.apache.activemq.broker.region.AbstractRegion | ActiveMQ Transport:
ssl:///172.17.5.16:52657
2012-04-07 13:20:25,797 | DEBUG | queue://SolidCloud.Requests.Desktops.IPA
add sub: QueueSubscription:
consumer=ID:WIIPAP101-52658-634694015719174302-1:0:1:1, destinations=0,
dispatched=0, delivered=0, pending=0, dequeues: 1, dispatched: 1, inflight:
0 | org.apache.activemq.broker.region.Queue | ActiveMQ Transport: ssl:///
172.17.5.16:52657
2012-04-07 13:20:25,798 | DEBUG | SolidCloud.Requests.Desktops.IPA
toPageIn: 0, Inflight: 0, pagedInMessages.size 9, enqueueCount: 3,
dequeueCount: 1 | org.apache.activemq.broker.region.Queue |
Queue:SolidCloud.Requests.Desktops.IPA
2012-04-07 13:20:25,810 | DEBUG | bridging (msipap101.vosh.net ->
mstmip101.vosh.net) ID:MSIPAP101-36535-1333817412870-1:1:0:0:33, consumer:
ID:MSIPAP101-36535-1333817412870-2:2:1:1, destination
topic://ActiveMQ.Advisory.Consumer.Queue.SolidCloud.Requests.Desktops.IPA,
brokerPath: [ID:MSIPAP101-36535-1333817412870-0:1], message:
ActiveMQMessage {commandId = 0, responseRequired = false, messageId =
ID:MSIPAP101-36535-1333817412870-1:1:0:0:33, originalDestination = null,
originalTransactionId = null, producerId =
ID:MSIPAP101-36535-1333817412870-2:1:1:1, destination =
topic://ActiveMQ.Advisory.Consumer.Queue.SolidCloud.Requests.Desktops.IPA,
transactionId = null, expiration = 0, timestamp = 0, arrival = 0,
brokerInTime = 1333819225809, brokerOutTime = 1333819225810, correlationId
= null, replyTo = null, persistent = false, type = Advisory, priority = 0,
groupID = null, groupSequence = 0, targetConsumerId = null, compressed =
false, userID = null, content = null, marshalledProperties = null,
dataStructure = ConsumerInfo {commandId = 3, responseRequired = true,
consumerId = ID:WIIPAP101-52658-634694015719174302-1:0:1:1, destination =
queue://SolidCloud.Requests.Desktops.IPA, prefetchSize = 1000,
maximumPendingMessageLimit = 0, browser = false, dispatchAsync = true,
selector = null, subscriptionName = null, noLocal = false, exclusive =
false, retroactive = false, priority = 0, brokerPath = null,
optimizedAcknowledge = false, noRangeAcks = false, additionalPredicate =
null}, redeliveryCounter = 0, size = 1024, properties = {consumerCount=2,
originBrokerURL=ssl://MSIPAP101:61616,
originBrokerId=ID:MSIPAP101-36535-1333817412870-0:1, originBrokerName=
msipap101.vosh.net}, readOnlyProperties = false, readOnlyBody = false,
droppable = false} |
org.apache.activemq.network.DemandForwardingBridgeSupport | ActiveMQ
Connection Dispatcher: vm://msipap101.vosh.net#0
2012-04-07 13:20:26,912 | DEBUG | Error occured while processing sync
command: ActiveMQTextMessage {commandId = 5, responseRequired = true,
messageId = ID:WIIPAP101-52658-634694015719174302-1:0:1:1:1,
originalDestination = null, originalTransactionId = null, producerId =
ID:WIIPAP101-52658-634694015719174302-1:0:1:1, destination =
temp-queue://ID:POTMIP102-60127-634693656236343522-1:38:1, transactionId =
null, expiration = 0, timestamp = 1333819173524, arrival = 0, brokerInTime
= 1333819226907, brokerOutTime = 0, correlationId = null, replyTo = null,
persistent = true, type = null, priority = 4, groupID = null, groupSequence
= 0, targetConsumerId = null, compressed = false, userID = null, content =
null, marshalledProperties = null, dataStructure = null, redeliveryCounter
= 0, size = 0, properties = null, readOnlyProperties = false, readOnlyBody
= false, droppable = false, text = []}, exception: javax.jms.JMSException:
The destination temp-queue://ID:POTMIP102-60127-634693656236343522-1:38:1
does not exist. | org.apache.activemq.broker.TransportConnection.Service |
ActiveMQ Transport: ssl:///172.17.5.16:52657
javax.jms.JMSException: The destination
temp-queue://ID:POTMIP102-60127-634693656236343522-1:38:1 does not exist.
at
org.apache.activemq.broker.region.AbstractRegion.addDestination(AbstractRegion.java:149)
at
org.apache.activemq.broker.region.RegionBroker.addDestination(RegionBroker.java:314)
at
org.apache.activemq.broker.BrokerFilter.addDestination(BrokerFilter.java:145)
at
org.apache.activemq.advisory.AdvisoryBroker.addDestination(AdvisoryBroker.java:161)
at
org.apache.activemq.broker.BrokerFilter.addDestination(BrokerFilter.java:145)
at
org.apache.activemq.broker.BrokerFilter.addDestination(BrokerFilter.java:145)
at
org.apache.activemq.broker.BrokerFilter.addDestination(BrokerFilter.java:145)
at
org.apache.activemq.broker.BrokerFilter.addDestination(BrokerFilter.java:145)
at
org.apache.activemq.security.AuthorizationBroker.addDestination(AuthorizationBroker.java:81)
at
org.apache.activemq.broker.MutableBrokerFilter.addDestination(MutableBrokerFilter.java:151)
at
org.apache.activemq.broker.region.RegionBroker.send(RegionBroker.java:506)
at
org.apache.activemq.broker.jmx.ManagedRegionBroker.send(ManagedRegionBroker.java:305)
at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:129)
at
org.apache.activemq.broker.CompositeDestinationBroker.send(CompositeDestinationBroker.java:96)
at
org.apache.activemq.broker.TransactionBroker.send(TransactionBroker.java:306)
at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:129)
at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:129)
at
org.apache.activemq.security.AuthorizationBroker.send(AuthorizationBroker.java:192)
at
org.apache.activemq.broker.MutableBrokerFilter.send(MutableBrokerFilter.java:135)
at
org.apache.activemq.broker.TransportConnection.processMessage(TransportConnection.java:452)
at
org.apache.activemq.command.ActiveMQMessage.visit(ActiveMQMessage.java:681)
at
org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:291)
at
org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:149)
at
org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
at
org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:113)
at
org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(AbstractInactivityMonitor.java:229)
at
org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83)
at
org.apache.activemq.transport.tcp.SslTransport.doConsume(SslTransport.java:91)
at
org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:222)
at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:204)
at java.lang.Thread.run(Thread.java:679)
2012-04-07 13:20:26,943 | DEBUG | Transport Connection to: tcp://
172.17.5.16:52657 failed: java.io.EOFException |
org.apache.activemq.broker.TransportConnection.Transport | ActiveMQ
Transport: ssl:///172.17.5.16:52657
java.io.EOFException
at java.io.DataInputStream.readInt(DataInputStream.java:392)
at
org.apache.activemq.openwire.OpenWireFormat.unmarshal(OpenWireFormat.java:275)
at
org.apache.activemq.transport.tcp.TcpTransport.readCommand(TcpTransport.java:229)
at
org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:221)
at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:204)
at java.lang.Thread.run(Thread.java:679)
2012-04-07 13:20:26,947 | DEBUG | Stopping connection: tcp://
172.17.5.16:52657 | org.apache.activemq.broker.TransportConnection |
StopAsync:tcp://172.17.5.16:52657-14
2012-04-07 13:20:26,948 | DEBUG | Stopping transport ssl:///
172.17.5.16:52657 | org.apache.activemq.transport.tcp.TcpTransport |
StopAsync:tcp://172.17.5.16:52657-14
2012-04-07 13:20:26,949 | DEBUG | Stopped transport:
tcp://172.17.5.16:52657|
org.apache.activemq.broker.TransportConnection |
StopAsync:tcp://172.17.5.16:52657-14
2012-04-07 13:20:26,950 | DEBUG | Cleaning up connection resources: tcp://
172.17.5.16:52657 | org.apache.activemq.broker.TransportConnection |
StopAsync:tcp://172.17.5.16:52657-14
2012-04-07 13:20:26,950 | DEBUG | remove connection id:
ID:WIIPAP101-52658-634694015719174302-1:0 |
org.apache.activemq.broker.TransportConnection |
StopAsync:tcp://172.17.5.16:52657-14
2012-04-07 13:20:26,951 | DEBUG | msipap101.vosh.net removing consumer:
ID:WIIPAP101-52658-634694015719174302-1:0:1:1 for destination:
queue://SolidCloud.Requests.Desktops.IPA |
org.apache.activemq.broker.region.AbstractRegion |
StopAsync:tcp://172.17.5.16:52657-14

For some reason the client is being disconnected. The log on the client is
showing the following:

2012-04-07
13:06:22.0000|ERROR|VOAuto.Services.Citrix.RequestInvoker|Channel was
inactive for too long:
ssl://msipap101.vosh.net:61616/EXCEPTIONOCCURRED:Apache.NMS.ActiveMQ.IOException
Channel was inactive for too long:
ssl://msipap101.vosh.net:61616/ Apache.NMS.ActiveMQ.Commands.Response
SyncRequest(Apache.NMS.ActiveMQ.Commands.Command, System.TimeSpan)    at
Apache.NMS.ActiveMQ.Connection.SyncRequest(Command command, TimeSpan
requestTimeout) in c:\dev\NMS.ActiveMQ\src\main\csharp\Connection.cs:line
667
   at Apache.NMS.ActiveMQ.Session.DoSend(ActiveMQDestination destination,
ActiveMQMessage message, MessageProducer producer, MemoryUsage
producerWindow, TimeSpan sendTimeout) in
c:\dev\NMS.ActiveMQ\src\main\csharp\Session.cs:line 716
   at Apache.NMS.ActiveMQ.MessageProducer.Send(IDestination destination,
IMessage message, MsgDeliveryMode deliveryMode, MsgPriority priority,
TimeSpan timeToLive, Boolean specifiedTimeToLive) in
c:\dev\NMS.ActiveMQ\src\main\csharp\MessageProducer.cs:line 258
   at Apache.NMS.ActiveMQ.MessageProducer.Send(IDestination destination,
IMessage message) in
c:\dev\NMS.ActiveMQ\src\main\csharp\MessageProducer.cs:line 170
   at
VirtualOffice.Automation.Messaging.Impl.ActiveMqMessagingProvider.<>c__DisplayClassd.<RegisterRequestReceiver>b__c(IMessage
message)

I'm sort of at a loss because the client is being disconnected and is not
reconnecting. Any suggestions?

Chris

Re: Client consumer exception and disconnection

Posted by Timothy Bish <ta...@gmail.com>.

On Sat, 2012-04-07 at 13:01 -0600, Chris Robison wrote: 
> Sorry, that was really badly written. Is the .NET client library supposed
> to be able to reconnect itself with the ActiveMQ broker or is that
> something I have to catch and do myself?

in order to have the client handle connection errors you need to use the
failover transport just like in the java client. 

> 
> On Sat, Apr 7, 2012 at 1:00 PM, Chris Robison <ch...@gmail.com>wrote:
> 
> > Is the .NET client library reconnect itself so is that something I have to
> > catch and do?
> >
> >
> > On Sat, Apr 7, 2012 at 12:37 PM, Chris Robison <ch...@gmail.com>wrote:
> >
> >> I'm assuming you mean set it on the connection factory. I've tried that,
> >> but no go. The only way I've found to recover from this is to delete the
> >> KahaDB on the activemq server and restart all services.
> >>
> >>
> >> On Sat, Apr 7, 2012 at 11:59 AM, Timothy Bish <ta...@gmail.com>wrote:
> >>
> >>> On Sat, 2012-04-07 at 11:56 -0600, Chris Robison wrote:
> >>> > I'm running into an interesting issue. I have a client connecting to an
> >>> > activemq server, trying to consume messages and reply to a temporary
> >>> > destination set. The ActiveMQ server debug is showing the following:
> >>> >
> >>> > 2012-04-07 13:20:25,708 | DEBUG | Received WireFormat: WireFormatInfo {
> >>> > version=6, properties={CacheSize=0, CacheEnabled=false,
> >>> > MaxInactivityDurationInitialDelay=10000, SizePrefixDisabled=false,
> >>> > TcpNoDelayEnabled=true, MaxInactivityDuration=30000,
> >>> > TightEncodingEnabled=false, StackTraceEnabled=false},
> >>> > magic=[A,c,t,i,v,e,M,Q]} |
> >>> > org.apache.activemq.transport.WireFormatNegotiator | ActiveMQ
> >>> Transport:
> >>> > ssl:///172.17.5.16:52657
> >>> > 2012-04-07 13:20:25,708 | DEBUG | ssl:///172.17.5.16:52657 before
> >>> > negotiation: OpenWireFormat{version=9, cacheEnabled=false,
> >>> > stackTraceEnabled=false, tightEncodingEnabled=false,
> >>> > sizePrefixDisabled=false, maxFrameSize=104857600} |
> >>> > org.apache.activemq.transport.WireFormatNegotiator | ActiveMQ
> >>> Transport:
> >>> > ssl:///172.17.5.16:52657
> >>> > 2012-04-07 13:20:25,709 | DEBUG | ssl:///172.17.5.16:52657 after
> >>> > negotiation: OpenWireFormat{version=6, cacheEnabled=false,
> >>> > stackTraceEnabled=false, tightEncodingEnabled=false,
> >>> > sizePrefixDisabled=false, maxFrameSize=104857600} |
> >>> > org.apache.activemq.transport.WireFormatNegotiator | ActiveMQ
> >>> Transport:
> >>> > ssl:///172.17.5.16:52657
> >>> > 2012-04-07 13:20:25,725 | DEBUG | Setting up new connection id:
> >>> > ID:WIIPAP101-52658-634694015719174302-1:0, address: tcp://
> >>> 172.17.5.16:52657,
> >>> > info: ConnectionInfo {commandId = 1, responseRequired = true,
> >>> connectionId
> >>> > = ID:WIIPAP101-52658-634694015719174302-1:0, clientId =
> >>> > ID:WIIPAP101-52658-634694015719174302-0:0, clientIp = null, userName =
> >>> > mqipauser, password = *****, brokerPath = null, brokerMasterConnector =
> >>> > false, manageable = false, clientMaster = false, faultTolerant = false,
> >>> > failoverReconnect = false} |
> >>> org.apache.activemq.broker.TransportConnection
> >>> > | ActiveMQ Transport: ssl:///172.17.5.16:52657
> >>> > 2012-04-07 13:20:25,727 | DEBUG | Create the LDAP initial context. |
> >>> > org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
> >>> > 172.17.5.16:52657
> >>> > 2012-04-07 13:20:25,739 | DEBUG | Get the user DN. |
> >>> > org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
> >>> > 172.17.5.16:52657
> >>> > 2012-04-07 13:20:25,739 | DEBUG | Looking for the user in LDAP with  |
> >>> > org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
> >>> > 172.17.5.16:52657
> >>> > 2012-04-07 13:20:25,740 | DEBUG |   base DN:
> >>> > OU=Users,OU=ActiveMQ,DC=VOSH,DC=NET |
> >>> > org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
> >>> > 172.17.5.16:52657
> >>> > 2012-04-07 13:20:25,740 | DEBUG |   filter: (sAMAccountName=mqipauser)
> >>> |
> >>> > org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
> >>> > 172.17.5.16:52657
> >>> > 2012-04-07 13:20:25,743 | DEBUG | Binding the user. |
> >>> > org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
> >>> > 172.17.5.16:52657
> >>> > 2012-04-07 13:20:25,750 | DEBUG | User CN=MQ IPA
> >>> > User,OU=Users,OU=ActiveMQ,DC=VOSH,DC=NET successfully bound. |
> >>> > org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
> >>> > 172.17.5.16:52657
> >>> > 2012-04-07 13:20:25,751 | DEBUG | Get user roles. |
> >>> > org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
> >>> > 172.17.5.16:52657
> >>> > 2012-04-07 13:20:25,751 | DEBUG | Looking for the user roles in LDAP
> >>> with
> >>> >  | org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport:
> >>> ssl:///
> >>> > 172.17.5.16:52657
> >>> > 2012-04-07 13:20:25,751 | DEBUG |   base DN:
> >>> > OU=Groups,OU=ActiveMQ,DC=VOSH,DC=NET |
> >>> > org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
> >>> > 172.17.5.16:52657
> >>> > 2012-04-07 13:20:25,751 | DEBUG |   filter: (member=CN=MQ IPA
> >>> > User,OU=Users,OU=ActiveMQ,DC=VOSH,DC=NET) |
> >>> > org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
> >>> > 172.17.5.16:52657
> >>> > 2012-04-07 13:20:25,762 | DEBUG | Roles [MQIPAUsers, MQUsers] for user
> >>> > mqipauser | org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ
> >>> Transport:
> >>> > ssl:///172.17.5.16:52657
> >>> > 2012-04-07 13:20:25,789 | DEBUG | msipap101.vosh.net adding consumer:
> >>> > ID:WIIPAP101-52658-634694015719174302-1:0:1:1 for destination:
> >>> > queue://SolidCloud.Requests.Desktops.IPA |
> >>> > org.apache.activemq.broker.region.AbstractRegion | ActiveMQ Transport:
> >>> > ssl:///172.17.5.16:52657
> >>> > 2012-04-07 13:20:25,797 | DEBUG |
> >>> queue://SolidCloud.Requests.Desktops.IPA
> >>> > add sub: QueueSubscription:
> >>> > consumer=ID:WIIPAP101-52658-634694015719174302-1:0:1:1, destinations=0,
> >>> > dispatched=0, delivered=0, pending=0, dequeues: 1, dispatched: 1,
> >>> inflight:
> >>> > 0 | org.apache.activemq.broker.region.Queue | ActiveMQ Transport:
> >>> ssl:///
> >>> > 172.17.5.16:52657
> >>> > 2012-04-07 13:20:25,798 | DEBUG | SolidCloud.Requests.Desktops.IPA
> >>> > toPageIn: 0, Inflight: 0, pagedInMessages.size 9, enqueueCount: 3,
> >>> > dequeueCount: 1 | org.apache.activemq.broker.region.Queue |
> >>> > Queue:SolidCloud.Requests.Desktops.IPA
> >>> > 2012-04-07 13:20:25,810 | DEBUG | bridging (msipap101.vosh.net ->
> >>> > mstmip101.vosh.net) ID:MSIPAP101-36535-1333817412870-1:1:0:0:33,
> >>> consumer:
> >>> > ID:MSIPAP101-36535-1333817412870-2:2:1:1, destination
> >>> >
> >>> topic://ActiveMQ.Advisory.Consumer.Queue.SolidCloud.Requests.Desktops.IPA,
> >>> > brokerPath: [ID:MSIPAP101-36535-1333817412870-0:1], message:
> >>> > ActiveMQMessage {commandId = 0, responseRequired = false, messageId =
> >>> > ID:MSIPAP101-36535-1333817412870-1:1:0:0:33, originalDestination =
> >>> null,
> >>> > originalTransactionId = null, producerId =
> >>> > ID:MSIPAP101-36535-1333817412870-2:1:1:1, destination =
> >>> >
> >>> topic://ActiveMQ.Advisory.Consumer.Queue.SolidCloud.Requests.Desktops.IPA,
> >>> > transactionId = null, expiration = 0, timestamp = 0, arrival = 0,
> >>> > brokerInTime = 1333819225809, brokerOutTime = 1333819225810,
> >>> correlationId
> >>> > = null, replyTo = null, persistent = false, type = Advisory, priority
> >>> = 0,
> >>> > groupID = null, groupSequence = 0, targetConsumerId = null, compressed
> >>> =
> >>> > false, userID = null, content = null, marshalledProperties = null,
> >>> > dataStructure = ConsumerInfo {commandId = 3, responseRequired = true,
> >>> > consumerId = ID:WIIPAP101-52658-634694015719174302-1:0:1:1,
> >>> destination =
> >>> > queue://SolidCloud.Requests.Desktops.IPA, prefetchSize = 1000,
> >>> > maximumPendingMessageLimit = 0, browser = false, dispatchAsync = true,
> >>> > selector = null, subscriptionName = null, noLocal = false, exclusive =
> >>> > false, retroactive = false, priority = 0, brokerPath = null,
> >>> > optimizedAcknowledge = false, noRangeAcks = false, additionalPredicate
> >>> =
> >>> > null}, redeliveryCounter = 0, size = 1024, properties =
> >>> {consumerCount=2,
> >>> > originBrokerURL=ssl://MSIPAP101:61616,
> >>> > originBrokerId=ID:MSIPAP101-36535-1333817412870-0:1, originBrokerName=
> >>> > msipap101.vosh.net}, readOnlyProperties = false, readOnlyBody = false,
> >>> > droppable = false} |
> >>> > org.apache.activemq.network.DemandForwardingBridgeSupport | ActiveMQ
> >>> > Connection Dispatcher: vm://msipap101.vosh.net#0
> >>> > 2012-04-07 13:20:26,912 | DEBUG | Error occured while processing sync
> >>> > command: ActiveMQTextMessage {commandId = 5, responseRequired = true,
> >>> > messageId = ID:WIIPAP101-52658-634694015719174302-1:0:1:1:1,
> >>> > originalDestination = null, originalTransactionId = null, producerId =
> >>> > ID:WIIPAP101-52658-634694015719174302-1:0:1:1, destination =
> >>> > temp-queue://ID:POTMIP102-60127-634693656236343522-1:38:1,
> >>> transactionId =
> >>> > null, expiration = 0, timestamp = 1333819173524, arrival = 0,
> >>> brokerInTime
> >>> > = 1333819226907, brokerOutTime = 0, correlationId = null, replyTo =
> >>> null,
> >>> > persistent = true, type = null, priority = 4, groupID = null,
> >>> groupSequence
> >>> > = 0, targetConsumerId = null, compressed = false, userID = null,
> >>> content =
> >>> > null, marshalledProperties = null, dataStructure = null,
> >>> redeliveryCounter
> >>> > = 0, size = 0, properties = null, readOnlyProperties = false,
> >>> readOnlyBody
> >>> > = false, droppable = false, text = []}, exception:
> >>> javax.jms.JMSException:
> >>> > The destination
> >>> temp-queue://ID:POTMIP102-60127-634693656236343522-1:38:1
> >>> > does not exist. |
> >>> org.apache.activemq.broker.TransportConnection.Service |
> >>> > ActiveMQ Transport: ssl:///172.17.5.16:52657
> >>> > javax.jms.JMSException: The destination
> >>> > temp-queue://ID:POTMIP102-60127-634693656236343522-1:38:1 does not
> >>> exist.
> >>> > at
> >>> >
> >>> org.apache.activemq.broker.region.AbstractRegion.addDestination(AbstractRegion.java:149)
> >>> > at
> >>> >
> >>> org.apache.activemq.broker.region.RegionBroker.addDestination(RegionBroker.java:314)
> >>> > at
> >>> >
> >>> org.apache.activemq.broker.BrokerFilter.addDestination(BrokerFilter.java:145)
> >>> > at
> >>> >
> >>> org.apache.activemq.advisory.AdvisoryBroker.addDestination(AdvisoryBroker.java:161)
> >>> > at
> >>> >
> >>> org.apache.activemq.broker.BrokerFilter.addDestination(BrokerFilter.java:145)
> >>> > at
> >>> >
> >>> org.apache.activemq.broker.BrokerFilter.addDestination(BrokerFilter.java:145)
> >>> > at
> >>> >
> >>> org.apache.activemq.broker.BrokerFilter.addDestination(BrokerFilter.java:145)
> >>> > at
> >>> >
> >>> org.apache.activemq.broker.BrokerFilter.addDestination(BrokerFilter.java:145)
> >>> > at
> >>> >
> >>> org.apache.activemq.security.AuthorizationBroker.addDestination(AuthorizationBroker.java:81)
> >>> > at
> >>> >
> >>> org.apache.activemq.broker.MutableBrokerFilter.addDestination(MutableBrokerFilter.java:151)
> >>> > at
> >>> >
> >>> org.apache.activemq.broker.region.RegionBroker.send(RegionBroker.java:506)
> >>> > at
> >>> >
> >>> org.apache.activemq.broker.jmx.ManagedRegionBroker.send(ManagedRegionBroker.java:305)
> >>> > at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:129)
> >>> > at
> >>> >
> >>> org.apache.activemq.broker.CompositeDestinationBroker.send(CompositeDestinationBroker.java:96)
> >>> > at
> >>> >
> >>> org.apache.activemq.broker.TransactionBroker.send(TransactionBroker.java:306)
> >>> > at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:129)
> >>> > at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:129)
> >>> > at
> >>> >
> >>> org.apache.activemq.security.AuthorizationBroker.send(AuthorizationBroker.java:192)
> >>> > at
> >>> >
> >>> org.apache.activemq.broker.MutableBrokerFilter.send(MutableBrokerFilter.java:135)
> >>> > at
> >>> >
> >>> org.apache.activemq.broker.TransportConnection.processMessage(TransportConnection.java:452)
> >>> > at
> >>> >
> >>> org.apache.activemq.command.ActiveMQMessage.visit(ActiveMQMessage.java:681)
> >>> > at
> >>> >
> >>> org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:291)
> >>> > at
> >>> >
> >>> org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:149)
> >>> > at
> >>> >
> >>> org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
> >>> > at
> >>> >
> >>> org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:113)
> >>> > at
> >>> >
> >>> org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(AbstractInactivityMonitor.java:229)
> >>> > at
> >>> >
> >>> org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83)
> >>> > at
> >>> >
> >>> org.apache.activemq.transport.tcp.SslTransport.doConsume(SslTransport.java:91)
> >>> > at
> >>> >
> >>> org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:222)
> >>> > at
> >>> org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:204)
> >>> > at java.lang.Thread.run(Thread.java:679)
> >>> > 2012-04-07 13:20:26,943 | DEBUG | Transport Connection to: tcp://
> >>> > 172.17.5.16:52657 failed: java.io.EOFException |
> >>> > org.apache.activemq.broker.TransportConnection.Transport | ActiveMQ
> >>> > Transport: ssl:///172.17.5.16:52657
> >>> > java.io.EOFException
> >>> > at java.io.DataInputStream.readInt(DataInputStream.java:392)
> >>> > at
> >>> >
> >>> org.apache.activemq.openwire.OpenWireFormat.unmarshal(OpenWireFormat.java:275)
> >>> > at
> >>> >
> >>> org.apache.activemq.transport.tcp.TcpTransport.readCommand(TcpTransport.java:229)
> >>> > at
> >>> >
> >>> org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:221)
> >>> > at
> >>> org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:204)
> >>> > at java.lang.Thread.run(Thread.java:679)
> >>> > 2012-04-07 13:20:26,947 | DEBUG | Stopping connection: tcp://
> >>> > 172.17.5.16:52657 | org.apache.activemq.broker.TransportConnection |
> >>> > StopAsync:tcp://172.17.5.16:52657-14
> >>> > 2012-04-07 13:20:26,948 | DEBUG | Stopping transport ssl:///
> >>> > 172.17.5.16:52657 | org.apache.activemq.transport.tcp.TcpTransport |
> >>> > StopAsync:tcp://172.17.5.16:52657-14
> >>> > 2012-04-07 13:20:26,949 | DEBUG | Stopped transport:
> >>> > tcp://172.17.5.16:52657|
> >>> > org.apache.activemq.broker.TransportConnection |
> >>> > StopAsync:tcp://172.17.5.16:52657-14
> >>> > 2012-04-07 13:20:26,950 | DEBUG | Cleaning up connection resources:
> >>> tcp://
> >>> > 172.17.5.16:52657 | org.apache.activemq.broker.TransportConnection |
> >>> > StopAsync:tcp://172.17.5.16:52657-14
> >>> > 2012-04-07 13:20:26,950 | DEBUG | remove connection id:
> >>> > ID:WIIPAP101-52658-634694015719174302-1:0 |
> >>> > org.apache.activemq.broker.TransportConnection |
> >>> > StopAsync:tcp://172.17.5.16:52657-14
> >>> > 2012-04-07 13:20:26,951 | DEBUG | msipap101.vosh.net removing
> >>> consumer:
> >>> > ID:WIIPAP101-52658-634694015719174302-1:0:1:1 for destination:
> >>> > queue://SolidCloud.Requests.Desktops.IPA |
> >>> > org.apache.activemq.broker.region.AbstractRegion |
> >>> > StopAsync:tcp://172.17.5.16:52657-14
> >>> >
> >>> > For some reason the client is being disconnected. The log on the
> >>> client is
> >>> > showing the following:
> >>> >
> >>> > 2012-04-07
> >>> > 13:06:22.0000|ERROR|VOAuto.Services.Citrix.RequestInvoker|Channel was
> >>> > inactive for too long:
> >>> > ssl://
> >>> msipap101.vosh.net:61616/EXCEPTIONOCCURRED:Apache.NMS.ActiveMQ.IOException
> >>> > Channel was inactive for too long:
> >>> > ssl://msipap101.vosh.net:61616/ Apache.NMS.ActiveMQ.Commands.Response
> >>> > SyncRequest(Apache.NMS.ActiveMQ.Commands.Command, System.TimeSpan)
> >>>  at
> >>> > Apache.NMS.ActiveMQ.Connection.SyncRequest(Command command, TimeSpan
> >>> > requestTimeout) in
> >>> c:\dev\NMS.ActiveMQ\src\main\csharp\Connection.cs:line
> >>> > 667
> >>> >    at Apache.NMS.ActiveMQ.Session.DoSend(ActiveMQDestination
> >>> destination,
> >>> > ActiveMQMessage message, MessageProducer producer, MemoryUsage
> >>> > producerWindow, TimeSpan sendTimeout) in
> >>> > c:\dev\NMS.ActiveMQ\src\main\csharp\Session.cs:line 716
> >>> >    at Apache.NMS.ActiveMQ.MessageProducer.Send(IDestination
> >>> destination,
> >>> > IMessage message, MsgDeliveryMode deliveryMode, MsgPriority priority,
> >>> > TimeSpan timeToLive, Boolean specifiedTimeToLive) in
> >>> > c:\dev\NMS.ActiveMQ\src\main\csharp\MessageProducer.cs:line 258
> >>> >    at Apache.NMS.ActiveMQ.MessageProducer.Send(IDestination
> >>> destination,
> >>> > IMessage message) in
> >>> > c:\dev\NMS.ActiveMQ\src\main\csharp\MessageProducer.cs:line 170
> >>> >    at
> >>> >
> >>> VirtualOffice.Automation.Messaging.Impl.ActiveMqMessagingProvider.<>c__DisplayClassd.<RegisterRequestReceiver>b__c(IMessage
> >>> > message)
> >>> >
> >>> > I'm sort of at a loss because the client is being disconnected and is
> >>> not
> >>> > reconnecting. Any suggestions?
> >>> >
> >>> > Chris
> >>>
> >>> Try turning off watchTopicAdvisories for the connection, there is a bug
> >>> in v 1.5.3 related to this.
> >>>
> >>> --
> >>> Tim Bish
> >>> Sr Software Engineer | FuseSource Corp
> >>> tim.bish@fusesource.com | www.fusesource.com
> >>> skype: tabish121 | twitter: @tabish121
> >>> blog: http://timbish.blogspot.com/
> >>>
> >>>
> >>
> >

-- 
Tim Bish
Sr Software Engineer | FuseSource Corp
tim.bish@fusesource.com | www.fusesource.com
skype: tabish121 | twitter: @tabish121
blog: http://timbish.blogspot.com/

Re: Client consumer exception and disconnection

Posted by Chris Robison <ch...@gmail.com>.

Sorry, that was really badly written. Is the .NET client library supposed
to be able to reconnect itself with the ActiveMQ broker or is that
something I have to catch and do myself?

On Sat, Apr 7, 2012 at 1:00 PM, Chris Robison <ch...@gmail.com>wrote:

> Is the .NET client library reconnect itself so is that something I have to
> catch and do?
>
>
> On Sat, Apr 7, 2012 at 12:37 PM, Chris Robison <ch...@gmail.com>wrote:
>
>> I'm assuming you mean set it on the connection factory. I've tried that,
>> but no go. The only way I've found to recover from this is to delete the
>> KahaDB on the activemq server and restart all services.
>>
>>
>> On Sat, Apr 7, 2012 at 11:59 AM, Timothy Bish <ta...@gmail.com>wrote:
>>
>>> On Sat, 2012-04-07 at 11:56 -0600, Chris Robison wrote:
>>> > I'm running into an interesting issue. I have a client connecting to an
>>> > activemq server, trying to consume messages and reply to a temporary
>>> > destination set. The ActiveMQ server debug is showing the following:
>>> >
>>> > 2012-04-07 13:20:25,708 | DEBUG | Received WireFormat: WireFormatInfo {
>>> > version=6, properties={CacheSize=0, CacheEnabled=false,
>>> > MaxInactivityDurationInitialDelay=10000, SizePrefixDisabled=false,
>>> > TcpNoDelayEnabled=true, MaxInactivityDuration=30000,
>>> > TightEncodingEnabled=false, StackTraceEnabled=false},
>>> > magic=[A,c,t,i,v,e,M,Q]} |
>>> > org.apache.activemq.transport.WireFormatNegotiator | ActiveMQ
>>> Transport:
>>> > ssl:///172.17.5.16:52657
>>> > 2012-04-07 13:20:25,708 | DEBUG | ssl:///172.17.5.16:52657 before
>>> > negotiation: OpenWireFormat{version=9, cacheEnabled=false,
>>> > stackTraceEnabled=false, tightEncodingEnabled=false,
>>> > sizePrefixDisabled=false, maxFrameSize=104857600} |
>>> > org.apache.activemq.transport.WireFormatNegotiator | ActiveMQ
>>> Transport:
>>> > ssl:///172.17.5.16:52657
>>> > 2012-04-07 13:20:25,709 | DEBUG | ssl:///172.17.5.16:52657 after
>>> > negotiation: OpenWireFormat{version=6, cacheEnabled=false,
>>> > stackTraceEnabled=false, tightEncodingEnabled=false,
>>> > sizePrefixDisabled=false, maxFrameSize=104857600} |
>>> > org.apache.activemq.transport.WireFormatNegotiator | ActiveMQ
>>> Transport:
>>> > ssl:///172.17.5.16:52657
>>> > 2012-04-07 13:20:25,725 | DEBUG | Setting up new connection id:
>>> > ID:WIIPAP101-52658-634694015719174302-1:0, address: tcp://
>>> 172.17.5.16:52657,
>>> > info: ConnectionInfo {commandId = 1, responseRequired = true,
>>> connectionId
>>> > = ID:WIIPAP101-52658-634694015719174302-1:0, clientId =
>>> > ID:WIIPAP101-52658-634694015719174302-0:0, clientIp = null, userName =
>>> > mqipauser, password = *****, brokerPath = null, brokerMasterConnector =
>>> > false, manageable = false, clientMaster = false, faultTolerant = false,
>>> > failoverReconnect = false} |
>>> org.apache.activemq.broker.TransportConnection
>>> > | ActiveMQ Transport: ssl:///172.17.5.16:52657
>>> > 2012-04-07 13:20:25,727 | DEBUG | Create the LDAP initial context. |
>>> > org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
>>> > 172.17.5.16:52657
>>> > 2012-04-07 13:20:25,739 | DEBUG | Get the user DN. |
>>> > org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
>>> > 172.17.5.16:52657
>>> > 2012-04-07 13:20:25,739 | DEBUG | Looking for the user in LDAP with  |
>>> > org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
>>> > 172.17.5.16:52657
>>> > 2012-04-07 13:20:25,740 | DEBUG |   base DN:
>>> > OU=Users,OU=ActiveMQ,DC=VOSH,DC=NET |
>>> > org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
>>> > 172.17.5.16:52657
>>> > 2012-04-07 13:20:25,740 | DEBUG |   filter: (sAMAccountName=mqipauser)
>>> |
>>> > org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
>>> > 172.17.5.16:52657
>>> > 2012-04-07 13:20:25,743 | DEBUG | Binding the user. |
>>> > org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
>>> > 172.17.5.16:52657
>>> > 2012-04-07 13:20:25,750 | DEBUG | User CN=MQ IPA
>>> > User,OU=Users,OU=ActiveMQ,DC=VOSH,DC=NET successfully bound. |
>>> > org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
>>> > 172.17.5.16:52657
>>> > 2012-04-07 13:20:25,751 | DEBUG | Get user roles. |
>>> > org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
>>> > 172.17.5.16:52657
>>> > 2012-04-07 13:20:25,751 | DEBUG | Looking for the user roles in LDAP
>>> with
>>> >  | org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport:
>>> ssl:///
>>> > 172.17.5.16:52657
>>> > 2012-04-07 13:20:25,751 | DEBUG |   base DN:
>>> > OU=Groups,OU=ActiveMQ,DC=VOSH,DC=NET |
>>> > org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
>>> > 172.17.5.16:52657
>>> > 2012-04-07 13:20:25,751 | DEBUG |   filter: (member=CN=MQ IPA
>>> > User,OU=Users,OU=ActiveMQ,DC=VOSH,DC=NET) |
>>> > org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
>>> > 172.17.5.16:52657
>>> > 2012-04-07 13:20:25,762 | DEBUG | Roles [MQIPAUsers, MQUsers] for user
>>> > mqipauser | org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ
>>> Transport:
>>> > ssl:///172.17.5.16:52657
>>> > 2012-04-07 13:20:25,789 | DEBUG | msipap101.vosh.net adding consumer:
>>> > ID:WIIPAP101-52658-634694015719174302-1:0:1:1 for destination:
>>> > queue://SolidCloud.Requests.Desktops.IPA |
>>> > org.apache.activemq.broker.region.AbstractRegion | ActiveMQ Transport:
>>> > ssl:///172.17.5.16:52657
>>> > 2012-04-07 13:20:25,797 | DEBUG |
>>> queue://SolidCloud.Requests.Desktops.IPA
>>> > add sub: QueueSubscription:
>>> > consumer=ID:WIIPAP101-52658-634694015719174302-1:0:1:1, destinations=0,
>>> > dispatched=0, delivered=0, pending=0, dequeues: 1, dispatched: 1,
>>> inflight:
>>> > 0 | org.apache.activemq.broker.region.Queue | ActiveMQ Transport:
>>> ssl:///
>>> > 172.17.5.16:52657
>>> > 2012-04-07 13:20:25,798 | DEBUG | SolidCloud.Requests.Desktops.IPA
>>> > toPageIn: 0, Inflight: 0, pagedInMessages.size 9, enqueueCount: 3,
>>> > dequeueCount: 1 | org.apache.activemq.broker.region.Queue |
>>> > Queue:SolidCloud.Requests.Desktops.IPA
>>> > 2012-04-07 13:20:25,810 | DEBUG | bridging (msipap101.vosh.net ->
>>> > mstmip101.vosh.net) ID:MSIPAP101-36535-1333817412870-1:1:0:0:33,
>>> consumer:
>>> > ID:MSIPAP101-36535-1333817412870-2:2:1:1, destination
>>> >
>>> topic://ActiveMQ.Advisory.Consumer.Queue.SolidCloud.Requests.Desktops.IPA,
>>> > brokerPath: [ID:MSIPAP101-36535-1333817412870-0:1], message:
>>> > ActiveMQMessage {commandId = 0, responseRequired = false, messageId =
>>> > ID:MSIPAP101-36535-1333817412870-1:1:0:0:33, originalDestination =
>>> null,
>>> > originalTransactionId = null, producerId =
>>> > ID:MSIPAP101-36535-1333817412870-2:1:1:1, destination =
>>> >
>>> topic://ActiveMQ.Advisory.Consumer.Queue.SolidCloud.Requests.Desktops.IPA,
>>> > transactionId = null, expiration = 0, timestamp = 0, arrival = 0,
>>> > brokerInTime = 1333819225809, brokerOutTime = 1333819225810,
>>> correlationId
>>> > = null, replyTo = null, persistent = false, type = Advisory, priority
>>> = 0,
>>> > groupID = null, groupSequence = 0, targetConsumerId = null, compressed
>>> =
>>> > false, userID = null, content = null, marshalledProperties = null,
>>> > dataStructure = ConsumerInfo {commandId = 3, responseRequired = true,
>>> > consumerId = ID:WIIPAP101-52658-634694015719174302-1:0:1:1,
>>> destination =
>>> > queue://SolidCloud.Requests.Desktops.IPA, prefetchSize = 1000,
>>> > maximumPendingMessageLimit = 0, browser = false, dispatchAsync = true,
>>> > selector = null, subscriptionName = null, noLocal = false, exclusive =
>>> > false, retroactive = false, priority = 0, brokerPath = null,
>>> > optimizedAcknowledge = false, noRangeAcks = false, additionalPredicate
>>> =
>>> > null}, redeliveryCounter = 0, size = 1024, properties =
>>> {consumerCount=2,
>>> > originBrokerURL=ssl://MSIPAP101:61616,
>>> > originBrokerId=ID:MSIPAP101-36535-1333817412870-0:1, originBrokerName=
>>> > msipap101.vosh.net}, readOnlyProperties = false, readOnlyBody = false,
>>> > droppable = false} |
>>> > org.apache.activemq.network.DemandForwardingBridgeSupport | ActiveMQ
>>> > Connection Dispatcher: vm://msipap101.vosh.net#0
>>> > 2012-04-07 13:20:26,912 | DEBUG | Error occured while processing sync
>>> > command: ActiveMQTextMessage {commandId = 5, responseRequired = true,
>>> > messageId = ID:WIIPAP101-52658-634694015719174302-1:0:1:1:1,
>>> > originalDestination = null, originalTransactionId = null, producerId =
>>> > ID:WIIPAP101-52658-634694015719174302-1:0:1:1, destination =
>>> > temp-queue://ID:POTMIP102-60127-634693656236343522-1:38:1,
>>> transactionId =
>>> > null, expiration = 0, timestamp = 1333819173524, arrival = 0,
>>> brokerInTime
>>> > = 1333819226907, brokerOutTime = 0, correlationId = null, replyTo =
>>> null,
>>> > persistent = true, type = null, priority = 4, groupID = null,
>>> groupSequence
>>> > = 0, targetConsumerId = null, compressed = false, userID = null,
>>> content =
>>> > null, marshalledProperties = null, dataStructure = null,
>>> redeliveryCounter
>>> > = 0, size = 0, properties = null, readOnlyProperties = false,
>>> readOnlyBody
>>> > = false, droppable = false, text = []}, exception:
>>> javax.jms.JMSException:
>>> > The destination
>>> temp-queue://ID:POTMIP102-60127-634693656236343522-1:38:1
>>> > does not exist. |
>>> org.apache.activemq.broker.TransportConnection.Service |
>>> > ActiveMQ Transport: ssl:///172.17.5.16:52657
>>> > javax.jms.JMSException: The destination
>>> > temp-queue://ID:POTMIP102-60127-634693656236343522-1:38:1 does not
>>> exist.
>>> > at
>>> >
>>> org.apache.activemq.broker.region.AbstractRegion.addDestination(AbstractRegion.java:149)
>>> > at
>>> >
>>> org.apache.activemq.broker.region.RegionBroker.addDestination(RegionBroker.java:314)
>>> > at
>>> >
>>> org.apache.activemq.broker.BrokerFilter.addDestination(BrokerFilter.java:145)
>>> > at
>>> >
>>> org.apache.activemq.advisory.AdvisoryBroker.addDestination(AdvisoryBroker.java:161)
>>> > at
>>> >
>>> org.apache.activemq.broker.BrokerFilter.addDestination(BrokerFilter.java:145)
>>> > at
>>> >
>>> org.apache.activemq.broker.BrokerFilter.addDestination(BrokerFilter.java:145)
>>> > at
>>> >
>>> org.apache.activemq.broker.BrokerFilter.addDestination(BrokerFilter.java:145)
>>> > at
>>> >
>>> org.apache.activemq.broker.BrokerFilter.addDestination(BrokerFilter.java:145)
>>> > at
>>> >
>>> org.apache.activemq.security.AuthorizationBroker.addDestination(AuthorizationBroker.java:81)
>>> > at
>>> >
>>> org.apache.activemq.broker.MutableBrokerFilter.addDestination(MutableBrokerFilter.java:151)
>>> > at
>>> >
>>> org.apache.activemq.broker.region.RegionBroker.send(RegionBroker.java:506)
>>> > at
>>> >
>>> org.apache.activemq.broker.jmx.ManagedRegionBroker.send(ManagedRegionBroker.java:305)
>>> > at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:129)
>>> > at
>>> >
>>> org.apache.activemq.broker.CompositeDestinationBroker.send(CompositeDestinationBroker.java:96)
>>> > at
>>> >
>>> org.apache.activemq.broker.TransactionBroker.send(TransactionBroker.java:306)
>>> > at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:129)
>>> > at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:129)
>>> > at
>>> >
>>> org.apache.activemq.security.AuthorizationBroker.send(AuthorizationBroker.java:192)
>>> > at
>>> >
>>> org.apache.activemq.broker.MutableBrokerFilter.send(MutableBrokerFilter.java:135)
>>> > at
>>> >
>>> org.apache.activemq.broker.TransportConnection.processMessage(TransportConnection.java:452)
>>> > at
>>> >
>>> org.apache.activemq.command.ActiveMQMessage.visit(ActiveMQMessage.java:681)
>>> > at
>>> >
>>> org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:291)
>>> > at
>>> >
>>> org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:149)
>>> > at
>>> >
>>> org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
>>> > at
>>> >
>>> org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:113)
>>> > at
>>> >
>>> org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(AbstractInactivityMonitor.java:229)
>>> > at
>>> >
>>> org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83)
>>> > at
>>> >
>>> org.apache.activemq.transport.tcp.SslTransport.doConsume(SslTransport.java:91)
>>> > at
>>> >
>>> org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:222)
>>> > at
>>> org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:204)
>>> > at java.lang.Thread.run(Thread.java:679)
>>> > 2012-04-07 13:20:26,943 | DEBUG | Transport Connection to: tcp://
>>> > 172.17.5.16:52657 failed: java.io.EOFException |
>>> > org.apache.activemq.broker.TransportConnection.Transport | ActiveMQ
>>> > Transport: ssl:///172.17.5.16:52657
>>> > java.io.EOFException
>>> > at java.io.DataInputStream.readInt(DataInputStream.java:392)
>>> > at
>>> >
>>> org.apache.activemq.openwire.OpenWireFormat.unmarshal(OpenWireFormat.java:275)
>>> > at
>>> >
>>> org.apache.activemq.transport.tcp.TcpTransport.readCommand(TcpTransport.java:229)
>>> > at
>>> >
>>> org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:221)
>>> > at
>>> org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:204)
>>> > at java.lang.Thread.run(Thread.java:679)
>>> > 2012-04-07 13:20:26,947 | DEBUG | Stopping connection: tcp://
>>> > 172.17.5.16:52657 | org.apache.activemq.broker.TransportConnection |
>>> > StopAsync:tcp://172.17.5.16:52657-14
>>> > 2012-04-07 13:20:26,948 | DEBUG | Stopping transport ssl:///
>>> > 172.17.5.16:52657 | org.apache.activemq.transport.tcp.TcpTransport |
>>> > StopAsync:tcp://172.17.5.16:52657-14
>>> > 2012-04-07 13:20:26,949 | DEBUG | Stopped transport:
>>> > tcp://172.17.5.16:52657|
>>> > org.apache.activemq.broker.TransportConnection |
>>> > StopAsync:tcp://172.17.5.16:52657-14
>>> > 2012-04-07 13:20:26,950 | DEBUG | Cleaning up connection resources:
>>> tcp://
>>> > 172.17.5.16:52657 | org.apache.activemq.broker.TransportConnection |
>>> > StopAsync:tcp://172.17.5.16:52657-14
>>> > 2012-04-07 13:20:26,950 | DEBUG | remove connection id:
>>> > ID:WIIPAP101-52658-634694015719174302-1:0 |
>>> > org.apache.activemq.broker.TransportConnection |
>>> > StopAsync:tcp://172.17.5.16:52657-14
>>> > 2012-04-07 13:20:26,951 | DEBUG | msipap101.vosh.net removing
>>> consumer:
>>> > ID:WIIPAP101-52658-634694015719174302-1:0:1:1 for destination:
>>> > queue://SolidCloud.Requests.Desktops.IPA |
>>> > org.apache.activemq.broker.region.AbstractRegion |
>>> > StopAsync:tcp://172.17.5.16:52657-14
>>> >
>>> > For some reason the client is being disconnected. The log on the
>>> client is
>>> > showing the following:
>>> >
>>> > 2012-04-07
>>> > 13:06:22.0000|ERROR|VOAuto.Services.Citrix.RequestInvoker|Channel was
>>> > inactive for too long:
>>> > ssl://
>>> msipap101.vosh.net:61616/EXCEPTIONOCCURRED:Apache.NMS.ActiveMQ.IOException
>>> > Channel was inactive for too long:
>>> > ssl://msipap101.vosh.net:61616/ Apache.NMS.ActiveMQ.Commands.Response
>>> > SyncRequest(Apache.NMS.ActiveMQ.Commands.Command, System.TimeSpan)
>>>  at
>>> > Apache.NMS.ActiveMQ.Connection.SyncRequest(Command command, TimeSpan
>>> > requestTimeout) in
>>> c:\dev\NMS.ActiveMQ\src\main\csharp\Connection.cs:line
>>> > 667
>>> >    at Apache.NMS.ActiveMQ.Session.DoSend(ActiveMQDestination
>>> destination,
>>> > ActiveMQMessage message, MessageProducer producer, MemoryUsage
>>> > producerWindow, TimeSpan sendTimeout) in
>>> > c:\dev\NMS.ActiveMQ\src\main\csharp\Session.cs:line 716
>>> >    at Apache.NMS.ActiveMQ.MessageProducer.Send(IDestination
>>> destination,
>>> > IMessage message, MsgDeliveryMode deliveryMode, MsgPriority priority,
>>> > TimeSpan timeToLive, Boolean specifiedTimeToLive) in
>>> > c:\dev\NMS.ActiveMQ\src\main\csharp\MessageProducer.cs:line 258
>>> >    at Apache.NMS.ActiveMQ.MessageProducer.Send(IDestination
>>> destination,
>>> > IMessage message) in
>>> > c:\dev\NMS.ActiveMQ\src\main\csharp\MessageProducer.cs:line 170
>>> >    at
>>> >
>>> VirtualOffice.Automation.Messaging.Impl.ActiveMqMessagingProvider.<>c__DisplayClassd.<RegisterRequestReceiver>b__c(IMessage
>>> > message)
>>> >
>>> > I'm sort of at a loss because the client is being disconnected and is
>>> not
>>> > reconnecting. Any suggestions?
>>> >
>>> > Chris
>>>
>>> Try turning off watchTopicAdvisories for the connection, there is a bug
>>> in v 1.5.3 related to this.
>>>
>>> --
>>> Tim Bish
>>> Sr Software Engineer | FuseSource Corp
>>> tim.bish@fusesource.com | www.fusesource.com
>>> skype: tabish121 | twitter: @tabish121
>>> blog: http://timbish.blogspot.com/
>>>
>>>
>>
>

Re: Client consumer exception and disconnection

Posted by Chris Robison <ch...@gmail.com>.

Is the .NET client library reconnect itself so is that something I have to
catch and do?

On Sat, Apr 7, 2012 at 12:37 PM, Chris Robison <ch...@gmail.com>wrote:

> I'm assuming you mean set it on the connection factory. I've tried that,
> but no go. The only way I've found to recover from this is to delete the
> KahaDB on the activemq server and restart all services.
>
>
> On Sat, Apr 7, 2012 at 11:59 AM, Timothy Bish <ta...@gmail.com> wrote:
>
>> On Sat, 2012-04-07 at 11:56 -0600, Chris Robison wrote:
>> > I'm running into an interesting issue. I have a client connecting to an
>> > activemq server, trying to consume messages and reply to a temporary
>> > destination set. The ActiveMQ server debug is showing the following:
>> >
>> > 2012-04-07 13:20:25,708 | DEBUG | Received WireFormat: WireFormatInfo {
>> > version=6, properties={CacheSize=0, CacheEnabled=false,
>> > MaxInactivityDurationInitialDelay=10000, SizePrefixDisabled=false,
>> > TcpNoDelayEnabled=true, MaxInactivityDuration=30000,
>> > TightEncodingEnabled=false, StackTraceEnabled=false},
>> > magic=[A,c,t,i,v,e,M,Q]} |
>> > org.apache.activemq.transport.WireFormatNegotiator | ActiveMQ Transport:
>> > ssl:///172.17.5.16:52657
>> > 2012-04-07 13:20:25,708 | DEBUG | ssl:///172.17.5.16:52657 before
>> > negotiation: OpenWireFormat{version=9, cacheEnabled=false,
>> > stackTraceEnabled=false, tightEncodingEnabled=false,
>> > sizePrefixDisabled=false, maxFrameSize=104857600} |
>> > org.apache.activemq.transport.WireFormatNegotiator | ActiveMQ Transport:
>> > ssl:///172.17.5.16:52657
>> > 2012-04-07 13:20:25,709 | DEBUG | ssl:///172.17.5.16:52657 after
>> > negotiation: OpenWireFormat{version=6, cacheEnabled=false,
>> > stackTraceEnabled=false, tightEncodingEnabled=false,
>> > sizePrefixDisabled=false, maxFrameSize=104857600} |
>> > org.apache.activemq.transport.WireFormatNegotiator | ActiveMQ Transport:
>> > ssl:///172.17.5.16:52657
>> > 2012-04-07 13:20:25,725 | DEBUG | Setting up new connection id:
>> > ID:WIIPAP101-52658-634694015719174302-1:0, address: tcp://
>> 172.17.5.16:52657,
>> > info: ConnectionInfo {commandId = 1, responseRequired = true,
>> connectionId
>> > = ID:WIIPAP101-52658-634694015719174302-1:0, clientId =
>> > ID:WIIPAP101-52658-634694015719174302-0:0, clientIp = null, userName =
>> > mqipauser, password = *****, brokerPath = null, brokerMasterConnector =
>> > false, manageable = false, clientMaster = false, faultTolerant = false,
>> > failoverReconnect = false} |
>> org.apache.activemq.broker.TransportConnection
>> > | ActiveMQ Transport: ssl:///172.17.5.16:52657
>> > 2012-04-07 13:20:25,727 | DEBUG | Create the LDAP initial context. |
>> > org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
>> > 172.17.5.16:52657
>> > 2012-04-07 13:20:25,739 | DEBUG | Get the user DN. |
>> > org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
>> > 172.17.5.16:52657
>> > 2012-04-07 13:20:25,739 | DEBUG | Looking for the user in LDAP with  |
>> > org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
>> > 172.17.5.16:52657
>> > 2012-04-07 13:20:25,740 | DEBUG |   base DN:
>> > OU=Users,OU=ActiveMQ,DC=VOSH,DC=NET |
>> > org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
>> > 172.17.5.16:52657
>> > 2012-04-07 13:20:25,740 | DEBUG |   filter: (sAMAccountName=mqipauser) |
>> > org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
>> > 172.17.5.16:52657
>> > 2012-04-07 13:20:25,743 | DEBUG | Binding the user. |
>> > org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
>> > 172.17.5.16:52657
>> > 2012-04-07 13:20:25,750 | DEBUG | User CN=MQ IPA
>> > User,OU=Users,OU=ActiveMQ,DC=VOSH,DC=NET successfully bound. |
>> > org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
>> > 172.17.5.16:52657
>> > 2012-04-07 13:20:25,751 | DEBUG | Get user roles. |
>> > org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
>> > 172.17.5.16:52657
>> > 2012-04-07 13:20:25,751 | DEBUG | Looking for the user roles in LDAP
>> with
>> >  | org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport:
>> ssl:///
>> > 172.17.5.16:52657
>> > 2012-04-07 13:20:25,751 | DEBUG |   base DN:
>> > OU=Groups,OU=ActiveMQ,DC=VOSH,DC=NET |
>> > org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
>> > 172.17.5.16:52657
>> > 2012-04-07 13:20:25,751 | DEBUG |   filter: (member=CN=MQ IPA
>> > User,OU=Users,OU=ActiveMQ,DC=VOSH,DC=NET) |
>> > org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
>> > 172.17.5.16:52657
>> > 2012-04-07 13:20:25,762 | DEBUG | Roles [MQIPAUsers, MQUsers] for user
>> > mqipauser | org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ
>> Transport:
>> > ssl:///172.17.5.16:52657
>> > 2012-04-07 13:20:25,789 | DEBUG | msipap101.vosh.net adding consumer:
>> > ID:WIIPAP101-52658-634694015719174302-1:0:1:1 for destination:
>> > queue://SolidCloud.Requests.Desktops.IPA |
>> > org.apache.activemq.broker.region.AbstractRegion | ActiveMQ Transport:
>> > ssl:///172.17.5.16:52657
>> > 2012-04-07 13:20:25,797 | DEBUG |
>> queue://SolidCloud.Requests.Desktops.IPA
>> > add sub: QueueSubscription:
>> > consumer=ID:WIIPAP101-52658-634694015719174302-1:0:1:1, destinations=0,
>> > dispatched=0, delivered=0, pending=0, dequeues: 1, dispatched: 1,
>> inflight:
>> > 0 | org.apache.activemq.broker.region.Queue | ActiveMQ Transport:
>> ssl:///
>> > 172.17.5.16:52657
>> > 2012-04-07 13:20:25,798 | DEBUG | SolidCloud.Requests.Desktops.IPA
>> > toPageIn: 0, Inflight: 0, pagedInMessages.size 9, enqueueCount: 3,
>> > dequeueCount: 1 | org.apache.activemq.broker.region.Queue |
>> > Queue:SolidCloud.Requests.Desktops.IPA
>> > 2012-04-07 13:20:25,810 | DEBUG | bridging (msipap101.vosh.net ->
>> > mstmip101.vosh.net) ID:MSIPAP101-36535-1333817412870-1:1:0:0:33,
>> consumer:
>> > ID:MSIPAP101-36535-1333817412870-2:2:1:1, destination
>> >
>> topic://ActiveMQ.Advisory.Consumer.Queue.SolidCloud.Requests.Desktops.IPA,
>> > brokerPath: [ID:MSIPAP101-36535-1333817412870-0:1], message:
>> > ActiveMQMessage {commandId = 0, responseRequired = false, messageId =
>> > ID:MSIPAP101-36535-1333817412870-1:1:0:0:33, originalDestination = null,
>> > originalTransactionId = null, producerId =
>> > ID:MSIPAP101-36535-1333817412870-2:1:1:1, destination =
>> >
>> topic://ActiveMQ.Advisory.Consumer.Queue.SolidCloud.Requests.Desktops.IPA,
>> > transactionId = null, expiration = 0, timestamp = 0, arrival = 0,
>> > brokerInTime = 1333819225809, brokerOutTime = 1333819225810,
>> correlationId
>> > = null, replyTo = null, persistent = false, type = Advisory, priority =
>> 0,
>> > groupID = null, groupSequence = 0, targetConsumerId = null, compressed =
>> > false, userID = null, content = null, marshalledProperties = null,
>> > dataStructure = ConsumerInfo {commandId = 3, responseRequired = true,
>> > consumerId = ID:WIIPAP101-52658-634694015719174302-1:0:1:1, destination
>> =
>> > queue://SolidCloud.Requests.Desktops.IPA, prefetchSize = 1000,
>> > maximumPendingMessageLimit = 0, browser = false, dispatchAsync = true,
>> > selector = null, subscriptionName = null, noLocal = false, exclusive =
>> > false, retroactive = false, priority = 0, brokerPath = null,
>> > optimizedAcknowledge = false, noRangeAcks = false, additionalPredicate =
>> > null}, redeliveryCounter = 0, size = 1024, properties =
>> {consumerCount=2,
>> > originBrokerURL=ssl://MSIPAP101:61616,
>> > originBrokerId=ID:MSIPAP101-36535-1333817412870-0:1, originBrokerName=
>> > msipap101.vosh.net}, readOnlyProperties = false, readOnlyBody = false,
>> > droppable = false} |
>> > org.apache.activemq.network.DemandForwardingBridgeSupport | ActiveMQ
>> > Connection Dispatcher: vm://msipap101.vosh.net#0
>> > 2012-04-07 13:20:26,912 | DEBUG | Error occured while processing sync
>> > command: ActiveMQTextMessage {commandId = 5, responseRequired = true,
>> > messageId = ID:WIIPAP101-52658-634694015719174302-1:0:1:1:1,
>> > originalDestination = null, originalTransactionId = null, producerId =
>> > ID:WIIPAP101-52658-634694015719174302-1:0:1:1, destination =
>> > temp-queue://ID:POTMIP102-60127-634693656236343522-1:38:1,
>> transactionId =
>> > null, expiration = 0, timestamp = 1333819173524, arrival = 0,
>> brokerInTime
>> > = 1333819226907, brokerOutTime = 0, correlationId = null, replyTo =
>> null,
>> > persistent = true, type = null, priority = 4, groupID = null,
>> groupSequence
>> > = 0, targetConsumerId = null, compressed = false, userID = null,
>> content =
>> > null, marshalledProperties = null, dataStructure = null,
>> redeliveryCounter
>> > = 0, size = 0, properties = null, readOnlyProperties = false,
>> readOnlyBody
>> > = false, droppable = false, text = []}, exception:
>> javax.jms.JMSException:
>> > The destination
>> temp-queue://ID:POTMIP102-60127-634693656236343522-1:38:1
>> > does not exist. |
>> org.apache.activemq.broker.TransportConnection.Service |
>> > ActiveMQ Transport: ssl:///172.17.5.16:52657
>> > javax.jms.JMSException: The destination
>> > temp-queue://ID:POTMIP102-60127-634693656236343522-1:38:1 does not
>> exist.
>> > at
>> >
>> org.apache.activemq.broker.region.AbstractRegion.addDestination(AbstractRegion.java:149)
>> > at
>> >
>> org.apache.activemq.broker.region.RegionBroker.addDestination(RegionBroker.java:314)
>> > at
>> >
>> org.apache.activemq.broker.BrokerFilter.addDestination(BrokerFilter.java:145)
>> > at
>> >
>> org.apache.activemq.advisory.AdvisoryBroker.addDestination(AdvisoryBroker.java:161)
>> > at
>> >
>> org.apache.activemq.broker.BrokerFilter.addDestination(BrokerFilter.java:145)
>> > at
>> >
>> org.apache.activemq.broker.BrokerFilter.addDestination(BrokerFilter.java:145)
>> > at
>> >
>> org.apache.activemq.broker.BrokerFilter.addDestination(BrokerFilter.java:145)
>> > at
>> >
>> org.apache.activemq.broker.BrokerFilter.addDestination(BrokerFilter.java:145)
>> > at
>> >
>> org.apache.activemq.security.AuthorizationBroker.addDestination(AuthorizationBroker.java:81)
>> > at
>> >
>> org.apache.activemq.broker.MutableBrokerFilter.addDestination(MutableBrokerFilter.java:151)
>> > at
>> >
>> org.apache.activemq.broker.region.RegionBroker.send(RegionBroker.java:506)
>> > at
>> >
>> org.apache.activemq.broker.jmx.ManagedRegionBroker.send(ManagedRegionBroker.java:305)
>> > at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:129)
>> > at
>> >
>> org.apache.activemq.broker.CompositeDestinationBroker.send(CompositeDestinationBroker.java:96)
>> > at
>> >
>> org.apache.activemq.broker.TransactionBroker.send(TransactionBroker.java:306)
>> > at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:129)
>> > at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:129)
>> > at
>> >
>> org.apache.activemq.security.AuthorizationBroker.send(AuthorizationBroker.java:192)
>> > at
>> >
>> org.apache.activemq.broker.MutableBrokerFilter.send(MutableBrokerFilter.java:135)
>> > at
>> >
>> org.apache.activemq.broker.TransportConnection.processMessage(TransportConnection.java:452)
>> > at
>> >
>> org.apache.activemq.command.ActiveMQMessage.visit(ActiveMQMessage.java:681)
>> > at
>> >
>> org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:291)
>> > at
>> >
>> org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:149)
>> > at
>> >
>> org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
>> > at
>> >
>> org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:113)
>> > at
>> >
>> org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(AbstractInactivityMonitor.java:229)
>> > at
>> >
>> org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83)
>> > at
>> >
>> org.apache.activemq.transport.tcp.SslTransport.doConsume(SslTransport.java:91)
>> > at
>> >
>> org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:222)
>> > at
>> org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:204)
>> > at java.lang.Thread.run(Thread.java:679)
>> > 2012-04-07 13:20:26,943 | DEBUG | Transport Connection to: tcp://
>> > 172.17.5.16:52657 failed: java.io.EOFException |
>> > org.apache.activemq.broker.TransportConnection.Transport | ActiveMQ
>> > Transport: ssl:///172.17.5.16:52657
>> > java.io.EOFException
>> > at java.io.DataInputStream.readInt(DataInputStream.java:392)
>> > at
>> >
>> org.apache.activemq.openwire.OpenWireFormat.unmarshal(OpenWireFormat.java:275)
>> > at
>> >
>> org.apache.activemq.transport.tcp.TcpTransport.readCommand(TcpTransport.java:229)
>> > at
>> >
>> org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:221)
>> > at
>> org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:204)
>> > at java.lang.Thread.run(Thread.java:679)
>> > 2012-04-07 13:20:26,947 | DEBUG | Stopping connection: tcp://
>> > 172.17.5.16:52657 | org.apache.activemq.broker.TransportConnection |
>> > StopAsync:tcp://172.17.5.16:52657-14
>> > 2012-04-07 13:20:26,948 | DEBUG | Stopping transport ssl:///
>> > 172.17.5.16:52657 | org.apache.activemq.transport.tcp.TcpTransport |
>> > StopAsync:tcp://172.17.5.16:52657-14
>> > 2012-04-07 13:20:26,949 | DEBUG | Stopped transport:
>> > tcp://172.17.5.16:52657|
>> > org.apache.activemq.broker.TransportConnection |
>> > StopAsync:tcp://172.17.5.16:52657-14
>> > 2012-04-07 13:20:26,950 | DEBUG | Cleaning up connection resources:
>> tcp://
>> > 172.17.5.16:52657 | org.apache.activemq.broker.TransportConnection |
>> > StopAsync:tcp://172.17.5.16:52657-14
>> > 2012-04-07 13:20:26,950 | DEBUG | remove connection id:
>> > ID:WIIPAP101-52658-634694015719174302-1:0 |
>> > org.apache.activemq.broker.TransportConnection |
>> > StopAsync:tcp://172.17.5.16:52657-14
>> > 2012-04-07 13:20:26,951 | DEBUG | msipap101.vosh.net removing consumer:
>> > ID:WIIPAP101-52658-634694015719174302-1:0:1:1 for destination:
>> > queue://SolidCloud.Requests.Desktops.IPA |
>> > org.apache.activemq.broker.region.AbstractRegion |
>> > StopAsync:tcp://172.17.5.16:52657-14
>> >
>> > For some reason the client is being disconnected. The log on the client
>> is
>> > showing the following:
>> >
>> > 2012-04-07
>> > 13:06:22.0000|ERROR|VOAuto.Services.Citrix.RequestInvoker|Channel was
>> > inactive for too long:
>> > ssl://
>> msipap101.vosh.net:61616/EXCEPTIONOCCURRED:Apache.NMS.ActiveMQ.IOException
>> > Channel was inactive for too long:
>> > ssl://msipap101.vosh.net:61616/ Apache.NMS.ActiveMQ.Commands.Response
>> > SyncRequest(Apache.NMS.ActiveMQ.Commands.Command, System.TimeSpan)    at
>> > Apache.NMS.ActiveMQ.Connection.SyncRequest(Command command, TimeSpan
>> > requestTimeout) in
>> c:\dev\NMS.ActiveMQ\src\main\csharp\Connection.cs:line
>> > 667
>> >    at Apache.NMS.ActiveMQ.Session.DoSend(ActiveMQDestination
>> destination,
>> > ActiveMQMessage message, MessageProducer producer, MemoryUsage
>> > producerWindow, TimeSpan sendTimeout) in
>> > c:\dev\NMS.ActiveMQ\src\main\csharp\Session.cs:line 716
>> >    at Apache.NMS.ActiveMQ.MessageProducer.Send(IDestination destination,
>> > IMessage message, MsgDeliveryMode deliveryMode, MsgPriority priority,
>> > TimeSpan timeToLive, Boolean specifiedTimeToLive) in
>> > c:\dev\NMS.ActiveMQ\src\main\csharp\MessageProducer.cs:line 258
>> >    at Apache.NMS.ActiveMQ.MessageProducer.Send(IDestination destination,
>> > IMessage message) in
>> > c:\dev\NMS.ActiveMQ\src\main\csharp\MessageProducer.cs:line 170
>> >    at
>> >
>> VirtualOffice.Automation.Messaging.Impl.ActiveMqMessagingProvider.<>c__DisplayClassd.<RegisterRequestReceiver>b__c(IMessage
>> > message)
>> >
>> > I'm sort of at a loss because the client is being disconnected and is
>> not
>> > reconnecting. Any suggestions?
>> >
>> > Chris
>>
>> Try turning off watchTopicAdvisories for the connection, there is a bug
>> in v 1.5.3 related to this.
>>
>> --
>> Tim Bish
>> Sr Software Engineer | FuseSource Corp
>> tim.bish@fusesource.com | www.fusesource.com
>> skype: tabish121 | twitter: @tabish121
>> blog: http://timbish.blogspot.com/
>>
>>
>

Re: Client consumer exception and disconnection

Posted by Chris Robison <ch...@gmail.com>.

I'm assuming you mean set it on the connection factory. I've tried that,
but no go. The only way I've found to recover from this is to delete the
KahaDB on the activemq server and restart all services.

On Sat, Apr 7, 2012 at 11:59 AM, Timothy Bish <ta...@gmail.com> wrote:

> On Sat, 2012-04-07 at 11:56 -0600, Chris Robison wrote:
> > I'm running into an interesting issue. I have a client connecting to an
> > activemq server, trying to consume messages and reply to a temporary
> > destination set. The ActiveMQ server debug is showing the following:
> >
> > 2012-04-07 13:20:25,708 | DEBUG | Received WireFormat: WireFormatInfo {
> > version=6, properties={CacheSize=0, CacheEnabled=false,
> > MaxInactivityDurationInitialDelay=10000, SizePrefixDisabled=false,
> > TcpNoDelayEnabled=true, MaxInactivityDuration=30000,
> > TightEncodingEnabled=false, StackTraceEnabled=false},
> > magic=[A,c,t,i,v,e,M,Q]} |
> > org.apache.activemq.transport.WireFormatNegotiator | ActiveMQ Transport:
> > ssl:///172.17.5.16:52657
> > 2012-04-07 13:20:25,708 | DEBUG | ssl:///172.17.5.16:52657 before
> > negotiation: OpenWireFormat{version=9, cacheEnabled=false,
> > stackTraceEnabled=false, tightEncodingEnabled=false,
> > sizePrefixDisabled=false, maxFrameSize=104857600} |
> > org.apache.activemq.transport.WireFormatNegotiator | ActiveMQ Transport:
> > ssl:///172.17.5.16:52657
> > 2012-04-07 13:20:25,709 | DEBUG | ssl:///172.17.5.16:52657 after
> > negotiation: OpenWireFormat{version=6, cacheEnabled=false,
> > stackTraceEnabled=false, tightEncodingEnabled=false,
> > sizePrefixDisabled=false, maxFrameSize=104857600} |
> > org.apache.activemq.transport.WireFormatNegotiator | ActiveMQ Transport:
> > ssl:///172.17.5.16:52657
> > 2012-04-07 13:20:25,725 | DEBUG | Setting up new connection id:
> > ID:WIIPAP101-52658-634694015719174302-1:0, address: tcp://
> 172.17.5.16:52657,
> > info: ConnectionInfo {commandId = 1, responseRequired = true,
> connectionId
> > = ID:WIIPAP101-52658-634694015719174302-1:0, clientId =
> > ID:WIIPAP101-52658-634694015719174302-0:0, clientIp = null, userName =
> > mqipauser, password = *****, brokerPath = null, brokerMasterConnector =
> > false, manageable = false, clientMaster = false, faultTolerant = false,
> > failoverReconnect = false} |
> org.apache.activemq.broker.TransportConnection
> > | ActiveMQ Transport: ssl:///172.17.5.16:52657
> > 2012-04-07 13:20:25,727 | DEBUG | Create the LDAP initial context. |
> > org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
> > 172.17.5.16:52657
> > 2012-04-07 13:20:25,739 | DEBUG | Get the user DN. |
> > org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
> > 172.17.5.16:52657
> > 2012-04-07 13:20:25,739 | DEBUG | Looking for the user in LDAP with  |
> > org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
> > 172.17.5.16:52657
> > 2012-04-07 13:20:25,740 | DEBUG |   base DN:
> > OU=Users,OU=ActiveMQ,DC=VOSH,DC=NET |
> > org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
> > 172.17.5.16:52657
> > 2012-04-07 13:20:25,740 | DEBUG |   filter: (sAMAccountName=mqipauser) |
> > org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
> > 172.17.5.16:52657
> > 2012-04-07 13:20:25,743 | DEBUG | Binding the user. |
> > org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
> > 172.17.5.16:52657
> > 2012-04-07 13:20:25,750 | DEBUG | User CN=MQ IPA
> > User,OU=Users,OU=ActiveMQ,DC=VOSH,DC=NET successfully bound. |
> > org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
> > 172.17.5.16:52657
> > 2012-04-07 13:20:25,751 | DEBUG | Get user roles. |
> > org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
> > 172.17.5.16:52657
> > 2012-04-07 13:20:25,751 | DEBUG | Looking for the user roles in LDAP with
> >  | org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
> > 172.17.5.16:52657
> > 2012-04-07 13:20:25,751 | DEBUG |   base DN:
> > OU=Groups,OU=ActiveMQ,DC=VOSH,DC=NET |
> > org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
> > 172.17.5.16:52657
> > 2012-04-07 13:20:25,751 | DEBUG |   filter: (member=CN=MQ IPA
> > User,OU=Users,OU=ActiveMQ,DC=VOSH,DC=NET) |
> > org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
> > 172.17.5.16:52657
> > 2012-04-07 13:20:25,762 | DEBUG | Roles [MQIPAUsers, MQUsers] for user
> > mqipauser | org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ
> Transport:
> > ssl:///172.17.5.16:52657
> > 2012-04-07 13:20:25,789 | DEBUG | msipap101.vosh.net adding consumer:
> > ID:WIIPAP101-52658-634694015719174302-1:0:1:1 for destination:
> > queue://SolidCloud.Requests.Desktops.IPA |
> > org.apache.activemq.broker.region.AbstractRegion | ActiveMQ Transport:
> > ssl:///172.17.5.16:52657
> > 2012-04-07 13:20:25,797 | DEBUG |
> queue://SolidCloud.Requests.Desktops.IPA
> > add sub: QueueSubscription:
> > consumer=ID:WIIPAP101-52658-634694015719174302-1:0:1:1, destinations=0,
> > dispatched=0, delivered=0, pending=0, dequeues: 1, dispatched: 1,
> inflight:
> > 0 | org.apache.activemq.broker.region.Queue | ActiveMQ Transport: ssl:///
> > 172.17.5.16:52657
> > 2012-04-07 13:20:25,798 | DEBUG | SolidCloud.Requests.Desktops.IPA
> > toPageIn: 0, Inflight: 0, pagedInMessages.size 9, enqueueCount: 3,
> > dequeueCount: 1 | org.apache.activemq.broker.region.Queue |
> > Queue:SolidCloud.Requests.Desktops.IPA
> > 2012-04-07 13:20:25,810 | DEBUG | bridging (msipap101.vosh.net ->
> > mstmip101.vosh.net) ID:MSIPAP101-36535-1333817412870-1:1:0:0:33,
> consumer:
> > ID:MSIPAP101-36535-1333817412870-2:2:1:1, destination
> >
> topic://ActiveMQ.Advisory.Consumer.Queue.SolidCloud.Requests.Desktops.IPA,
> > brokerPath: [ID:MSIPAP101-36535-1333817412870-0:1], message:
> > ActiveMQMessage {commandId = 0, responseRequired = false, messageId =
> > ID:MSIPAP101-36535-1333817412870-1:1:0:0:33, originalDestination = null,
> > originalTransactionId = null, producerId =
> > ID:MSIPAP101-36535-1333817412870-2:1:1:1, destination =
> >
> topic://ActiveMQ.Advisory.Consumer.Queue.SolidCloud.Requests.Desktops.IPA,
> > transactionId = null, expiration = 0, timestamp = 0, arrival = 0,
> > brokerInTime = 1333819225809, brokerOutTime = 1333819225810,
> correlationId
> > = null, replyTo = null, persistent = false, type = Advisory, priority =
> 0,
> > groupID = null, groupSequence = 0, targetConsumerId = null, compressed =
> > false, userID = null, content = null, marshalledProperties = null,
> > dataStructure = ConsumerInfo {commandId = 3, responseRequired = true,
> > consumerId = ID:WIIPAP101-52658-634694015719174302-1:0:1:1, destination =
> > queue://SolidCloud.Requests.Desktops.IPA, prefetchSize = 1000,
> > maximumPendingMessageLimit = 0, browser = false, dispatchAsync = true,
> > selector = null, subscriptionName = null, noLocal = false, exclusive =
> > false, retroactive = false, priority = 0, brokerPath = null,
> > optimizedAcknowledge = false, noRangeAcks = false, additionalPredicate =
> > null}, redeliveryCounter = 0, size = 1024, properties = {consumerCount=2,
> > originBrokerURL=ssl://MSIPAP101:61616,
> > originBrokerId=ID:MSIPAP101-36535-1333817412870-0:1, originBrokerName=
> > msipap101.vosh.net}, readOnlyProperties = false, readOnlyBody = false,
> > droppable = false} |
> > org.apache.activemq.network.DemandForwardingBridgeSupport | ActiveMQ
> > Connection Dispatcher: vm://msipap101.vosh.net#0
> > 2012-04-07 13:20:26,912 | DEBUG | Error occured while processing sync
> > command: ActiveMQTextMessage {commandId = 5, responseRequired = true,
> > messageId = ID:WIIPAP101-52658-634694015719174302-1:0:1:1:1,
> > originalDestination = null, originalTransactionId = null, producerId =
> > ID:WIIPAP101-52658-634694015719174302-1:0:1:1, destination =
> > temp-queue://ID:POTMIP102-60127-634693656236343522-1:38:1, transactionId
> =
> > null, expiration = 0, timestamp = 1333819173524, arrival = 0,
> brokerInTime
> > = 1333819226907, brokerOutTime = 0, correlationId = null, replyTo = null,
> > persistent = true, type = null, priority = 4, groupID = null,
> groupSequence
> > = 0, targetConsumerId = null, compressed = false, userID = null, content
> =
> > null, marshalledProperties = null, dataStructure = null,
> redeliveryCounter
> > = 0, size = 0, properties = null, readOnlyProperties = false,
> readOnlyBody
> > = false, droppable = false, text = []}, exception:
> javax.jms.JMSException:
> > The destination temp-queue://ID:POTMIP102-60127-634693656236343522-1:38:1
> > does not exist. | org.apache.activemq.broker.TransportConnection.Service
> |
> > ActiveMQ Transport: ssl:///172.17.5.16:52657
> > javax.jms.JMSException: The destination
> > temp-queue://ID:POTMIP102-60127-634693656236343522-1:38:1 does not exist.
> > at
> >
> org.apache.activemq.broker.region.AbstractRegion.addDestination(AbstractRegion.java:149)
> > at
> >
> org.apache.activemq.broker.region.RegionBroker.addDestination(RegionBroker.java:314)
> > at
> >
> org.apache.activemq.broker.BrokerFilter.addDestination(BrokerFilter.java:145)
> > at
> >
> org.apache.activemq.advisory.AdvisoryBroker.addDestination(AdvisoryBroker.java:161)
> > at
> >
> org.apache.activemq.broker.BrokerFilter.addDestination(BrokerFilter.java:145)
> > at
> >
> org.apache.activemq.broker.BrokerFilter.addDestination(BrokerFilter.java:145)
> > at
> >
> org.apache.activemq.broker.BrokerFilter.addDestination(BrokerFilter.java:145)
> > at
> >
> org.apache.activemq.broker.BrokerFilter.addDestination(BrokerFilter.java:145)
> > at
> >
> org.apache.activemq.security.AuthorizationBroker.addDestination(AuthorizationBroker.java:81)
> > at
> >
> org.apache.activemq.broker.MutableBrokerFilter.addDestination(MutableBrokerFilter.java:151)
> > at
> >
> org.apache.activemq.broker.region.RegionBroker.send(RegionBroker.java:506)
> > at
> >
> org.apache.activemq.broker.jmx.ManagedRegionBroker.send(ManagedRegionBroker.java:305)
> > at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:129)
> > at
> >
> org.apache.activemq.broker.CompositeDestinationBroker.send(CompositeDestinationBroker.java:96)
> > at
> >
> org.apache.activemq.broker.TransactionBroker.send(TransactionBroker.java:306)
> > at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:129)
> > at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:129)
> > at
> >
> org.apache.activemq.security.AuthorizationBroker.send(AuthorizationBroker.java:192)
> > at
> >
> org.apache.activemq.broker.MutableBrokerFilter.send(MutableBrokerFilter.java:135)
> > at
> >
> org.apache.activemq.broker.TransportConnection.processMessage(TransportConnection.java:452)
> > at
> >
> org.apache.activemq.command.ActiveMQMessage.visit(ActiveMQMessage.java:681)
> > at
> >
> org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:291)
> > at
> >
> org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:149)
> > at
> >
> org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
> > at
> >
> org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:113)
> > at
> >
> org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(AbstractInactivityMonitor.java:229)
> > at
> >
> org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83)
> > at
> >
> org.apache.activemq.transport.tcp.SslTransport.doConsume(SslTransport.java:91)
> > at
> >
> org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:222)
> > at
> org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:204)
> > at java.lang.Thread.run(Thread.java:679)
> > 2012-04-07 13:20:26,943 | DEBUG | Transport Connection to: tcp://
> > 172.17.5.16:52657 failed: java.io.EOFException |
> > org.apache.activemq.broker.TransportConnection.Transport | ActiveMQ
> > Transport: ssl:///172.17.5.16:52657
> > java.io.EOFException
> > at java.io.DataInputStream.readInt(DataInputStream.java:392)
> > at
> >
> org.apache.activemq.openwire.OpenWireFormat.unmarshal(OpenWireFormat.java:275)
> > at
> >
> org.apache.activemq.transport.tcp.TcpTransport.readCommand(TcpTransport.java:229)
> > at
> >
> org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:221)
> > at
> org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:204)
> > at java.lang.Thread.run(Thread.java:679)
> > 2012-04-07 13:20:26,947 | DEBUG | Stopping connection: tcp://
> > 172.17.5.16:52657 | org.apache.activemq.broker.TransportConnection |
> > StopAsync:tcp://172.17.5.16:52657-14
> > 2012-04-07 13:20:26,948 | DEBUG | Stopping transport ssl:///
> > 172.17.5.16:52657 | org.apache.activemq.transport.tcp.TcpTransport |
> > StopAsync:tcp://172.17.5.16:52657-14
> > 2012-04-07 13:20:26,949 | DEBUG | Stopped transport:
> > tcp://172.17.5.16:52657|
> > org.apache.activemq.broker.TransportConnection |
> > StopAsync:tcp://172.17.5.16:52657-14
> > 2012-04-07 13:20:26,950 | DEBUG | Cleaning up connection resources:
> tcp://
> > 172.17.5.16:52657 | org.apache.activemq.broker.TransportConnection |
> > StopAsync:tcp://172.17.5.16:52657-14
> > 2012-04-07 13:20:26,950 | DEBUG | remove connection id:
> > ID:WIIPAP101-52658-634694015719174302-1:0 |
> > org.apache.activemq.broker.TransportConnection |
> > StopAsync:tcp://172.17.5.16:52657-14
> > 2012-04-07 13:20:26,951 | DEBUG | msipap101.vosh.net removing consumer:
> > ID:WIIPAP101-52658-634694015719174302-1:0:1:1 for destination:
> > queue://SolidCloud.Requests.Desktops.IPA |
> > org.apache.activemq.broker.region.AbstractRegion |
> > StopAsync:tcp://172.17.5.16:52657-14
> >
> > For some reason the client is being disconnected. The log on the client
> is
> > showing the following:
> >
> > 2012-04-07
> > 13:06:22.0000|ERROR|VOAuto.Services.Citrix.RequestInvoker|Channel was
> > inactive for too long:
> > ssl://
> msipap101.vosh.net:61616/EXCEPTIONOCCURRED:Apache.NMS.ActiveMQ.IOException
> > Channel was inactive for too long:
> > ssl://msipap101.vosh.net:61616/ Apache.NMS.ActiveMQ.Commands.Response
> > SyncRequest(Apache.NMS.ActiveMQ.Commands.Command, System.TimeSpan)    at
> > Apache.NMS.ActiveMQ.Connection.SyncRequest(Command command, TimeSpan
> > requestTimeout) in c:\dev\NMS.ActiveMQ\src\main\csharp\Connection.cs:line
> > 667
> >    at Apache.NMS.ActiveMQ.Session.DoSend(ActiveMQDestination destination,
> > ActiveMQMessage message, MessageProducer producer, MemoryUsage
> > producerWindow, TimeSpan sendTimeout) in
> > c:\dev\NMS.ActiveMQ\src\main\csharp\Session.cs:line 716
> >    at Apache.NMS.ActiveMQ.MessageProducer.Send(IDestination destination,
> > IMessage message, MsgDeliveryMode deliveryMode, MsgPriority priority,
> > TimeSpan timeToLive, Boolean specifiedTimeToLive) in
> > c:\dev\NMS.ActiveMQ\src\main\csharp\MessageProducer.cs:line 258
> >    at Apache.NMS.ActiveMQ.MessageProducer.Send(IDestination destination,
> > IMessage message) in
> > c:\dev\NMS.ActiveMQ\src\main\csharp\MessageProducer.cs:line 170
> >    at
> >
> VirtualOffice.Automation.Messaging.Impl.ActiveMqMessagingProvider.<>c__DisplayClassd.<RegisterRequestReceiver>b__c(IMessage
> > message)
> >
> > I'm sort of at a loss because the client is being disconnected and is not
> > reconnecting. Any suggestions?
> >
> > Chris
>
> Try turning off watchTopicAdvisories for the connection, there is a bug
> in v 1.5.3 related to this.
>
> --
> Tim Bish
> Sr Software Engineer | FuseSource Corp
> tim.bish@fusesource.com | www.fusesource.com
> skype: tabish121 | twitter: @tabish121
> blog: http://timbish.blogspot.com/
>
>

Re: Client consumer exception and disconnection

Posted by Timothy Bish <ta...@gmail.com>.

On Sat, 2012-04-07 at 11:56 -0600, Chris Robison wrote: 
> I'm running into an interesting issue. I have a client connecting to an
> activemq server, trying to consume messages and reply to a temporary
> destination set. The ActiveMQ server debug is showing the following:
> 
> 2012-04-07 13:20:25,708 | DEBUG | Received WireFormat: WireFormatInfo {
> version=6, properties={CacheSize=0, CacheEnabled=false,
> MaxInactivityDurationInitialDelay=10000, SizePrefixDisabled=false,
> TcpNoDelayEnabled=true, MaxInactivityDuration=30000,
> TightEncodingEnabled=false, StackTraceEnabled=false},
> magic=[A,c,t,i,v,e,M,Q]} |
> org.apache.activemq.transport.WireFormatNegotiator | ActiveMQ Transport:
> ssl:///172.17.5.16:52657
> 2012-04-07 13:20:25,708 | DEBUG | ssl:///172.17.5.16:52657 before
> negotiation: OpenWireFormat{version=9, cacheEnabled=false,
> stackTraceEnabled=false, tightEncodingEnabled=false,
> sizePrefixDisabled=false, maxFrameSize=104857600} |
> org.apache.activemq.transport.WireFormatNegotiator | ActiveMQ Transport:
> ssl:///172.17.5.16:52657
> 2012-04-07 13:20:25,709 | DEBUG | ssl:///172.17.5.16:52657 after
> negotiation: OpenWireFormat{version=6, cacheEnabled=false,
> stackTraceEnabled=false, tightEncodingEnabled=false,
> sizePrefixDisabled=false, maxFrameSize=104857600} |
> org.apache.activemq.transport.WireFormatNegotiator | ActiveMQ Transport:
> ssl:///172.17.5.16:52657
> 2012-04-07 13:20:25,725 | DEBUG | Setting up new connection id:
> ID:WIIPAP101-52658-634694015719174302-1:0, address: tcp://172.17.5.16:52657,
> info: ConnectionInfo {commandId = 1, responseRequired = true, connectionId
> = ID:WIIPAP101-52658-634694015719174302-1:0, clientId =
> ID:WIIPAP101-52658-634694015719174302-0:0, clientIp = null, userName =
> mqipauser, password = *****, brokerPath = null, brokerMasterConnector =
> false, manageable = false, clientMaster = false, faultTolerant = false,
> failoverReconnect = false} | org.apache.activemq.broker.TransportConnection
> | ActiveMQ Transport: ssl:///172.17.5.16:52657
> 2012-04-07 13:20:25,727 | DEBUG | Create the LDAP initial context. |
> org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
> 172.17.5.16:52657
> 2012-04-07 13:20:25,739 | DEBUG | Get the user DN. |
> org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
> 172.17.5.16:52657
> 2012-04-07 13:20:25,739 | DEBUG | Looking for the user in LDAP with  |
> org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
> 172.17.5.16:52657
> 2012-04-07 13:20:25,740 | DEBUG |   base DN:
> OU=Users,OU=ActiveMQ,DC=VOSH,DC=NET |
> org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
> 172.17.5.16:52657
> 2012-04-07 13:20:25,740 | DEBUG |   filter: (sAMAccountName=mqipauser) |
> org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
> 172.17.5.16:52657
> 2012-04-07 13:20:25,743 | DEBUG | Binding the user. |
> org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
> 172.17.5.16:52657
> 2012-04-07 13:20:25,750 | DEBUG | User CN=MQ IPA
> User,OU=Users,OU=ActiveMQ,DC=VOSH,DC=NET successfully bound. |
> org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
> 172.17.5.16:52657
> 2012-04-07 13:20:25,751 | DEBUG | Get user roles. |
> org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
> 172.17.5.16:52657
> 2012-04-07 13:20:25,751 | DEBUG | Looking for the user roles in LDAP with
>  | org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
> 172.17.5.16:52657
> 2012-04-07 13:20:25,751 | DEBUG |   base DN:
> OU=Groups,OU=ActiveMQ,DC=VOSH,DC=NET |
> org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
> 172.17.5.16:52657
> 2012-04-07 13:20:25,751 | DEBUG |   filter: (member=CN=MQ IPA
> User,OU=Users,OU=ActiveMQ,DC=VOSH,DC=NET) |
> org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport: ssl:///
> 172.17.5.16:52657
> 2012-04-07 13:20:25,762 | DEBUG | Roles [MQIPAUsers, MQUsers] for user
> mqipauser | org.apache.activemq.jaas.LDAPLoginModule | ActiveMQ Transport:
> ssl:///172.17.5.16:52657
> 2012-04-07 13:20:25,789 | DEBUG | msipap101.vosh.net adding consumer:
> ID:WIIPAP101-52658-634694015719174302-1:0:1:1 for destination:
> queue://SolidCloud.Requests.Desktops.IPA |
> org.apache.activemq.broker.region.AbstractRegion | ActiveMQ Transport:
> ssl:///172.17.5.16:52657
> 2012-04-07 13:20:25,797 | DEBUG | queue://SolidCloud.Requests.Desktops.IPA
> add sub: QueueSubscription:
> consumer=ID:WIIPAP101-52658-634694015719174302-1:0:1:1, destinations=0,
> dispatched=0, delivered=0, pending=0, dequeues: 1, dispatched: 1, inflight:
> 0 | org.apache.activemq.broker.region.Queue | ActiveMQ Transport: ssl:///
> 172.17.5.16:52657
> 2012-04-07 13:20:25,798 | DEBUG | SolidCloud.Requests.Desktops.IPA
> toPageIn: 0, Inflight: 0, pagedInMessages.size 9, enqueueCount: 3,
> dequeueCount: 1 | org.apache.activemq.broker.region.Queue |
> Queue:SolidCloud.Requests.Desktops.IPA
> 2012-04-07 13:20:25,810 | DEBUG | bridging (msipap101.vosh.net ->
> mstmip101.vosh.net) ID:MSIPAP101-36535-1333817412870-1:1:0:0:33, consumer:
> ID:MSIPAP101-36535-1333817412870-2:2:1:1, destination
> topic://ActiveMQ.Advisory.Consumer.Queue.SolidCloud.Requests.Desktops.IPA,
> brokerPath: [ID:MSIPAP101-36535-1333817412870-0:1], message:
> ActiveMQMessage {commandId = 0, responseRequired = false, messageId =
> ID:MSIPAP101-36535-1333817412870-1:1:0:0:33, originalDestination = null,
> originalTransactionId = null, producerId =
> ID:MSIPAP101-36535-1333817412870-2:1:1:1, destination =
> topic://ActiveMQ.Advisory.Consumer.Queue.SolidCloud.Requests.Desktops.IPA,
> transactionId = null, expiration = 0, timestamp = 0, arrival = 0,
> brokerInTime = 1333819225809, brokerOutTime = 1333819225810, correlationId
> = null, replyTo = null, persistent = false, type = Advisory, priority = 0,
> groupID = null, groupSequence = 0, targetConsumerId = null, compressed =
> false, userID = null, content = null, marshalledProperties = null,
> dataStructure = ConsumerInfo {commandId = 3, responseRequired = true,
> consumerId = ID:WIIPAP101-52658-634694015719174302-1:0:1:1, destination =
> queue://SolidCloud.Requests.Desktops.IPA, prefetchSize = 1000,
> maximumPendingMessageLimit = 0, browser = false, dispatchAsync = true,
> selector = null, subscriptionName = null, noLocal = false, exclusive =
> false, retroactive = false, priority = 0, brokerPath = null,
> optimizedAcknowledge = false, noRangeAcks = false, additionalPredicate =
> null}, redeliveryCounter = 0, size = 1024, properties = {consumerCount=2,
> originBrokerURL=ssl://MSIPAP101:61616,
> originBrokerId=ID:MSIPAP101-36535-1333817412870-0:1, originBrokerName=
> msipap101.vosh.net}, readOnlyProperties = false, readOnlyBody = false,
> droppable = false} |
> org.apache.activemq.network.DemandForwardingBridgeSupport | ActiveMQ
> Connection Dispatcher: vm://msipap101.vosh.net#0
> 2012-04-07 13:20:26,912 | DEBUG | Error occured while processing sync
> command: ActiveMQTextMessage {commandId = 5, responseRequired = true,
> messageId = ID:WIIPAP101-52658-634694015719174302-1:0:1:1:1,
> originalDestination = null, originalTransactionId = null, producerId =
> ID:WIIPAP101-52658-634694015719174302-1:0:1:1, destination =
> temp-queue://ID:POTMIP102-60127-634693656236343522-1:38:1, transactionId =
> null, expiration = 0, timestamp = 1333819173524, arrival = 0, brokerInTime
> = 1333819226907, brokerOutTime = 0, correlationId = null, replyTo = null,
> persistent = true, type = null, priority = 4, groupID = null, groupSequence
> = 0, targetConsumerId = null, compressed = false, userID = null, content =
> null, marshalledProperties = null, dataStructure = null, redeliveryCounter
> = 0, size = 0, properties = null, readOnlyProperties = false, readOnlyBody
> = false, droppable = false, text = []}, exception: javax.jms.JMSException:
> The destination temp-queue://ID:POTMIP102-60127-634693656236343522-1:38:1
> does not exist. | org.apache.activemq.broker.TransportConnection.Service |
> ActiveMQ Transport: ssl:///172.17.5.16:52657
> javax.jms.JMSException: The destination
> temp-queue://ID:POTMIP102-60127-634693656236343522-1:38:1 does not exist.
> at
> org.apache.activemq.broker.region.AbstractRegion.addDestination(AbstractRegion.java:149)
> at
> org.apache.activemq.broker.region.RegionBroker.addDestination(RegionBroker.java:314)
> at
> org.apache.activemq.broker.BrokerFilter.addDestination(BrokerFilter.java:145)
> at
> org.apache.activemq.advisory.AdvisoryBroker.addDestination(AdvisoryBroker.java:161)
> at
> org.apache.activemq.broker.BrokerFilter.addDestination(BrokerFilter.java:145)
> at
> org.apache.activemq.broker.BrokerFilter.addDestination(BrokerFilter.java:145)
> at
> org.apache.activemq.broker.BrokerFilter.addDestination(BrokerFilter.java:145)
> at
> org.apache.activemq.broker.BrokerFilter.addDestination(BrokerFilter.java:145)
> at
> org.apache.activemq.security.AuthorizationBroker.addDestination(AuthorizationBroker.java:81)
> at
> org.apache.activemq.broker.MutableBrokerFilter.addDestination(MutableBrokerFilter.java:151)
> at
> org.apache.activemq.broker.region.RegionBroker.send(RegionBroker.java:506)
> at
> org.apache.activemq.broker.jmx.ManagedRegionBroker.send(ManagedRegionBroker.java:305)
> at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:129)
> at
> org.apache.activemq.broker.CompositeDestinationBroker.send(CompositeDestinationBroker.java:96)
> at
> org.apache.activemq.broker.TransactionBroker.send(TransactionBroker.java:306)
> at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:129)
> at org.apache.activemq.broker.BrokerFilter.send(BrokerFilter.java:129)
> at
> org.apache.activemq.security.AuthorizationBroker.send(AuthorizationBroker.java:192)
> at
> org.apache.activemq.broker.MutableBrokerFilter.send(MutableBrokerFilter.java:135)
> at
> org.apache.activemq.broker.TransportConnection.processMessage(TransportConnection.java:452)
> at
> org.apache.activemq.command.ActiveMQMessage.visit(ActiveMQMessage.java:681)
> at
> org.apache.activemq.broker.TransportConnection.service(TransportConnection.java:291)
> at
> org.apache.activemq.broker.TransportConnection$1.onCommand(TransportConnection.java:149)
> at
> org.apache.activemq.transport.MutexTransport.onCommand(MutexTransport.java:50)
> at
> org.apache.activemq.transport.WireFormatNegotiator.onCommand(WireFormatNegotiator.java:113)
> at
> org.apache.activemq.transport.AbstractInactivityMonitor.onCommand(AbstractInactivityMonitor.java:229)
> at
> org.apache.activemq.transport.TransportSupport.doConsume(TransportSupport.java:83)
> at
> org.apache.activemq.transport.tcp.SslTransport.doConsume(SslTransport.java:91)
> at
> org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:222)
> at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:204)
> at java.lang.Thread.run(Thread.java:679)
> 2012-04-07 13:20:26,943 | DEBUG | Transport Connection to: tcp://
> 172.17.5.16:52657 failed: java.io.EOFException |
> org.apache.activemq.broker.TransportConnection.Transport | ActiveMQ
> Transport: ssl:///172.17.5.16:52657
> java.io.EOFException
> at java.io.DataInputStream.readInt(DataInputStream.java:392)
> at
> org.apache.activemq.openwire.OpenWireFormat.unmarshal(OpenWireFormat.java:275)
> at
> org.apache.activemq.transport.tcp.TcpTransport.readCommand(TcpTransport.java:229)
> at
> org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:221)
> at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:204)
> at java.lang.Thread.run(Thread.java:679)
> 2012-04-07 13:20:26,947 | DEBUG | Stopping connection: tcp://
> 172.17.5.16:52657 | org.apache.activemq.broker.TransportConnection |
> StopAsync:tcp://172.17.5.16:52657-14
> 2012-04-07 13:20:26,948 | DEBUG | Stopping transport ssl:///
> 172.17.5.16:52657 | org.apache.activemq.transport.tcp.TcpTransport |
> StopAsync:tcp://172.17.5.16:52657-14
> 2012-04-07 13:20:26,949 | DEBUG | Stopped transport:
> tcp://172.17.5.16:52657|
> org.apache.activemq.broker.TransportConnection |
> StopAsync:tcp://172.17.5.16:52657-14
> 2012-04-07 13:20:26,950 | DEBUG | Cleaning up connection resources: tcp://
> 172.17.5.16:52657 | org.apache.activemq.broker.TransportConnection |
> StopAsync:tcp://172.17.5.16:52657-14
> 2012-04-07 13:20:26,950 | DEBUG | remove connection id:
> ID:WIIPAP101-52658-634694015719174302-1:0 |
> org.apache.activemq.broker.TransportConnection |
> StopAsync:tcp://172.17.5.16:52657-14
> 2012-04-07 13:20:26,951 | DEBUG | msipap101.vosh.net removing consumer:
> ID:WIIPAP101-52658-634694015719174302-1:0:1:1 for destination:
> queue://SolidCloud.Requests.Desktops.IPA |
> org.apache.activemq.broker.region.AbstractRegion |
> StopAsync:tcp://172.17.5.16:52657-14
> 
> For some reason the client is being disconnected. The log on the client is
> showing the following:
> 
> 2012-04-07
> 13:06:22.0000|ERROR|VOAuto.Services.Citrix.RequestInvoker|Channel was
> inactive for too long:
> ssl://msipap101.vosh.net:61616/EXCEPTIONOCCURRED:Apache.NMS.ActiveMQ.IOException
> Channel was inactive for too long:
> ssl://msipap101.vosh.net:61616/ Apache.NMS.ActiveMQ.Commands.Response
> SyncRequest(Apache.NMS.ActiveMQ.Commands.Command, System.TimeSpan)    at
> Apache.NMS.ActiveMQ.Connection.SyncRequest(Command command, TimeSpan
> requestTimeout) in c:\dev\NMS.ActiveMQ\src\main\csharp\Connection.cs:line
> 667
>    at Apache.NMS.ActiveMQ.Session.DoSend(ActiveMQDestination destination,
> ActiveMQMessage message, MessageProducer producer, MemoryUsage
> producerWindow, TimeSpan sendTimeout) in
> c:\dev\NMS.ActiveMQ\src\main\csharp\Session.cs:line 716
>    at Apache.NMS.ActiveMQ.MessageProducer.Send(IDestination destination,
> IMessage message, MsgDeliveryMode deliveryMode, MsgPriority priority,
> TimeSpan timeToLive, Boolean specifiedTimeToLive) in
> c:\dev\NMS.ActiveMQ\src\main\csharp\MessageProducer.cs:line 258
>    at Apache.NMS.ActiveMQ.MessageProducer.Send(IDestination destination,
> IMessage message) in
> c:\dev\NMS.ActiveMQ\src\main\csharp\MessageProducer.cs:line 170
>    at
> VirtualOffice.Automation.Messaging.Impl.ActiveMqMessagingProvider.<>c__DisplayClassd.<RegisterRequestReceiver>b__c(IMessage
> message)
> 
> I'm sort of at a loss because the client is being disconnected and is not
> reconnecting. Any suggestions?
> 
> Chris

Try turning off watchTopicAdvisories for the connection, there is a bug
in v 1.5.3 related to this.

-- 
Tim Bish
Sr Software Engineer | FuseSource Corp
tim.bish@fusesource.com | www.fusesource.com
skype: tabish121 | twitter: @tabish121
blog: http://timbish.blogspot.com/