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.b...@fusesource.com | www.fusesource.com
skype: tabish121 | twitter: @tabish121
blog: http://timbish.blogspot.com/
