[QPID-7313] [Java Broker] Connection close REST request can hang when client application does not reply with ConnectionCloseOk to broker ConnectionClose command

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Affects Version/s: qpid-java-6.0, qpid-java-6.0.1, qpid-java-6.0.2, qpid-java-6.0.3, qpid-java-6.1
• Fix Version/s: qpid-java-6.0.4, qpid-java-6.1
• Component/s: Broker-J
• Assignee: Keith Wall
• Reporter: Alex Rudyy
• Created: 21/Jun/16 09:22
• Updated: 01/Jul/16 14:47
• Resolved: 22/Jun/16 14:44

Description

Connection delete REST request hangs. The operation blocks forever.
Jetty HTTP thread is BLOCKED as below:

"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)

The operation log about connection close by operator is issued into broker log:

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

The connection is reported as being in active state via REST interface:

{
    "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
    }
}