activemq-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Frank Gynnild (Commented) (JIRA)" <jira+amq...@apache.org>
Subject [jira] [Commented] (AMQNET-350) Clients using the NMS library sometimes hijacks (binds) to the port that ActiveMQ is listening to
Date Wed, 16 Nov 2011 12:30:51 GMT

    [ 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

        

Mime
View raw message