activemq-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Chris Robison <chrisdrobi...@gmail.com>
Subject Client consumer exception and disconnection
Date Sat, 07 Apr 2012 17:56:03 GMT
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

Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message