Details
-
Bug
-
Status: Closed
-
Minor
-
Resolution: Fixed
-
qpid-java-broker-8.0.0, qpid-java-broker-8.0.1
-
None
Description
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.
# 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
When using JMS-based clients issue is not reproducible because of JMSException thrown by client after failed authentication.
Log:
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)
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.