Add a per-test log
This patch adds a new per-test logging feature to Patrole
To accomplish this, it adds two new config variables
The logging now prints a log message containing the results of each RBAC
test to a separate log file, as well as to the normal
tempest.log file. This message is of the form:
[Service] <nova, neutron, etc>
[Test] <name of the test's method>
followed by either the result of the test as Allowed/Denied/Error, or
the expected result (from oslopolicy) and then the actual result
There are two new config variables that control this, added in a new
config group called patrole_log:
enable_reporting - defaults to True, which enables this new logging
functionality
report_log_name - defaults to patrole.log, controls the name of the log
the output is written to.
report_log_path - Defaults to the local directory, path (relative or
absolute) where to store the log
Change-Id: Iff2176f1a7c7d10f78b96d748f1d70b222fd5072
diff --git a/HACKING.rst b/HACKING.rst
index 3bc8270..a94b47c 100644
--- a/HACKING.rst
+++ b/HACKING.rst
@@ -46,7 +46,7 @@
test does not call ``rbac_utils.switch_role`` with ``toggle_rbac_role=True``
within the RBAC test, then the test is *not* a valid RBAC test: The API
endpoint under test will be performed with admin credentials, which is always
-wrong unless ``CONF.rbac_test_role`` is admin.
+wrong unless ``CONF.patrole.rbac_test_role`` is admin.
.. note::
diff --git a/patrole_tempest_plugin/config.py b/patrole_tempest_plugin/config.py
index a53edd4..fcf29af 100644
--- a/patrole_tempest_plugin/config.py
+++ b/patrole_tempest_plugin/config.py
@@ -147,3 +147,23 @@
help="This group is deprecated and will be removed "
"in the next release. Use the [patrole] group "
"instead.")
+
+patrole_log_group = cfg.OptGroup(
+ name='patrole_log', title='Patrole Logging Options')
+
+PatroleLogGroup = [
+ cfg.BoolOpt('enable_reporting',
+ default=False,
+ help="Enables reporting on RBAC expected and actual test "
+ "results for each Patrole test"),
+ cfg.StrOpt('report_log_name',
+ default='patrole.log',
+ help="Name of file where output from 'enable_reporting' is "
+ "logged. Note that this file is recreated on each "
+ "invocation of patrole"),
+ cfg.StrOpt('report_log_path',
+ default='.',
+ help="Path (relative or absolute) where the output from "
+ "'enable_reporting' is logged. This is combined with"
+ "report_log_name to generate the full path."),
+]
diff --git a/patrole_tempest_plugin/plugin.py b/patrole_tempest_plugin/plugin.py
index 4bba037..b7717ea 100644
--- a/patrole_tempest_plugin/plugin.py
+++ b/patrole_tempest_plugin/plugin.py
@@ -13,15 +13,21 @@
# License for the specific language governing permissions and limitations
# under the License.
+import logging
import os
+from oslo_concurrency import lockutils
+
from tempest import config
from tempest.test_discover import plugins
from patrole_tempest_plugin import config as project_config
+RBACLOG = logging.getLogger('rbac_reporting')
+
class PatroleTempestPlugin(plugins.TempestPlugin):
+
def load_tests(self):
base_path = os.path.split(os.path.dirname(
os.path.abspath(__file__)))[0]
@@ -29,6 +35,32 @@
full_test_dir = os.path.join(base_path, test_dir)
return full_test_dir, base_path
+ @lockutils.synchronized('_reset_log_file')
+ def _reset_log_file(self, logfile):
+ try:
+ os.remove(logfile)
+ except OSError:
+ pass
+
+ def _configure_per_test_logging(self, conf):
+ # Separate log handler for rbac reporting
+ RBACLOG.setLevel(level=logging.INFO)
+ # Set up proper directory handling
+ report_abs_path = os.path.abspath(conf.patrole_log.report_log_path)
+ report_path = os.path.join(
+ report_abs_path, conf.patrole_log.report_log_name)
+
+ # Remove the log file if it exists
+ self._reset_log_file(report_path)
+
+ # Delay=True so that we don't end up creating an empty file if we
+ # never log to it.
+ rbac_report_handler = logging.FileHandler(
+ filename=report_path, delay=True, mode='a')
+ rbac_report_handler.setFormatter(
+ fmt=logging.Formatter(fmt='%(message)s'))
+ RBACLOG.addHandler(rbac_report_handler)
+
def register_opts(self, conf):
# TODO(fmontei): Remove ``rbac_group`` in a future release as it is
# currently deprecated.
@@ -40,6 +72,13 @@
conf,
project_config.patrole_group,
project_config.PatroleGroup)
+ config.register_opt_group(
+ conf,
+ project_config.patrole_log_group,
+ project_config.PatroleLogGroup)
+
+ if conf.patrole_log.enable_reporting:
+ self._configure_per_test_logging(conf)
def get_opt_lists(self):
return [(project_config.patrole_group.name,
diff --git a/patrole_tempest_plugin/rbac_rule_validation.py b/patrole_tempest_plugin/rbac_rule_validation.py
index d06986a..69a98e3 100644
--- a/patrole_tempest_plugin/rbac_rule_validation.py
+++ b/patrole_tempest_plugin/rbac_rule_validation.py
@@ -33,6 +33,8 @@
_SUPPORTED_ERROR_CODES = [403, 404]
+RBACLOG = logging.getLogger('rbac_reporting')
+
def action(service, rule='', admin_only=False, expected_error_code=403,
extra_target_data=None):
@@ -118,7 +120,7 @@
if extra_target_data is None:
extra_target_data = {}
- def decorator(func):
+ def decorator(test_func):
role = CONF.patrole.rbac_test_role
def wrapper(*args, **kwargs):
@@ -129,28 +131,26 @@
'`rbac_rule_validation` decorator can only be applied to '
'an instance of `tempest.test.BaseTestCase`.')
- if admin_only:
- LOG.info("As admin_only is True, only admin role should be "
- "allowed to perform the API. Skipping oslo.policy "
- "check for policy action {0}.".format(rule))
- allowed = rbac_utils.is_admin()
- else:
- allowed = _is_authorized(test_obj, service, rule,
- extra_target_data)
+ allowed = _is_authorized(test_obj, service, rule,
+ extra_target_data, admin_only)
expected_exception, irregular_msg = _get_exception_type(
expected_error_code)
+ test_status = 'Allowed'
+
try:
- func(*args, **kwargs)
+ test_func(*args, **kwargs)
except rbac_exceptions.RbacInvalidService as e:
msg = ("%s is not a valid service." % service)
+ test_status = ('Error, %s' % (msg))
LOG.error(msg)
raise exceptions.NotFound(
"%s RbacInvalidService was: %s" % (msg, e))
except (expected_exception,
rbac_exceptions.RbacConflictingPolicies,
rbac_exceptions.RbacMalformedResponse) as e:
+ test_status = 'Denied'
if irregular_msg:
LOG.warning(irregular_msg.format(rule, service))
if allowed:
@@ -162,9 +162,10 @@
except Exception as e:
exc_info = sys.exc_info()
error_details = exc_info[1].__str__()
- msg = ("%s An unexpected exception has occurred: Expected "
- "exception was %s, which was not thrown."
- % (error_details, expected_exception.__name__))
+ msg = ("An unexpected exception has occurred during test: %s, "
+ "Exception was: %s"
+ % (test_func.__name__, error_details))
+ test_status = ('Error, %s' % (error_details))
LOG.error(msg)
six.reraise(exc_info[0], exc_info[0](msg), exc_info[2])
else:
@@ -177,13 +178,20 @@
finally:
test_obj.rbac_utils.switch_role(test_obj,
toggle_rbac_role=False)
+ if CONF.patrole_log.enable_reporting:
+ RBACLOG.info(
+ "[Service]: %s, [Test]: %s, [Rule]: %s, "
+ "[Expected]: %s, [Actual]: %s",
+ service, test_func.__name__, rule,
+ "Allowed" if allowed else "Denied",
+ test_status)
_wrapper = testtools.testcase.attr(role)(wrapper)
return _wrapper
return decorator
-def _is_authorized(test_obj, service, rule, extra_target_data):
+def _is_authorized(test_obj, service, rule, extra_target_data, admin_only):
"""Validates whether current RBAC role has permission to do policy action.
:param test_obj: An instance or subclass of `tempest.base.BaseTestCase`.
@@ -195,8 +203,15 @@
`tempest.base.BaseTestCase` attributes. Used by `oslo.policy` for
performing matching against attributes that are sent along with the API
calls.
+ :param admin_only: Skips over `oslo.policy` check because the policy action
+ defined by `rule` is not enforced by the service's policy
+ enforcement engine. For example, Keystone v2 performs an admin check
+ for most of its endpoints. If True, `rule` is effectively
+ ignored.
+
:returns: True if the current RBAC role can perform the policy action,
else False.
+
:raises RbacResourceSetupFailed: If `project_id` or `user_id` are missing
from the `auth_provider` attribute in `test_obj`.
:raises RbacParsingException: if ``[patrole] strict_policy_check`` is True
@@ -204,6 +219,13 @@
:raises skipException: If ``[patrole] strict_policy_check`` is False and
the ``rule`` does not exist in the system.
"""
+
+ if admin_only:
+ LOG.info("As admin_only is True, only admin role should be "
+ "allowed to perform the API. Skipping oslo.policy "
+ "check for policy action {0}.".format(rule))
+ return rbac_utils.is_admin()
+
try:
project_id = test_obj.os_primary.credentials.project_id
user_id = test_obj.os_primary.credentials.user_id
@@ -260,7 +282,7 @@
irregular_msg = None
if not isinstance(expected_error_code, six.integer_types) \
- or expected_error_code not in _SUPPORTED_ERROR_CODES:
+ or expected_error_code not in _SUPPORTED_ERROR_CODES:
msg = ("Please pass an expected error code. Currently "
"supported codes: {0}".format(_SUPPORTED_ERROR_CODES))
LOG.error(msg)
diff --git a/patrole_tempest_plugin/tests/unit/fixtures.py b/patrole_tempest_plugin/tests/unit/fixtures.py
index 9d53eb9..ce13029 100644
--- a/patrole_tempest_plugin/tests/unit/fixtures.py
+++ b/patrole_tempest_plugin/tests/unit/fixtures.py
@@ -73,7 +73,7 @@
'os_primary.credentials.project_id': self.PROJECT_ID,
'get_identity_version.return_value': 'v3'
}
- self.mock_test_obj = mock.Mock(**test_obj_kwargs)
+ self.mock_test_obj = mock.Mock(__name__='foo', **test_obj_kwargs)
# Mock out functionality that can't be used by unit tests.
self.mock_time = mock.patch.object(rbac_utils, 'time').start()
diff --git a/patrole_tempest_plugin/tests/unit/test_rbac_policy_parser.py b/patrole_tempest_plugin/tests/unit/test_rbac_policy_parser.py
index 6f173a2..5fa26df 100644
--- a/patrole_tempest_plugin/tests/unit/test_rbac_policy_parser.py
+++ b/patrole_tempest_plugin/tests/unit/test_rbac_policy_parser.py
@@ -81,7 +81,7 @@
group='identity-feature-enabled')
def _get_fake_policy_rule(self, name, rule):
- fake_rule = mock.Mock(check=rule)
+ fake_rule = mock.Mock(check=rule, __name__='foo')
fake_rule.name = name
return fake_rule
@@ -291,6 +291,7 @@
parser = rbac_policy_parser.RbacPolicyParser(
test_tenant_id, test_user_id, "custom_rbac_policy")
parser.rules = mock.MagicMock(
+ __name__='foo',
**{'__getitem__.return_value.side_effect': Exception(
mock.sentinel.error)})
@@ -314,7 +315,7 @@
'rule:code_rule_3'),
]
- mock_manager = mock.Mock(obj=fake_policy_rules)
+ mock_manager = mock.Mock(obj=fake_policy_rules, __name__='foo')
mock_manager.configure_mock(name='fake_service')
mock_stevedore.named.NamedExtensionManager.return_value = [
mock_manager
@@ -355,7 +356,7 @@
'rule:code_rule_3'),
]
- mock_manager = mock.Mock(obj=fake_policy_rules)
+ mock_manager = mock.Mock(obj=fake_policy_rules, __name__='foo')
mock_manager.configure_mock(name='fake_service')
mock_stevedore.named.NamedExtensionManager.return_value = [
mock_manager
@@ -401,10 +402,10 @@
@mock.patch.object(rbac_policy_parser, 'stevedore', autospec=True)
def test_get_policy_data_without_valid_policy(self, mock_stevedore,
mock_json):
- test_policy_action = mock.Mock(check='rule:bar')
+ test_policy_action = mock.Mock(check='rule:bar', __name__='foo')
test_policy_action.configure_mock(name='foo')
- test_policy = mock.Mock(obj=[test_policy_action])
+ test_policy = mock.Mock(obj=[test_policy_action], __name__='foo')
test_policy.configure_mock(name='test_service')
mock_stevedore.named.NamedExtensionManager\
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 8a69ff6..0dcaaa7 100644
--- a/patrole_tempest_plugin/tests/unit/test_rbac_rule_validation.py
+++ b/patrole_tempest_plugin/tests/unit/test_rbac_rule_validation.py
@@ -40,6 +40,9 @@
CONF.set_override('rbac_test_role', 'Member', group='patrole')
self.addCleanup(CONF.clear_override, 'rbac_test_role', group='patrole')
+ self.mock_rbaclog = mock.patch.object(
+ rbac_rv.RBACLOG, 'info', autospec=False).start()
+
@mock.patch.object(rbac_rv, 'LOG', autospec=True)
@mock.patch.object(rbac_rv, 'rbac_policy_parser', autospec=True)
def test_rule_validation_have_permission_no_exc(self, mock_policy,
@@ -50,7 +53,7 @@
"""
decorator = rbac_rv.action(mock.sentinel.service, mock.sentinel.action)
- mock_function = mock.Mock()
+ mock_function = mock.Mock(__name__='foo')
wrapper = decorator(mock_function)
mock_policy.RbacPolicyParser.return_value.allowed.return_value = True
@@ -71,7 +74,7 @@
"""
decorator = rbac_rv.action(mock.sentinel.service, mock.sentinel.action)
- mock_function = mock.Mock()
+ mock_function = mock.Mock(__name__='foo')
mock_function.side_effect = exceptions.Forbidden
wrapper = decorator(mock_function)
@@ -93,7 +96,7 @@
raised.
"""
decorator = rbac_rv.action(mock.sentinel.service, mock.sentinel.action)
- mock_function = mock.Mock()
+ mock_function = mock.Mock(__name__='foo')
mock_function.side_effect = exceptions.Forbidden
wrapper = decorator(mock_function)
@@ -108,16 +111,15 @@
@mock.patch.object(rbac_rv, 'LOG', autospec=True)
@mock.patch.object(rbac_rv, 'rbac_policy_parser', autospec=True)
- def test_rule_validation_rbac_malformed_response_positive(self,
- mock_policy,
- mock_log):
+ def test_rule_validation_rbac_malformed_response_positive(
+ self, mock_policy, mock_log):
"""Test RbacMalformedResponse error is thrown without permission passes.
Positive test case: if RbacMalformedResponse is thrown and the user is
not allowed to perform the action, then this is a success.
"""
decorator = rbac_rv.action(mock.sentinel.service, mock.sentinel.action)
- mock_function = mock.Mock()
+ mock_function = mock.Mock(__name__='foo')
mock_function.side_effect = rbac_exceptions.RbacMalformedResponse
wrapper = decorator(mock_function)
@@ -131,16 +133,15 @@
@mock.patch.object(rbac_rv, 'LOG', autospec=True)
@mock.patch.object(rbac_rv, 'rbac_policy_parser', autospec=True)
- def test_rule_validation_rbac_malformed_response_negative(self,
- mock_policy,
- mock_log):
+ def test_rule_validation_rbac_malformed_response_negative(
+ self, mock_policy, mock_log):
"""Test RbacMalformedResponse error is thrown with permission fails.
Negative test case: if RbacMalformedResponse is thrown and the user is
allowed to perform the action, then this is an expected failure.
"""
decorator = rbac_rv.action(mock.sentinel.service, mock.sentinel.action)
- mock_function = mock.Mock()
+ mock_function = mock.Mock(__name__='foo')
mock_function.side_effect = rbac_exceptions.RbacMalformedResponse
wrapper = decorator(mock_function)
@@ -156,16 +157,15 @@
@mock.patch.object(rbac_rv, 'LOG', autospec=True)
@mock.patch.object(rbac_rv, 'rbac_policy_parser', autospec=True)
- def test_rule_validation_rbac_conflicting_policies_positive(self,
- mock_policy,
- mock_log):
+ def test_rule_validation_rbac_conflicting_policies_positive(
+ self, mock_policy, mock_log):
"""Test RbacConflictingPolicies error is thrown without permission passes.
Positive test case: if RbacConflictingPolicies is thrown and the user
is not allowed to perform the action, then this is a success.
"""
decorator = rbac_rv.action(mock.sentinel.service, mock.sentinel.action)
- mock_function = mock.Mock()
+ mock_function = mock.Mock(__name__='foo')
mock_function.side_effect = rbac_exceptions.RbacConflictingPolicies
wrapper = decorator(mock_function)
@@ -179,16 +179,15 @@
@mock.patch.object(rbac_rv, 'LOG', autospec=True)
@mock.patch.object(rbac_rv, 'rbac_policy_parser', autospec=True)
- def test_rule_validation_rbac_conflicting_policies_negative(self,
- mock_policy,
- mock_log):
+ def test_rule_validation_rbac_conflicting_policies_negative(
+ self, mock_policy, mock_log):
"""Test RbacConflictingPolicies error is thrown with permission fails.
Negative test case: if RbacConflictingPolicies is thrown and the user
is allowed to perform the action, then this is an expected failure.
"""
decorator = rbac_rv.action(mock.sentinel.service, mock.sentinel.action)
- mock_function = mock.Mock()
+ mock_function = mock.Mock(__name__='foo')
mock_function.side_effect = rbac_exceptions.RbacConflictingPolicies
wrapper = decorator(mock_function)
@@ -217,13 +216,12 @@
decorator = rbac_rv.action(mock.sentinel.service,
mock.sentinel.action,
expected_error_code=404)
- mock_function = mock.Mock()
+ mock_function = mock.Mock(__name__='foo')
mock_function.side_effect = exceptions.Forbidden('Random message.')
wrapper = decorator(mock_function)
- expected_error = "Forbidden\nDetails: Random message. An unexpected "\
- "exception has occurred: Expected exception was "\
- "NotFound, which was not thrown."
+ expected_error = "An unexpected exception has occurred during test: "\
+ "foo, Exception was: Forbidden\nDetails: Random message."
for permission in [True, False]:
mock_policy.RbacPolicyParser.return_value.allowed.return_value =\
@@ -237,7 +235,8 @@
@mock.patch.object(rbac_rv, 'LOG', autospec=True)
@mock.patch.object(rbac_rv, 'rbac_policy_parser', autospec=True)
- def test_expect_not_found_and_raise_not_found(self, mock_policy, mock_log):
+ def test_expect_not_found_and_raise_not_found(self, mock_policy,
+ mock_log):
"""Test that expecting 404 and getting 404 works for all scenarios.
Tests the following scenarios:
@@ -250,7 +249,7 @@
decorator = rbac_rv.action(mock.sentinel.service,
mock.sentinel.action,
expected_error_code=404)
- mock_function = mock.Mock()
+ mock_function = mock.Mock(__name__='foo')
mock_function.side_effect = exceptions.NotFound
wrapper = decorator(mock_function)
@@ -293,7 +292,7 @@
"""
decorator = rbac_rv.action(mock.sentinel.service, mock.sentinel.action)
- mock_function = mock.Mock()
+ mock_function = mock.Mock(__name__='foo')
wrapper = decorator(mock_function)
mock_policy.RbacPolicyParser.return_value.allowed.return_value = False
@@ -301,7 +300,7 @@
e = self.assertRaises(rbac_exceptions.RbacOverPermission, wrapper,
self.mock_args)
self.assertIn(("OverPermission: Role Member was allowed to perform "
- "sentinel.action"), e.__str__())
+ "sentinel.action"), e.__str__())
mock_log.error.assert_called_once_with(
'Role %s was allowed to perform %s', 'Member',
mock.sentinel.action)
@@ -319,7 +318,7 @@
decorator = rbac_rv.action(mock.sentinel.service,
mock.sentinel.policy_rule)
- wrapper = decorator(mock.Mock())
+ wrapper = decorator(mock.Mock(__name__='foo'))
e = self.assertRaises(rbac_exceptions.RbacParsingException, wrapper,
self.mock_args)
@@ -382,3 +381,51 @@
"codes: [403, 404]")
mock_log.error.reset_mock()
+
+ @mock.patch.object(rbac_rv, 'RBACLOG', autospec=True)
+ @mock.patch.object(rbac_rv, 'rbac_policy_parser', autospec=True)
+ def test_rbac_report_logging_disabled(self, mock_policy, mock_rbaclog):
+ """Test case to ensure that we DON'T write logs when
+ enable_reporting is False
+ """
+ CONF.set_override('enable_reporting', False, group='patrole_log')
+ self.addCleanup(CONF.clear_override,
+ 'enable_reporting', group='patrole_log')
+
+ decorator = rbac_rv.action(mock.sentinel.service, mock.sentinel.action)
+
+ mock_function = mock.Mock(__name__='foo-nolog')
+ wrapper = decorator(mock_function)
+
+ mock_policy.RbacPolicyParser.return_value.allowed.return_value = True
+
+ wrapper(self.mock_args)
+
+ self.assertFalse(mock_rbaclog.info.called)
+
+ @mock.patch.object(rbac_rv, 'RBACLOG', autospec=True)
+ @mock.patch.object(rbac_rv, 'rbac_policy_parser', autospec=True)
+ def test_rbac_report_logging_enabled(self, mock_policy, mock_rbaclog):
+ """Test case to ensure that we DO write logs when
+ enable_reporting is True
+ """
+ CONF.set_override('enable_reporting', True, group='patrole_log')
+ self.addCleanup(CONF.clear_override,
+ 'enable_reporting', group='patrole_log')
+
+ decorator = rbac_rv.action(mock.sentinel.service, mock.sentinel.action)
+
+ mock_function = mock.Mock(__name__='foo-log')
+ wrapper = decorator(mock_function)
+
+ mock_policy.RbacPolicyParser.return_value.allowed.return_value = True
+
+ wrapper(self.mock_args)
+
+ mock_rbaclog.info.assert_called_once_with(
+ "[Service]: %s, [Test]: %s, [Rule]: %s, "
+ "[Expected]: %s, [Actual]: %s",
+ mock.sentinel.service, 'foo-log',
+ mock.sentinel.action,
+ "Allowed",
+ "Allowed")
diff --git a/releasenotes/notes/rbac-per-test-log-071a530e957c1c26.yaml b/releasenotes/notes/rbac-per-test-log-071a530e957c1c26.yaml
new file mode 100644
index 0000000..b1d400c
--- /dev/null
+++ b/releasenotes/notes/rbac-per-test-log-071a530e957c1c26.yaml
@@ -0,0 +1,28 @@
+---
+features:
+ - |
+ Added in a new logging feature which logs the result of each Patrole test
+
+ The format of the new log output is:
+
+ "[Service]: %s, [Test]: %s, [Rule]: %s, [Expected]: %s, [Actual]: %s"
+
+ where each "%s" is a string that contains:
+
+ * [Service] - The openstack service being tested (Nova, Neutron, etc)
+ * [Test] - The name of the test function being invoked (eg: test_list_aggregate_rbac)
+ * [Rule] - The name of the rule the Patrole test is testing (eg: os_compute_api:os-aggregates)
+ * [Expected] - The expected outcome (one of Allowed/Denied)
+ * [Actual] - The actual outcome from the Patrole test (one of Allowed/Denied/Error)
+
+ This logging feature has two config variables:
+
+ These variables are part of a new config group ``patrole_log``
+
+ * enable_reporting:
+ This enables or disables the enhanced rbac reporting
+ * report_log_name:
+ This variable specifies the name of the log file to write
+ * report_log_path:
+ This variable specifies the path (relative or absolute)
+ of the log file to write