Keystone fails to log policy target data

[John Dennis]

The Oslo Policy Enforcer requires 3 pieces of run-time information in addition to the policy rules to issue a RBAC decision:

1) the name of the rule to be evaluated (called target in the oslo-policy doc)
2) the auth context (called credentials in the oslo-policy doc)
3) the target data (resource data relevant to the rule)

If you are trying to debug policy enforcement or simply validate your policy works as expect one can use the oslopolicy-checker tool. But the oslopolicy-checker tool needs the *exact* same data keystone passes to the policy enforcement engine.

The fact the target data needs to be logged but isn't is captured in this comment from Henry Nash in authorize.py

    # TODO(henry-nash) need to log the target attributes as well

https://github.com/openstack/keystone/blob/stable/rocky/keystone/common/authorization.py#L139

But that is not the best location to log, the best place is where oslo.policy is called to evaluate a policy rule, that occurs in Policy.enforce() in keystone/policy/backends/policy.py

https://github.com/openstack/keystone/blob/stable/rocky/keystone/policy/backends/rules.py#L29:#L34

Here we can see it logs the rule name (e.g. action) and the auth context (credentials)

msg = 'enforce %(action)s: %(credentials)s'

but the target data is not logged.

Besides the fact the target data is not logged is the fact the logging relies on Python's str() method to convert an object into a string representation. This has two problems, 1) all contained objects must also have __str__() methods that fully log their contents, 2) the formatting is often in Python's "representation" style which only humans and Python can parse.

Since both the credential and targets parameters to the enforce method are dicts (with arbitrary complex nesting) and the fact JSON is the data format we use for data exchange and the format used by oslopolicy-checker it makes sense to log the enforcement parameters in JSON format. This way no data is lost (because there wasn't an appropriate formatter for the object) and it makes it easy import the data to another tool (again, without loss of data).

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/rocky
Review: https://review.openstack.org/618911

[Lance Bragstad (lbragstad)]

Thanks for the report, John. What do you think about adding this to oslo.policy directly and having it use an instance of oslo_log from the service?

I'm thinking if keystone isn't logging this information properly, then it's probably safe to assume others aren't either. We could put proper logging in a common place for re-use.

Thoughts?

[OpenStack Infra (hudson-openstack)]

Change abandoned by John Dennis (<email address hidden>) on branch: stable/rocky
Review: https://review.openstack.org/618911
Reason: Submitted against wrong branch, should have been master.

[Morgan Fainberg (mdrnstm)]

This is 100% encompassed in the RBAC Enforcer. Rule Name, Credential Data, and Target Data are emitted in debug.

Rocky will not see all of the data as not everything was under flask/RBACEnforcer. Stein will emit this data.

[Morgan Fainberg (mdrnstm)]

https://github.com/openstack/keystone/blob/5ff37f10280639737527226ca4bd97919d3725ea/keystone/common/rbac_enforcer/enforcer.py#L403-L426

[Adam Young (ayoung)]

Added Oslo.policy to the bug report, as this is going to be an issue across all of the projects. Barbican, especially, needs target info, but the same is true for anything that enforces the scope check.

[John Dennis (jdennis-a)]

In the Keystone team meeting it was decided the logging needed to be in one central location so that all projects using olso.policy would benefit as opposed to fixing just one project (i.e. Keystone). Therefore this bug was moved from keystone to olso.policy

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/619260

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/619260
Committed: https://git.openstack.org/cgit/openstack/oslo.policy/commit/?id=0d7c5b3947bcb5b6155e3ce5152aef4f34710a00
Submitter: Zuul
Branch: master

commit 0d7c5b3947bcb5b6155e3ce5152aef4f34710a00
Author: John Dennis <email address hidden>
Date: Tue Nov 20 15:19:13 2018 -0500

    Fully log RBAC enforcement data

    Data passed to the RBAC enforce function consistes of 3 items:

    * rule name or rule object
    * credential data
    * target data

    Both the credential and target are dicts. When policy enforcement
    does not work as expected it's essential to capture the input to
    the enforcement engine as to ascertain why the rule did not work
    as expected. It would also be highly advantageous if the logging
    were in a format that could be digested by other tools
    (e.g. oslopolicy-checker).

    This patch does two things:

    1) It logs the policy relevant input to Enforcer.enforce()

    2) It eschews the use of Python's string formatting which may not
    fully dump the contents of the dicts and is not easily parsed in favor
    of using JSON format which does fully capture the object's content and
    can be used in data exchange (and can be read by oslopolicy-checker).

    Contents of the credentials dict are filtered to scrub security
    sensitive data.

    Closes-Bug: #1804073

    Change-Id: I4642c57990b145c0e691140970574412682e66a5
    Signed-off-by: John Dennis <email address hidden>

[OpenStack Infra (hudson-openstack)]

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