[
https://issues.apache.org/jira/browse/QPID-8477?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17214339#comment-17214339
]
ASF GitHub Bot commented on QPID-8477:
--------------------------------------
alex-rufous commented on a change in pull request #64:
URL: https://github.com/apache/qpid-broker-j/pull/64#discussion_r505093207
##########
File path:
broker-plugins/amqp-1-0-protocol/src/main/java/org/apache/qpid/server/protocol/v1_0/AMQPConnection_1_0Impl.java
##########
@@ -1197,6 +1197,9 @@ private void closeConnection(final Error error)
default:
throw new ServerScopedRuntimeException("Unknown state: " +
_connectionState);
}
+
+ getSender().close();
Review comment:
Closing the network connection at line 1201 looks wrong to me. If
connection state is OPEN, the counterpart should get a chance to respond with a
CLOSE perforrmative after sending CLOSE by broker. I would argue that more
correct fix for the issue would be to close the network connection only when
state is AWAIT_OPEN as illustrated below
`
---
a/broker-plugins/amqp-1-0-protocol/src/main/java/org/apache/qpid/server/protocol/v1_0/AMQPConnection_1_0Impl.java
+++
b/broker-plugins/amqp-1-0-protocol/src/main/java/org/apache/qpid/server/protocol/v1_0/AMQPConnection_1_0Impl.java
@@ -1179,6 +1179,7 @@ public class AMQPConnection_1_0Impl extends
AbstractAMQPConnection<AMQPConnectio
sendOpen(0, 0);
sendClose(close);
_connectionState = ConnectionState.CLOSED;
+ getSender().close();
break;
case OPENED:
sendClose(close);
`
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
[email protected]
> Broker is not closing connections denied with ACL-1002 (this can lead to
> connection_limit being bypassed)
> ---------------------------------------------------------------------------------------------------------
>
> Key: QPID-8477
> URL: https://issues.apache.org/jira/browse/QPID-8477
> Project: Qpid
> Issue Type: Bug
> Components: Broker-J
> Affects Versions: qpid-java-broker-8.0.1
> Reporter: Daniil Kirilyuk
> Priority: Minor
>
> When a connection is denied with ACL-1002 the broker sends Amqp Close message
> ([http://docs.oasis-open.org/amqp/core/v1.0/os/amqp-core-complete-v1.0-os.pdf]
> - the message described in 2.7.9) but does not close the connection *and*
> keeps sending keep-alives on this connection *and* does not count the
> connection to the connection limit for the user/vhost anymore -> this can
> lead to a misbehaving client bypassing its' connection limit.
> Issue is easy to reproduce:
> 1) Set connection_limit for the vhost/user to 1
> 2) Create two connections to the broker and do not close those connections
> on the client side. Observe the number of connections on the broker.
> 3) Create one more connection for the same vhost/user. Do not close the
> connections on the client side and observe the number of connections on the
> broker.
> {noformat}
> # edit broker ACL and set connection_limit to 1 for your test user and reset
> the broker or reload ACL
> pip install python-qpid-proton==0.31.0 requests==2.24.0
> cat <<EOF > connect.py
> #!/usr/bin/env python3
> import sys
> import proton
> from proton.utils import BlockingConnection
> import time
> try:
> c = BlockingConnection(sys.argv[1], timeout=10)
> except (proton.ConnectionException, proton.Timeout):
> pass# we are not well behaving client -> broker must handle this
> while True:
> time.sleep(60)
> EOF
> chmod u+x connect.py
> ./connect.py amqp://your_user:password@your_broker_host:port &
> ./connect.py amqp://your_user:password@your_broker_host:port &
> ./connect.py amqp://your_user:password@your_broker_host:port
> # observe the number of connections is higher than what is allowed
> # for the user as per connection_limit ACL, you can also use netstat
> # or lsof to observe that the connections have not been closed, you can put
> # 'socat' in between the client and the broker to observe the network traffic
> # (you could also use socat with a jms client to simulate a misbehaving
> client)
> curl
> http://admin_user:password@your_broker_host:http_administration_port/api/latest/querybroker/VirtualHost?select=connectionCount
> {noformat}
> When using JMS-based clients issue is not reproducible because of
> JMSException thrown by client after failed authentication.
> Log:
> {noformat}
> 2020-10-01 14:24:20,923 DEBUG [IO-/127.0.0.1:38722]
> (o.a.q.s.t.NonBlockingConnection) - Read 8 byte(s)
> 2020-10-01 14:24:20,923 DEBUG [Broker-Config] (o.a.q.s.c.u.TaskExecutorImpl)
> - Performing Task['create' on '/127.0.0.1:38722(?)']
> 2020-10-01 14:24:20,924 INFO [Broker-Config] (q.m.c.open) -
> [con:8(/127.0.0.1:38722)] CON-1001 : Open : Destination :
> amqp(127.0.0.1:20101) : Protocol Version : 1.0
> 2020-10-01 14:24:20,924 DEBUG [Broker-Config] (o.a.q.s.c.u.TaskExecutorImpl)
> - Task['create' on '/127.0.0.1:38722(?)'] performed successfully with result:
> null
> 2020-10-01 14:24:20,925 DEBUG [IO-/127.0.0.1:38722] (o.a.q.s.p.frame) -
> SEND[/127.0.0.1:38722|0] :
> SaslMechanisms{saslServerMechanisms=[SCRAM-SHA-256, PLAIN]}
> 2020-10-01 14:24:20,925 DEBUG [IO-/127.0.0.1:38722]
> (o.a.q.s.p.v.f.FrameHandler) - RECV 0 bytes
> 2020-10-01 14:24:20,925 DEBUG [IO-/127.0.0.1:38722]
> (o.a.q.s.t.NonBlockingConnection) - Written 46 bytes
> 2020-10-01 14:24:20,925 DEBUG [IO-/127.0.0.1:38722]
> (o.a.q.s.t.NonBlockingConnection) - Read 0 byte(s)
> 2020-10-01 14:24:20,925 DEBUG [IO-/127.0.0.1:38722]
> (o.a.q.s.t.NonBlockingConnection) - Read 61 byte(s)
> 2020-10-01 14:24:20,925 DEBUG [IO-/127.0.0.1:38722]
> (o.a.q.s.p.v.f.FrameHandler) - RECV 61 bytes
> 2020-10-01 14:24:20,925 DEBUG [IO-/127.0.0.1:38722] (o.a.q.s.p.frame) -
> RECV[/127.0.0.1:38722|0] :
> SaslInit{mechanism=PLAIN,initialResponse=ENTITLEMENT\x00ENTITLEMENT\x0012345678}
> 2020-10-01 14:24:20,935 DEBUG [IO-/127.0.0.1:38722] (o.a.q.s.p.frame) -
> SEND[/127.0.0.1:38722|0] : SaslOutcome{code=ok}
> 2020-10-01 14:24:20,936 DEBUG [IO-/127.0.0.1:38722]
> (o.a.q.s.t.NonBlockingConnection) - Written 16 bytes
> 2020-10-01 14:24:20,936 DEBUG [IO-/127.0.0.1:38722]
> (o.a.q.s.t.NonBlockingConnection) - Read 0 byte(s)
> 2020-10-01 14:24:20,937 DEBUG [IO-/127.0.0.1:38722]
> (o.a.q.s.t.NonBlockingConnection) - Read 86 byte(s)
> 2020-10-01 14:24:20,937 DEBUG [IO-/127.0.0.1:38722]
> (o.a.q.s.p.v.f.FrameHandler) - RECV 78 bytes
> 2020-10-01 14:24:20,937 DEBUG [IO-/127.0.0.1:38722] (o.a.q.s.p.frame) -
> RECV[/127.0.0.1:38722|0] :
> Open{containerId=2cac9aa2-bcb2-498b-a4c4-704fa907fffb,hostname=localhost,channelMax=32767,idleTimeOut=5000}
> 2020-10-01 14:24:20,937 DEBUG [VirtualHostNode-default-Config]
> (o.a.q.s.c.u.TaskExecutorImpl) - Performing Task['register connection' on
> 'VirtualHost[id=16ed85e6-eb6b-47da-a449-78bc97c45dcd, name=default,
> type=BDB]' with arguments '/127.0.0.1:38722(ENTITLEMENT)']
> 2020-10-01 14:24:20,938 DEBUG [VirtualHostNode-default-Config]
> (o.a.q.s.c.u.TaskExecutorImpl) - Task['register connection' on
> 'VirtualHost[id=16ed85e6-eb6b-47da-a449-78bc97c45dcd, name=default,
> type=BDB]' with arguments '/127.0.0.1:38722(ENTITLEMENT)'] performed
> successfully with result: null
> 2020-10-01 14:24:20,938 INFO [IO-/127.0.0.1:38722] (q.m.c.open) -
> [con:8(ENTITLEMENT@/127.0.0.1:38722/default)] CON-1001 : Open : Destination :
> amqp(127.0.0.1:20101) : Protocol Version : 1.0 : Client ID :
> 2cac9aa2-bcb2-498b-a4c4-704fa907fffb
> 2020-10-01 14:24:20,938 DEBUG [IO-/127.0.0.1:38722]
> (o.a.q.s.s.a.c.RuleBasedAccessControl) - Checking Access Virtualhost
> 2020-10-01 14:24:20,938 DEBUG [IO-/127.0.0.1:38722] (o.a.q.s.s.a.c.RuleSet) -
> Checking action: ClientAction[clientAction=Action[operation=Access,
> object=Virtualhost, properties=NAME=default,VIRTUALHOST_NAME=default]]
> 2020-10-01 14:24:20,939 DEBUG [IO-/127.0.0.1:38722] (o.a.q.s.s.a.c.RuleSet) -
> Cached Virtualhost RulesList: [Rule[identity='ENTITLEMENT',
> action=AclAction[action=Action[operation=Access, object=Virtualhost,
> properties=], predicates=AclRulePredicates[CONNECTION_FREQUENCY_LIMIT=60
> CONNECTION_LIMIT=1]], permission=ALLOW_LOG], Rule[identity='ALL',
> action=AclAction[action=Action[operation=All, object=All, properties=],
> predicates=null], permission=DENY_LOG]]
> 2020-10-01 14:24:20,940 DEBUG [IO-/127.0.0.1:38722] (o.a.q.s.s.a.c.RuleSet) -
> Returning RuleList: [Rule[identity='ENTITLEMENT',
> action=AclAction[action=Action[operation=Access, object=Virtualhost,
> properties=], predicates=AclRulePredicates[CONNECTION_FREQUENCY_LIMIT=60
> CONNECTION_LIMIT=1]], permission=ALLOW_LOG], Rule[identity='ALL',
> action=AclAction[action=Action[operation=All, object=All, properties=],
> predicates=null], permission=DENY_LOG]]
> 2020-10-01 14:24:20,940 DEBUG [IO-/127.0.0.1:38722] (o.a.q.s.s.a.c.RuleSet) -
> Checking against rule: Rule[identity='ENTITLEMENT',
> action=AclAction[action=Action[operation=Access, object=Virtualhost,
> properties=], predicates=AclRulePredicates[CONNECTION_FREQUENCY_LIMIT=60
> CONNECTION_LIMIT=1]], permission=ALLOW_LOG]
> 2020-10-01 14:24:20,940 DEBUG [IO-/127.0.0.1:38722] (o.a.q.s.s.a.c.RuleSet) -
> Checking against rule: Rule[identity='ALL',
> action=AclAction[action=Action[operation=All, object=All, properties=],
> predicates=null], permission=DENY_LOG]
> 2020-10-01 14:24:20,940 DEBUG [IO-/127.0.0.1:38722] (o.a.q.s.s.a.c.RuleSet) -
> Action matches. Result: DENY_LOG
> 2020-10-01 14:24:20,941 INFO [IO-/127.0.0.1:38722] (q.m.a.denied) -
> [con:8(ENTITLEMENT@/127.0.0.1:38722/default)] ACL-1002 : Denied : Access
> Virtualhost NAME=default,VIRTUALHOST_NAME=default
> 2020-10-01 14:24:20,941 DEBUG [IO-/127.0.0.1:38722]
> (o.a.q.s.m.AbstractConfiguredObject) - authorise returned DENIED
> 2020-10-01 14:24:20,941 DEBUG [IO-/127.0.0.1:38722] (o.a.q.s.p.frame) -
> SEND[/127.0.0.1:38722|0] :
> Open{containerId=16ed85e6-eb6b-47da-a449-78bc97c45dcd,maxFrameSize=0,channelMax=0,idleTimeOut=0,offeredCapabilities=[ANONYMOUS-RELAY,
> SHARED-SUBS, sole-connection-for-container],properties={product=Apache Qpid
> Broker-J Core, version=JB.001.002.000,
> qpid.build=95d953b581c184bf805d2eb5d7b1526bdf15ea3c, qpid.instance_name=cil,
> qpid.virtualhost_properties_supported=true}}
> 2020-10-01 14:24:20,941 DEBUG [IO-/127.0.0.1:38722] (o.a.q.s.p.frame) -
> SEND[/127.0.0.1:38722|0] :
> Close{error=Error{condition=not-allowed,description=Permission
> PERFORM_ACTION(connect) is denied for : VirtualHost 'default' on
> VirtualHostNode 'default'}}
> 2020-10-01 14:24:20,941 DEBUG [IO-/127.0.0.1:38722]
> (o.a.q.s.t.NonBlockingConnection) - Written 466 bytes
> 2020-10-01 14:24:22,147 DEBUG [IO-/127.0.0.1:38580] (o.a.q.s.p.frame) -
> SEND[/127.0.0.1:38580|0] : <<HEARTBEAT>>
> 2020-10-01 14:24:22,148 DEBUG [IO-/127.0.0.1:38580]
> (o.a.q.s.t.NonBlockingConnection) - Read 0 byte(s)
> 2020-10-01 14:24:22,148 DEBUG [IO-/127.0.0.1:38580]
> (o.a.q.s.t.NonBlockingConnection) - Written 8 bytes
> 2020-10-01 14:24:22,924 DEBUG [IO-/127.0.0.1:38722]
> (o.a.q.s.t.NonBlockingConnection) - Read 0 byte(s)
> 2020-10-01 14:24:23,441 DEBUG [IO-/127.0.0.1:38722] (o.a.q.s.p.frame) -
> SEND[/127.0.0.1:38722|0] : <<HEARTBEAT>>
> 2020-10-01 14:24:23,441 DEBUG [IO-/127.0.0.1:38722]
> (o.a.q.s.t.NonBlockingConnection) - Read 0 byte(s)
> 2020-10-01 14:24:23,441 DEBUG [IO-/127.0.0.1:38722]
> (o.a.q.s.t.NonBlockingConnection) - Written 8 bytes
> 2020-10-01 14:24:24,650 DEBUG [IO-/127.0.0.1:38580] (o.a.q.s.p.frame) -
> SEND[/127.0.0.1:38580|0] : <<HEARTBEAT>>
> 2020-10-01 14:24:24,650 DEBUG [IO-/127.0.0.1:38580]
> (o.a.q.s.t.NonBlockingConnection) - Read 0 byte(s)
> 2020-10-01 14:24:24,650 DEBUG [IO-/127.0.0.1:38580]
> (o.a.q.s.t.NonBlockingConnection) - Written 8 bytes
> 2020-10-01 14:24:25,944 DEBUG [IO-/127.0.0.1:38722] (o.a.q.s.p.frame) -
> SEND[/127.0.0.1:38722|0] : <<HEARTBEAT>>
> 2020-10-01 14:24:25,944 DEBUG [IO-/127.0.0.1:38722]
> (o.a.q.s.t.NonBlockingConnection) - Read 0 byte(s)
> 2020-10-01 14:24:25,944 DEBUG [IO-/127.0.0.1:38722]
> (o.a.q.s.t.NonBlockingConnection) - Written 8 bytes
> 2020-10-01 14:24:28,447 DEBUG [IO-/127.0.0.1:38722] (o.a.q.s.p.frame) -
> SEND[/127.0.0.1:38722|0] : <<HEARTBEAT>>
> 2020-10-01 14:24:28,447 DEBUG [IO-/127.0.0.1:38722]
> (o.a.q.s.t.NonBlockingConnection) - Read 0 byte(s)
> 2020-10-01 14:24:28,447 DEBUG [IO-/127.0.0.1:38722]
> (o.a.q.s.t.NonBlockingConnection) - Written 8 bytes
> 2020-10-01 14:24:30,926 DEBUG [IO-/127.0.0.1:38722]
> (o.a.q.s.t.NonBlockingConnection) - Read 0 byte(s)
> 2020-10-01 14:24:30,948 DEBUG [IO-/127.0.0.1:38722] (o.a.q.s.p.frame) -
> SEND[/127.0.0.1:38722|0] : <<HEARTBEAT>>
> 2020-10-01 14:24:30,948 DEBUG [IO-/127.0.0.1:38722]
> (o.a.q.s.t.NonBlockingConnection) - Read 0 byte(s)
> 2020-10-01 14:24:30,948 DEBUG [IO-/127.0.0.1:38722]
> (o.a.q.s.t.NonBlockingConnection) - Written 8 bytes
> 2020-10-01 14:24:33,451 DEBUG [IO-/127.0.0.1:38722] (o.a.q.s.p.frame) -
> SEND[/127.0.0.1:38722|0] : <<HEARTBEAT>>
> 2020-10-01 14:24:33,451 DEBUG [IO-/127.0.0.1:38722]
> (o.a.q.s.t.NonBlockingConnection) - Read 0 byte(s)
> 2020-10-01 14:24:33,451 DEBUG [IO-/127.0.0.1:38722]
> (o.a.q.s.t.NonBlockingConnection) - Written 8 bytes
> 2020-10-01 14:24:35,954 DEBUG [IO-/127.0.0.1:38722] (o.a.q.s.p.frame) -
> SEND[/127.0.0.1:38722|0] : <<HEARTBEAT>>
> 2020-10-01 14:24:35,954 DEBUG [IO-/127.0.0.1:38722]
> (o.a.q.s.t.NonBlockingConnection) - Read 0 byte(s)
> 2020-10-01 14:24:35,954 DEBUG [IO-/127.0.0.1:38722]
> (o.a.q.s.t.NonBlockingConnection) - Written 8 bytes
> 2020-10-01 14:24:38,457 DEBUG [IO-/127.0.0.1:38722] (o.a.q.s.p.frame) -
> SEND[/127.0.0.1:38722|0] : <<HEARTBEAT>>
> 2020-10-01 14:24:38,457 DEBUG [IO-/127.0.0.1:38722]
> (o.a.q.s.t.NonBlockingConnection) - Read 0 byte(s)
> 2020-10-01 14:24:38,457 DEBUG [IO-/127.0.0.1:38722]
> (o.a.q.s.t.NonBlockingConnection) - Written 8 bytes
> 2020-10-01 14:24:38,725 DEBUG [IO-/127.0.0.1:38722]
> (o.a.q.s.t.NonBlockingConnection) - Read -1 byte(s)
> 2020-10-01 14:24:38,726 DEBUG [IO-/127.0.0.1:38722]
> (o.a.q.s.t.MultiVersionProtocolEngine) - Closed
> 2020-10-01 14:24:38,726 DEBUG [VirtualHostNode-default-Config]
> (o.a.q.s.c.u.TaskExecutorImpl) - Performing Task['deregister connection' on
> 'VirtualHost[id=16ed85e6-eb6b-47da-a449-78bc97c45dcd, name=default,
> type=BDB]' with arguments '/127.0.0.1:38722(ENTITLEMENT)']
> 2020-10-01 14:24:38,726 DEBUG [VirtualHostNode-default-Config]
> (o.a.q.s.c.u.TaskExecutorImpl) - Task['deregister connection' on
> 'VirtualHost[id=16ed85e6-eb6b-47da-a449-78bc97c45dcd, name=default,
> type=BDB]' with arguments '/127.0.0.1:38722(ENTITLEMENT)'] performed
> successfully with result: null
> 2020-10-01 14:24:38,726 DEBUG [IO-/127.0.0.1:38722]
> (o.a.q.s.t.SelectorThread) - Failed to unregister with selector for
> connection [NonBlockingConnection /127.0.0.1:38722]. Connection is probably
> being closed by peer.
> 2020-10-01 14:24:38,726 DEBUG [Broker-Config] (o.a.q.s.c.u.TaskExecutorImpl)
> - Performing Task['close' on '/127.0.0.1:38722(ENTITLEMENT)']
> 2020-10-01 14:24:38,727 DEBUG [Broker-Config]
> (o.a.q.s.m.AbstractConfiguredObject) - Closing AMQPConnection_1_0Impl : [8]
> 127.0.0.1:38722
> 2020-10-01 14:24:38,727 DEBUG [Broker-Config]
> (o.a.q.s.m.AbstractConfiguredObject) - All children closed
> AMQPConnection_1_0Impl : [8] 127.0.0.1:38722
> 2020-10-01 14:24:38,727 DEBUG [Broker-Config]
> (o.a.q.s.m.AbstractConfiguredObject) - Closed AMQPConnection_1_0Impl : [8]
> 127.0.0.1:38722
> 2020-10-01 14:24:38,727 DEBUG [Broker-Config] (o.a.q.s.c.u.TaskExecutorImpl)
> - Task['close' on '/127.0.0.1:38722(ENTITLEMENT)'] performed successfully
> with result: null
> 2020-10-01 14:24:38,727 INFO [Broker-Config] (q.m.c.dropped_connection) -
> [con:8(ENTITLEMENT@/127.0.0.1:38722/default)] CON-1004 : Connection dropped
> 2020-10-01 14:24:38,728 DEBUG [Selector-Port-amqp] (o.a.q.s.t.SelectorThread)
> - Failed to register with selector for connection [NonBlockingConnection
> /127.0.0.1:38722]. Connection is probably being closed by peer.
> java.nio.channels.ClosedChannelException: null
> at
> java.nio.channels.spi.AbstractSelectableChannel.register(AbstractSelectableChannel.java:204)
> at
> org.apache.qpid.server.transport.SelectorThread$SelectionTask.processUnscheduledConnections(SelectorThread.java:150)
> at
> org.apache.qpid.server.transport.SelectorThread$SelectionTask.performSelect(SelectorThread.java:345)
> at
> org.apache.qpid.server.transport.SelectorThread$SelectionTask.run(SelectorThread.java:97)
> at
> org.apache.qpid.server.transport.SelectorThread.run(SelectorThread.java:533)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> at
> org.apache.qpid.server.bytebuffer.QpidByteBufferFactory.lambda$null$0(QpidByteBufferFactory.java:464)
> at java.lang.Thread.run(Thread.java:748)
> {noformat}
> In log it is visible that NonBlockingConnection sends heartbeat messages to
> the client. Connection was dropped only after client dropped it on its side.
> Authentication is performed by AbstractConfiguredObject.authorize() =>
> AbstractVirtualHost.authoriseCreateConnection() =>
> AMQPConnection_1_0Impl.receiveOpenInternal().
> AMQPConnection_1_0Impl handles AccessControlException, calling
> closeConnection(), but it seems that NonBlockingConnection remains active.
>
>
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
