Uploaded image for project: 'Qpid'
  1. Qpid
  2. QPID-8274

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

    XMLWordPrintableJSON

    Details

    • 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
    • Component/s: Broker-J
    • Labels:
      None
    • Environment:

      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).

        Attachments

        1. thread-dump.txt
          151 kB
          Alex Rudyy

          Issue Links

            Activity

              People

              • Assignee:
                Unassigned
                Reporter:
                orudyy Alex Rudyy
              • Votes:
                0 Vote for this issue
                Watchers:
                1 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: