[
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
