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
This commit is contained in:
Sean Pryor 2017-08-14 12:53:17 -04:00
parent 472b84c9bc
commit 7f8993fe3c
8 changed files with 207 additions and 50 deletions

View File

@ -46,7 +46,7 @@ Correct role switching is vital to correct RBAC testing within Patrole. If a
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::

View File

@ -147,3 +147,23 @@ rbac_group = cfg.OptGroup(name='rbac',
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."),
]

View File

@ -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 @@ class PatroleTempestPlugin(plugins.TempestPlugin):
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 @@ class PatroleTempestPlugin(plugins.TempestPlugin):
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,

View File

@ -33,6 +33,8 @@ LOG = logging.getLogger(__name__)
_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 @@ def action(service, rule='', admin_only=False, expected_error_code=403,
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 @@ def action(service, rule='', admin_only=False, expected_error_code=403,
'`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 @@ def action(service, rule='', admin_only=False, expected_error_code=403,
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 @@ def action(service, rule='', admin_only=False, expected_error_code=403,
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 @@ def _is_authorized(test_obj, service, rule, extra_target_data):
`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 @@ def _is_authorized(test_obj, service, rule, extra_target_data):
: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 @@ def _get_exception_type(expected_error_code=403):
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)

View File

@ -73,7 +73,7 @@ class RbacUtilsFixture(fixtures.Fixture):
'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()

View File

@ -81,7 +81,7 @@ class RbacPolicyTest(base.TestCase):
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 @@ class RbacPolicyTest(base.TestCase):
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 @@ class RbacPolicyTest(base.TestCase):
'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 @@ class RbacPolicyTest(base.TestCase):
'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 @@ class RbacPolicyTest(base.TestCase):
@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\

View File

@ -40,6 +40,9 @@ class RBACRuleValidationTest(base.TestCase):
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 @@ class RBACRuleValidationTest(base.TestCase):
"""
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 @@ class RBACRuleValidationTest(base.TestCase):
"""
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 @@ class RBACRuleValidationTest(base.TestCase):
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 @@ class RBACRuleValidationTest(base.TestCase):
@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 @@ class RBACRuleValidationTest(base.TestCase):
@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 @@ class RBACRuleValidationTest(base.TestCase):
@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 @@ class RBACRuleValidationTest(base.TestCase):
@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 @@ class RBACRuleValidationTest(base.TestCase):
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 @@ class RBACRuleValidationTest(base.TestCase):
@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 @@ class RBACRuleValidationTest(base.TestCase):
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 @@ class RBACRuleValidationTest(base.TestCase):
"""
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 @@ class RBACRuleValidationTest(base.TestCase):
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 @@ class RBACRuleValidationTest(base.TestCase):
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 @@ class RBACRuleValidationTest(base.TestCase):
"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")

View File

@ -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