Open Stack

Hi!

I'm currently troubleshooting some transient Keystone/Neutron 403 issues
when creating ports in RBAC-ed networks.

   - As part of our CI process,we are running a few sanity tests in virtual
   Openstack setups with 3 controllers and 2 computes.
   - One of those test validates the following scenarios (everything is
   done through the Openstack python sdk) :
      - Create projectA / UserA / ProjectB / UserB
      - Create Network in project A
      - RBAC Network in projectA to ProjectB
      - With a token issued to a user in projectB, try to create the
      following ports in project.
         - regular port
         - update regular port with a fixed IP
         - update regular port with an allowed_address_pair
         - create port with a fixed IP
         - create port with an allowed address pair.
      - The behavior that I'm seeing the most is that the port creation
   will fail with the following error (the logs are from the sdk with
   logging/debug enabled.
   - It fails maybe 1/3 - and I'm unable to see a common pattern.
   - This is testing against the same Openstack env and the
   failures/success can happen within a few seconds of each others.

Sun Apr 19 01:54:06 2020 -- From ProjectB - create a port with a fixed
> address in the network shared from ProjectA
> REQ: curl -g -i -X GET
> https://OPENSTACK_URL_HERE:13696/v2.0/subnets/77c3fad2-bf78-4b4e-bcfb-8114f95d7884
> -H "User-Agent: openstacksdk/0.37.0 keystoneauth1/3.18.0
> python-requests/2.22.0 CPython/3.7.5" -H "X-Auth-Token:
> {SHA256}d80fe300742786033376f0591f98d3b4c342103cda1f802087809963694a7935"
> RESP: [200] Content-Length: 619 Content-Type: application/json Date: Sun,
> 19 Apr 2020 01:54:06 GMT X-Openstack-Request-Id:
> req-fcee8345-7daa-499e-a985-92d59a31d0dd
> RESP BODY:
> {"subnet":{"service_types":[],"description":"","enable_dhcp":true,"tags":[],"network_id":"4ba08203-4328-418b-89e6-b82d474275d5","tenant_id":"472631dbfc5f4dfda9293fb93b5e493f","created_at":"2020-04-19T01:54:03Z","dns_nameservers":[],"updated_at":"2020-04-19T01:54:03Z","gateway_ip":"1.1.1.1","ipv6_ra_mode":null,"allocation_pools":[{"start":"1.1.1.2","end":"1.1.1.254"}],"host_routes":[],"revision_number":0,"ip_version":4,"ipv6_address_mode":null,"cidr":"
> 1.1.1.0/24
> ","project_id":"472631dbfc5f4dfda9293fb93b5e493f","id":"77c3fad2-bf78-4b4e-bcfb-8114f95d7884","subnetpool_id":null,"name":"neutronpolicy_shared_network"}}
> GET call to network for
> https://OPENSTACK_URL_HERE:13696/v2.0/subnets/77c3fad2-bf78-4b4e-bcfb-8114f95d7884
> used request id req-fcee8345-7daa-499e-a985-92d59a31d0dd
> REQ: curl -g -i -X POST https://OPENSTACK_URL_HERE:13696/v2.0/ports -H
> "Content-Type: application/json" -H "User-Agent: openstacksdk/0.37.0
> keystoneauth1/3.18.0 python-requests/2.22.0 CPython/3.7.5" -H
> "X-Auth-Token:
> {SHA256}d80fe300742786033376f0591f98d3b4c342103cda1f802087809963694a7935"
> -d '{"port": {"name": "neutronpolicy_portb-fixed-ip", "network_id":
> "4ba08203-4328-418b-89e6-b82d474275d5", "fixed_ips": [{"subnet_id":
> "77c3fad2-bf78-4b4e-bcfb-8114f95d7884", "ip_address": "1.1.1.100"}]}}'
> RESP: [403] Content-Length: 151 Content-Type: application/json Date: Sun,
> 19 Apr 2020 01:54:07 GMT X-Openstack-Request-Id:
> req-00277dbc-faca-479f-8736-563595d2729b
> RESP BODY: {"NeutronError": {"message": "(rule:create_port and
> rule:create_port:fixed_ips) is disallowed by policy", "type":
> "PolicyNotAuthorized", "detail": ""}}
> POST call to network for https://OPENSTACK_URL_HERE:13696/v2.0/ports used
> request id req-00277dbc-faca-479f-8736-563595d2729b


When it works, it looks the same, just without the 403 during the port
creation.

Sun Apr 19 02:29:54 2020 -- From ProjectB - create a port with a fixed
> address in the network shared from ProjectA
> REQ: curl -g -i -X GET
> https://OPENSTACK_URL_HERE:13696/v2.0/subnets/6d2231b6-3ce2-4121-a9a6-7284823c48ab
> -H "User-Agent: openstacksdk/0.37.0 keystoneauth1/3.18.0
> python-requests/2.22.0 CPython/3.7.5" -H "X-Auth-Token:
> {SHA256}d39995434f6a0f106cae7408b07eee93846230f2bb5c922a8e16cfc7c8b26599"
> RESP: [200] Content-Length: 619 Content-Type: application/json Date: Sun,
> 19 Apr 2020 02:29:54 GMT X-Openstack-Request-Id:
> req-bd41b51f-b6e9-454c-8c9a-ee444140459e
> RESP BODY:
> {"subnet":{"service_types":[],"description":"","enable_dhcp":true,"tags":[],"network_id":"e0d7e7a1-2863-45ec-bd7b-1767a1d02822","tenant_id":"4530b70143ec4cd0ad929a4ca571bdd8","created_at":"2020-04-19T02:29:51Z","dns_nameservers":[],"updated_at":"2020-04-19T02:29:51Z","gateway_ip":"1.1.1.1","ipv6_ra_mode":null,"allocation_pools":[{"start":"1.1.1.2","end":"1.1.1.254"}],"host_routes":[],"revision_number":0,"ip_version":4,"ipv6_address_mode":null,"cidr":"
> 1.1.1.0/24
> ","project_id":"4530b70143ec4cd0ad929a4ca571bdd8","id":"6d2231b6-3ce2-4121-a9a6-7284823c48ab","subnetpool_id":null,"name":"neutronpolicy_shared_network"}}
> GET call to network for
> https:/OPENSTACK_URL_HERE:13696/v2.0/subnets/6d2231b6-3ce2-4121-a9a6-7284823c48ab
> used request id req-bd41b51f-b6e9-454c-8c9a-ee444140459e
> REQ: curl -g -i -X POST https://OPENSTACK_URL_HERE:13696/v2.0/ports -H
> "Content-Type: application/json" -H "User-Agent: openstacksdk/0.37.0
> keystoneauth1/3.18.0 python-requests/2.22.0 CPython/3.7.5" -H
> "X-Auth-Token:
> {SHA256}d39995434f6a0f106cae7408b07eee93846230f2bb5c922a8e16cfc7c8b26599"
> -d '{"port": {"name": "neutronpolicy_portb-fixed-ip", "network_id":
> "e0d7e7a1-2863-45ec-bd7b-1767a1d02822", "fixed_ips": [{"subnet_id":
> "6d2231b6-3ce2-4121-a9a6-7284823c48ab", "ip_address": "1.1.1.100"}]}}'
> RESP: [201] Content-Length: 769 Content-Type: application/json Date: Sun,
> 19 Apr 2020 02:29:56 GMT X-Openstack-Request-Id:
> req-898dadfb-366d-4a78-8e89-c9d5e9a512f6
> RESP BODY:
> {"port":{"allowed_address_pairs":[],"extra_dhcp_opts":[],"updated_at":"2020-04-19T02:29:55Z","device_owner":"","revision_number":6,"port_security_enabled":true,"fixed_ips":[{"subnet_id":"6d2231b6-3ce2-4121-a9a6-7284823c48ab","ip_address":"1.1.1.100"}],"id":"9999784b-c38d-4cf2-b951-e8255d3483f4","security_groups":["4c022e69-b575-435b-bfb7-9cc81f50d49e"],"mac_address":"fa:16:3e:3e:22:fb","device_id":"","status":"DOWN","description":"","tags":[],"name":"neutronpolicy_portb-fixed-ip","project_id":"253ee9b6b5964185ab0818580129c011","qos_policy_id":null,"admin_state_up":true,"network_id":"e0d7e7a1-2863-45ec-bd7b-1767a1d02822","tenant_id":"253ee9b6b5964185ab0818580129c011","created_at":"2020-04-19T02:29:55Z","binding:vnic_type":"normal","ip_allocation":"immediate"}}
> POST call to network for https://OPENSTACK_URL_HERE:13696/v2.0/ports used
> request id req-898dadfb-366d-4a78-8e89-c9d5e9a512f6
> Sun Apr 19 02:29:56 2020 -- PORT-OK


This is what I see in the Neutron server logs (with debug enabled)

DEBUG neutron.api.v2.base [req-00277dbc-faca-479f-8736-563595d2729b
> c905a7d0011e4bb4ae388cfd699e5989 4bae655884b44e8e9c8dbb5983fb3cd8 - default
> default] Request body: {u'port': {u'network_id':
> u'4ba08203-4328-418b-89e6-b82d474275d5', u'fixed_ips': [{u'subnet_id':
> u'77c3fad2-bf78-4b4e-bcfb-8114f95d7884', u'ip_address': u'1.1.1.100'}],
> u'name': u'neutronpolicy_portb-fixed-ip'}} prepare_request_body
> /usr/lib/python2.7/site-packages/neutron/api/v2/base.py:690
> DEBUG neutron.db.quota.driver [req-00277dbc-faca-479f-8736-563595d2729b
> c905a7d0011e4bb4ae388cfd699e5989 4bae655884b44e8e9c8dbb5983fb3cd8 - default
> default] Resources subnetpool,trunk have unlimited quota limit. It is not
> required to calculate headroom  make_reservation
> /usr/lib/python2.7/site-packages/neutron/db/quota/driver.py:223
> DEBUG neutron.quota.resource [req-00277dbc-faca-479f-8736-563595d2729b
> c905a7d0011e4bb4ae388cfd699e5989 4bae655884b44e8e9c8dbb5983fb3cd8 - default
> default] Usage tracker for resource:port and
> tenant:4bae655884b44e8e9c8dbb5983fb3cd8 is out of sync, need to count used
> quota count_used
> /usr/lib/python2.7/site-packages/neutron/quota/resource.py:272
> DEBUG neutron.quota.resource [req-00277dbc-faca-479f-8736-563595d2729b
> c905a7d0011e4bb4ae388cfd699e5989 4bae655884b44e8e9c8dbb5983fb3cd8 - default
> default] Quota usage for port was recalculated. Used quota:0. count_used
> /usr/lib/python2.7/site-packages/neutron/quota/resource.py:292
> DEBUG neutron.db.quota.driver [req-00277dbc-faca-479f-8736-563595d2729b
> c905a7d0011e4bb4ae388cfd699e5989 4bae655884b44e8e9c8dbb5983fb3cd8 - default
> default] Attempting to reserve 1 items for resource port. Total usage: 0;
> quota limit: 500; headroom:500 make_reservation
> /usr/lib/python2.7/site-packages/neutron/db/quota/driver.py:255
> DEBUG neutron.pecan_wsgi.hooks.quota_enforcement
> [req-00277dbc-faca-479f-8736-563595d2729b c905a7d0011e4bb4ae388cfd699e5989
> 4bae655884b44e8e9c8dbb5983fb3cd8 - default default] Made reservation on
> behalf of 4bae655884b44e8e9c8dbb5983fb3cd8 for: {'port': 1} before
> /usr/lib/python2.7/site-packages/neutron/pecan_wsgi/hooks/quota_enforcement.py:55
> DEBUG neutron.policy [req-00277dbc-faca-479f-8736-563595d2729b
> c905a7d0011e4bb4ae388cfd699e5989 4bae655884b44e8e9c8dbb5983fb3cd8 - default
> default] Unable to find requested field: shared in target:
> {'binding:host_id': <neutron_lib.constants.Sentinel object at
> 0x7f2a3b214d50>, u'name': u'neutronpolicy_portb-fixed-ip',
> 'allowed_address_pairs': <neutron_lib.constants.Sentinel object at
> 0x7f2a3b214d50>, 'admin_state_up': True, u'network_id':
> u'4ba08203-4328-418b-89e6-b82d474275d5', 'tenant_id':
> u'4bae655884b44e8e9c8dbb5983fb3cd8', 'extra_dhcp_opts': None,
> 'mac_address': <neutron_lib.constants.Sentinel object at 0x7f2a3b214d50>,
> 'binding:vnic_type': 'normal', 'device_owner': '', 'qos_policy_id': None,
> 'device_id': '', 'binding:profile': <neutron_lib.constants.Sentinel object
> at 0x7f2a3b214d50>, 'port_security_enabled':
> <neutron_lib.constants.Sentinel object at 0x7f2a3b214d50>, 'project_id':
> u'4bae655884b44e8e9c8dbb5983fb3cd8', u'fixed_ips': [{u'subnet_id':
> u'77c3fad2-bf78-4b4e-bcfb-8114f95d7884', u'ip_address': u'1.1.1.100'}],
> u'network:tenant_id': u'472631dbfc5f4dfda9293fb93b5e493f',
> 'security_groups': <neutron_lib.constants.Sentinel object at
> 0x7f2a3b214d50>, 'description': ''} __call__
> /usr/lib/python2.7/site-packages/neutron/policy.py:314
> DEBUG neutron.policy [req-00277dbc-faca-479f-8736-563595d2729b
> c905a7d0011e4bb4ae388cfd699e5989 4bae655884b44e8e9c8dbb5983fb3cd8 - default
> default] Enforcing rules: ['create_port', 'create_port:fixed_ips']
> log_rule_list /usr/lib/python2.7/site-packages/neutron/policy.py:334
> DEBUG neutron.policy [req-00277dbc-faca-479f-8736-563595d2729b
> c905a7d0011e4bb4ae388cfd699e5989 4bae655884b44e8e9c8dbb5983fb3cd8 - default
> default] Failed policy check for 'create_port' enforce
> /usr/lib/python2.7/site-packages/neutron/policy.py:405
> INFO neutron.pecan_wsgi.hooks.translation
> [req-00277dbc-faca-479f-8736-563595d2729b c905a7d0011e4bb4ae388cfd699e5989
> 4bae655884b44e8e9c8dbb5983fb3cd8 - default default] POST failed (client
> error): Access was denied to this resource.
> DEBUG neutron.pecan_wsgi.hooks.notifier
> [req-00277dbc-faca-479f-8736-563595d2729b c905a7d0011e4bb4ae388cfd699e5989
> 4bae655884b44e8e9c8dbb5983fb3cd8 - default default] No notification will be
> sent due to unsuccessful status code: 403 after
> /usr/lib/python2.7/site-packages/neutron/pecan_wsgi/hooks/notifier.py:79
> INFO neutron.wsgi [req-00277dbc-faca-479f-8736-563595d2729b
> c905a7d0011e4bb4ae388cfd699e5989 4bae655884b44e8e9c8dbb5983fb3cd8 - default
> default] 192.168.20.29 "POST /v2.0/ports HTTP/1.1" status: 403  len: 333
> time: 0.3625510
>


I haven't found a whole lot online - just a couple of possibly related bugs
https://bugs.launchpad.net/neutron/+bug/1808112
https://bugzilla.redhat.com/show_bug.cgi?id=1683385

Does anyone have any good tips/debugging methods?

Thanks!
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.openstack.org/pipermail/openstack-discuss/attachments/20200419/352b6cce/attachment-0001.html>