[ https://issues.apache.org/jira/browse/QPID-8477?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Alex Rudyy updated QPID-8477: ----------------------------- Affects Version/s: qpid-java-broker-8.0.0 qpid-java-broker-7.1.6 qpid-java-broker-7.1.7 qpid-java-broker-7.1.8 qpid-java-broker-7.1.9 > [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-7.1.6, > qpid-java-broker-7.1.7, qpid-java-broker-7.1.8, qpid-java-broker-8.0.1, > qpid-java-broker-7.1.9 > Reporter: Daniil Kirilyuk > Priority: Minor > Fix For: qpid-java-broker-8.0.2, qpid-java-broker-7.1.10 > > > 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-unsubscr...@qpid.apache.org For additional commands, e-mail: dev-h...@qpid.apache.org