You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@activemq.apache.org by "Frank Gynnild (Commented) (JIRA)" <ji...@apache.org> on 2011/11/16 13:30:51 UTC
[jira] [Commented] (AMQNET-350) Clients using the NMS library
sometimes hijacks (binds) to the port that ActiveMQ is listening to
[ 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