multi policy: Fix logging issues with multiple policies

This patchset mostly aims to fix logging issues surrounding
multiple policies introduced by [0]. Some of the LOG messages
still only log `rule` arg when they should log all the `rules`
arg instead to capture all the policies being enforced.

In addition, this patchset:

* corrects docstring formatting with rbac_rule_validation following [1]
* changes unit tests in test_rbac_rule_validation to test non-deprecated
  arg `rules` instead of `rule` (tests also exist for ensuring that
  `rule` is handled correctly until it is finally removed from code)
* rewords some log messages to better conform to multi policy support

[0] https://review.openstack.org/#/c/554764/
[1] https://review.openstack.org/#/c/570262/

Partially Implements: bp rbac-testing-multiple-policies
Story: 2002620
Task: 22250

Change-Id: I3df69d5a476416378bde14ee6a258ff5ed40e363
diff --git a/patrole_tempest_plugin/rbac_rule_validation.py b/patrole_tempest_plugin/rbac_rule_validation.py
index 7d48870..fa87158 100644
--- a/patrole_tempest_plugin/rbac_rule_validation.py
+++ b/patrole_tempest_plugin/rbac_rule_validation.py
@@ -82,10 +82,10 @@
 
             Patrole currently only supports custom JSON policy files.
 
-    :param int expected_error_code: Overrides default value of 403 (Forbidden)
-        with endpoint-specific error code. Currently only supports 403 and 404.
-        Support for 404 is needed because some services, like Neutron,
-        intentionally throw a 404 for security reasons.
+    :param int expected_error_code: (DEPRECATED) Overrides default value of 403
+        (Forbidden) with endpoint-specific error code. Currently only supports
+        403 and 404. Support for 404 is needed because some services, like
+        Neutron, intentionally throw a 404 for security reasons.
 
         .. warning::
 
@@ -99,6 +99,7 @@
         in the rules list.
 
         Example::
+
             rules=["api_action1", "api_action2"]
             expected_error_codes=[404, 403]
 
@@ -192,7 +193,10 @@
                     rbac_exceptions.RbacMalformedResponse) as e:
                 test_status = 'Denied'
                 if irregular_msg:
-                    LOG.warning(irregular_msg.format(rule, service))
+                    LOG.warning(irregular_msg,
+                                test_func.__name__,
+                                ', '.join(rules),
+                                service)
                 if allowed:
                     msg = ("Role %s was not allowed to perform the following "
                            "actions: %s. Expected allowed actions: %s. "
@@ -225,9 +229,9 @@
             finally:
                 if CONF.patrole_log.enable_reporting:
                     RBACLOG.info(
-                        "[Service]: %s, [Test]: %s, [Rule]: %s, "
+                        "[Service]: %s, [Test]: %s, [Rules]: %s, "
                         "[Expected]: %s, [Actual]: %s",
-                        service, test_func.__name__, rule,
+                        service, test_func.__name__, ', '.join(rules),
                         "Allowed" if allowed else "Denied",
                         test_status)
 
@@ -331,16 +335,16 @@
     is_allowed = authority.allowed(rule, role)
 
     if is_allowed:
-        LOG.debug("[Action]: %s, [Role]: %s is allowed!", rule,
+        LOG.debug("[Policy action]: %s, [Role]: %s is allowed!", rule,
                   role)
     else:
-        LOG.debug("[Action]: %s, [Role]: %s is NOT allowed!",
+        LOG.debug("[Policy action]: %s, [Role]: %s is NOT allowed!",
                   rule, role)
 
     return is_allowed
 
 
-def _get_exception_type(expected_error_code=403):
+def _get_exception_type(expected_error_code=_DEFAULT_ERROR_CODE):
     """Dynamically calculate the expected exception to be caught.
 
     Dynamically calculate the expected exception to be caught by the test case.
@@ -369,9 +373,10 @@
         expected_exception = exceptions.Forbidden
     elif expected_error_code == 404:
         expected_exception = exceptions.NotFound
-        irregular_msg = ("NotFound exception was caught for policy action "
-                         "{0}. The service {1} throws a 404 instead of a 403, "
-                         "which is irregular.")
+        irregular_msg = ("NotFound exception was caught for test %s. Expected "
+                         "policies which may have caused the error: %s. The "
+                         "service %s throws a 404 instead of a 403, which is "
+                         "irregular.")
 
     return expected_exception, irregular_msg
 
diff --git a/patrole_tempest_plugin/tests/unit/test_rbac_rule_validation.py b/patrole_tempest_plugin/tests/unit/test_rbac_rule_validation.py
index 2ae860c..bdba242 100644
--- a/patrole_tempest_plugin/tests/unit/test_rbac_rule_validation.py
+++ b/patrole_tempest_plugin/tests/unit/test_rbac_rule_validation.py
@@ -64,7 +64,7 @@
         """
         mock_authority.PolicyAuthority.return_value.allowed.return_value = True
 
-        @rbac_rv.action(mock.sentinel.service, mock.sentinel.action)
+        @rbac_rv.action(mock.sentinel.service, rules=[mock.sentinel.action])
         def test_policy(*args):
             pass
 
@@ -83,7 +83,7 @@
         mock_authority.PolicyAuthority.return_value.allowed.return_value =\
             False
 
-        @rbac_rv.action(mock.sentinel.service, mock.sentinel.action)
+        @rbac_rv.action(mock.sentinel.service, rules=[mock.sentinel.action])
         def test_policy(*args):
             raise exceptions.Forbidden()
 
@@ -103,7 +103,7 @@
         """
         mock_authority.PolicyAuthority.return_value.allowed.return_value = True
 
-        @rbac_rv.action(mock.sentinel.service, mock.sentinel.action)
+        @rbac_rv.action(mock.sentinel.service, rules=[mock.sentinel.action])
         def test_policy(*args):
             raise exceptions.Forbidden()
 
@@ -125,7 +125,7 @@
         mock_authority.PolicyAuthority.return_value.allowed.return_value =\
             False
 
-        @rbac_rv.action(mock.sentinel.service, mock.sentinel.action)
+        @rbac_rv.action(mock.sentinel.service, rules=[mock.sentinel.action])
         def test_policy(*args):
             raise rbac_exceptions.RbacMalformedResponse()
 
@@ -143,7 +143,7 @@
         """
         mock_authority.PolicyAuthority.return_value.allowed.return_value = True
 
-        @rbac_rv.action(mock.sentinel.service, mock.sentinel.action)
+        @rbac_rv.action(mock.sentinel.service, rules=[mock.sentinel.action])
         def test_policy(*args):
             raise rbac_exceptions.RbacMalformedResponse()
 
@@ -165,7 +165,7 @@
         mock_authority.PolicyAuthority.return_value.allowed.return_value =\
             False
 
-        @rbac_rv.action(mock.sentinel.service, mock.sentinel.action)
+        @rbac_rv.action(mock.sentinel.service, rules=[mock.sentinel.action])
         def test_policy(*args):
             raise rbac_exceptions.RbacConflictingPolicies()
 
@@ -184,7 +184,7 @@
         """
         mock_authority.PolicyAuthority.return_value.allowed.return_value = True
 
-        @rbac_rv.action(mock.sentinel.service, mock.sentinel.action)
+        @rbac_rv.action(mock.sentinel.service, rules=[mock.sentinel.action])
         def test_policy(*args):
             raise rbac_exceptions.RbacConflictingPolicies()
 
@@ -206,7 +206,7 @@
         2) Test have permission and 404 is expected but 403 is thrown throws
            exception.
         """
-        @rbac_rv.action(mock.sentinel.service, mock.sentinel.action,
+        @rbac_rv.action(mock.sentinel.service, rules=[mock.sentinel.action],
                         expected_error_code=404)
         def test_policy(*args):
             raise exceptions.Forbidden('Test message')
@@ -236,14 +236,16 @@
         In both cases, a LOG.warning is called with the "irregular message"
         that signals to user that a 404 was expected and caught.
         """
-        @rbac_rv.action(mock.sentinel.service, mock.sentinel.action,
+        policy_names = ['foo:bar']
+
+        @rbac_rv.action(mock.sentinel.service, rules=policy_names,
                         expected_error_code=404)
         def test_policy(*args):
             raise exceptions.NotFound()
 
         expected_errors = [
             ("Role Member was not allowed to perform the following "
-             "actions: \[%s\].*" % (mock.sentinel.action)),
+             "actions: \['%s'\].*" % policy_names[0]),
             None
         ]
 
@@ -262,10 +264,12 @@
                 mock_log.error.assert_not_called()
 
             mock_log.warning.assert_called_with(
-                "NotFound exception was caught for policy action {0}. The "
-                "service {1} throws a 404 instead of a 403, which is "
-                "irregular.".format(mock.sentinel.action,
-                                    mock.sentinel.service))
+                "NotFound exception was caught for test %s. Expected policies "
+                "which may have caused the error: %s. The service %s throws a "
+                "404 instead of a 403, which is irregular.",
+                test_policy.__name__,
+                ', '.join(policy_names),
+                mock.sentinel.service)
 
             mock_log.warning.reset_mock()
             mock_log.error.reset_mock()
@@ -282,11 +286,11 @@
         mock_authority.PolicyAuthority.return_value.allowed.return_value =\
             False
 
-        @rbac_rv.action(mock.sentinel.service, mock.sentinel.action)
+        @rbac_rv.action(mock.sentinel.service, rules=[mock.sentinel.action])
         def test_policy_expect_forbidden(*args):
             pass
 
-        @rbac_rv.action(mock.sentinel.service, mock.sentinel.action,
+        @rbac_rv.action(mock.sentinel.service, rules=[mock.sentinel.action],
                         expected_error_code=404)
         def test_policy_expect_not_found(*args):
             pass
@@ -324,9 +328,10 @@
     def test_get_exception_type_404(self, _):
         """Test that getting a 404 exception type returns NotFound."""
         expected_exception = exceptions.NotFound
-        expected_irregular_msg = ("NotFound exception was caught for policy "
-                                  "action {0}. The service {1} throws a 404 "
-                                  "instead of a 403, which is irregular.")
+        expected_irregular_msg = (
+            "NotFound exception was caught for test %s. Expected policies "
+            "which may have caused the error: %s. The service %s throws a "
+            "404 instead of a 403, which is irregular.")
 
         actual_exception, actual_irregular_msg = \
             rbac_rv._get_exception_type(404)
@@ -371,6 +376,12 @@
 
             mock_log.error.reset_mock()
 
+
+class RBACRuleValidationLoggingTest(BaseRBACRuleValidationTest):
+    """Test class for validating the RBAC log, dedicated to just logging
+    Patrole RBAC validation work flows.
+    """
+
     @mock.patch.object(rbac_rv, 'RBACLOG', autospec=True)
     @mock.patch.object(rbac_rv, 'policy_authority', autospec=True)
     def test_rbac_report_logging_disabled(self, mock_authority, mock_rbaclog):
@@ -382,7 +393,7 @@
 
         mock_authority.PolicyAuthority.return_value.allowed.return_value = True
 
-        @rbac_rv.action(mock.sentinel.service, mock.sentinel.action)
+        @rbac_rv.action(mock.sentinel.service, rules=[mock.sentinel.action])
         def test_policy(*args):
             pass
 
@@ -399,17 +410,19 @@
             fixtures.ConfPatcher(enable_reporting=True, group='patrole_log'))
 
         mock_authority.PolicyAuthority.return_value.allowed.return_value = True
+        policy_names = ['foo:bar', 'baz:qux']
 
-        @rbac_rv.action(mock.sentinel.service, mock.sentinel.action)
+        @rbac_rv.action(mock.sentinel.service, rules=policy_names)
         def test_policy(*args):
             pass
 
         test_policy(self.mock_test_args)
         mock_rbaclog.info.assert_called_once_with(
-            "[Service]: %s, [Test]: %s, [Rule]: %s, "
+            "[Service]: %s, [Test]: %s, [Rules]: %s, "
             "[Expected]: %s, [Actual]: %s",
-            mock.sentinel.service, 'test_policy',
-            mock.sentinel.action,
+            mock.sentinel.service,
+            'test_policy',
+            ', '.join(policy_names),
             "Allowed",
             "Allowed")
 
@@ -583,8 +596,8 @@
         """
 
         rules = [
-            mock.sentinel.action1, mock.sentinel.action2,
-            mock.sentinel.action3, mock.sentinel.action4
+            'mock.sentinel.action1', 'mock.sentinel.action2',
+            'mock.sentinel.action3', 'mock.sentinel.action4'
         ]
         exp_ecodes = [403, 404, 403, 403]
 
@@ -603,8 +616,8 @@
             mock_log.error.assert_not_called()
             self._assert_policy_authority_called_with(rules, mock_authority)
 
-        _do_test([True, False, False, True], mock.sentinel.action2)
-        _do_test([True, False, True, False], mock.sentinel.action2)
+        _do_test([True, False, False, True], 'mock.sentinel.action2')
+        _do_test([True, False, True, False], 'mock.sentinel.action2')
 
     @mock.patch.object(rbac_rv, 'LOG', autospec=True)
     def test_prepare_multi_policy_allowed_usages(self, mock_log):