RH-OSP 13 | Queens | Troubleshooting transient 403 in RBAC networks.

Laurent Dumont laurentfdumont at gmail.com
Mon Apr 20 15:08:00 UTC 2020


Hi!

Here is what Neutron is complaining about.

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've tried removing each controller one by one (to validate if one was out
of sync) - and I had the issue in all three cases.

Very weird. I'll keep digging.



On Sun, Apr 19, 2020 at 5:27 AM Slawek Kaplonski <skaplons at redhat.com>
wrote:

> Hi,
>
> If it fails only in some cases, it seems for me like maybe You have
> different
> policy.json configured (or different neutron version installed) on
> controllers.
> Can You check if all is the same in all cases?
> Also please send logs from neutron-server from when this failed.
>
> On Sun, Apr 19, 2020 at 02:08:09AM -0400, Laurent Dumont wrote:
> > 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!
>
> --
> Slawek Kaplonski
> Senior software engineer
> Red Hat
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.openstack.org/pipermail/openstack-discuss/attachments/20200420/dfaec2c5/attachment-0001.html>


More information about the openstack-discuss mailing list