activemq-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Korny Sietsma <ko...@sietsma.com>
Subject Master broker not restarting cleanly after errors - Address already in use
Date Tue, 19 Jul 2016 13:07:46 GMT
Hi folks - I'm testing a system using ActiveMQ 5.9.1 with an NFS server for
shared filesystem master/slave

I'm trying to set up and test failover and fail-back.  I'm using Jepsen to
fake a network split, where the Master broker can't communicate with the
NFS server - after some headaches I have it at a stage where the Master
times out writing to the file system, and shuts down and restarts - but it
fails to restart cleanly, with a BindException error starting the web app
at http://0.0.0.0:8161/fileserver

Relevant bits from the activemq logs:

2016-07-19 11:18:36,837 [main           ] INFO  AbstractConnector
   - Started SelectChannelConnector@0.0.0.0:8161
2016-07-19 11:22:55,991 [KeepAlive Timer] ERROR LockableServiceSupport
    - activemq-server.corporate.thoughtworks.com, no longer able to keep
the exclusive lock so giving up being a master
2016-07-19 11:22:55,992 [KeepAlive Timer] INFO  BrokerService
   - Apache ActiveMQ 5.9.1 (activemq-server.corporate.thoughtworks.com,
ID:activemq-server-48763-1468927115062-0:1) is shutting down
2016-07-19 11:23:00,999 [KeepAlive Timer] INFO  TransportConnection
   - The connection to 'tcp://172.10.10.1:49275' is taking a long time to
shutdown.
... this repeated several times, every 5 seconds - not quite sure why, nor
if it's relevant, until:
2016-07-19 11:34:21,195 [KeepAlive Timer] INFO  TransportConnection
   - The connection to 'tcp://172.10.10.1:49275' is taking a long time to
shutdown.
2016-07-19 11:34:26,012 [ata File Writer] INFO  DataFileAppender
    - Journal failed while writing at: 417675
2016-07-19 11:34:26,013 [toreAndDispatch] ERROR MessageDatabase
   - KahaDB failed to store to Journal
java.io.IOException: Input/output error
at sun.nio.ch.FileDispatcherImpl.force0(Native Method)
at sun.nio.ch.FileDispatcherImpl.force(FileDispatcherImpl.java:76)
at sun.nio.ch.FileChannelImpl.force(FileChannelImpl.java:386)
at
org.apache.activemq.util.RecoverableRandomAccessFile.sync(RecoverableRandomAccessFile.java:402)
at
org.apache.activemq.store.kahadb.disk.journal.DataFileAppender.processQueue(DataFileAppender.java:373)
at
org.apache.activemq.store.kahadb.disk.journal.DataFileAppender$1.run(DataFileAppender.java:193)
2016-07-19 11:34:26,029 [toreAndDispatch] INFO  DefaultIOExceptionHandler
   - Stopping BrokerService[activemq-server.corporate.thoughtworks.com] due
to exception,

... some I/O errors removed, naturally there are I/O errors as we've broken
the NFS connection

2016-07-19 11:34:26,161 [KeepAlive Timer] INFO  TransportConnector
    - Connector openwire stopped
2016-07-19 11:34:26,162 [KeepAlive Timer] INFO  TransportConnector
    - Connector amqp stopped
2016-07-19 11:34:26,491 [KeepAlive Timer] INFO  PListStoreImpl
    - PListStore:[/share/nfs_share/db/
activemq-server.corporate.thoughtworks.com/tmp_storage] stopped
2016-07-19 11:34:26,494 [KeepAlive Timer] INFO  KahaDBStore
   - Stopping async queue tasks
2016-07-19 11:34:26,494 [KeepAlive Timer] INFO  KahaDBStore
   - Stopping async topic tasks
2016-07-19 11:34:26,496 [KeepAlive Timer] INFO  KahaDBStore
   - Stopped KahaDB
2016-07-19 11:34:26,509 [KeepAlive Timer] INFO  MessageDatabase
   - KahaDB: Recovering checkpoint thread after death
2016-07-19 11:34:26,638 [KeepAlive Timer] INFO  BrokerService
   - Apache ActiveMQ 5.9.1 (activemq-server.corporate.thoughtworks.com,
ID:activemq-server-48763-1468927115062-0:1) uptime 15 minutes
2016-07-19 11:34:26,638 [KeepAlive Timer] INFO  BrokerService
   - Apache ActiveMQ 5.9.1 (activemq-server.corporate.thoughtworks.com,
ID:activemq-server-48763-1468927115062-0:1) is shutdown
2016-07-19 11:34:26,639 [main           ] INFO  XBeanBrokerFactory$1
    - Refreshing org.apache.activemq.xbean.XBeanBrokerFactory$1@7f132176:
startup date [Tue Jul 19 11:34:26 UTC 2016]; root of context hierarchy
2016-07-19 11:34:30,971 [main           ] INFO  PListStoreImpl
    - PListStore:[/share/nfs_share/db/
activemq-server.corporate.thoughtworks.com/tmp_storage] started

... removed a bunch of valid looking startup messages, including recovering
from journal corruption...

2016-07-19 11:34:36,754 [main           ] INFO  StatisticsBrokerPlugin
    - Installing StaticsBroker
2016-07-19 11:34:36,754 [main           ] INFO  BrokerService
   - Apache ActiveMQ 5.9.1 (activemq-server.corporate.thoughtworks.com,
ID:activemq-server-48763-1468927115062-0:2) is starting
2016-07-19 11:34:36,776 [main           ] INFO  StatisticsBroker
    - Starting StatisticsBroker
2016-07-19 11:34:36,782 [main           ] INFO
 TransportServerThreadSupport   - Listening for connections at:
tcp://activemq-server:61616?maximumConnections=1000&wireFormat.maxFrameSize=104857600
2016-07-19 11:34:36,783 [main           ] INFO  TransportConnector
    - Connector openwire started
2016-07-19 11:34:36,788 [main           ] INFO
 TransportServerThreadSupport   - Listening for connections at:
amqp://activemq-server:5672?maximumConnections=1000&wireFormat.maxFrameSize=104857600
2016-07-19 11:34:36,788 [main           ] INFO  TransportConnector
    - Connector amqp started
2016-07-19 11:34:36,788 [main           ] INFO  BrokerService
   - Apache ActiveMQ 5.9.1 (activemq-server.corporate.thoughtworks.com,
ID:activemq-server-48763-1468927115062-0:2) started
2016-07-19 11:34:36,788 [main           ] INFO  BrokerService
   - For help or more information please see: http://activemq.apache.org
2016-07-19 11:34:37,035 [main           ] INFO  Server
    - jetty-7.6.9.v20130131
2016-07-19 11:34:37,478 [main           ] INFO  ContextHandler
    - started
o.e.j.w.WebAppContext{/admin,file:/var/lib/activemq/webapps/admin/}
2016-07-19 11:34:37,504 [main           ] INFO  /admin
    - Initializing Spring FrameworkServlet 'dispatcher'

... removed a bunch of spring mappings

2016-07-19 11:34:37,574 [main           ] INFO  WebAppContext
   - ActiveMQ Console at http://0.0.0.0:8161/admin
2016-07-19 11:34:37,601 [main           ] INFO  ContextHandler
    - started
o.e.j.w.WebAppContext{/camel,file:/var/lib/activemq/webapps/camel}
2016-07-19 11:34:37,615 [main           ] INFO  WebAppContext
   - WebApp@396485834 at http://0.0.0.0:8161/camel
2016-07-19 11:34:37,648 [main           ] INFO  ContextHandler
    - started
o.e.j.w.WebAppContext{/demo,file:/var/lib/activemq/webapps/demo}
2016-07-19 11:34:37,658 [main           ] INFO  WebAppContext
   - WebApp@396485834 at http://0.0.0.0:8161/demo
2016-07-19 11:34:37,673 [main           ] INFO  ContextHandler
    - started
o.e.j.w.WebAppContext{/fileserver,file:/var/lib/activemq/webapps/fileserver}
2016-07-19 11:34:37,683 [main           ] INFO  WebAppContext
   - WebApp@396485834 at http://0.0.0.0:8161/fileserver
2016-07-19 11:34:37,704 [main           ] WARN  AbstractLifeCycle
   - FAILED SelectChannelConnector@0.0.0.0:8161: java.net.BindException:
Address already in use
java.net.BindException: Address already in use
at sun.nio.ch.Net.bind0(Native Method)
at sun.nio.ch.Net.bind(Net.java:437)
at sun.nio.ch.Net.bind(Net.java:429)
at sun.nio.ch.ServerSocketChannelImpl.bind(ServerSocketChannelImpl.java:223)
at sun.nio.ch.ServerSocketAdaptor.bind(ServerSocketAdaptor.java:74)
at
org.eclipse.jetty.server.nio.SelectChannelConnector.open(SelectChannelConnector.java:187)
at
org.eclipse.jetty.server.AbstractConnector.doStart(AbstractConnector.java:316)
at
org.eclipse.jetty.server.nio.SelectChannelConnector.doStart(SelectChannelConnector.java:265)
at
org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:64)
at org.eclipse.jetty.server.Server.doStart(Server.java:290)
at
org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:64)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at
org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeCustomInitMethod(AbstractAutowireCapableBeanFactory.java:1638)
at
org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1579)
at
org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1509)
at
org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:521)
at
org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:458)
at
org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:296)
at
org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:223)
at
org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:293)
at
org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:194)
at
org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:628)
at
org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:932)
at
org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:479)
at
org.apache.xbean.spring.context.ResourceXmlApplicationContext.<init>(ResourceXmlApplicationContext.java:64)
at
org.apache.xbean.spring.context.ResourceXmlApplicationContext.<init>(ResourceXmlApplicationContext.java:52)
at
org.apache.activemq.xbean.XBeanBrokerFactory$1.<init>(XBeanBrokerFactory.java:104)
at
org.apache.activemq.xbean.XBeanBrokerFactory.createApplicationContext(XBeanBrokerFactory.java:104)
at
org.apache.activemq.xbean.XBeanBrokerFactory.createBroker(XBeanBrokerFactory.java:67)
at
org.apache.activemq.broker.BrokerFactory.createBroker(BrokerFactory.java:71)
at
org.apache.activemq.broker.BrokerFactory.createBroker(BrokerFactory.java:54)
at
org.apache.activemq.console.command.StartCommand.runTask(StartCommand.java:87)
at
org.apache.activemq.console.command.AbstractCommand.execute(AbstractCommand.java:57)
at
org.apache.activemq.console.command.ShellCommand.runTask(ShellCommand.java:150)
at
org.apache.activemq.console.command.AbstractCommand.execute(AbstractCommand.java:57)
at
org.apache.activemq.console.command.ShellCommand.main(ShellCommand.java:104)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at org.apache.activemq.console.Main.runTaskClass(Main.java:262)
at org.apache.activemq.console.Main.main(Main.java:115)
2016-07-19 11:34:37,706 [main           ] WARN  AbstractLifeCycle
   - FAILED org.eclipse.jetty.server.Server@7103cb56:
java.net.BindException: Address already in use


So it seems that something in the admin app failed to shut down properly?
Or something else?  I'm going to try disabling the admin app and trying
again.  But any other thoughts would be appreciated.

- Korny

-- 
Kornelis Sietsma  korny at my surname dot com http://korny.info
.fnord { display: none !important; }

Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message