search

ISISComputingGroup / IBEX

Top level repository for IBEX stories
5 stars 2 forks source link

ActiveMQ / JMS port in use #2315

Closed Tom-Willemsen closed 7 years ago

Tom-Willemsen commented 7 years ago

This has been seen on Polaris: Some other service (presumably one using freeport) used port 61616. This caused ActiveMQ / JMS to constantly crash and attempt to restart. This was fixed on NDXPOLARIS by restarting IBEX server, but we should fix the root cause as well.

Possible solutions to this ticket:

Below is a sample of the log / error as found on polaris.

[Mon May  8 20:24:59 2017] @@@ @@@ @@@ @@@ @@@
[Mon May  8 20:24:59 2017] @@@ Received a sigChild for process 1208. Normal exit status = 0
[Mon May  8 20:24:59 2017] @@@ Current time: Mon May  8 20:24:59 2017
[Mon May  8 20:24:59 2017] @@@ Child process is shutting down, a new one will be restarted shortly
[Mon May  8 20:24:59 2017] @@@ ^R or ^X restarts the child, ^Q quits the server
[Mon May  8 20:25:10 2017] @@@ Restarting child "JMS"
[Mon May  8 20:25:10 2017] @@@    (as C:\Windows\system32\cmd.exe)
[Mon May  8 20:25:10 2017] @@@ The PID of new child "JMS" is: 17816
[Mon May  8 20:25:10 2017] @@@ @@@ @@@ @@@ @@@
[Mon May  8 20:25:11 2017] 

[Mon May  8 20:25:11 2017] Warning: JAVA_HOME environment variable is not set.

[Mon May  8 20:25:11 2017] 

[Mon May  8 20:25:11 2017] Java Runtime: Oracle Corporation 1.8.0_131 C:\Program Files (x86)\Java\jre1.8.0_131

[Mon May  8 20:25:11 2017]   Heap sizes: current=63360k  free=62309k  max=63360k

[Mon May  8 20:25:11 2017]     JVM args: -Xms64m -Xmx64m -Djava.util.logging.config.file=logging.properties -Djava.security.auth.login.config=C:\Instrument\Apps\EPICS\ISIS\ActiveMQ\master\bin\..\conf\login.config -Dorg.apache.activemq.UseDedicatedTaskRunner=false -Dactivemq.classpath=C:\Instrument\Apps\EPICS\ISIS\ActiveMQ\master\bin\..\conf;C:\Instrument\Apps\EPICS\ISIS\ActiveMQ\master\bin\../conf;C:\Instrument\Apps\EPICS\ISIS\ActiveMQ\master\bin\../conf; -Dactivemq.home=C:\Instrument\Apps\EPICS\ISIS\ActiveMQ\master\bin\.. -Dactivemq.base=C:\Instrument\Apps\EPICS\ISIS\ActiveMQ\master\bin\.. -Dactivemq.conf=C:\Instrument\Apps\EPICS\ISIS\ActiveMQ\master\bin\..\conf -Dactivemq.data=C:\Instrument\Apps\EPICS\ISIS\ActiveMQ\master\bin\..\data -Djava.io.tmpdir=C:\Instrument\Apps\EPICS\ISIS\ActiveMQ\master\bin\..\data\tmp

[Mon May  8 20:25:11 2017] Extensions classpath:
[Mon May  8 20:25:11 2017]   [C:\Instrument\Apps\EPICS\ISIS\ActiveMQ\master\bin\..\lib,C:\Instrument\Apps\EPICS\ISIS\ActiveMQ\master\bin\..\lib\camel,C:\Instrument\Apps\EPICS\ISIS\ActiveMQ\master\bin\..\lib\optional,C:\Instrument\Apps\EPICS\ISIS\ActiveMQ\master\bin\..\lib\web,C:\Instrument\Apps\EPICS\ISIS\ActiveMQ\master\bin\..\lib\extra]

[Mon May  8 20:25:11 2017] ACTIVEMQ_HOME: C:\Instrument\Apps\EPICS\ISIS\ActiveMQ\master\bin\..

[Mon May  8 20:25:11 2017] ACTIVEMQ_BASE: C:\Instrument\Apps\EPICS\ISIS\ActiveMQ\master\bin\..

[Mon May  8 20:25:11 2017] ACTIVEMQ_CONF: C:\Instrument\Apps\EPICS\ISIS\ActiveMQ\master\bin\..\conf

[Mon May  8 20:25:11 2017] ACTIVEMQ_DATA: C:\Instrument\Apps\EPICS\ISIS\ActiveMQ\master\bin\..\data

[Mon May  8 20:25:11 2017] Loading message broker from: xbean:activemq.xml

[Mon May  8 20:25:11 2017]  INFO | Refreshing org.apache.activemq.xbean.XBeanBrokerFactory$1@d041cf: startup date [Mon May 08 20:25:11 BST 2017]; root of context hierarchy

[Mon May  8 20:25:12 2017]  INFO | PListStore:[C:\Instrument\Apps\EPICS\ISIS\ActiveMQ\master\bin\..\data\localhost\tmp_storage] started

[Mon May  8 20:25:12 2017]  INFO | Using Persistence Adapter: KahaDBPersistenceAdapter[C:\Instrument\Apps\EPICS\ISIS\ActiveMQ\master\bin\..\data\localhost\KahaDB]

[Mon May  8 20:25:14 2017]  INFO | KahaDB is version 5

[Mon May  8 20:25:14 2017]  INFO | Recovering from the journal ...

[Mon May  8 20:25:14 2017]  INFO | Recovery replayed 1 operations from the journal in 0.061 seconds.

[Mon May  8 20:25:14 2017]  INFO | Apache ActiveMQ 5.10.0 (localhost, ID:NDXPOLARIS-50047-1494271514110-0:1) is starting

[Mon May  8 20:25:14 2017] ERROR | Failed to start Apache ActiveMQ ([localhost, ID:NDXPOLARIS-50047-1494271514110-0:1], java.io.IOException: Failed to bind to server socket: tcp://0.0.0.0:61616?maximumConnections=1000&wireFormat.maxFrameSize=104857600 due to: java.net.BindException: Address already in use: JVM_Bind)

[Mon May  8 20:25:14 2017]  INFO | Apache ActiveMQ 5.10.0 (localhost, ID:NDXPOLARIS-50047-1494271514110-0:1) is shutting down

[Mon May  8 20:25:14 2017]  INFO | Connector openwire stopped

[Mon May  8 20:25:14 2017]  INFO | Connector stomp stopped

[Mon May  8 20:25:14 2017]  INFO | PListStore:[C:\Instrument\Apps\EPICS\ISIS\ActiveMQ\master\bin\..\data\localhost\tmp_storage] stopped

[Mon May  8 20:25:14 2017]  INFO | Stopping async queue tasks

[Mon May  8 20:25:14 2017]  INFO | Stopping async topic tasks

[Mon May  8 20:25:14 2017]  INFO | Stopped KahaDB

[Mon May  8 20:25:14 2017]  INFO | Apache ActiveMQ 5.10.0 (localhost, ID:NDXPOLARIS-50047-1494271514110-0:1) uptime 1.896 seconds

[Mon May  8 20:25:14 2017]  INFO | Apache ActiveMQ 5.10.0 (localhost, ID:NDXPOLARIS-50047-1494271514110-0:1) is shutdown

[Mon May  8 20:25:14 2017]  INFO | Closing org.apache.activemq.xbean.XBeanBrokerFactory$1@d041cf: startup date [Mon May 08 20:25:11 BST 2017]; root of context hierarchy

[Mon May  8 20:25:14 2017]  WARN | Exception thrown from LifecycleProcessor on context close

[Mon May  8 20:25:14 2017] java.lang.IllegalStateException: LifecycleProcessor not initialized - call 'refresh' before invoking lifecycle methods via the context: org.apache.activemq.xbean.XBeanBrokerFactory$1@d041cf: startup date [Mon May 08 20:25:11 BST 2017]; root of context hierarchy

[Mon May  8 20:25:14 2017]  at org.springframework.context.support.AbstractApplicationContext.getLifecycleProcessor(AbstractApplicationContext.java:360)[spring-context-3.2.8.RELEASE.jar:3.2.8.RELEASE]

[Mon May  8 20:25:14 2017]  at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:1057)[spring-context-3.2.8.RELEASE.jar:3.2.8.RELEASE]

[Mon May  8 20:25:14 2017]  at org.springframework.context.support.AbstractApplicationContext.close(AbstractApplicationContext.java:1010)[spring-context-3.2.8.RELEASE.jar:3.2.8.RELEASE]

[Mon May  8 20:25:14 2017]  at org.apache.activemq.hooks.SpringContextHook.run(SpringContextHook.java:30)[activemq-spring-5.10.0.jar:5.10.0]

[Mon May  8 20:25:14 2017]  at org.apache.activemq.broker.BrokerService.stop(BrokerService.java:809)[activemq-broker-5.10.0.jar:5.10.0]

[Mon May  8 20:25:14 2017]  at org.apache.activemq.xbean.XBeanBrokerService.stop(XBeanBrokerService.java:122)[activemq-spring-5.10.0.jar:5.10.0]

[Mon May  8 20:25:14 2017]  at org.apache.activemq.broker.BrokerService.start(BrokerService.java:601)[activemq-broker-5.10.0.jar:5.10.0]

[Mon May  8 20:25:14 2017]  at org.apache.activemq.xbean.XBeanBrokerService.afterPropertiesSet(XBeanBrokerService.java:73)[activemq-spring-5.10.0.jar:5.10.0]

[Mon May  8 20:25:14 2017]  at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)[:1.8.0_131]

[Mon May  8 20:25:14 2017]  at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)[:1.8.0_131]

[Mon May  8 20:25:14 2017]  at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)[:1.8.0_131]

[Mon May  8 20:25:14 2017]  at java.lang.reflect.Method.invoke(Unknown Source)[:1.8.0_131]

[Mon May  8 20:25:14 2017]  at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeCustomInitMethod(AbstractAutowireCapableBeanFactory.java:1638)[spring-beans-3.2.8.RELEASE.jar:3.2.8.RELEASE]

[Mon May  8 20:25:14 2017]  at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1579)[spring-beans-3.2.8.RELEASE.jar:3.2.8.RELEASE]
FreddieAkeroyd commented 7 years ago

Any port above 49152 is in the dynamic allocation range and can be allocated by any windows process - ActiveMQ should either dynamically allocate a port or be changed to use one with a lower number. Restarting ibex suggests it was one of our processes, so starting activeMQ earlier instartup sequence might fix it. Note that it is not just explicit use of our own freeport() function that might claim this port - any IOC that starts up and cannot bind to 5064 will allocate a dynamic port implicitly. These IOC ports are on loopback, but Active MQ may try to bind to all interfaces. Is the activemq port hard-coded in ibex somewhere?

DominicOram commented 7 years ago

When changing port will also need to change it on:

DominicOram commented 7 years ago

Port 39990 chosen as it's far from anything in use on SECI or IBEX systems and appears unassigned generally.