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 (Created) (JIRA)" <ji...@apache.org> on 2011/11/16 11:24:52 UTC
[jira] [Created] (AMQNET-350) Clients using the NMS library
sometimes hijacks (binds) to the port that ActiveMQ is listening to
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.1, 1.5.0, 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
[jira] [Assigned] (AMQNET-350) Clients using the NMS library
sometimes hijacks (binds) to the port that ActiveMQ is listening to
Posted by "Timothy Bish (Assigned) (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/AMQNET-350?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Timothy Bish reassigned AMQNET-350:
-----------------------------------
Assignee: Timothy Bish (was: Jim Gomes)
> 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: Timothy Bish
>
> 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
[jira] [Commented] (AMQNET-350) Clients using the NMS library
sometimes hijacks (binds) to the port that ActiveMQ is listening to
Posted by "Timothy Bish (Commented) (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/AMQNET-350?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13151563#comment-13151563 ]
Timothy Bish commented on AMQNET-350:
-------------------------------------
If you look at the code you will see that the only time a Bind is done if when there's a local address and port specified otherwise the if test surrounding that code cannot be true. As far as I can tell there's no Bind occurring, you can always run in the debugger and find out for sure though.
> 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: Timothy Bish
>
> 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
[jira] [Commented] (AMQNET-350) Clients using the NMS library
sometimes hijacks (binds) to the port that ActiveMQ is listening to
Posted by "Frank Gynnild (Commented) (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/AMQNET-350?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13151232#comment-13151232 ]
Frank Gynnild commented on AMQNET-350:
--------------------------------------
We're using the failover protocol:
BrokerUri=failover:(tcp://GELADO:61616?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000)
> 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: Timothy Bish
>
> 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
[jira] [Commented] (AMQNET-350) Clients using the NMS library
sometimes hijacks (binds) to the port that ActiveMQ is listening to
Posted by "Frank Gynnild (Commented) (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/AMQNET-350?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13151444#comment-13151444 ]
Frank Gynnild commented on AMQNET-350:
--------------------------------------
I reproduced it again, this time with debug tracing turned on. There is no signs of "Binding", so that's probably a lead in the dark.
A common denominator has been that the address occupying it is an IPv6 address.
How's the free, local port determined? I just had a brief look at the code, it seems to use the "-1" as input,
I think it needs to be "0", but don't know if that causes the above problem or not.
---
2011-11-16 19:55:40,643 <32472> [ActiveMQ Failover Worker: 66629781] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Opening socket to: gelado on port: 61616
2011-11-16 19:55:42,674 <32472> [ActiveMQ Failover Worker: 39864430] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Connect fail to: tcp://gelado:61616/?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000, reason: Error connecting to gelado:61616.
2011-11-16 19:55:42,674 <32472> [ActiveMQ Failover Worker: 39864430] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting 2560ms before attempting connection.
2011-11-16 19:55:42,674 <32472> [ActiveMQ Failover Worker: 56931087] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Connect fail to: tcp://gelado:61616/?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000, reason: Error connecting to gelado:61616.
2011-11-16 19:55:42,674 <32472> [ActiveMQ Failover Worker: 56931087] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting 2560ms before attempting connection.
2011-11-16 19:55:42,674 <32472> [ActiveMQ Failover Worker: 66629781] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Connect fail to: tcp://gelado:61616/?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000, reason: Error connecting to gelado:61616.
2011-11-16 19:55:42,674 <32472> [ActiveMQ Failover Worker: 66629781] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting 2560ms before attempting connection.
2011-11-16 19:55:45,237 <32472> [ActiveMQ Failover Worker: 39864430] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Attempting sync connect to: tcp://gelado:61616/?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000
2011-11-16 19:55:45,237 <32472> [ActiveMQ Failover Worker: 39864430] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Opening socket to: gelado on port: 61616
2011-11-16 19:55:45,237 <32472> [ActiveMQ Failover Worker: 56931087] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Attempting sync connect to: tcp://gelado:61616/?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000
2011-11-16 19:55:45,237 <32472> [ActiveMQ Failover Worker: 56931087] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Opening socket to: gelado on port: 61616
2011-11-16 19:55:45,237 <32472> [ActiveMQ Failover Worker: 66629781] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Attempting sync connect to: tcp://gelado:61616/?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000
2011-11-16 19:55:45,237 <32472> [ActiveMQ Failover Worker: 66629781] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Opening socket to: gelado on port: 61616
2011-11-16 19:55:47,284 <32472> [ActiveMQ Failover Worker: 39864430] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Connect fail to: tcp://gelado:61616/?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000, reason: Error connecting to gelado:61616.
2011-11-16 19:55:47,284 <32472> [ActiveMQ Failover Worker: 39864430] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting 5120ms before attempting connection.
2011-11-16 19:55:47,284 <32472> [ActiveMQ Failover Worker: 56931087] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Connect fail to: tcp://gelado:61616/?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000, reason: Error connecting to gelado:61616.
2011-11-16 19:55:47,284 <32472> [ActiveMQ Failover Worker: 56931087] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting 5120ms before attempting connection.
2011-11-16 19:55:47,284 <32472> [ActiveMQ Failover Worker: 66629781] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Connect fail to: tcp://gelado:61616/?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000, reason: Error connecting to gelado:61616.
2011-11-16 19:55:47,284 <32472> [ActiveMQ Failover Worker: 66629781] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting 5120ms before attempting connection.
2011-11-16 19:55:52,409 <32472> [ActiveMQ Failover Worker: 39864430] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Attempting sync connect to: tcp://gelado:61616/?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000
2011-11-16 19:55:52,409 <32472> [ActiveMQ Failover Worker: 39864430] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Opening socket to: gelado on port: 61616
2011-11-16 19:55:52,424 <32472> [ActiveMQ Failover Worker: 56931087] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Attempting sync connect to: tcp://gelado:61616/?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000
2011-11-16 19:55:52,424 <32472> [ActiveMQ Failover Worker: 56931087] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Opening socket to: gelado on port: 61616
2011-11-16 19:55:52,440 <32472> [ActiveMQ Failover Worker: 66629781] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Attempting sync connect to: tcp://gelado:61616/?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000
2011-11-16 19:55:52,440 <32472> [ActiveMQ Failover Worker: 66629781] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Opening socket to: gelado on port: 61616
2011-11-16 19:55:54,456 <32472> [ActiveMQ Failover Worker: 39864430] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Connect fail to: tcp://gelado:61616/?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000, reason: Error connecting to gelado:61616.
2011-11-16 19:55:54,456 <32472> [ActiveMQ Failover Worker: 39864430] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting 10240ms before attempting connection.
2011-11-16 19:55:54,456 <32472> [ActiveMQ Failover Worker: 56931087] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Connect fail to: tcp://gelado:61616/?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000, reason: Error connecting to gelado:61616.
2011-11-16 19:55:54,456 <32472> [ActiveMQ Failover Worker: 56931087] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting 10240ms before attempting connection.
2011-11-16 19:55:54,456 <32472> [ActiveMQ Failover Worker: 66629781] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Connect fail to: tcp://gelado:61616/?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000, reason: Error connecting to gelado:61616.
2011-11-16 19:55:54,456 <32472> [ActiveMQ Failover Worker: 66629781] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting 10240ms before attempting connection.
2011-11-16 19:56:04,706 <32472> [ActiveMQ Failover Worker: 39864430] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Attempting sync connect to: tcp://gelado:61616/?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000
2011-11-16 19:56:04,706 <32472> [ActiveMQ Failover Worker: 39864430] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Opening socket to: gelado on port: 61616
2011-11-16 19:56:04,722 <32472> [ActiveMQ Failover Worker: 56931087] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Attempting sync connect to: tcp://gelado:61616/?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000
2011-11-16 19:56:04,722 <32472> [ActiveMQ Failover Worker: 56931087] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Opening socket to: gelado on port: 61616
2011-11-16 19:56:04,722 <32472> [ActiveMQ Failover Worker: 66629781] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Attempting sync connect to: tcp://gelado:61616/?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000
2011-11-16 19:56:04,722 <32472> [ActiveMQ Failover Worker: 66629781] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Opening socket to: gelado on port: 61616
2011-11-16 19:56:06,722 <32472> [ActiveMQ Failover Worker: 39864430] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Connect fail to: tcp://gelado:61616/?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000, reason: Error connecting to gelado:61616.
2011-11-16 19:56:06,722 <32472> [ActiveMQ Failover Worker: 39864430] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting 20480ms before attempting connection.
2011-11-16 19:56:06,722 <32472> [ActiveMQ Failover Worker: 56931087] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Connect fail to: tcp://gelado:61616/?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000, reason: Error connecting to gelado:61616.
2011-11-16 19:56:06,722 <32472> [ActiveMQ Failover Worker: 56931087] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting 20480ms before attempting connection.
2011-11-16 19:56:06,768 <32472> [ActiveMQ Failover Worker: 66629781] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Connect fail to: tcp://gelado:61616/?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000, reason: Error connecting to gelado:61616.
2011-11-16 19:56:06,768 <32472> [ActiveMQ Failover Worker: 66629781] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting 20480ms before attempting connection.
2011-11-16 19:56:27,206 <32472> [ActiveMQ Failover Worker: 56931087] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Attempting sync connect to: tcp://gelado:61616/?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000
2011-11-16 19:56:27,206 <32472> [ActiveMQ Failover Worker: 56931087] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Opening socket to: gelado on port: 61616
2011-11-16 19:56:27,206 <32472> [ActiveMQ Failover Worker: 39864430] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Attempting sync connect to: tcp://gelado:61616/?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000
2011-11-16 19:56:27,206 <32472> [ActiveMQ Failover Worker: 39864430] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Opening socket to: gelado on port: 61616
2011-11-16 19:56:27,253 <32472> [ActiveMQ Failover Worker: 66629781] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Attempting sync connect to: tcp://gelado:61616/?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000
2011-11-16 19:56:27,253 <32472> [ActiveMQ Failover Worker: 66629781] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Opening socket to: gelado on port: 61616
2011-11-16 19:56:29,237 <32472> [ActiveMQ Failover Worker: 56931087] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Connect fail to: tcp://gelado:61616/?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000, reason: Error connecting to gelado:61616.
2011-11-16 19:56:29,237 <32472> [ActiveMQ Failover Worker: 56931087] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting 30000ms before attempting connection.
2011-11-16 19:56:29,237 <32472> [ActiveMQ Failover Worker: 39864430] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Connect fail to: tcp://gelado:61616/?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000, reason: Error connecting to gelado:61616.
2011-11-16 19:56:29,237 <32472> [ActiveMQ Failover Worker: 39864430] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting 30000ms before attempting connection.
2011-11-16 19:56:29,284 <32472> [ActiveMQ Failover Worker: 66629781] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Connect fail to: tcp://gelado:61616/?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000, reason: Error connecting to gelado:61616.
2011-11-16 19:56:29,284 <32472> [ActiveMQ Failover Worker: 66629781] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Waiting 30000ms before attempting connection.
2011-11-16 19:56:59,238 <32472> [ActiveMQ Failover Worker: 39864430] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Attempting sync connect to: tcp://gelado:61616/?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000
2011-11-16 19:56:59,238 <32472> [ActiveMQ Failover Worker: 39864430] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Opening socket to: gelado on port: 61616
2011-11-16 19:56:59,238 <32472> [ActiveMQ Failover Worker: 56931087] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Attempting sync connect to: tcp://gelado:61616/?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000
2011-11-16 19:56:59,238 <32472> [ActiveMQ Failover Worker: 56931087] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Opening socket to: gelado on port: 61616
2011-11-16 19:56:59,285 <32472> [ActiveMQ Failover Worker: 66629781] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Attempting sync connect to: tcp://gelado:61616/?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000
2011-11-16 19:56:59,285 <32472> [ActiveMQ Failover Worker: 66629781] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Opening socket to: gelado on port: 61616
2011-11-16 19:56:59,285 <32472> [ActiveMQ Failover Worker: 66629781] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Connected to gelado:61616 using InterNetworkV6 protocol.
2011-11-16 19:56:59,285 <32472> [ActiveMQ Failover Worker: 66629781] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Creating Inactivity Monitor: 4
2011-11-16 19:56:59,285 <32472> [15288] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - InactivityMonitor[4]: Read Check time interval: 300000
2011-11-16 19:56:59,285 <32472> [15288] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - InactivityMonitor[4]: Initial Delay time interval: 10000
2011-11-16 19:56:59,285 <32472> [ActiveMQ Failover Worker: 66629781] INFO InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Restoring previous transport connection.
2011-11-16 19:56:59,285 <32472> [15288] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - InactivityMonitor[4]: Write Check time interval: 100000
2011-11-16 19:56:59,300 <32472> [ActiveMQ Failover Worker: 66629781] INFO InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Sending queued commands...
2011-11-16 19:56:59,300 <32472> [ActiveMQ Failover Worker: 66629781] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Transport has resumed normal operation.
2011-11-16 19:56:59,300 <32472> [ActiveMQ Failover Worker: 66629781] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Connection established
2011-11-16 19:56:59,300 <32472> [ActiveMQ Failover Worker: 66629781] 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 19:56:59,300 <32472> [15288] 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 19:57:01,269 <32472> [ActiveMQ Failover Worker: 39864430] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Connect fail to: tcp://gelado:61616/?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000, reason: Error connecting to gelado:61616.
2011-11-16 19:57:01,269 <32472> [ActiveMQ Failover Worker: 56931087] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - Connect fail to: tcp://gelado:61616/?nms.PrefetchPolicy.queuePrefetch=0&keepAlive=true&wireFormat.TightEncodingEnabled=false&wireFormat.CacheEnabled=false&wireFormat.MaxInactivityDuration=300000, reason: Error connecting to gelado:61616.
2011-11-16 19:57:09,316 <32472> [22188] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - InactivityMonitor[4]: Message sent since last write check. Resetting flag.
2011-11-16 19:58:49,380 <32472> [26280] DEBUG InfoFinder.Framework.Diagnostics.NmsClientLibraryLogger [(null)] - InactivityMonitor[4]: Message sent since last write check. Resetting flag.
---
> 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: Timothy Bish
>
> 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
[jira] [Commented] (AMQNET-350) Clients using the NMS library
sometimes hijacks (binds) to the port that ActiveMQ is listening to
Posted by "Timothy Bish (Commented) (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/AMQNET-350?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13151215#comment-13151215 ]
Timothy Bish commented on AMQNET-350:
-------------------------------------
What is the client's connection Uri string?
> 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: Timothy Bish
>
> 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
[jira] [Closed] (AMQNET-350) Clients using the NMS library
sometimes hijacks (binds) to the port that ActiveMQ is listening to
Posted by "Timothy Bish (Closed) (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/AMQNET-350?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Timothy Bish closed AMQNET-350.
-------------------------------
Resolution: Cannot Reproduce
I can't reproduce this. If you can create a test case that shows the problem please reopen and attach.
> 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: Timothy Bish
>
> 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
[jira] [Commented] (AMQNET-350) Clients using the NMS library
sometimes hijacks (binds) to the port that ActiveMQ is listening to
Posted by "Frank Gynnild (Commented) (JIRA)" <ji...@apache.org>.
[ 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