RH-OSP 13 | Queens | Troubleshooting transient 403 in RBAC networks.
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-8114f9... -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-8114f9... 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-728482... -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!
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-8114f9... -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-8114f9... 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-728482... -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
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@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-8114f9...
-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-8114f9...
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-728482...
-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
Just for anyone in the future, we we're able to narrow down the cause. It looks like there is kind of caching for the auth tokens (either locally or at the Openstack level). I had to re-establish the Openstack session object from my script before trying to create the privileged object. Oh well, lesson learned... On Mon, Apr 20, 2020 at 11:08 AM Laurent Dumont <laurentfdumont@gmail.com> wrote:
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@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-8114f9...
-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-8114f9...
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-728482...
-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
participants (2)
-
Laurent Dumont
-
Slawek Kaplonski