activemq-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Frank Gynnild (Issue Comment Edited) (JIRA)" <jira+amq...@apache.org>
Subject [jira] [Issue Comment Edited] (AMQNET-369) Seems like there is a race condition that can lead to an InvalidDestinationException for tempoary queues after failover has resumed
Date Tue, 07 Feb 2012 20:28:59 GMT

    [ https://issues.apache.org/jira/browse/AMQNET-369?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13202666#comment-13202666
] 

Frank Gynnild edited comment on AMQNET-369 at 2/7/12 8:28 PM:
--------------------------------------------------------------

Here's more of the exact log. The problem temporary queue is "temp-queue://ID:Duracell-61594-634642411329432145-1:0:1"
so search for it below to trace this destination.

...
2012-02-07 19:52:09,974 <4568> [ActiveMQ Failover Worker: 3686381] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger
[(null)] - Transport has resumed normal operation.
2012-02-07 19:52:09,974 <4568> [ActiveMQ Failover Worker: 3686381] WARN  InfoFinder.Framework.Communication.Sender
[(null)] - AMQ event: Connection was resumed on the sender end.
2012-02-07 19:52:09,974 <4568> [ActiveMQ Failover Worker: 3686381] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger
[(null)] - Connection established
2012-02-07 19:52:09,974 <4568> [ActiveMQ Failover Worker: 3686381] INFO  InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger
[(null)] - Successfully reconnected to: tcp://duracell:61616/?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000
2012-02-07 19:52:09,974 <4568> [ActiveMQ Failover Worker: 66629781] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger
[(null)] - restore consumer: ID:Duracell-61509-634642410176768518-1:0:-1:1
2012-02-07 19:52:09,974 <4568> [ActiveMQ Failover Worker: 66629781] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger
[(null)] - restore consumer: ID:Duracell-61509-634642410176768518-1:0:1:1
2012-02-07 19:52:09,974 <4568> [ActiveMQ Failover Worker: 66629781] INFO  InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger
[(null)] - Sending queued commands...
2012-02-07 19:52:09,974 <4568> [ActiveMQ Failover Worker: 66629781] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger
[(null)] - Transport has resumed normal operation.
2012-02-07 19:52:09,974 <4568> [ActiveMQ Failover Worker: 66629781] WARN  InfoFinder.Framework.Communication.Receiver
[(null)] - AMQ event: Connection was resumed on the receiver end.
2012-02-07 19:52:09,974 <4568> [ActiveMQ Failover Worker: 66629781] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger
[(null)] - Connection established
2012-02-07 19:52:09,974 <4568> [ActiveMQ Failover Worker: 66629781] INFO  InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger
[(null)] - Successfully reconnected to: tcp://duracell:61616/?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000
2012-02-07 19:52:10,005 <4568> [3272] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger
[(null)] - Unknown response ID: 0 for response: Response[ commandId = 0, responseRequired
= False, CorrelationId = 1 ]
2012-02-07 19:52:10,005 <4568> [10368] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger
[(null)] - Unknown response ID: 0 for response: Response[ commandId = 0, responseRequired
= False, CorrelationId = 1 ]
2012-02-07 19:52:10,036 <4568> [3272] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger
[(null)] - Unknown response ID: 0 for response: Response[ commandId = 0, responseRequired
= False, CorrelationId = 2 ]
2012-02-07 19:52:10,036 <4568> [10368] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger
[(null)] - Unknown response ID: 0 for response: Response[ commandId = 0, responseRequired
= False, CorrelationId = 2 ]
2012-02-07 19:52:10,052 <4568> [3272] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger
[(null)] - Unknown response ID: 0 for response: Response[ commandId = 0, responseRequired
= False, CorrelationId = 4 ]
...
2012-02-07 19:52:13,349 <4568> [3272] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger
[(null)] - AdvisoryConsumer adding: temp-queue://ID:Duracell-61594-634642411329432145-1:0:1
2012-02-07 19:52:13,599 <4568> [ActiveMQ Task] DEBUG InfoFinder.Framework.Communication.Receiver
[(null)] - OnMessage called.
2012-02-07 19:52:13,599 <4568> [ActiveMQ Task] DEBUG InfoFinder.Framework.Communication.Receiver
[(null)] - Received a message with message ID: ID:Duracell-61594-634642411329432145-1:0:1:1:1.
NMSType: InfoFinder.Framework.Communication.Message.Licensing.LicenseCoreObjectRequestCommand.
2012-02-07 19:52:13,599 <4568> [ActiveMQ Task] DEBUG InfoFinder.Framework.Communication.Receiver
[(null)] - 	More details. CorrelationID: . Timestamp: 07.02.2012 19:52:13. Time to live: 00:01:00.
2012-02-07 19:52:13,599 <4568> [ActiveMQ Task] DEBUG InfoFinder.Framework.Communication.Receiver
[(null)] - # of generic arguments: 1.
2012-02-07 19:52:13,615 <4568> [ActiveMQ Task] DEBUG InfoFinder.Framework.Communication.CommandTransceiver
[(null)] - Text message received.
...
2012-02-07 19:52:13,646 <4568> [ActiveMQ Task] DEBUG InfoFinder.Framework.Communication.Sender
[(null)] - Using a different return channel. Type: 'TemporaryQueue'. Name: temp-queue://ID:Duracell-61594-634642411329432145-1:0:1
2012-02-07 19:52:13,646 <4568> [ActiveMQ Task] DEBUG InfoFinder.Framework.Configuration.BasicLocalConfiguration
[(null)] - Config path is: 'C:\ProgramData\VirtualWorks\ViaWorks\Configuration\Communication.config'.
2012-02-07 19:52:13,646 <4568> [ActiveMQ Task] DEBUG InfoFinder.Framework.Communication.CommunicationConfiguration
[(null)] - Using RequestResponseTimeOut='00:01:00'.
2012-02-07 19:52:13,646 <4568> [ActiveMQ Task] DEBUG InfoFinder.Framework.Communication.CommandTransceiver
[(null)] - Constructing and sending a NMS command. Type is 'InfoFinder.Framework.Communication.Message.Licensing.LicenseResponseCommand'.
2012-02-07 19:52:13,646 <4568> [ActiveMQ Task] DEBUG InfoFinder.Framework.Communication.CommandTransceiver
[(null)] - Sending command. Command : InfoFinder.Framework.Communication.Message.Licensing.LicenseResponseCommand
...
2012-02-07 19:52:13,646 <4568> [ActiveMQ Task] WARN  InfoFinder.Framework.Communication.CommandTransceiver
[(null)] - Error occurred while sending a command.
Apache.NMS.InvalidDestinationException: Cannot publish to a deleted Destination: temp-queue://ID:Duracell-61594-634642411329432145-1:0:1
   at Apache.NMS.ActiveMQ.Session.DoSend(ActiveMQDestination destination, ActiveMQMessage
message, MessageProducer producer, MemoryUsage producerWindow, TimeSpan sendTimeout) in :line
0
   at Apache.NMS.ActiveMQ.MessageProducer.Send(IDestination destination, IMessage message,
MsgDeliveryMode deliveryMode, MsgPriority priority, TimeSpan timeToLive, Boolean specifiedTimeToLive)
in :line 0
   at Apache.NMS.ActiveMQ.MessageProducer.Send(IMessage message) in :line 0
   at InfoFinder.Framework.Communication.CommandTransceiver.SendCommand[T](IMessageProducer
producer, T cmd, IDestination destination, TimeSpan timeToLive) in C:\infofinder\VirtualWorks\trunk\src\InfoFinder.Framework\Communication\CommandTransceiver.cs:line
203
   at InfoFinder.Framework.Communication.CommandTransceiver.SendCommand[T](IMessageProducer
producer, T cmd, IDestination destination) in C:\infofinder\VirtualWorks\trunk\src\InfoFinder.Framework\Communication\CommandTransceiver.cs:line
105
   at InfoFinder.Framework.Communication.CommandTransceiver.SendCommand[T](IMessageProducer
producer, T cmd) in C:\infofinder\VirtualWorks\trunk\src\InfoFinder.Framework\Communication\CommandTransceiver.cs:line
80
2012-02-07 19:52:13,646 <4568> [ActiveMQ Task] DEBUG InfoFinder.Framework.Communication.Sender
[(null)] - Entering finally clean-up.
2012-02-07 19:52:13,646 <4568> [ActiveMQ Task] DEBUG InfoFinder.Framework.Communication.Sender
[(null)] - Closing return channel.
2012-02-07 19:52:13,646 <4568> [ActiveMQ Task] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger
[(null)] - Remove of Producer[ID:Duracell-61509-634642410176768518-1:1:1:9] sent.
2012-02-07 19:52:13,646 <4568> [ActiveMQ Task] DEBUG InfoFinder.Framework.Communication.Sender
[(null)] - Closed return channel.
2012-02-07 19:52:13,646 <4568> [ActiveMQ Task] WARN  InfoFinder.License.Host.LicenseHost
[(null)] - Can't send to an invalid destination.
2012-02-07 19:52:13,646 <4568> [ActiveMQ Task] DEBUG InfoFinder.Framework.Communication.Receiver
[(null)] - Returned from subscription handlers.
2012-02-07 19:52:13,646 <4568> [ActiveMQ Task] DEBUG InfoFinder.Framework.Communication.Receiver
[(null)] - OnMessage completed.
2012-02-07 19:52:19,974 <4568> [13800] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger
[(null)] - InactivityMonitor[5]: Message sent since last write check. Resetting flag.
....
2012-02-07 19:53:13,724 <4568> [3272] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger
[(null)] - AdvisoryConsumer removing: temp-queue://ID:Duracell-61594-634642411329432145-1:0:1

                
      was (Author: fgynnild):
    Here's more of the exact log. The problem temporary queue is "temp-queue://ID:Duracell-61594-634642411329432145-1:0:1"
so search for it below to trace this destination.

...
2012-02-07 19:52:09,974 <4568> [ActiveMQ Failover Worker: 3686381] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger
[(null)] - Transport has resumed normal operation.
2012-02-07 19:52:09,974 <4568> [ActiveMQ Failover Worker: 3686381] WARN  InfoFinder.Framework.Communication.Sender
[(null)] - AMQ event: Connection was resumed on the sender end.
2012-02-07 19:52:09,974 <4568> [ActiveMQ Failover Worker: 3686381] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger
[(null)] - Connection established
2012-02-07 19:52:09,974 <4568> [ActiveMQ Failover Worker: 3686381] INFO  InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger
[(null)] - Successfully reconnected to: tcp://duracell:61616/?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000
2012-02-07 19:52:09,974 <4568> [ActiveMQ Failover Worker: 66629781] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger
[(null)] - restore consumer: ID:Duracell-61509-634642410176768518-1:0:-1:1
2012-02-07 19:52:09,974 <4568> [ActiveMQ Failover Worker: 66629781] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger
[(null)] - restore consumer: ID:Duracell-61509-634642410176768518-1:0:1:1
2012-02-07 19:52:09,974 <4568> [ActiveMQ Failover Worker: 66629781] INFO  InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger
[(null)] - Sending queued commands...
2012-02-07 19:52:09,974 <4568> [ActiveMQ Failover Worker: 66629781] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger
[(null)] - Transport has resumed normal operation.
2012-02-07 19:52:09,974 <4568> [ActiveMQ Failover Worker: 66629781] WARN  InfoFinder.Framework.Communication.Receiver
[(null)] - AMQ event: Connection was resumed on the receiver end.
2012-02-07 19:52:09,974 <4568> [ActiveMQ Failover Worker: 66629781] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger
[(null)] - Connection established
2012-02-07 19:52:09,974 <4568> [ActiveMQ Failover Worker: 66629781] INFO  InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger
[(null)] - Successfully reconnected to: tcp://duracell:61616/?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000
2012-02-07 19:52:10,005 <4568> [3272] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger
[(null)] - Unknown response ID: 0 for response: Response[ commandId = 0, responseRequired
= False, CorrelationId = 1 ]
2012-02-07 19:52:10,005 <4568> [10368] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger
[(null)] - Unknown response ID: 0 for response: Response[ commandId = 0, responseRequired
= False, CorrelationId = 1 ]
2012-02-07 19:52:10,036 <4568> [3272] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger
[(null)] - Unknown response ID: 0 for response: Response[ commandId = 0, responseRequired
= False, CorrelationId = 2 ]
2012-02-07 19:52:10,036 <4568> [10368] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger
[(null)] - Unknown response ID: 0 for response: Response[ commandId = 0, responseRequired
= False, CorrelationId = 2 ]
2012-02-07 19:52:10,052 <4568> [3272] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger
[(null)] - Unknown response ID: 0 for response: Response[ commandId = 0, responseRequired
= False, CorrelationId = 4 ]
...
2012-02-07 19:52:13,646 <4568> [ActiveMQ Task] DEBUG InfoFinder.Framework.Communication.Sender
[(null)] - Using a different return channel. Type: 'TemporaryQueue'. Name: temp-queue://ID:Duracell-61594-634642411329432145-1:0:1
2012-02-07 19:52:13,646 <4568> [ActiveMQ Task] DEBUG InfoFinder.Framework.Configuration.BasicLocalConfiguration
[(null)] - Config path is: 'C:\ProgramData\VirtualWorks\ViaWorks\Configuration\Communication.config'.
2012-02-07 19:52:13,646 <4568> [ActiveMQ Task] DEBUG InfoFinder.Framework.Communication.CommunicationConfiguration
[(null)] - Using RequestResponseTimeOut='00:01:00'.
2012-02-07 19:52:13,646 <4568> [ActiveMQ Task] DEBUG InfoFinder.Framework.Communication.CommandTransceiver
[(null)] - Constructing and sending a NMS command. Type is 'InfoFinder.Framework.Communication.Message.Licensing.LicenseResponseCommand'.
2012-02-07 19:52:13,646 <4568> [ActiveMQ Task] DEBUG InfoFinder.Framework.Communication.CommandTransceiver
[(null)] - Sending command. Command : InfoFinder.Framework.Communication.Message.Licensing.LicenseResponseCommand
...
2012-02-07 19:52:13,646 <4568> [ActiveMQ Task] WARN  InfoFinder.Framework.Communication.CommandTransceiver
[(null)] - Error occurred while sending a command.
Apache.NMS.InvalidDestinationException: Cannot publish to a deleted Destination: temp-queue://ID:Duracell-61594-634642411329432145-1:0:1
   at Apache.NMS.ActiveMQ.Session.DoSend(ActiveMQDestination destination, ActiveMQMessage
message, MessageProducer producer, MemoryUsage producerWindow, TimeSpan sendTimeout) in :line
0
   at Apache.NMS.ActiveMQ.MessageProducer.Send(IDestination destination, IMessage message,
MsgDeliveryMode deliveryMode, MsgPriority priority, TimeSpan timeToLive, Boolean specifiedTimeToLive)
in :line 0
   at Apache.NMS.ActiveMQ.MessageProducer.Send(IMessage message) in :line 0
   at InfoFinder.Framework.Communication.CommandTransceiver.SendCommand[T](IMessageProducer
producer, T cmd, IDestination destination, TimeSpan timeToLive) in C:\infofinder\VirtualWorks\trunk\src\InfoFinder.Framework\Communication\CommandTransceiver.cs:line
203
   at InfoFinder.Framework.Communication.CommandTransceiver.SendCommand[T](IMessageProducer
producer, T cmd, IDestination destination) in C:\infofinder\VirtualWorks\trunk\src\InfoFinder.Framework\Communication\CommandTransceiver.cs:line
105
   at InfoFinder.Framework.Communication.CommandTransceiver.SendCommand[T](IMessageProducer
producer, T cmd) in C:\infofinder\VirtualWorks\trunk\src\InfoFinder.Framework\Communication\CommandTransceiver.cs:line
80
2012-02-07 19:52:13,646 <4568> [ActiveMQ Task] DEBUG InfoFinder.Framework.Communication.Sender
[(null)] - Entering finally clean-up.
2012-02-07 19:52:13,646 <4568> [ActiveMQ Task] DEBUG InfoFinder.Framework.Communication.Sender
[(null)] - Closing return channel.
2012-02-07 19:52:13,646 <4568> [ActiveMQ Task] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger
[(null)] - Remove of Producer[ID:Duracell-61509-634642410176768518-1:1:1:9] sent.
2012-02-07 19:52:13,646 <4568> [ActiveMQ Task] DEBUG InfoFinder.Framework.Communication.Sender
[(null)] - Closed return channel.
2012-02-07 19:52:13,646 <4568> [ActiveMQ Task] WARN  InfoFinder.License.Host.LicenseHost
[(null)] - Can't send to an invalid destination.
2012-02-07 19:52:13,646 <4568> [ActiveMQ Task] DEBUG InfoFinder.Framework.Communication.Receiver
[(null)] - Returned from subscription handlers.
2012-02-07 19:52:13,646 <4568> [ActiveMQ Task] DEBUG InfoFinder.Framework.Communication.Receiver
[(null)] - OnMessage completed.
2012-02-07 19:52:19,974 <4568> [13800] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger
[(null)] - InactivityMonitor[5]: Message sent since last write check. Resetting flag.
....
2012-02-07 19:53:13,724 <4568> [3272] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger
[(null)] - AdvisoryConsumer removing: temp-queue://ID:Duracell-61594-634642411329432145-1:0:1

                  
> Seems like there is a race condition that can lead to an InvalidDestinationException
for tempoary queues after failover has resumed
> -----------------------------------------------------------------------------------------------------------------------------------
>
>                 Key: AMQNET-369
>                 URL: https://issues.apache.org/jira/browse/AMQNET-369
>             Project: ActiveMQ .Net
>          Issue Type: Bug
>    Affects Versions: 1.5.3
>            Reporter: Frank Gynnild
>            Assignee: Jim Gomes
>
> If I repeat the test below I sometimes get a:
> Apache.NMS.InvalidDestinationException: Cannot publish to a deleted Destination: temp-queue://ID:Duracell-61594-634642411329432145-1:0:1
> Test:
> 1. Start Message bus
> 2. Start server code.
> 3. Stop Message bus
> 4. Start Message bus
> 5. Start client code.
> The client/server uses the request/response pattern.
> I don't have a unit test since it doesn't happen all the time. But if happens often enough
that I am sure there is a race condition bug here
> somewhere. And I think it's in NMS since I can see these log lines:
> AdvisoryConsumer adding: temp-queue://ID:Duracell-61594-634642411329432145-1:0:1
> ...Get InvalidDestinationException here...
> AdvisoryConsumer removing: temp-queue://ID:Duracell-61594-634642411329432145-1:0:1

--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira

        

Mime
View raw message