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 2020/10/18 20:28:00 UTC
[jira] [Resolved] (QPID-8477) [Broker-J] Broker is not closing
connections denied with ACL-1002 (this can lead to connection_limit being
bypassed)
[ https://issues.apache.org/jira/browse/QPID-8477?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Alex Rudyy resolved QPID-8477.
------------------------------
Resolution: Fixed
> [Broker-J] 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.0, qpid-java-broker-8.0.1
> Reporter: Daniil Kirilyuk
> Priority: Minor
> Fix For: qpid-java-broker-8.0.2
>
>
> 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: dev-unsubscribe@qpid.apache.org
For additional commands, e-mail: dev-help@qpid.apache.org