qpid-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Keith Wall (JIRA)" <j...@apache.org>
Subject [jira] [Updated] (QPID-5856) Closing 0-10 messaging connection from management leads to spurious exception and timeout
Date Fri, 27 Jun 2014 12:21:24 GMT

     [ https://issues.apache.org/jira/browse/QPID-5856?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]

Keith Wall updated QPID-5856:
-----------------------------

    Description: 
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 [apache.qpid.transport.Connection]
SEND: [conn:4bd56a3a] ch=0 ConnectionClose(replyCode=CONNECTION_FORCED, replyText=Connection
closed by external action)
Broker-Configuration-Thread 2014-06-27 13:08:43,462 DEBUG [apache.qpid.transport.Connection]
FLUSH: [conn:4bd56a3a]

IoReceiver - /127.0.0.1:49997 2014-06-27 13:08:43,462 DEBUG [apache.qpid.transport.Connection]
RECV: [conn:4bd56a3a] ch=1 MessageFlow(destination=1, unit=MESSAGE, value=1000)
IoReceiver - /127.0.0.1:49997 2014-06-27 13:08:43,462 DEBUG [apache.qpid.transport.Session]
identify: ch=1, commandId=15

IoReceiver - localhost/127.0.0.1:15672 2014-06-27 13:08:43,462 DEBUG [apache.qpid.transport.Connection]
RECV: [conn:33c38a88] ch=0 ConnectionClose(replyCode=CONNECTION_FORCED, replyText=Connection
closed by external action)
IoReceiver - localhost/127.0.0.1:15672 2014-06-27 13:08:43,462 DEBUG [apache.qpid.transport.Connection]
SEND: [conn:33c38a88] ch=0 ConnectionCloseOk()
IoReceiver - localhost/127.0.0.1:15672 2014-06-27 13:08:43,462 DEBUG [apache.qpid.transport.Connection]
FLUSH: [conn:33c38a88]
IoReceiver - localhost/127.0.0.1:15672 2014-06-27 13:08:43,463 DEBUG [apache.qpid.transport.Connection]
connection closed: conn:33c38a88
IoReceiver - localhost/127.0.0.1:15672 2014-06-27 13:08:43,463 DEBUG [apache.qpid.transport.SessionDelegate]
DETACHED: [ssn:"9b9aee4d-a5ec-4831-b850-91eb6e7458ea"]
IoReceiver - localhost/127.0.0.1:15672 2014-06-27 13:08:43,463 DEBUG [apache.qpid.transport.SessionDelegate]
DETACHED: [ssn:"d8479447-7f98-4a2c-8863-2280c6f9200d"]
IoReceiver - localhost/127.0.0.1:15672 2014-06-27 13:08:43,463 DEBUG [apache.qpid.jms.FailoverPolicy]
All failover methods exhausted

IoReceiver - /127.0.0.1:49997 2014-06-27 13:08:43,463 DEBUG [apache.qpid.transport.Connection]
SEND: [conn:4bd56a3a] ch=1 id=1 ExecutionException(errorCode=NOT_FOUND, commandId=15, description=not-found:
destination '1')
IoReceiver - /127.0.0.1:49997 2014-06-27 13:08:43,463 DEBUG [apache.qpid.transport.Connection]
FLUSH: [conn:4bd56a3a]
IoReceiver - localhost/127.0.0.1:15672 2014-06-27 13:08:43,463 ERROR [apache.qpid.client.AMQConnectionDelegate_0_10]
connection exception: conn:33c38a88
{noformat}

  was:
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 [apache.qpid.transport.Connection]
SEND: [conn:4bd56a3a] ch=0 ConnectionClose(replyCode=CONNECTION_FORCED, replyText=Connection
closed by external action)
Broker-Configuration-Thread 2014-06-27 13:08:43,462 DEBUG [apache.qpid.transport.Connection]
FLUSH: [conn:4bd56a3a]

IoReceiver - /127.0.0.1:49997 2014-06-27 13:08:43,462 DEBUG [apache.qpid.transport.Connection]
RECV: [conn:4bd56a3a] ch=1 MessageFlow(destination=1, unit=MESSAGE, value=1000)
IoReceiver - /127.0.0.1:49997 2014-06-27 13:08:43,462 DEBUG [apache.qpid.transport.Session]
identify: ch=1, commandId=15

IoReceiver - localhost/127.0.0.1:15672 2014-06-27 13:08:43,462 DEBUG [apache.qpid.transport.Connection]
RECV: [conn:33c38a88] ch=0 ConnectionClose(replyCode=CONNECTION_FORCED, replyText=Connection
closed by external action)
IoReceiver - localhost/127.0.0.1:15672 2014-06-27 13:08:43,462 DEBUG [apache.qpid.transport.Connection]
SEND: [conn:33c38a88] ch=0 ConnectionCloseOk()
IoReceiver - localhost/127.0.0.1:15672 2014-06-27 13:08:43,462 DEBUG [apache.qpid.transport.Connection]
FLUSH: [conn:33c38a88]
IoReceiver - localhost/127.0.0.1:15672 2014-06-27 13:08:43,463 DEBUG [apache.qpid.transport.Connection]
connection closed: conn:33c38a88
IoReceiver - localhost/127.0.0.1:15672 2014-06-27 13:08:43,463 DEBUG [apache.qpid.transport.SessionDelegate]
DETACHED: [ssn:"9b9aee4d-a5ec-4831-b850-91eb6e7458ea"]
IoReceiver - localhost/127.0.0.1:15672 2014-06-27 13:08:43,463 DEBUG [apache.qpid.transport.SessionDelegate]
DETACHED: [ssn:"d8479447-7f98-4a2c-8863-2280c6f9200d"]
IoReceiver - localhost/127.0.0.1:15672 2014-06-27 13:08:43,463 DEBUG [apache.qpid.jms.FailoverPolicy]
All failover methods exhausted

IoReceiver - /127.0.0.1:49997 2014-06-27 13:08:43,463 DEBUG [apache.qpid.transport.Connection]
SEND: [conn:4bd56a3a] ch=1 id=1 ExecutionException(errorCode=NOT_FOUND, commandId=15, description=not-found:
destination '1')
IoReceiver - /127.0.0.1:49997 2014-06-27 13:08:43,463 DEBUG [apache.qpid.transport.Connection]
FLUSH: [conn:4bd56a3a]
IoReceiver - localhost/127.0.0.1:15672 2014-06-27 13:08:43,463 ERROR [apache.qpid.client.AMQConnectionDelegate_0_10]
connection exception: conn:33c38a88
{noformat}


> 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
>            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 [apache.qpid.transport.Connection]
SEND: [conn:4bd56a3a] ch=0 ConnectionClose(replyCode=CONNECTION_FORCED, replyText=Connection
closed by external action)
> Broker-Configuration-Thread 2014-06-27 13:08:43,462 DEBUG [apache.qpid.transport.Connection]
FLUSH: [conn:4bd56a3a]
> IoReceiver - /127.0.0.1:49997 2014-06-27 13:08:43,462 DEBUG [apache.qpid.transport.Connection]
RECV: [conn:4bd56a3a] ch=1 MessageFlow(destination=1, unit=MESSAGE, value=1000)
> IoReceiver - /127.0.0.1:49997 2014-06-27 13:08:43,462 DEBUG [apache.qpid.transport.Session]
identify: ch=1, commandId=15
> IoReceiver - localhost/127.0.0.1:15672 2014-06-27 13:08:43,462 DEBUG [apache.qpid.transport.Connection]
RECV: [conn:33c38a88] ch=0 ConnectionClose(replyCode=CONNECTION_FORCED, replyText=Connection
closed by external action)
> IoReceiver - localhost/127.0.0.1:15672 2014-06-27 13:08:43,462 DEBUG [apache.qpid.transport.Connection]
SEND: [conn:33c38a88] ch=0 ConnectionCloseOk()
> IoReceiver - localhost/127.0.0.1:15672 2014-06-27 13:08:43,462 DEBUG [apache.qpid.transport.Connection]
FLUSH: [conn:33c38a88]
> IoReceiver - localhost/127.0.0.1:15672 2014-06-27 13:08:43,463 DEBUG [apache.qpid.transport.Connection]
connection closed: conn:33c38a88
> IoReceiver - localhost/127.0.0.1:15672 2014-06-27 13:08:43,463 DEBUG [apache.qpid.transport.SessionDelegate]
DETACHED: [ssn:"9b9aee4d-a5ec-4831-b850-91eb6e7458ea"]
> IoReceiver - localhost/127.0.0.1:15672 2014-06-27 13:08:43,463 DEBUG [apache.qpid.transport.SessionDelegate]
DETACHED: [ssn:"d8479447-7f98-4a2c-8863-2280c6f9200d"]
> IoReceiver - localhost/127.0.0.1:15672 2014-06-27 13:08:43,463 DEBUG [apache.qpid.jms.FailoverPolicy]
All failover methods exhausted
> IoReceiver - /127.0.0.1:49997 2014-06-27 13:08:43,463 DEBUG [apache.qpid.transport.Connection]
SEND: [conn:4bd56a3a] ch=1 id=1 ExecutionException(errorCode=NOT_FOUND, commandId=15, description=not-found:
destination '1')
> IoReceiver - /127.0.0.1:49997 2014-06-27 13:08:43,463 DEBUG [apache.qpid.transport.Connection]
FLUSH: [conn:4bd56a3a]
> IoReceiver - localhost/127.0.0.1:15672 2014-06-27 13:08:43,463 ERROR [apache.qpid.client.AMQConnectionDelegate_0_10]
connection exception: conn:33c38a88
> {noformat}



--
This message was sent by Atlassian JIRA
(v6.2#6252)

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@qpid.apache.org
For additional commands, e-mail: dev-help@qpid.apache.org


Mime
View raw message