You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@qpid.apache.org by "Alex Rudyy (JIRA)" <ji...@apache.org> on 2016/06/21 09:45:58 UTC
[jira] [Commented] (QPID-7313) [Java Broker] Connection close REST
request hangs
[ https://issues.apache.org/jira/browse/QPID-7313?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15341457#comment-15341457 ]
Alex Rudyy commented on QPID-7313:
----------------------------------
The debug log indicates that Broker sends the ConnectionClose command to the client but if client does not reply the AbstractAMQPConnection#_modelClosedFuture is not set .
CloseConnectionTicker does not close the connection either.
{noformat}
2016-06-21 10:31:41,687 DEBUG [HttpManagement-HTTP-170] (o.a.q.s.m.p.f.LoggingFilter) - REQUEST user='[admin]' method='DELETE' url='http://localhost:8080/api/latest/connection/AMQP/%255B12%255D%2520127.0.0.1%253A50800'
2016-06-21 10:31:41,687 TRACE [HttpManagement-HTTP-170] (o.a.q.s.c.u.TaskExecutorImpl) - Submitting Task['set desired state' on '/127.0.0.1:50800(admin)' with arguments 'DELETED'] to executor Broker-Config
2016-06-21 10:31:41,688 DEBUG [Broker-Config] (o.a.q.s.c.u.TaskExecutorImpl) - Performing Task['set desired state' on '/127.0.0.1:50800(admin)' with arguments 'DELETED']
2016-06-21 10:31:41,688 INFO [Broker-Config] (q.m.c.model_delete) - <<UNKNOWN>> [con:12(admin@/127.0.0.1:50800/default)] CON-1007 : Connection close initiated by operator
2016-06-21 10:31:41,688 DEBUG [Broker-Config] (o.a.q.s.c.u.TaskExecutorImpl) - Task['set desired state' on '/127.0.0.1:50800(admin)' with arguments 'DELETED'] performed successfully with result: null
2016-06-21 10:31:41,688 DEBUG [IO-/127.0.0.1:50800] (o.a.q.s.p.v.AMQChannel) - Unsubscribing all consumers on channel (true, true, true) [/127.0.0.1:50800(admin):2]
2016-06-21 10:31:41,688 DEBUG [IO-/127.0.0.1:50800] (o.a.q.s.p.v.AMQChannel) - Unsubscribing consumer '1' on channel (true, true, true) [/127.0.0.1:50800(admin):2]
2016-06-21 10:31:41,689 TRACE [IO-/127.0.0.1:50800] (o.a.q.s.c.u.TaskExecutorImpl) - Submitting Task['close' on 'Consumer[id=37ab96e3-9dc2-476d-9065-85e988f3a231, name=1, type=Consumer]'] to executor VirtualHostNode-default-Config
2016-06-21 10:31:41,689 DEBUG [VirtualHostNode-default-Config] (o.a.q.s.c.u.TaskExecutorImpl) - Performing Task['close' on 'Consumer[id=37ab96e3-9dc2-476d-9065-85e988f3a231, name=1, type=Consumer]']
2016-06-21 10:31:41,689 DEBUG [VirtualHostNode-default-Config] (o.a.q.s.m.AbstractConfiguredObject) - Closing QueueConsumerImpl : 1
2016-06-21 10:31:41,689 TRACE [VirtualHostNode-default-Config] (o.a.q.s.c.u.TaskExecutorImpl) - Running runnable com.google.common.util.concurrent.Futures$6@718c2805 through executor interface
2016-06-21 10:31:41,689 TRACE [VirtualHostNode-default-Config] (o.a.q.s.c.u.TaskExecutorImpl) - Running runnable com.google.common.util.concurrent.Futures$6@415db372 through executor interface
2016-06-21 10:31:41,689 DEBUG [VirtualHostNode-default-Config] (o.a.q.s.m.AbstractConfiguredObject) - All children closed QueueConsumerImpl : 1
2016-06-21 10:31:41,689 TRACE [VirtualHostNode-default-Config] (o.a.q.s.c.u.TaskExecutorImpl) - Running runnable com.google.common.util.concurrent.Futures$6@30322e66 through executor interface
2016-06-21 10:31:41,689 TRACE [VirtualHostNode-default-Config] (o.a.q.s.c.u.TaskExecutorImpl) - Running runnable com.google.common.util.concurrent.Futures$6@4cfb134a through executor interface
2016-06-21 10:31:41,689 INFO [VirtualHostNode-default-Config] (q.m.s.close) - [IO Pool] [sub:25(vh(/default)/qu(foo-12)] SUB-1002 : Close
2016-06-21 10:31:41,689 TRACE [VirtualHostNode-default-Config] (o.a.q.s.c.u.TaskExecutorImpl) - Running Task['close' on 'Consumer[id=37ab96e3-9dc2-476d-9065-85e988f3a231, name=1, type=Consumer]'] immediately
2016-06-21 10:31:41,689 DEBUG [VirtualHostNode-default-Config] (o.a.q.s.c.u.TaskExecutorImpl) - Performing Task['close' on 'Consumer[id=37ab96e3-9dc2-476d-9065-85e988f3a231, name=1, type=Consumer]']
2016-06-21 10:31:41,689 DEBUG [VirtualHostNode-default-Config] (o.a.q.s.m.AbstractConfiguredObject) - Closing QueueConsumerImpl : 1
2016-06-21 10:31:41,689 DEBUG [VirtualHostNode-default-Config] (o.a.q.s.m.AbstractConfiguredObject) - Closed QueueConsumerImpl : 1
2016-06-21 10:31:41,689 DEBUG [VirtualHostNode-default-Config] (o.a.q.s.c.u.TaskExecutorImpl) - Task['close' on 'Consumer[id=37ab96e3-9dc2-476d-9065-85e988f3a231, name=1, type=Consumer]'] performed successfully with result: null
2016-06-21 10:31:41,689 DEBUG [VirtualHostNode-default-Config] (o.a.q.s.m.AbstractConfiguredObject) - Closed QueueConsumerImpl : 1
2016-06-21 10:31:41,689 DEBUG [VirtualHostNode-default-Config] (o.a.q.s.c.u.TaskExecutorImpl) - Task['close' on 'Consumer[id=37ab96e3-9dc2-476d-9065-85e988f3a231, name=1, type=Consumer]'] performed successfully with result: null
2016-06-21 10:31:41,689 TRACE [IO-/127.0.0.1:50800] (o.a.q.s.c.u.TaskExecutorImpl) - Submitting Task['set desired state' on 'Session[id=1bfbd2d2-ad6a-43e6-9ab5-60b69ec52e05, name=2, type=Session]' with arguments 'DELETED'] to executor VirtualHostNode-default-Config
2016-06-21 10:31:41,690 DEBUG [VirtualHostNode-default-Config] (o.a.q.s.c.u.TaskExecutorImpl) - Performing Task['set desired state' on 'Session[id=1bfbd2d2-ad6a-43e6-9ab5-60b69ec52e05, name=2, type=Session]' with arguments 'DELETED']
2016-06-21 10:31:41,690 TRACE [VirtualHostNode-default-Config] (o.a.q.s.c.u.TaskExecutorImpl) - Running runnable com.google.common.util.concurrent.Futures$6@5ca7c6d0 through executor interface
2016-06-21 10:31:41,690 DEBUG [VirtualHostNode-default-Config] (o.a.q.s.c.u.TaskExecutorImpl) - Task['set desired state' on 'Session[id=1bfbd2d2-ad6a-43e6-9ab5-60b69ec52e05, name=2, type=Session]' with arguments 'DELETED'] performed successfully with result: null
2016-06-21 10:31:41,690 INFO [IO-/127.0.0.1:50800] (q.m.c.close) - [IO Pool] [con:12(admin@/127.0.0.1:50800/default)/ch:2] CHN-1003 : Close
2016-06-21 10:31:41,690 DEBUG [IO-/127.0.0.1:50800] (o.a.q.s.p.v.AMQPConnection_0_8Impl) - SEND: Frame channelId: 0, bodyFrame: [ConnectionCloseBodyImpl: replyCode=320, replyText=Connection closed by external action, classId=0, methodId=0]
2016-06-21 10:31:41,690 DEBUG [IO-/127.0.0.1:50800] (o.a.q.s.t.NonBlockingConnection) - Read 0 byte(s)
2016-06-21 10:31:41,690 DEBUG [IO-/127.0.0.1:50800] (o.a.q.s.t.NonBlockingConnection) - Written 55 bytes
{noformat}
> [Java Broker] Connection close REST request hangs
> -------------------------------------------------
>
> Key: QPID-7313
> URL: https://issues.apache.org/jira/browse/QPID-7313
> Project: Qpid
> Issue Type: Bug
> Components: Java Broker
> Affects Versions: qpid-java-6.1
> Reporter: Alex Rudyy
>
> Connection delete REST request hangs. The operation blocks forever.
> Jetty HTTP thread is BLOCKED as below:
> {noformat}
> "HttpManagement-HTTP-123" #123 prio=5 os_prio=0 tid=0x00007f98f0002800 nid=0x22d9 waiting on condition [0x00007f9857cf8000]
> java.lang.Thread.State: WAITING (parking)
> at sun.misc.Unsafe.park(Native Method)
> - parking to wait for <0x0000000774d5ae60> (a com.google.common.util.concurrent.AbstractFuture$Sync)
> at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
> at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
> at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:997)
> at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1304)
> at com.google.common.util.concurrent.AbstractFuture$Sync.get(AbstractFuture.java:285)
> at com.google.common.util.concurrent.AbstractFuture.get(AbstractFuture.java:116)
> at org.apache.qpid.server.model.AbstractConfiguredObject.doSync(AbstractConfiguredObject.java:2008)
> at org.apache.qpid.server.model.AbstractConfiguredObject.delete(AbstractConfiguredObject.java:2001)
> at org.apache.qpid.server.management.plugin.servlet.rest.RestServlet.doDeleteWithSubjectAndActor(RestServlet.java:1132)
> at org.apache.qpid.server.management.plugin.servlet.rest.AbstractServlet$4.run(AbstractServlet.java:178)
> at org.apache.qpid.server.management.plugin.servlet.rest.AbstractServlet$4.run(AbstractServlet.java:174)
> at java.security.AccessController.doPrivileged(Native Method)
> at javax.security.auth.Subject.doAs(Subject.java:422)
> at org.apache.qpid.server.management.plugin.servlet.rest.AbstractServlet.doWithSubjectAndActor(AbstractServlet.java:214)
> at org.apache.qpid.server.management.plugin.servlet.rest.AbstractServlet.doDelete(AbstractServlet.java:172)
> at javax.servlet.http.HttpServlet.service(HttpServlet.java:601)
> at org.apache.qpid.server.management.plugin.servlet.rest.RestServlet.service(RestServlet.java:541)
> at javax.servlet.http.HttpServlet.service(HttpServlet.java:668)
> at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:684)
> at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1496)
> at org.apache.qpid.server.management.plugin.filter.ForbiddingAuthorisationFilter.doFilter(ForbiddingAuthorisationFilter.java:90)
> at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1467)
> at org.apache.qpid.server.management.plugin.filter.ForbiddingTraceFilter.doFilter(ForbiddingTraceFilter.java:65)
> at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1467)
> at org.apache.qpid.server.management.plugin.filter.LoggingFilter.doFilter(LoggingFilter.java:70)
> at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1467)
> at org.apache.qpid.server.management.plugin.filter.ExceptionHandlingFilter.doFilter(ExceptionHandlingFilter.java:56)
> at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1467)
> at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:501)
> at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:229)
> at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1086)
> at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:429)
> at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:193)
> at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1020)
> at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135)
> at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116)
> at org.eclipse.jetty.server.Server.handle(Server.java:370)
> at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:494)
> at org.eclipse.jetty.server.AbstractHttpConnection.headerComplete(AbstractHttpConnection.java:971)
> at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.headerComplete(AbstractHttpConnection.java:1033)
> at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:644)
> at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:235)
> at org.eclipse.jetty.server.AsyncHttpConnection.handle(AsyncHttpConnection.java:82)
> at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:696)
> at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:53)
> at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)
> at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)
> at java.lang.Thread.run(Thread.java:745)
> {noformat}
> The operation log about connection close by operator is issued into broker log:
> {noformat}
> 2016-06-21 09:57:02,008 INFO [Broker-Config] (q.m.c.model_delete) - <<UNKNOWN>> [con:2(admin@/127.0.0.1:50780/default)] CON-1007 : Connection close initiated by operator
> 2016-06-21 09:57:02,012 INFO [VirtualHostNode-default-Config] (q.m.s.close) - [IO Pool] [sub:5(vh(/default)/qu(foo-2)] SUB-1002 : Close
> 2016-06-21 09:57:02,013 INFO [IO-/127.0.0.1:50780] (q.m.c.close) - [IO Pool] [con:2(admin@/127.0.0.1:50780/default)/ch:2] CHN-1003 : Close
> {noformat}
> The connection is reported as being in active state via REST interface:
> {code:javascript}
> {
> "id": "0a9509cb-dc34-4b2e-9991-33ffab41e433",
> "name": "[2] 127.0.0.1:50780",
> "type": "Connection",
> "desiredState": "ACTIVE",
> "state": "ACTIVE",
> "durable": false,
> "lifetimePolicy": "PERMANENT",
> "addressSpace": "default",
> "clientId": "clientid",
> "clientProduct": "qpid",
> "clientVersion": "6.1.0-SNAPSHOT",
> "incoming": true,
> "lastOpenedTime": 1466499376456,
> "port": "AMQP",
> "principal": "admin",
> "protocol": "AMQP_0_9",
> "remoteAddress": "/127.0.0.1:50780",
> "remoteProcessPid": "9081",
> "sessionCountLimit": 256,
> "transport": "TCP",
> "transportInfo": "",
> "lastUpdatedTime": 1466499376454,
> "createdTime": 1466499376454,
> "statistics": {
> "bytesIn": 0,
> "bytesOut": 0,
> "lastIoTime": 1466499422013,
> "messagesIn": 0,
> "messagesOut": 1,
> "sessionCount": 0
> }
> }
> {code}
--
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