[QPID-8274] [Broker-J][BDB HA] Broker can fail to become active when BDB HA virtual host times out to join the group

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Not A Problem
• Affects Version/s: qpid-java-6.1.6, qpid-java-broker-7.0.3, qpid-java-broker-7.0.2, qpid-java-6.0, qpid-java-6.0.1, qpid-java-6.0.2, qpid-java-6.0.3, qpid-java-6.0.4, qpid-java-6.0.5, qpid-java-6.1, qpid-java-6.0.6, qpid-java-6.1.1, qpid-java-6.1.2, qpid-java-6.0.7, qpid-java-6.1.3, qpid-java-6.0.8, qpid-java-6.1.4, qpid-java-broker-7.0.0, qpid-java-6.1.5, qpid-java-broker-7.0.1, qpid-java-6.1.7, qpid-java-broker-7.1.0, qpid-java-broker-7.0.4, qpid-java-broker-7.0.5, qpid-java-broker-7.0.6
• Fix Version/s: qpid-java-broker-7.0.7, qpid-java-broker-7.1.1
• Component/s: Broker-J

Environment

[Broker-Config] (q.m.b.platform) - [Broker] BRK-1010 : Platform : JVM : Oracle Corporation version: 1.8.0_161-b12 OS : Linux version: 3.10.0-514.6.1.el7.x86_64 arch: amd64 cores: 40

• Assignee: Unassigned
• Reporter: Alex Rudyy
• Created: 21/Jan/19 14:38
• Updated: 24/Feb/19 16:27
• Resolved: 24/Feb/19 16:27

Description

Broker containing a BDB HA Virtual Host node (belonging to the cluster consisting of several nodes) can fail to start when BDB HA Virtual Host node times out to join the group. The broker cannot complete activation (transition into an ACTIVE state).

The stack traces like bellow are reported on BDB HA VHN timeout:

ERROR [Broker-Config] (o.a.q.s.m.AbstractConfiguredObject) - Failed to open object with name 'node2'.  Object will be put into ERROR state.
java.lang.RuntimeException: JE replicated environment creation took too long (permitted time 180000ms)
        at org.apache.qpid.server.store.berkeleydb.replication.ReplicatedEnvironmentFacade.createEnvironmentInSeparateThread(ReplicatedEnvironmentFacade.java:1577)
        at org.apache.qpid.server.store.berkeleydb.replication.ReplicatedEnvironmentFacade.createEnvironment(ReplicatedEnvironmentFacade.java:1521)
        at org.apache.qpid.server.store.berkeleydb.replication.ReplicatedEnvironmentFacade.<init>(ReplicatedEnvironmentFacade.java:287)
        at org.apache.qpid.server.store.berkeleydb.replication.ReplicatedEnvironmentFacadeFactory.createEnvironmentFacade(ReplicatedEnvironmentFacadeFactory.java:130)
        at org.apache.qpid.server.store.berkeleydb.BDBConfigurationStore.init(BDBConfigurationStore.java:122)
        at org.apache.qpid.server.virtualhostnode.berkeleydb.BDBHAVirtualHostNodeImpl.activate(BDBHAVirtualHostNodeImpl.java:338)
        at org.apache.qpid.server.virtualhostnode.AbstractVirtualHostNode.doActivate(AbstractVirtualHostNode.java:162)
        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:498)
        at org.apache.qpid.server.model.AbstractConfiguredObject.attainState(AbstractConfiguredObject.java:1524)
        at org.apache.qpid.server.model.AbstractConfiguredObject.attainState(AbstractConfiguredObject.java:1503)
        at org.apache.qpid.server.model.AbstractConfiguredObject$8.onSuccess(AbstractConfiguredObject.java:1070)
        at org.apache.qpid.server.model.AbstractConfiguredObject$8.onSuccess(AbstractConfiguredObject.java:1064)
        at org.apache.qpid.server.model.AbstractConfiguredObject$22$1.run(AbstractConfiguredObject.java:2639)
        at org.apache.qpid.server.model.AbstractConfiguredObject$22$1.run(AbstractConfiguredObject.java:2635)
        at java.security.AccessController.doPrivileged(Native Method)
        at javax.security.auth.Subject.doAs(Subject.java:360)
        at org.apache.qpid.server.model.AbstractConfiguredObject$22.onSuccess(AbstractConfiguredObject.java:2634)
        at com.google.common.util.concurrent.Futures$CallbackListener.run(Futures.java:1237)
        at org.apache.qpid.server.configuration.updater.TaskExecutorImpl$ImmediateIfSameThreadExecutor.execute(TaskExecutorImpl.java:400)
        at org.apache.qpid.server.configuration.updater.TaskExecutorImpl.execute(TaskExecutorImpl.java:183)
        at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:911)
        at com.google.common.util.concurrent.AbstractFuture.addListener(AbstractFuture.java:645)
        at com.google.common.util.concurrent.AbstractFuture$TrustedFuture.addListener(AbstractFuture.java:101)
        at com.google.common.util.concurrent.Futures.addCallback(Futures.java:1209)
        at org.apache.qpid.server.model.AbstractConfiguredObject.addFutureCallback(AbstractConfiguredObject.java:2629)
        at org.apache.qpid.server.model.AbstractConfiguredObject.doAttainState(AbstractConfiguredObject.java:1063)
        at org.apache.qpid.server.model.AbstractConfiguredObject.access$600(AbstractConfiguredObject.java:95)
        at org.apache.qpid.server.model.AbstractConfiguredObject$7.performAction(AbstractConfiguredObject.java:1048)
        at org.apache.qpid.server.model.AbstractConfiguredObject$7.performAction(AbstractConfiguredObject.java:1038)
        at org.apache.qpid.server.model.AbstractConfiguredObject.applyToChildren(AbstractConfiguredObject.java:1311)
        at org.apache.qpid.server.model.AbstractConfiguredObject.doAttainState(AbstractConfiguredObject.java:1037)
        at org.apache.qpid.server.model.AbstractConfiguredObject.access$600(AbstractConfiguredObject.java:95)
        at org.apache.qpid.server.model.AbstractConfiguredObject$1.execute(AbstractConfiguredObject.java:589)
        at org.apache.qpid.server.model.AbstractConfiguredObject$1.execute(AbstractConfiguredObject.java:576)
        at org.apache.qpid.server.model.AbstractConfiguredObject$2.execute(AbstractConfiguredObject.java:637)
        at org.apache.qpid.server.model.AbstractConfiguredObject$2.execute(AbstractConfiguredObject.java:630)
        at org.apache.qpid.server.configuration.updater.TaskExecutorImpl$TaskLoggingWrapper.execute(TaskExecutorImpl.java:248)
        at org.apache.qpid.server.configuration.updater.TaskExecutorImpl.submitWrappedTask(TaskExecutorImpl.java:165)
        at org.apache.qpid.server.configuration.updater.TaskExecutorImpl.submit(TaskExecutorImpl.java:153)
        at org.apache.qpid.server.model.AbstractConfiguredObject.doOnConfigThread(AbstractConfiguredObject.java:629)
        at org.apache.qpid.server.model.AbstractConfiguredObject.openAsync(AbstractConfiguredObject.java:575)
        at org.apache.qpid.server.model.AbstractSystemConfig.makeActive(AbstractSystemConfig.java:304)
        at org.apache.qpid.server.model.AbstractSystemConfig.activate(AbstractSystemConfig.java:280)
        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:498)
        at org.apache.qpid.server.model.AbstractConfiguredObject.attainState(AbstractConfiguredObject.java:1524)
        at org.apache.qpid.server.model.AbstractConfiguredObject.attainState(AbstractConfiguredObject.java:1503)
        at org.apache.qpid.server.model.AbstractConfiguredObject$8.onSuccess(AbstractConfiguredObject.java:1070)
        at org.apache.qpid.server.model.AbstractConfiguredObject$8.onSuccess(AbstractConfiguredObject.java:1064)
        at org.apache.qpid.server.model.AbstractConfiguredObject$22$1.run(AbstractConfiguredObject.java:2639)
        at org.apache.qpid.server.model.AbstractConfiguredObject$22$1.run(AbstractConfiguredObject.java:2635)
        at java.security.AccessController.doPrivileged(Native Method)
        at javax.security.auth.Subject.doAs(Subject.java:360)
        at org.apache.qpid.server.model.AbstractConfiguredObject$22.onSuccess(AbstractConfiguredObject.java:2634)
        at com.google.common.util.concurrent.Futures$CallbackListener.run(Futures.java:1237)
        at org.apache.qpid.server.configuration.updater.TaskExecutorImpl$ImmediateIfSameThreadExecutor.execute(TaskExecutorImpl.java:400)
        at org.apache.qpid.server.configuration.updater.TaskExecutorImpl.execute(TaskExecutorImpl.java:183)
        at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:911)
        at com.google.common.util.concurrent.AbstractFuture.addListener(AbstractFuture.java:645)
        at com.google.common.util.concurrent.AbstractFuture$TrustedFuture.addListener(AbstractFuture.java:101)
        at com.google.common.util.concurrent.Futures.addCallback(Futures.java:1209)
        at org.apache.qpid.server.model.AbstractConfiguredObject.addFutureCallback(AbstractConfiguredObject.java:2629)
        at org.apache.qpid.server.model.AbstractConfiguredObject.doAttainState(AbstractConfiguredObject.java:1063)
        at org.apache.qpid.server.model.AbstractConfiguredObject.access$600(AbstractConfiguredObject.java:95)
        at org.apache.qpid.server.model.AbstractConfiguredObject$1.execute(AbstractConfiguredObject.java:589)
        at org.apache.qpid.server.model.AbstractConfiguredObject$1.execute(AbstractConfiguredObject.java:576)
        at org.apache.qpid.server.model.AbstractConfiguredObject$2.execute(AbstractConfiguredObject.java:637)
        at org.apache.qpid.server.model.AbstractConfiguredObject$2.execute(AbstractConfiguredObject.java:630)
        at org.apache.qpid.server.configuration.updater.TaskExecutorImpl$TaskLoggingWrapper.execute(TaskExecutorImpl.java:248)
        at org.apache.qpid.server.configuration.updater.TaskExecutorImpl$CallableWrapper$1.run(TaskExecutorImpl.java:320)
        at java.security.AccessController.doPrivileged(Native Method)
        at javax.security.auth.Subject.doAs(Subject.java:360)
 at org.apache.qpid.server.configuration.updater.TaskExecutorImpl$CallableWrapper.call(TaskExecutorImpl.java:313)
        at com.google.common.util.concurrent.TrustedListenableFutureTask$TrustedFutureInterruptibleTask.runInterruptibly(TrustedListenableFutureTask.java:111)
        at com.google.common.util.concurrent.InterruptibleTask.run(InterruptibleTask.java:58)
        at com.google.common.util.concurrent.TrustedListenableFutureTask.run(TrustedListenableFutureTask.java:75)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at org.apache.qpid.server.bytebuffer.QpidByteBufferFactory.lambda$null$0(QpidByteBufferFactory.java:464)
        at java.lang.Thread.run(Thread.java:748)

The VHN configuration store is closed

2019-01-14 03:21:29,882 INFO  [Broker-Config] (q.m.c.close) - [Broker] [vh(/group)/ms(BDBConfigurationStore)] CFG-1003 : Closed

The VHN transits into ERRORed state but broker activation does not finish. The broker state does not change and remains to be UNINITIALIZED. As result, some operations on Broker might fail due to underlying objects not being created or broker state not being ACTIVE. For example, user management login can fail with NPE as below:

ERROR [qtp2099124276-161] (o.a.q.s.m.p.f.ExceptionHandlingFilter) - Unexpected exception in servlet '/service/sasl':
java.lang.NullPointerException: null
        at org.apache.qpid.server.model.AbstractContainer.scheduleTask(AbstractContainer.java:490)
        at org.apache.qpid.server.management.plugin.HttpManagementUtil.scheduleAbsoluteSessionTimeout(HttpManagementUtil.java:179)
        at org.apache.qpid.server.management.plugin.HttpManagementUtil.saveAuthorisedSubject(HttpManagementUtil.java:171)
        at org.apache.qpid.server.management.plugin.servlet.rest.SaslServlet.evaluateSaslResponse(SaslServlet.java:254)
        at org.apache.qpid.server.management.plugin.servlet.rest.SaslServlet.doPost(SaslServlet.java:179)
        at org.apache.qpid.server.management.plugin.servlet.rest.AbstractServlet.doPost(AbstractServlet.java:146)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
        at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:841)
        at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1634)
        at org.apache.qpid.server.management.plugin.filter.AuthenticationCheckFilter$1.run(AuthenticationCheckFilter.java:157)
        at org.apache.qpid.server.management.plugin.filter.AuthenticationCheckFilter$1.run(AuthenticationCheckFilter.java:153)
        at java.security.AccessController.doPrivileged(Native Method)
        at javax.security.auth.Subject.doAs(Subject.java:422)
        at org.apache.qpid.server.management.plugin.filter.AuthenticationCheckFilter.doFilterChainAs(AuthenticationCheckFilter.java:152)
        at org.apache.qpid.server.management.plugin.filter.AuthenticationCheckFilter.doFilter(AuthenticationCheckFilter.java:122)
        at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1621)
        at org.apache.qpid.server.management.plugin.filter.LoggingFilter.doFilter(LoggingFilter.java:63)
        at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1621)
        at org.apache.qpid.server.management.plugin.filter.ForbiddingTraceFilter.doFilter(ForbiddingTraceFilter.java:65)
        at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1621)
        at org.eclipse.jetty.servlets.CrossOriginFilter.handle(CrossOriginFilter.java:308)
        at org.eclipse.jetty.servlets.CrossOriginFilter.doFilter(CrossOriginFilter.java:262)
        at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1621)
        at org.apache.qpid.server.management.plugin.filter.ExceptionHandlingFilter.doFilter(ExceptionHandlingFilter.java:59)
        at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1621)
        at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:541)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:188)
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1593)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:188)
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1239)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:168)
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:481)
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1562)
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:166)
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1141)
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
        at org.eclipse.jetty.server.Server.handle(Server.java:564)
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:320)
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:251)
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:279)
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:110)
        at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:258)
        at org.eclipse.jetty.io.ssl.SslConnection$3.succeeded(SslConnection.java:147)
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:110)
        at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:124)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:672)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:590)
        at org.apache.qpid.server.bytebuffer.QpidByteBufferFactory.lambda$null$0(QpidByteBufferFactory.java:464)
        at java.lang.Thread.run(Thread.java:748)

It is unclear why BDB JE node fails to join the group in timely manner, but, the Broker activation should not be affected by BDB JE node failures: the broker should transit either into ACTIVE or ERRORED state (with JVM exit for the latter).

Issue Links

• is duplicated by: QPID-8252 [Broker-J][BDB HA] Start-up of BDB HA Virtual Host Node can hang sporadically