[
https://issues.apache.org/jira/browse/QPID-6671?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14659910#comment-14659910
]
Keith Wall edited comment on QPID-6671 at 8/6/15 2:23 PM:
----------------------------------------------------------
There are at least two issues here.
Firstly, AbstractVirtualHostNode#getVirtualHost has a check then act
anti-pattern. The virtual host can be unregistered (by the task executor) from
the parent whilst the getVirtualHost is in flight (by the
virtualhost-io-thread). However, the first issue should not be able to
manifest as the VHN should not unregister the VH child *until* the VH's
connections are closed. Connection close does not complete until its
_modelClosedFuture completes (which completes once the _transportClosedFuture
completes). This is not happening.
{noformat}
2015-07-29 19:01:53,332 DEBUG [Broker-Config]
o.a.q.s.m.AbstractConfiguredObject Closing MemoryVirtualHostNode : test
2015-07-29 19:01:53,332 DEBUG [VirtualHostNode-test-Config]
o.a.q.s.m.AbstractConfiguredObject Closing ProvidedStoreVirtualHostImpl : test
## IO-/127.0.0.1:42956 calls AbstractVirtualHost.deregisterConnection (adds
job to the vh executor)
## IO-/127.0.0.1:42956 completes _transportClosedFuture
2015-07-29 19:01:53,332 INFO [IO-/127.0.0.1:42956] q.m.c.close
[con:603(guest@/127.0.0.1:42956/test)] CON-1002 : Close
2015-07-29 19:01:53,333 DEBUG [Broker-Config]
o.a.q.s.m.AbstractConfiguredObject Closing AMQPConnection_0_8 : [603]
127.0.0.1:42956
2015-07-29 19:01:53,333 DEBUG [Broker-Config]
o.a.q.s.m.AbstractConfiguredObject All children closed AMQPConnection_0_8 :
[603] 127.0.0.1:42956
2015-07-29 19:01:53,333 DEBUG [Broker-Config]
o.a.q.s.m.AbstractConfiguredObject Closed AMQPConnection_0_8 : [603]
127.0.0.1:42956
### How can I be observing a VHN in the process of the VH child being removed???
2015-07-29 19:01:53,334 ERROR [virtualhost-test-iopool-1]
o.a.q.t.u.InternalBrokerHolder Uncaught exception from thread
virtualhost-test-iopool-1
2015-07-29 19:01:53,335 INFO [VirtualHostNode-test-Config]
q.m.v.closed [IO Pool] VHT-1002 : Closed : test
2015-07-29 19:01:53,335 DEBUG [VirtualHostNode-test-Config]
o.a.q.s.m.AbstractConfiguredObject Closed ProvidedStoreVirtualHostImpl : test
2015-07-29 19:01:53,335 DEBUG [VirtualHostNode-test-Config]
o.a.q.s.m.AbstractConfiguredObject All children closed MemoryVirtualHostNode :
test
{noformat}
I cannot explain how the virtualhost-io-thread can encounter this exception as
it should be scheduling the task on the executor *before* completing the
future. The ordering the log statements is also surprising, specifically the
appearance of the CON-1001 before the Exception.
was (Author: k-wall):
There are at least two issues here.
Firstly, AbstractVirtualHostNode#getVirtualHost has a check then act
anti-pattern. The virtual host can be unregistered (by the task executor) from
the parent whilst the getVirtualHost is in flight (by the
virtualhost-io-thread). However, the first issue should not be able to
manifest as the VHN should not unregister the VH child *until* the VH's
connections are closed. Connection close does not complete until its
_modelClosedFuture completes (which completes once the _transportClosedFuture
completes). This is not happening.
{noformat}
2015-07-29 19:01:53,332 DEBUG [Broker-Config]
o.a.q.s.m.AbstractConfiguredObject Closing MemoryVirtualHostNode : test
2015-07-29 19:01:53,332 DEBUG [VirtualHostNode-test-Config]
o.a.q.s.m.AbstractConfiguredObject Closing ProvidedStoreVirtualHostImpl : test
## IO-/127.0.0.1:42956 calls AbstractVirtualHost.deregisterConnection (adds
job to the vh executor)
## IO-/127.0.0.1:42956 completes _transportClosedFuture
2015-07-29 19:01:53,332 INFO [IO-/127.0.0.1:42956] q.m.c.close
[con:603(guest@/127.0.0.1:42956/test)] CON-1002 : Close
2015-07-29 19:01:53,333 DEBUG [Broker-Config]
o.a.q.s.m.AbstractConfiguredObject Closing AMQPConnection_0_8 : [603]
127.0.0.1:42956
2015-07-29 19:01:53,333 DEBUG [Broker-Config]
o.a.q.s.m.AbstractConfiguredObject All children closed AMQPConnection_0_8 :
[603] 127.0.0.1:42956
2015-07-29 19:01:53,333 DEBUG [Broker-Config]
o.a.q.s.m.AbstractConfiguredObject Closed AMQPConnection_0_8 : [603]
127.0.0.1:42956
### How can I be observing a VHN in the process of the VH child being removed???
2015-07-29 19:01:53,334 ERROR [virtualhost-test-iopool-1]
o.a.q.t.u.InternalBrokerHolder Uncaught exception from thread
virtualhost-test-iopool-1
2015-07-29 19:01:53,335 INFO [VirtualHostNode-test-Config]
q.m.v.closed [IO Pool] VHT-1002 : Closed : test
2015-07-29 19:01:53,335 DEBUG [VirtualHostNode-test-Config]
o.a.q.s.m.AbstractConfiguredObject Closed ProvidedStoreVirtualHostImpl : test
2015-07-29 19:01:53,335 DEBUG [VirtualHostNode-test-Config]
o.a.q.s.m.AbstractConfiguredObject All children closed MemoryVirtualHostNode :
test
{noformat}
> java.util.NoSuchElementException whilst trying to deregister a connection
> mbean
> -------------------------------------------------------------------------------
>
> Key: QPID-6671
> URL: https://issues.apache.org/jira/browse/QPID-6671
> Project: Qpid
> Issue Type: Bug
> Components: Java Broker
> Reporter: Keith Wall
> Fix For: qpid-java-6.0
>
> Attachments:
> TEST-org.apache.qpid.test.unit.ack.RecoverTest.testOrderingWithSyncConsumer.txt
>
>
> The Broker failed during shutdown of test
> RecoverTest#testOrderingWithSyncConsumer. It appears that the deregistration
> was show how attempted after the virtual host was unregistered from its
> parent. This should not be possible: the virtual host should await its
> associated connections closing *before* allowing itself to close, therefore
> the VH should not yet be deregistered from the VHN.
> {noformat}
> 2015-07-29 19:01:53,334 ERROR [virtualhost-test-iopool-1]
> o.a.q.t.u.InternalBrokerHolder Uncaught exception from thread
> virtualhost-test-iopool-1
> java.util.NoSuchElementException: null
> at
> java.util.concurrent.CopyOnWriteArrayList$COWIterator.next(CopyOnWriteArrayList.java:1015)
> ~[na:1.7.0_67]
> at
> java.util.Collections$UnmodifiableCollection$1.next(Collections.java:1067)
> ~[na:1.7.0_67]
> at
> org.apache.qpid.server.virtualhostnode.AbstractVirtualHostNode.getVirtualHost(AbstractVirtualHostNode.java:217)
> ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
> at
> org.apache.qpid.server.virtualhostnode.AbstractVirtualHostNode$1.getPrincipal(AbstractVirtualHostNode.java:114)
> ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
> at
> org.apache.qpid.server.configuration.updater.TaskExecutorImpl.getContextSubject(TaskExecutorImpl.java:327)
> ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
> at
> org.apache.qpid.server.configuration.updater.TaskExecutorImpl.access$500(TaskExecutorImpl.java:48)
> ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
> at
> org.apache.qpid.server.configuration.updater.TaskExecutorImpl$CallableWrapper.<init>(TaskExecutorImpl.java:350)
> ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
> at
> org.apache.qpid.server.configuration.updater.TaskExecutorImpl.submit(TaskExecutorImpl.java:151)
> ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
> at
> org.apache.qpid.server.model.AbstractConfiguredObject.doOnConfigThread(AbstractConfiguredObject.java:499)
> ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
> at
> org.apache.qpid.server.virtualhost.AbstractVirtualHost.deregisterConnectionAsync(AbstractVirtualHost.java:1802)
> ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
> at
> org.apache.qpid.server.virtualhost.AbstractVirtualHost.deregisterConnection(AbstractVirtualHost.java:1797)
> ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
> at
> org.apache.qpid.server.protocol.v0_8.AMQPConnection_0_8.closed(AMQPConnection_0_8.java:849)
> ~[qpid-broker-plugins-amqp-0-8-protocol-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
> at
> org.apache.qpid.server.transport.MultiVersionProtocolEngine.closed(MultiVersionProtocolEngine.java:108)
> ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
> at
> org.apache.qpid.server.transport.NonBlockingConnection.shutdown(NonBlockingConnection.java:268)
> ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
> at
> org.apache.qpid.server.transport.NonBlockingConnection.doWork(NonBlockingConnection.java:255)
> ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
> at
> org.apache.qpid.server.transport.NetworkConnectionScheduler.processConnection(NetworkConnectionScheduler.java:119)
> ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
> at
> org.apache.qpid.server.transport.NetworkConnectionScheduler.access$000(NetworkConnectionScheduler.java:37)
> ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
> at
> org.apache.qpid.server.transport.NetworkConnectionScheduler$2.run(NetworkConnectionScheduler.java:100)
> ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> ~[na:1.7.0_67]
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> ~[na:1.7.0_67]
> at java.lang.Thread.run(Thread.java:745) ~[na:1.7.0_67]
> 2015-07-29 19:01:53,334 DEBUG [VirtualHostNode-test-Config]
> o.a.q.s.c.u.TaskExecutorImpl Submitting task: org.apache.qpid.se
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
