[QPID-8066] [Broker-J] Virtual host logger rules are left over in configuration store after deletion of virtual host logger on provided virtual host causing virtualhost restart failure

• Type: Bug
• Status: Closed
• Priority: Critical
• Resolution: Fixed
• Affects Version/s: 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
• Fix Version/s: qpid-java-broker-7.0.1, qpid-java-broker-7.1.0
• Component/s: Broker-J
• Assignee: Keith Wall
• Reporter: Alex Rudyy
• Created: 14/Dec/17 14:29
• Updated: 02/Oct/19 19:21
• Resolved: 02/Feb/18 09:25

Description

Virtual host logger rules are left over in configuration store after deletion of virtual host logger on provided virtual host. On restart of VHN or Broker, virtual host recovery fails with IllegalArgumentException as the one below:

java.lang.IllegalArgumentException: Recovered configured object record BDBConfiguredObjectRecord [id=8e9c5547-c41b-4443-9333-48dac61f3b40, type=VirtualHostLogInclusionRule, name=test, parents={}] has no recorded parents and is not a valid child type [[interface org.apache.qpid.server.model.VirtualHost, interface org.apache.qpid.server.model.RemoteReplicationNode]] for the root BDBVirtualHostNodeImplWithAccessChecking [id=591aa6d9-c2e0-474c-a0a9-86eb14bc3c6a, name=bdb, storePath=/home/alex/.qpid-7.1.0-SNAPSHOT/bdb/config]
        at org.apache.qpid.server.store.GenericRecoverer.resolveDiscontinuity(GenericRecoverer.java:119)
        at org.apache.qpid.server.store.GenericRecoverer.performRecover(GenericRecoverer.java:90)
        at org.apache.qpid.server.store.GenericRecoverer.access$000(GenericRecoverer.java:41)
        at org.apache.qpid.server.store.GenericRecoverer$1.execute(GenericRecoverer.java:59)
        at org.apache.qpid.server.store.GenericRecoverer$1.execute(GenericRecoverer.java:55)
        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.run(TaskExecutorImpl.java:190)
        at org.apache.qpid.server.store.GenericRecoverer.recover(GenericRecoverer.java:54)
        at org.apache.qpid.server.store.VirtualHostStoreUpgraderAndRecoverer.recover(VirtualHostStoreUpgraderAndRecoverer.java:1085)
        at org.apache.qpid.server.store.VirtualHostStoreUpgraderAndRecoverer.upgradeAndRecover(VirtualHostStoreUpgraderAndRecoverer.java:1058)
        at org.apache.qpid.server.virtualhostnode.AbstractStandardVirtualHostNode.activate(AbstractStandardVirtualHostNode.java:91)
        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:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at org.apache.qpid.server.bytebuffer.QpidByteBufferFactory.lambda$null$0(QpidByteBufferFactory.java:464)
        at java.lang.Thread.run(Thread.java:745)

The rule entry can only be deleted from outside of the Broker which would be difficult to achieve with BDB store. If entry cannot be deleted, the Virtual host node removal can only resolve the issue which means the loss of the configuration and messages. Though, configuration and messages can be exported from impacted VHN and re-imported into re-created VHN.
Alternatively, all VH logging rules need to be deleted before the deletion of VH logger

I would vote for fixing this issue in 7.0.1 and porting the changes into 6.x

Issue Links

• is related to: QPID-7547 [Java Broker] Refactor closing and deletion of AbstractConfiguredObjects
• relates to: QPID-8086 [Broker-J] Create tool to permit recovery from QPID-8066