You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@qpid.apache.org by "Keith Wall (JIRA)" <ji...@apache.org> on 2015/07/19 23:07:04 UTC
[jira] [Updated] (QPID-6649) Client initiated connection close can
race with Broker shutdown leading to exception and unclosed socket
[ https://issues.apache.org/jira/browse/QPID-6649?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Keith Wall updated QPID-6649:
-----------------------------
Description:
There is a potential for a race in the Java Broker that is being exposed by the System Tests. The unlucky case is as follows. The client closes the connection by sending ConnectionClose. On receiving this, ServerConnectionDelegate.connectionClose() invokes ServerConnection.setState() which invokes AbstractVirtualHost.deregisterConnectionAsync(). This causes the AVH to 'forget' the connection (removed from AVH#_connections) even though it is not yet closed. Meanwhile, QBTC begins to close the Broker. The Broker closes the AVH which calls closeConnections - but the connection is already for forgotten (_connections#size() == 0) so as far as it is concerned there are no connections to await for, so the VH close concludes and the VHN shutdowns the VH's executor. Then the IO thread gets scheduled, sends the ConnectionCloseOk bytes down the wire and then NBC#shutdown invokes MVPE#close.... which finally invokesServerConnection.setState which calls AbstractVirtualHost.deregisterConnectionAsync, which fails (stack trace below) because the task executor is already closed.
This causes a socket to remain open.
{noformat}
015-07-19 17:57:53,998 ERROR [virtualhost-test-iopool-7] o.a.q.t.u.InternalBrokerHolder Uncaught exception from thread virtualhost-test-iopool-7
java.lang.IllegalStateException: Task executor is not in ACTIVE state
at org.apache.qpid.server.configuration.updater.TaskExecutorImpl.checkState(TaskExecutorImpl.java:310) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
at org.apache.qpid.server.configuration.updater.TaskExecutorImpl.submit(TaskExecutorImpl.java:141) ~[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.model.AbstractConfiguredObject.setDesiredState(AbstractConfiguredObject.java:1315) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
at org.apache.qpid.server.model.AbstractConfiguredObject.deleteAsync(AbstractConfiguredObject.java:1837) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
at org.apache.qpid.server.model.AbstractConfiguredObject.delete(AbstractConfiguredObject.java:1766) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
at org.apache.qpid.server.exchange.AbstractExchange.removeBinding(AbstractExchange.java:666) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:na]
at org.apache.qpid.server.exchange.AbstractExchange.access$000(AbstractExchange.java:80) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:na]
at org.apache.qpid.server.exchange.AbstractExchange$1.stateChanged(AbstractExchange.java:138) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:na]
at org.apache.qpid.server.exchange.AbstractExchange$1.stateChanged(AbstractExchange.java:132) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:na]
at org.apache.qpid.server.binding.BindingImpl.doDelete(BindingImpl.java:208) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_45]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_45]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_45]
at java.lang.reflect.Method.invoke(Method.java:497) ~[na:1.8.0_45]
at org.apache.qpid.server.model.AbstractConfiguredObject.attainState(AbstractConfiguredObject.java:1194) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
at org.apache.qpid.server.model.AbstractConfiguredObject.attainStateIfOpenedOrReopenFailed(AbstractConfiguredObject.java:1162) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
at org.apache.qpid.server.model.AbstractConfiguredObject.access$1500(AbstractConfiguredObject.java:83) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
at org.apache.qpid.server.model.AbstractConfiguredObject$15.call(AbstractConfiguredObject.java:1354) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
at org.apache.qpid.server.model.AbstractConfiguredObject$15.call(AbstractConfiguredObject.java:1316) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
at org.apache.qpid.server.model.AbstractConfiguredObject$2.execute(AbstractConfiguredObject.java:507) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
at org.apache.qpid.server.model.AbstractConfiguredObject$2.execute(AbstractConfiguredObject.java:500) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
at org.apache.qpid.server.configuration.updater.TaskExecutorImpl.executeTask(TaskExecutorImpl.java:317) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
at org.apache.qpid.server.configuration.updater.TaskExecutorImpl.access$700(TaskExecutorImpl.java:48) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
at org.apache.qpid.server.configuration.updater.TaskExecutorImpl$CallableWrapper$1.run(TaskExecutorImpl.java:361) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
at java.security.AccessController.doPrivileged(Native Method) ~[na:1.8.0_45]
at javax.security.auth.Subject.doAs(Subject.java:360) ~[na:1.8.0_45]
at org.apache.qpid.server.configuration.updater.TaskExecutorImpl$CallableWrapper.call(TaskExecutorImpl.java:356) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[na:1.8.0_45]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) ~[na:1.8.0_45]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) ~[na:1.8.0_45]
at java.lang.Thread.run(Thread.java:745) ~[na:1.8.0_45]
{noformat}
was:
There is a potential for a race in the Java Broker that is being exposed by the System Tests. The unlucky case is as follows. The client closes the connection by sending ConnectionClose. On receiving this, ServerConnectionDelegate.connectionClose() invokes ServerConnection.setState() which invokes AbstractVirtualHost.deregisterConnectionAsync(). This causes the AVH to 'forget' the connection (removed from AVH#_connections) even though it is not yet closed. Meanwhile, QBTC begins to close the Broker. The Broker closes the AVH which calls closeConnections - but the connection is already for forgotten (_connections#size() == 0) so as far as it is concerned there are no connections to await for, so the VH close concludes and the VHN shutdowns the VH's executor. Then the IO thread gets scheduled, sends the ConnectionCloseOk bytes down the wire and then NBC#shutdown invokes MVPE#close.... which finally invokesServerConnection.setState which calls AbstractVirtualHost.deregisterConnectionAsync, which fails (stack trace from email earlier today) because the task executor is already closed.
This causes a socket to remain open.
{noformat}
015-07-19 17:57:53,998 ERROR [virtualhost-test-iopool-7] o.a.q.t.u.InternalBrokerHolder Uncaught exception from thread virtualhost-test-iopool-7
java.lang.IllegalStateException: Task executor is not in ACTIVE state
at org.apache.qpid.server.configuration.updater.TaskExecutorImpl.checkState(TaskExecutorImpl.java:310) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
at org.apache.qpid.server.configuration.updater.TaskExecutorImpl.submit(TaskExecutorImpl.java:141) ~[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.model.AbstractConfiguredObject.setDesiredState(AbstractConfiguredObject.java:1315) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
at org.apache.qpid.server.model.AbstractConfiguredObject.deleteAsync(AbstractConfiguredObject.java:1837) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
at org.apache.qpid.server.model.AbstractConfiguredObject.delete(AbstractConfiguredObject.java:1766) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
at org.apache.qpid.server.exchange.AbstractExchange.removeBinding(AbstractExchange.java:666) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:na]
at org.apache.qpid.server.exchange.AbstractExchange.access$000(AbstractExchange.java:80) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:na]
at org.apache.qpid.server.exchange.AbstractExchange$1.stateChanged(AbstractExchange.java:138) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:na]
at org.apache.qpid.server.exchange.AbstractExchange$1.stateChanged(AbstractExchange.java:132) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:na]
at org.apache.qpid.server.binding.BindingImpl.doDelete(BindingImpl.java:208) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_45]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_45]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_45]
at java.lang.reflect.Method.invoke(Method.java:497) ~[na:1.8.0_45]
at org.apache.qpid.server.model.AbstractConfiguredObject.attainState(AbstractConfiguredObject.java:1194) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
at org.apache.qpid.server.model.AbstractConfiguredObject.attainStateIfOpenedOrReopenFailed(AbstractConfiguredObject.java:1162) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
at org.apache.qpid.server.model.AbstractConfiguredObject.access$1500(AbstractConfiguredObject.java:83) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
at org.apache.qpid.server.model.AbstractConfiguredObject$15.call(AbstractConfiguredObject.java:1354) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
at org.apache.qpid.server.model.AbstractConfiguredObject$15.call(AbstractConfiguredObject.java:1316) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
at org.apache.qpid.server.model.AbstractConfiguredObject$2.execute(AbstractConfiguredObject.java:507) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
at org.apache.qpid.server.model.AbstractConfiguredObject$2.execute(AbstractConfiguredObject.java:500) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
at org.apache.qpid.server.configuration.updater.TaskExecutorImpl.executeTask(TaskExecutorImpl.java:317) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
at org.apache.qpid.server.configuration.updater.TaskExecutorImpl.access$700(TaskExecutorImpl.java:48) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
at org.apache.qpid.server.configuration.updater.TaskExecutorImpl$CallableWrapper$1.run(TaskExecutorImpl.java:361) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
at java.security.AccessController.doPrivileged(Native Method) ~[na:1.8.0_45]
at javax.security.auth.Subject.doAs(Subject.java:360) ~[na:1.8.0_45]
at org.apache.qpid.server.configuration.updater.TaskExecutorImpl$CallableWrapper.call(TaskExecutorImpl.java:356) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[na:1.8.0_45]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) ~[na:1.8.0_45]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) ~[na:1.8.0_45]
at java.lang.Thread.run(Thread.java:745) ~[na:1.8.0_45]
{noformat}
> Client initiated connection close can race with Broker shutdown leading to exception and unclosed socket
> --------------------------------------------------------------------------------------------------------
>
> Key: QPID-6649
> URL: https://issues.apache.org/jira/browse/QPID-6649
> Project: Qpid
> Issue Type: Bug
> Components: Java Broker
> Reporter: Keith Wall
> Assignee: Keith Wall
> Fix For: 6.0 [Java]
>
>
> There is a potential for a race in the Java Broker that is being exposed by the System Tests. The unlucky case is as follows. The client closes the connection by sending ConnectionClose. On receiving this, ServerConnectionDelegate.connectionClose() invokes ServerConnection.setState() which invokes AbstractVirtualHost.deregisterConnectionAsync(). This causes the AVH to 'forget' the connection (removed from AVH#_connections) even though it is not yet closed. Meanwhile, QBTC begins to close the Broker. The Broker closes the AVH which calls closeConnections - but the connection is already for forgotten (_connections#size() == 0) so as far as it is concerned there are no connections to await for, so the VH close concludes and the VHN shutdowns the VH's executor. Then the IO thread gets scheduled, sends the ConnectionCloseOk bytes down the wire and then NBC#shutdown invokes MVPE#close.... which finally invokesServerConnection.setState which calls AbstractVirtualHost.deregisterConnectionAsync, which fails (stack trace below) because the task executor is already closed.
> This causes a socket to remain open.
> {noformat}
> 015-07-19 17:57:53,998 ERROR [virtualhost-test-iopool-7] o.a.q.t.u.InternalBrokerHolder Uncaught exception from thread virtualhost-test-iopool-7
> java.lang.IllegalStateException: Task executor is not in ACTIVE state
> at org.apache.qpid.server.configuration.updater.TaskExecutorImpl.checkState(TaskExecutorImpl.java:310) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
> at org.apache.qpid.server.configuration.updater.TaskExecutorImpl.submit(TaskExecutorImpl.java:141) ~[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.model.AbstractConfiguredObject.setDesiredState(AbstractConfiguredObject.java:1315) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
> at org.apache.qpid.server.model.AbstractConfiguredObject.deleteAsync(AbstractConfiguredObject.java:1837) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
> at org.apache.qpid.server.model.AbstractConfiguredObject.delete(AbstractConfiguredObject.java:1766) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
> at org.apache.qpid.server.exchange.AbstractExchange.removeBinding(AbstractExchange.java:666) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:na]
> at org.apache.qpid.server.exchange.AbstractExchange.access$000(AbstractExchange.java:80) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:na]
> at org.apache.qpid.server.exchange.AbstractExchange$1.stateChanged(AbstractExchange.java:138) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:na]
> at org.apache.qpid.server.exchange.AbstractExchange$1.stateChanged(AbstractExchange.java:132) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:na]
> at org.apache.qpid.server.binding.BindingImpl.doDelete(BindingImpl.java:208) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_45]
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_45]
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_45]
> at java.lang.reflect.Method.invoke(Method.java:497) ~[na:1.8.0_45]
> at org.apache.qpid.server.model.AbstractConfiguredObject.attainState(AbstractConfiguredObject.java:1194) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
> at org.apache.qpid.server.model.AbstractConfiguredObject.attainStateIfOpenedOrReopenFailed(AbstractConfiguredObject.java:1162) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
> at org.apache.qpid.server.model.AbstractConfiguredObject.access$1500(AbstractConfiguredObject.java:83) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
> at org.apache.qpid.server.model.AbstractConfiguredObject$15.call(AbstractConfiguredObject.java:1354) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
> at org.apache.qpid.server.model.AbstractConfiguredObject$15.call(AbstractConfiguredObject.java:1316) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
> at org.apache.qpid.server.model.AbstractConfiguredObject$2.execute(AbstractConfiguredObject.java:507) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
> at org.apache.qpid.server.model.AbstractConfiguredObject$2.execute(AbstractConfiguredObject.java:500) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
> at org.apache.qpid.server.configuration.updater.TaskExecutorImpl.executeTask(TaskExecutorImpl.java:317) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
> at org.apache.qpid.server.configuration.updater.TaskExecutorImpl.access$700(TaskExecutorImpl.java:48) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
> at org.apache.qpid.server.configuration.updater.TaskExecutorImpl$CallableWrapper$1.run(TaskExecutorImpl.java:361) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
> at java.security.AccessController.doPrivileged(Native Method) ~[na:1.8.0_45]
> at javax.security.auth.Subject.doAs(Subject.java:360) ~[na:1.8.0_45]
> at org.apache.qpid.server.configuration.updater.TaskExecutorImpl$CallableWrapper.call(TaskExecutorImpl.java:356) ~[qpid-broker-core-6.0.0-SNAPSHOT.jar:6.0.0-SNAPSHOT]
> at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[na:1.8.0_45]
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) ~[na:1.8.0_45]
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) ~[na:1.8.0_45]
> at java.lang.Thread.run(Thread.java:745) ~[na:1.8.0_45]
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@qpid.apache.org
For additional commands, e-mail: dev-help@qpid.apache.org