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 <jdennis@redhat.com>

2 files changed, 33 insertions, 0 deletions

diff --git a/oslo_policy/policy.py b/oslo_policy/policy.py
index 1758579..fdd48bb 100644
--- a/oslo_policy/policy.py
+++ b/oslo_policy/policy.py
@@ -230,6 +230,7 @@ import warnings
 from oslo_config import cfg
 from oslo_context import context
 from oslo_serialization import jsonutils
+from oslo_utils import strutils
 import six
 import yaml
 
@@ -838,6 +839,37 @@ class Enforcer(object):
             )
             raise InvalidContextObject(msg)
 
+        if LOG.isEnabledFor(logging.DEBUG):
+            try:
+                # NOTE(jdennis) Although a MutableMapping behaves like
+                # a dict oslo.strutils.mask_dict_password() requires a
+                # dict. Bug #1804528 was opened to fix this, once that
+                # bug is fixed the conversion to dict can be removed.
+                if isinstance(creds, dict):
+                    creds_dict = creds
+                elif isinstance(creds, collections.MutableMapping):
+                    creds_dict = dict(creds)
+                else:
+                    raise TypeError('unexpected type %(creds_type)s' %
+                                    {'creds_type': type(creds)})
+                creds_dict = strutils.mask_dict_password(creds_dict)
+                creds_msg = jsonutils.dumps(creds_dict,
+                                            skipkeys=True, sort_keys=True)
+            except Exception as e:
+                creds_msg = ('cannot format data, exception: %(exp)s' %
+                             {'exp': e})
+
+            try:
+                target_msg = jsonutils.dumps(target,
+                                             skipkeys=True, sort_keys=True)
+            except Exception as e:
+                target_msg = ('cannot format data, exception: %(exp)s' %
+                              {'exp': e})
+
+            LOG.debug('enforce: rule=%s creds=%s target=%s',
+                      rule.__class__ if isinstance(rule, _checks.BaseCheck)
+                      else '"%s"' % rule, creds_msg, target_msg)
+
         # Allow the rule to be a Check tree
         if isinstance(rule, _checks.BaseCheck):
             # If the thing we're given is a Check, we don't know the
diff --git a/oslo_policy/tests/test_policy.py b/oslo_policy/tests/test_policy.py
index d5e6686..bc439dc 100644
--- a/oslo_policy/tests/test_policy.py
+++ b/oslo_policy/tests/test_policy.py
@@ -742,6 +742,7 @@ class EnforcerTest(base.PolicyBaseTestCase):
 
     @mock.patch.object(policy.Enforcer, '_map_context_attributes_into_creds')
     def test_enforcer_call_map_context_attributes(self, map_mock):
+        map_mock.return_value = {}
         rule = policy.RuleDefault(name='fake_rule', check_str='role:test')
         self.enforcer.register_default(rule)