[jira] [Commented] (QPID-5856) Closing 0-10 messaging connection from management leads to spurious exception and timeout
[
https://issues.apache.org/jira/browse/QPID-5856?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanelfocusedCommentId=14358911#comment-14358911
]
Keith Wall commented on QPID-5856:
--
Fixed by IO refactoring of QPID-6262.
Closing 0-10 messaging connection from management leads to spurious exception
and timeout
-
Key: QPID-5856
URL: https://issues.apache.org/jira/browse/QPID-5856
Project: Qpid
Issue Type: Bug
Components: Java Broker
Affects Versions: 0.22, 0.24, 0.26, 0.28, 0.29
Reporter: Keith Wall
If I close a messaging connection from the REST interface whist the
connection is busy, the thread causing the management action hangs for 30
seconds, then I see exception.
{noformat}
qtp1676624311-30 2014-06-27 13:10:43,468 WARN
[plugin.servlet.rest.RestServlet] Caught exception
org.apache.qpid.transport.ConnectionException: close() timed out
at org.apache.qpid.transport.Connection.close(Connection.java:657)
at org.apache.qpid.transport.Connection.close(Connection.java:630)
at
org.apache.qpid.server.protocol.v0_10.ServerConnection.close(ServerConnection.java:356)
at
org.apache.qpid.server.model.adapter.ConnectionAdapter.doDelete(ConnectionAdapter.java:153)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at
org.apache.qpid.server.model.AbstractConfiguredObject.attainState(AbstractConfiguredObject.java:648)
at
org.apache.qpid.server.model.AbstractConfiguredObject.attainStateIfResolved(AbstractConfiguredObject.java:628)
at sun.reflect.GeneratedMethodAccessor1.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at
org.apache.qpid.server.model.AbstractConfiguredObject.automatedSetValue(AbstractConfiguredObject.java:379)
at
org.apache.qpid.server.model.AbstractConfiguredObject.changeAttribute(AbstractConfiguredObject.java:956)
at
org.apache.qpid.server.model.AbstractConfiguredObject.changeAttributes(AbstractConfiguredObject.java:1239)
at
org.apache.qpid.server.model.AbstractConfiguredObject$11.execute(AbstractConfiguredObject.java:1218)
at
org.apache.qpid.server.configuration.updater.TaskExecutorImpl$2.execute(TaskExecutorImpl.java:148)
at
org.apache.qpid.server.configuration.updater.TaskExecutorImpl$2.execute(TaskExecutorImpl.java:144)
at
org.apache.qpid.server.configuration.updater.TaskExecutorImpl.executeTask(TaskExecutorImpl.java:298)
at
org.apache.qpid.server.configuration.updater.TaskExecutorImpl.submit(TaskExecutorImpl.java:130)
at
org.apache.qpid.server.configuration.updater.TaskExecutorImpl.run(TaskExecutorImpl.java:250)
at
org.apache.qpid.server.configuration.updater.TaskExecutorImpl.run(TaskExecutorImpl.java:143)
at
org.apache.qpid.server.model.AbstractConfiguredObject.runTask(AbstractConfiguredObject.java:1195)
at
org.apache.qpid.server.model.AbstractConfiguredObject.setAttributes(AbstractConfiguredObject.java:1212)
at
org.apache.qpid.server.model.AbstractConfiguredObject$7.execute(AbstractConfiguredObject.java:750)
at
org.apache.qpid.server.model.AbstractConfiguredObject$7.execute(AbstractConfiguredObject.java:735)
at
org.apache.qpid.server.configuration.updater.TaskExecutorImpl.executeTask(TaskExecutorImpl.java:298)
at
org.apache.qpid.server.configuration.updater.TaskExecutorImpl.access$400(TaskExecutorImpl.java:43)
at
org.apache.qpid.server.configuration.updater.TaskExecutorImpl$CallableWrapper$1.run(TaskExecutorImpl.java:326)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAs(Subject.java:356)
at
org.apache.qpid.server.configuration.updater.TaskExecutorImpl$CallableWrapper.call(TaskExecutorImpl.java:321)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
{noformat}
It appears that the Broker continues to try to emit frame after it has sent
ConnectionClose and then timing out awaiting the ConnectionCloseOk. The
client is receiving the ConnectionClose, and emitting the ConnectionCloseOk
before closing the connection.
{noformat}
Broker-Configuration-Thread 2014-06-27 13:08:43,462 DEBUG
[jira] [Commented] (QPID-5856) Closing 0-10 messaging connection from management leads to spurious exception and timeout
[
https://issues.apache.org/jira/browse/QPID-5856?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanelfocusedCommentId=14045949#comment-14045949
]
Keith Wall commented on QPID-5856:
--
Demonstrated that the same issue exists at least as far back as 0.22 when
connection close is invoked through the JMX interface. From a user
perspective, the messaging connection is still closed properly, it is just that
the JMX thread suffers the exception.
Closing 0-10 messaging connection from management leads to spurious exception
and timeout
-
Key: QPID-5856
URL: https://issues.apache.org/jira/browse/QPID-5856
Project: Qpid
Issue Type: Bug
Components: Java Broker
Affects Versions: 0.22, 0.24, 0.26, 0.28, 0.29
Reporter: Keith Wall
If I close a messaging connection from the REST interface whist the
connection is busy, the thread causing the management action hangs for 30
seconds, then I see exception.
{noformat}
qtp1676624311-30 2014-06-27 13:10:43,468 WARN
[plugin.servlet.rest.RestServlet] Caught exception
org.apache.qpid.transport.ConnectionException: close() timed out
at org.apache.qpid.transport.Connection.close(Connection.java:657)
at org.apache.qpid.transport.Connection.close(Connection.java:630)
at
org.apache.qpid.server.protocol.v0_10.ServerConnection.close(ServerConnection.java:356)
at
org.apache.qpid.server.model.adapter.ConnectionAdapter.doDelete(ConnectionAdapter.java:153)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at
org.apache.qpid.server.model.AbstractConfiguredObject.attainState(AbstractConfiguredObject.java:648)
at
org.apache.qpid.server.model.AbstractConfiguredObject.attainStateIfResolved(AbstractConfiguredObject.java:628)
at sun.reflect.GeneratedMethodAccessor1.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at
org.apache.qpid.server.model.AbstractConfiguredObject.automatedSetValue(AbstractConfiguredObject.java:379)
at
org.apache.qpid.server.model.AbstractConfiguredObject.changeAttribute(AbstractConfiguredObject.java:956)
at
org.apache.qpid.server.model.AbstractConfiguredObject.changeAttributes(AbstractConfiguredObject.java:1239)
at
org.apache.qpid.server.model.AbstractConfiguredObject$11.execute(AbstractConfiguredObject.java:1218)
at
org.apache.qpid.server.configuration.updater.TaskExecutorImpl$2.execute(TaskExecutorImpl.java:148)
at
org.apache.qpid.server.configuration.updater.TaskExecutorImpl$2.execute(TaskExecutorImpl.java:144)
at
org.apache.qpid.server.configuration.updater.TaskExecutorImpl.executeTask(TaskExecutorImpl.java:298)
at
org.apache.qpid.server.configuration.updater.TaskExecutorImpl.submit(TaskExecutorImpl.java:130)
at
org.apache.qpid.server.configuration.updater.TaskExecutorImpl.run(TaskExecutorImpl.java:250)
at
org.apache.qpid.server.configuration.updater.TaskExecutorImpl.run(TaskExecutorImpl.java:143)
at
org.apache.qpid.server.model.AbstractConfiguredObject.runTask(AbstractConfiguredObject.java:1195)
at
org.apache.qpid.server.model.AbstractConfiguredObject.setAttributes(AbstractConfiguredObject.java:1212)
at
org.apache.qpid.server.model.AbstractConfiguredObject$7.execute(AbstractConfiguredObject.java:750)
at
org.apache.qpid.server.model.AbstractConfiguredObject$7.execute(AbstractConfiguredObject.java:735)
at
org.apache.qpid.server.configuration.updater.TaskExecutorImpl.executeTask(TaskExecutorImpl.java:298)
at
org.apache.qpid.server.configuration.updater.TaskExecutorImpl.access$400(TaskExecutorImpl.java:43)
at
org.apache.qpid.server.configuration.updater.TaskExecutorImpl$CallableWrapper$1.run(TaskExecutorImpl.java:326)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAs(Subject.java:356)
at
org.apache.qpid.server.configuration.updater.TaskExecutorImpl$CallableWrapper.call(TaskExecutorImpl.java:321)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
{noformat}
It appears that the Broker continues to try to emit frame after it has sent
ConnectionClose and then timing out awaiting the
