Enforcer performs deprecation logic unnecessarily

[Slawek Kaplonski]

Example of failure https://25ba0cd8b717ae4bad76-16713fdfca2d55e13bffb4aa24c202fc.ssl.cf5.rackcdn.com/772255/5/check/neutron-rally-task/9009341/results/report.html
But it happens very often since 27.01.
It is probably related to some patches from secure-rbac BP: https://review.opendev.org/q/project:openstack/neutron+status:merged+topic:secure-rbac

[Lance Bragstad (lbragstad)]

I can recreate this and I can do it by toggling `neutron.conf [oslo_policy] enforce_new_defaults`.

When that configuration option is True, oslo.policy will short-circuits code to logically OR the deprecated policy with the new policy [0].

In my environment I have enforce_new_defaults = False (the default) and listing 380 ports takes anywhere from 12 - 16 seconds. With enforce_new_defaults = True, listing 380 ports takes about 5 seconds.

[0] https://opendev.org/openstack/oslo.policy/src/branch/master/oslo_policy/policy.py#L758-L767

[Lance Bragstad (lbragstad)]

I timed the processing time into oslo.policy on the initial enforcement call and it seems consistent between the two situations. I did notice that neutron implements a post request hook in pecan that does additional things with the rules [0].

It appears the enforce() is called to enforce the main API, but check() is called to execute RBAC rules against each port in the list.

The oslo.policy Enforcer invocation is very similar in both methods, but check() is doing additional things with the rules before calling enforcement. It could be that it's not expecting an OrCheck rule modification from oslo.policy, which happens by default when policies are deprecated.

I might need to sit down with someone more familiar with how policy enforcement works in neutron.

This might be another reason to make oslo.policy's Enforcer object operate on a copy of the rules before it modifies them [1].

[0] https://opendev.org/openstack/neutron/src/branch/master/neutron/pecan_wsgi/hooks/policy_enforcement.py#L187-L189
[1] https://storyboard.openstack.org/#!/story/2008556

[Slawek Kaplonski (slaweq)]

@Lance, thx for taking look into this.
I was checking it also and I'm not sure if the problem is in that call to "check()" method in policy_enforcement hook really.

I checked time spent on calling _ENFORCER.enforce() in the https://opendev.org/openstack/neutron/src/branch/master/neutron/policy.py#L461 - to check that I applied simple patch to my neutron code: http://paste.openstack.org/show/802167/

And I run that code with and without our already merged "secure-rbac" patches. Results are below:

- current master (with secure rbac patches):

Feb 01 12:38:02 devstack-ubuntu-ovs neutron-server[6437]: DEBUG neutron.policy [None req-64f43b02-78ec-46f3-aff3-8e54e9c08a0c demo demo] SK; longest execution of the _ENFORCER.enforce is: 0.004007101058959961 {{(pid=6437) check /opt/stack/neutron/neutron/policy.py:473}}
Feb 01 12:38:02 devstack-ubuntu-ovs neutron-server[6437]: DEBUG neutron.policy [None req-64f43b02-78ec-46f3-aff3-8e54e9c08a0c demo demo] SK; longest execution of the _ENFORCER.enforce is: 0.004117727279663086 {{(pid=6437) check /opt/stack/neutron/neutron/policy.py:473}}
Feb 01 12:38:02 devstack-ubuntu-ovs neutron-server[6437]: DEBUG neutron.policy [None req-64f43b02-78ec-46f3-aff3-8e54e9c08a0c demo demo] SK; longest execution of the _ENFORCER.enforce is: 0.0044574737548828125 {{(pid=6437) check /opt/stack/neutron/neutron/policy.py:473}}
Feb 01 12:38:02 devstack-ubuntu-ovs neutron-server[6437]: DEBUG neutron.policy [None req-64f43b02-78ec-46f3-aff3-8e54e9c08a0c demo demo] SK; longest execution of the _ENFORCER.enforce is: 0.0045013427734375 {{(pid=6437) check /opt/stack/neutron/neutron/policy.py:473}}
Feb 01 12:38:02 devstack-ubuntu-ovs neutron-server[6437]: DEBUG neutron.policy [None req-64f43b02-78ec-46f3-aff3-8e54e9c08a0c demo demo] SK; longest execution of the _ENFORCER.enforce is: 0.0045757293701171875 {{(pid=6437) check /opt/stack/neutron/neutron/policy.py:473}}
Feb 01 12:38:02 devstack-ubuntu-ovs neutron-server[6437]: DEBUG neutron.policy [None req-64f43b02-78ec-46f3-aff3-8e54e9c08a0c demo demo] SK; longest execution of the _ENFORCER.enforce is: 0.004602193832397461 {{(pid=6437) check /opt/stack/neutron/neutron/policy.py:473}}
Feb 01 12:38:03 devstack-ubuntu-ovs neutron-server[6437]: DEBUG neutron.policy [None req-64f43b02-78ec-46f3-aff3-8e54e9c08a0c demo demo] SK; longest execution of the _ENFORCER.enforce is: 0.0046977996826171875 {{(pid=6437) check /opt/stack/neutron/neutron/policy.py:473}}
Feb 01 12:38:03 devstack-ubuntu-ovs neutron-server[6437]: DEBUG neutron.policy [None req-64f43b02-78ec-46f3-aff3-8e54e9c08a0c demo demo] SK; longest execution of the _ENFORCER.enforce is: 0.004942893981933594 {{(pid=6437) check /opt/stack/neutron/neutron/policy.py:473}}
Feb 01 12:38:03 devstack-ubuntu-ovs neutron-server[6437]: DEBUG neutron.policy [None req-64f43b02-78ec-46f3-aff3-8e54e9c08a0c demo demo] SK; longest execution of the _ENFORCER.enforce is: 0.005093574523925781 {{(pid=6437) check /opt/stack/neutron/neutron/policy.py:473}}
Feb 01 12:38:05 devstack-ubuntu-ovs neutron-server[6437]: DEBUG neutron.policy [None req-64f43b02-78ec-46f3-aff3-8e54e9c08a0c demo demo] SK; longest execution of the _ENFORCER.enforce is: 0.006113290786743164 {{...

[Slawek Kaplonski (slaweq)]

After some more digging I see that indeed there is problem of how many times we are calling policy.check() function in Neutron. E.g. in [0] mentioned by Lance, it is called for every resource (port in my reproducer) but also, for each port it is calling _get_filtered_items() method and that is calling "_exclude_attributes_by_policy()" [1]. And this method is calling policy.check() for every attribute of the checked resource to check if e.g. "get_port:id", "get_port:network_id", etc. can be returned or not. If not, such attribute is excluded from the list which is returned back to the client.

[0] https://opendev.org/openstack/neutron/src/branch/master/neutron/pecan_wsgi/hooks/policy_enforcement.py#L187-L189
[1] https://github.com/openstack/neutron/blob/0841265a7b9894174a965a6421d7a68a07822d70/neutron/pecan_wsgi/hooks/policy_enforcement.py#L217

[Slawek Kaplonski (slaweq)]

Proposed patch for oslo_policy: https://review.opendev.org/c/openstack/oslo.policy/+/773414 - IDK if that can be good approach to fix that problem. Lets see what oslo developers will tell about it.

[Ghanshyam Mann (ghanshyammann)]

adding oslo.policy also.

slaweq, lbragstad, and I discussed it in the neutron IRC channel today[1].

Loading rules should be done during init time of policy instead of each rule check. we could move the load_rules() call from enforcer()[2] which is called for every check to policy __init__(). But we need to consider both cases here to know the side effect of it.

1. no policy file: this case will be fine and have no impact as there is no change in the rule after policy init.

2. policy file and operator change rule dynamically: This will be impacted and the operator needs to restart the API service to re-init the policy and load the latest rule. This is something we need to discuss more and get operator feedback if they do restart API service for any modification in policy file or not?

3. policy file name change or new policy file: this anyways needs policy restart. self.policy_file pick the right policy file during policy's init only[3] so new policy file need service restart now also which means no impact of moving load_rule() from enforce(). One example: https://review.opendev.org/c/openstack/nova/+/773192

[1] http://eavesdrop.openstack.org/irclogs/%23openstack-neutron/%23openstack-neutron.2021-02-01.log.html#t2021-02-01T15:30:03

[2] https://opendev.org/openstack/oslo.policy/src/branch/master/oslo_policy/policy.py#L948

[3] https://opendev.org/openstack/oslo.policy/src/branch/master/oslo_policy/policy.py#L533

[Ghanshyam Mann (ghanshyammann)]

fix https://review.opendev.org/c/openstack/oslo.policy/+/773414/

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/oslo.policy 3.6.1 release.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/neutron 18.0.0.0rc1 release candidate.