[
https://issues.apache.org/jira/browse/AMQNET-350?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13151161#comment-13151161
]
Frank Gynnild commented on AMQNET-350:
--------------------------------------
I was able to reproduce the issue, this time it was a different client process
"stealing" the port.
This time I had the tracing turned on.
I shutdown the ActiveMQ (kept the logs so you can see the time stamps):
---
2011-11-16 13:19:13,432 | INFO | ActiveMQ Message Broker (IES_GELADO,
ID:Gelado-63368-1321443434351-0:1) is shutting down |
org.apache.activemq.broker.BrokerService | ActiveMQ ShutdownHook
2011-11-16 13:19:13,432 | INFO | ActiveMQ Message Broker (IES_GELADO,
ID:Gelado-63368-1321443434351-0:1) is shutting down |
org.apache.activemq.broker.BrokerService | Thread-15
2011-11-16 13:19:14,214 | INFO | Connector openwire Stopped |
org.apache.activemq.broker.TransportConnector | Thread-15
2011-11-16 13:19:14,214 | INFO | Connector openwire Stopped |
org.apache.activemq.broker.TransportConnector | ActiveMQ ShutdownHook
2011-11-16 13:19:14,276 | INFO | PListStore:[C:\Program
Files\VirtualWorks\ViaWorks\FuseMB\data\IES_GELADO\tmp_storage ] stopped |
org.apache.activemq.store.kahadb.plist.PListStore | ActiveMQ ShutdownHook
2011-11-16 13:19:14,276 | INFO | Stopping async queue tasks |
org.apache.activemq.store.kahadb.KahaDBStore | ActiveMQ ShutdownHook
2011-11-16 13:19:14,276 | INFO | Stopping async topic tasks |
org.apache.activemq.store.kahadb.KahaDBStore | ActiveMQ ShutdownHook
2011-11-16 13:19:14,276 | INFO | Stopped KahaDB |
org.apache.activemq.store.kahadb.KahaDBStore | ActiveMQ ShutdownHook
2011-11-16 13:19:14,307 | INFO | ActiveMQ JMS Message Broker (IES_GELADO,
ID:Gelado-63368-1321443434351-0:1) stopped |
org.apache.activemq.broker.BrokerService | Thread-15
2011-11-16 13:19:14,370 | INFO | ActiveMQ JMS Message Broker (IES_GELADO,
ID:Gelado-63368-1321443434351-0:1) stopped |
org.apache.activemq.broker.BrokerService | ActiveMQ ShutdownHook
Client side:
---
2011-11-16 13:19:02,932 <11204> [6304] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Keep alive
message received.
2011-11-16 13:19:02,932 <11204> [6304] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Returning
KeepAliveInfo Response.
2011-11-16 13:19:13,526 <11204> [25732] WARN
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Transport
failed to
tcp://gelado:61616/?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000,
attempting to automatically reconnect due to: Unable to read beyond the end of
the stream.
2011-11-16 13:19:14,885 <11204> [5616] WARN
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Transport
failed to
tcp://gelado:61616/?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000,
attempting to automatically reconnect due to: Unable to read beyond the end of
the stream.
2011-11-16 13:19:14,885 <11204> [6304] WARN
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Transport
failed to
tcp://gelado:61616/?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000,
attempting to automatically reconnect due to: Unable to read beyond the end of
the stream.
2011-11-16 13:19:24,182 <11204> [ActiveMQ Failover Worker: 58903342] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Restoring
previous transport connection.
2011-11-16 13:19:24,198 <11204> [ActiveMQ Failover Worker: 58903342] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Sending
queued commands...
2011-11-16 13:19:24,198 <11204> [ActiveMQ Failover Worker: 58903342] WARN
InfoFinder.Framework.Communication.Receiver [(null)] - AMQ event: Connection
was resumed on the receiver end.
2011-11-16 13:19:24,198 <11204> [ActiveMQ Failover Worker: 58903342] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Successfully
reconnected to:
tcp://gelado:61616/?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000
2011-11-16 13:19:24,198 <11204> [27780] ERROR
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Unknown
command: ConnectionControl[ commandId = 0, responseRequired = False, Close =
False, Exit = False, FaultTolerant = True, Resume = False, Suspend = False,
ConnectedBrokers = , ReconnectTo = , RebalanceConnection = False ]
2011-11-16 13:19:24,245 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - BrokerUri
set =
failover:(tcp://GELADO:61616?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000)
2011-11-16 13:19:24,245 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Connecting
to:
failover:(tcp://GELADO:61616?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000)
2011-11-16 13:19:26,276 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:19:28,323 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:19:30,370 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:19:32,495 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:19:34,589 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:19:36,854 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:19:39,230 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:19:41,870 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:19:42,870 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:19:45,198 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:19:46,198 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:19:47,198 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:19:49,792 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:19:50,792 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:19:51,792 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:19:52,792 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:19:53,792 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:19:54,792 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:19:56,917 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:19:57,917 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:19:58,917 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:19:59,917 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:20:00,917 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:20:01,917 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:20:02,917 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:20:03,917 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:20:04,917 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:20:05,917 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:20:06,917 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:20:09,214 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:20:10,214 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:20:11,214 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:20:12,214 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:20:13,214 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:20:14,214 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:20:15,214 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:20:16,214 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:20:17,214 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:20:18,214 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:20:19,214 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:20:20,214 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:20:21,214 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:20:22,214 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:20:23,214 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
2011-11-16 13:20:24,214 <11204> [27780] INFO
InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting for
transport to reconnect.
=====
I see there is an Error in the log:
Unknown command: ConnectionControl
Could this be related to it?
> Clients using the NMS library sometimes hijacks (binds) to the port that
> ActiveMQ is listening to
> -------------------------------------------------------------------------------------------------
>
> Key: AMQNET-350
> URL: https://issues.apache.org/jira/browse/AMQNET-350
> Project: ActiveMQ .Net
> Issue Type: Bug
> Affects Versions: 1.5.0, 1.5.1, 1.5.2
> Reporter: Frank Gynnild
> Assignee: Jim Gomes
>
> If we stop ActiveMQ service first, we've sometimes seen that various clients
> (using the NMS library) binds to the same port as ActiveMQ uses for listening
> (61616).
> This causes the ActiveMQ service to fail to start since its listening port is
> occupied.
> Doing a "netstat -a -b" we can see the problem:
> ---
> TCP [fe80::c591:4e66:8992:debb%11]:61616 Gelado:61616 ESTABLISHED
> TestClient.exe]
> ---
> When trying to start ActiveMQ we get this:
> ---
> 2011-11-16 10:27:38,223 | ERROR | Failed to start ActiveMQ JMS Message
> Broker. Reason: java.io.IOException: Transport Connector could not be
> registered in JMX: Failed to bind to server socket:
> tcp://0.0.0.0:61616?keepAlive=true&wireFormat.tightEncodingEnabled=false&wireFormat.cacheEnabled=false&wireFormat.maxInactivityDuration=300000
> due to: java.net.SocketException: Unrecognized Windows Sockets error: 0:
> JVM_Bind | org.apache.activemq.broker.BrokerService | main
> java.io.IOException: Transport Connector could not be registered in JMX:
> Failed to bind to server socket:
> tcp://0.0.0.0:61616?keepAlive=true&wireFormat.tightEncodingEnabled=false&wireFormat.cacheEnabled=false&wireFormat.maxInactivityDuration=300000
> due to: java.net.SocketException: Unrecognized Windows Sockets error: 0:
> JVM_Bind
> at
> org.apache.activemq.util.IOExceptionSupport.create(IOExceptionSupport.java:27)
> at
> org.apache.activemq.broker.BrokerService.registerConnectorMBean(BrokerService.java:1678)
> at
> org.apache.activemq.broker.BrokerService.startTransportConnector(BrokerService.java:2166)
> at
> org.apache.activemq.broker.BrokerService.startAllConnectors(BrokerService.java:2082)
> at org.apache.activemq.broker.BrokerService.start(BrokerService.java:516)
> ---
> When exiting the client process, the ActiveMQ service is able to start up
> again.
> I had a look at the source code, and I think the bug is inside the
> TcpTransportFactory.cs:
> {code}
> if(!String.IsNullOrEmpty(location.AbsolutePath) &&
> !location.AbsolutePath.Equals("/"))
> {
> int index = location.AbsolutePath.IndexOf(':');
> try
> {
> localPort =
> Int16.Parse(location.AbsolutePath.Substring(index + 1));
>
> localAddress =
> location.AbsolutePath.Substring(1, index - 1);
> Tracer.DebugFormat("Binding Socket to
> {0} on port: {1}", localAddress, localPort);
> }
> catch
> {
> Tracer.Warn("Invalid Port value on URI for local bind
> option, ignoring.");
> }
> }
> {code}
--
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
