From f8a588a6a9a0536d7398ee5435d46685879ff1ad Mon Sep 17 00:00:00 2001 From: David Stanek Date: Wed, 3 Sep 2014 19:18:10 +0000 Subject: [PATCH] Extends hacking check for logging to verify i18n hints The original check would make sure that debug logging didn't use the translation function. The check will now make sure that none of the translation helpers are used for debug logging and that the correct helper is used for logging statements. bp more-code-style-automation Change-Id: I536de5f21fe82fa3426040b8a4cfa5b81bdd5a8b --- keystone/hacking/checks.py | 187 ++++++++++++++++++---- keystone/tests/ksfixtures/hacking.py | 222 ++++++++++++++++++++++++++ keystone/tests/test_hacking_checks.py | 35 +++- 3 files changed, 409 insertions(+), 35 deletions(-) diff --git a/keystone/hacking/checks.py b/keystone/hacking/checks.py index df1aa6ed85..4ae8907d88 100644 --- a/keystone/hacking/checks.py +++ b/keystone/hacking/checks.py @@ -137,23 +137,51 @@ class CheckForAssertingNoneEquality(BaseASTChecker): super(CheckForAssertingNoneEquality, self).generic_visit(node) -class CheckForTranslationsInDebugLogging(BaseASTChecker): +class CheckForLoggingIssues(BaseASTChecker): - CHECK_DESC = 'K005 Using translated string in debug logging' + DEBUG_CHECK_DESC = 'K005 Using translated string in debug logging' + NONDEBUG_CHECK_DESC = 'K006 Not using translating helper for logging' + EXCESS_HELPER_CHECK_DESC = 'K007 Using hints when _ is necessary' LOG_MODULES = ('logging', 'keystone.openstack.common.log') - I18N_MODULES = ('keystone.i18n._') + I18N_MODULES = ( + 'keystone.i18n._', + 'keystone.i18n._LI', + 'keystone.i18n._LW', + 'keystone.i18n._LE', + 'keystone.i18n._LC', + ) + TRANS_HELPER_MAP = { + 'debug': None, + 'info': '_LI', + 'warn': '_LW', + 'warning': '_LW', + 'error': '_LE', + 'exception': '_LE', + 'critical': '_LC', + } def __init__(self, tree, filename): - super(CheckForTranslationsInDebugLogging, self).__init__( - tree, filename) + super(CheckForLoggingIssues, self).__init__(tree, filename) self.logger_names = [] self.logger_module_names = [] - self.i18n_names = [] + self.i18n_names = {} # NOTE(dstanek): this kinda accounts for scopes when talking # about only leaf node in the graph - self.assignments = [] + self.assignments = {} + + def generic_visit(self, node): + """Called if no explicit visitor function exists for a node.""" + for field, value in ast.iter_fields(node): + if isinstance(value, list): + for item in value: + if isinstance(item, ast.AST): + item._parent = node + self.visit(item) + elif isinstance(value, ast.AST): + value._parent = node + self.visit(value) def _filter_imports(self, module_name, alias): """Keeps lists of logging and i18n imports @@ -162,18 +190,18 @@ class CheckForTranslationsInDebugLogging(BaseASTChecker): if module_name in self.LOG_MODULES: self.logger_module_names.append(alias.asname or alias.name) elif module_name in self.I18N_MODULES: - self.i18n_names.append(alias.asname or alias.name) + self.i18n_names[alias.asname or alias.name] = alias.name def visit_Import(self, node): for alias in node.names: self._filter_imports(alias.name, alias) - super(CheckForTranslationsInDebugLogging, self).generic_visit(node) + return super(CheckForLoggingIssues, self).generic_visit(node) def visit_ImportFrom(self, node): for alias in node.names: full_name = '%s.%s' % (node.module, alias.name) self._filter_imports(full_name, alias) - super(CheckForTranslationsInDebugLogging, self).generic_visit(node) + return super(CheckForLoggingIssues, self).generic_visit(node) def _find_name(self, node): """Return the fully qualified name or a Name or Attribute.""" @@ -194,38 +222,55 @@ class CheckForTranslationsInDebugLogging(BaseASTChecker): def visit_Assign(self, node): """Look for 'LOG = logging.getLogger' - This only handles the simple case: + This handles the simple case: name = [logging_module].getLogger(...) - or - name = [i18n_name](...) + And some much more comple ones: + name = [i18n_name](...) % X + + - or - + + self.name = [i18n_name](...) % X + """ attr_node_types = (ast.Name, ast.Attribute) if (len(node.targets) != 1 or not isinstance(node.targets[0], attr_node_types)): # say no to: "x, y = ..." - return + return super(CheckForLoggingIssues, self).generic_visit(node) target_name = self._find_name(node.targets[0]) + if (isinstance(node.value, ast.BinOp) and + isinstance(node.value.op, ast.Mod)): + if (isinstance(node.value.left, ast.Call) and + isinstance(node.value.left.func, ast.Name) and + node.value.left.func.id in self.i18n_names): + # NOTE(dstanek): this is done to match cases like: + # `msg = _('something %s') % x` + node = ast.Assign(value=node.value.left) + if not isinstance(node.value, ast.Call): # node.value must be a call to getLogger - return + self.assignments.pop(target_name, None) + return super(CheckForLoggingIssues, self).generic_visit(node) # is this a call to an i18n function? if (isinstance(node.value.func, ast.Name) and node.value.func.id in self.i18n_names): - self.assignments.append(target_name) - return + self.assignments[target_name] = node.value.func.id + return super(CheckForLoggingIssues, self).generic_visit(node) if (not isinstance(node.value.func, ast.Attribute) or not isinstance(node.value.func.value, attr_node_types)): # function must be an attribute on an object like # logging.getLogger - return + return super(CheckForLoggingIssues, self).generic_visit(node) object_name = self._find_name(node.value.func.value) func_name = node.value.func.attr @@ -234,8 +279,10 @@ class CheckForTranslationsInDebugLogging(BaseASTChecker): and func_name == 'getLogger'): self.logger_names.append(target_name) + return super(CheckForLoggingIssues, self).generic_visit(node) + def visit_Call(self, node): - """Look for the 'LOG.debug' calls. + """Look for the 'LOG.*' calls. """ @@ -248,30 +295,108 @@ class CheckForTranslationsInDebugLogging(BaseASTChecker): obj_name = self._find_name(node.func.value) method_name = node.func.attr else: # could be Subscript, Call or many more - return + return super(CheckForLoggingIssues, self).generic_visit(node) - # must be a logger instance and the debug method - if obj_name not in self.logger_names or method_name != 'debug': - return + # must be a logger instance and one of the support logging methods + if (obj_name not in self.logger_names + or method_name not in self.TRANS_HELPER_MAP): + return super(CheckForLoggingIssues, self).generic_visit(node) # the call must have arguments if not len(node.args): + return super(CheckForLoggingIssues, self).generic_visit(node) + + if method_name == 'debug': + self._process_debug(node) + elif method_name in self.TRANS_HELPER_MAP: + self._process_non_debug(node, method_name) + + return super(CheckForLoggingIssues, self).generic_visit(node) + + def _process_debug(self, node): + msg = node.args[0] # first arg to a logging method is the msg + + # if first arg is a call to a i18n name + if (isinstance(msg, ast.Call) + and isinstance(msg.func, ast.Name) + and msg.func.id in self.i18n_names): + self.add_error(msg, message=self.DEBUG_CHECK_DESC) + + # if the first arg is a reference to a i18n call + elif (isinstance(msg, ast.Name) + and msg.id in self.assignments + and not self._is_raised_later(node, msg.id)): + self.add_error(msg, message=self.DEBUG_CHECK_DESC) + + def _process_non_debug(self, node, method_name): + msg = node.args[0] # first arg to a logging method is the msg + + # if first arg is a call to a i18n name + if isinstance(msg, ast.Call): + func_name = msg.func.id + + # the function name is the correct translation helper + # for the logging method + if func_name == self.TRANS_HELPER_MAP[method_name]: return - # if first arg is a call to a i18n name - if (isinstance(node.args[0], ast.Call) - and isinstance(node.args[0].func, ast.Name) - and node.args[0].func.id in self.i18n_names): - self.add_error(node.args[0]) + # the function name is an alias for the correct translation + # helper for the loggine method + if (self.i18n_names[func_name] == + self.TRANS_HELPER_MAP[method_name]): + return - # if the first arg is a reference to a i18n call - elif (isinstance(node.args[0], ast.Name) - and node.args[0].id in self.assignments): - self.add_error(node.args[0]) + self.add_error(msg, message=self.NONDEBUG_CHECK_DESC) + + # if the first arg is not a reference to the correct i18n hint + elif isinstance(msg, ast.Name): + + # FIXME(dstanek): to make sure more robust we should be checking + # all names passed into a logging method. we can't right now + # because: + # 1. We have code like this that we'll fix when dealing with the %: + # msg = _('....') % {} + # LOG.warn(msg) + # 2. We also do LOG.exception(e) in several places. I'm not sure + # exactly what we should be doing about that. + if msg.id not in self.assignments: + return + + helper_method_name = self.TRANS_HELPER_MAP[method_name] + if (self.assignments[msg.id] != helper_method_name + and not self._is_raised_later(node, msg.id)): + self.add_error(msg, message=self.NONDEBUG_CHECK_DESC) + elif (self.assignments[msg.id] == helper_method_name + and self._is_raised_later(node, msg.id)): + self.add_error(msg, message=self.EXCESS_HELPER_CHECK_DESC) + + def _is_raised_later(self, node, name): + + def find_peers(node): + node_for_line = node._parent + for _field, value in ast.iter_fields(node._parent._parent): + if isinstance(value, list) and node_for_line in value: + return value[value.index(node_for_line) + 1:] + continue + return [] + + peers = find_peers(node) + for peer in peers: + if isinstance(peer, ast.Raise): + if (isinstance(peer.type, ast.Call) and + len(peer.type.args) > 0 and + isinstance(peer.type.args[0], ast.Name) and + name in (a.id for a in peer.type.args)): + return True + else: + return False + elif isinstance(peer, ast.Assign): + if name in (t.id for t in peer.targets): + return False def factory(register): register(CheckForMutableDefaultArgs) register(block_comments_begin_with_a_space) register(CheckForAssertingNoneEquality) - register(CheckForTranslationsInDebugLogging) + register(CheckForLoggingIssues) diff --git a/keystone/tests/ksfixtures/hacking.py b/keystone/tests/ksfixtures/hacking.py index 62c481358e..965ffd94c4 100644 --- a/keystone/tests/ksfixtures/hacking.py +++ b/keystone/tests/ksfixtures/hacking.py @@ -129,6 +129,24 @@ class HackingCode(fixtures.Fixture): # translation on a separate line msg = _('text') L2.debug(msg) + + # this should not fail + if True: + msg = _('message %s') % X + L2.error(msg) + raise TypeError(msg) + if True: + msg = 'message' + L2.debug(msg) + + # this should not fail + if True: + if True: + msg = _('message') + else: + msg = _('message') + L2.debug(msg) + raise Exception(msg) """, 'expected_errors': [ (10, 9, 'K005'), @@ -139,3 +157,207 @@ class HackingCode(fixtures.Fixture): (36, 9, 'K005'), ] } + + +class HackingLogging(fixtures.Fixture): + + shared_imports = """ + import logging + import logging as stlib_logging + from keystone.i18n import _ + from keystone.i18n import _ as oslo_i18n + from keystone.i18n import _LC + from keystone.i18n import _LE + from keystone.i18n import _LE as error_hint + from keystone.i18n import _LI + from keystone.i18n import _LW + from keystone.openstack.common import log + from keystone.openstack.common import log as oslo_logging + """ + + examples = [ + { + 'code': """ + # stdlib logging + LOG = logging.getLogger() + LOG.info(_('text')) + class C: + def __init__(self): + LOG.warn(oslo_i18n('text', {})) + LOG.warn(_LW('text', {})) + """, + 'expected_errors': [ + (3, 9, 'K006'), + (6, 17, 'K006'), + ], + }, + { + 'code': """ + # stdlib logging w/ alias and specifying a logger + class C: + def __init__(self): + self.L = logging.getLogger(__name__) + def m(self): + self.L.warning( + _('text'), {} + ) + self.L.warning( + _LW('text'), {} + ) + """, + 'expected_errors': [ + (7, 12, 'K006'), + ], + }, + { + 'code': """ + # oslo logging and specifying a logger + L = log.getLogger(__name__) + L.error(oslo_i18n('text')) + L.error(error_hint('text')) + """, + 'expected_errors': [ + (3, 8, 'K006'), + ], + }, + { + 'code': """ + # oslo logging w/ alias + class C: + def __init__(self): + self.LOG = oslo_logging.getLogger() + self.LOG.critical(_('text')) + self.LOG.critical(_LC('text')) + """, + 'expected_errors': [ + (5, 26, 'K006'), + ], + }, + { + 'code': """ + LOG = log.getLogger(__name__) + # translation on a separate line + msg = _('text') + LOG.exception(msg) + msg = _LE('text') + LOG.exception(msg) + """, + 'expected_errors': [ + (4, 14, 'K006'), + ], + }, + { + 'code': """ + LOG = logging.getLogger() + + # ensure the correct helper is being used + LOG.warn(_LI('this should cause an error')) + + # debug should not allow any helpers either + LOG.debug(_LI('this should cause an error')) + """, + 'expected_errors': [ + (4, 9, 'K006'), + (7, 10, 'K005'), + ], + }, + { + 'code': """ + # this should not be an error + L = log.getLogger(__name__) + msg = _('text') + L.warn(msg) + raise Exception(msg) + """, + 'expected_errors': [], + }, + { + 'code': """ + L = log.getLogger(__name__) + def f(): + msg = _('text') + L2.warn(msg) + something = True # add an extra statement here + raise Exception(msg) + """, + 'expected_errors': [], + }, + { + 'code': """ + LOG = log.getLogger(__name__) + def func(): + msg = _('text') + LOG.warn(msg) + raise Exception('some other message') + """, + 'expected_errors': [ + (4, 13, 'K006'), + ], + }, + { + 'code': """ + LOG = log.getLogger(__name__) + if True: + msg = _('text') + else: + msg = _('text') + LOG.warn(msg) + raise Exception(msg) + """, + 'expected_errors': [ + ], + }, + { + 'code': """ + LOG = log.getLogger(__name__) + if True: + msg = _('text') + else: + msg = _('text') + LOG.warn(msg) + """, + 'expected_errors': [ + (6, 9, 'K006'), + ], + }, + { + 'code': """ + LOG = log.getLogger(__name__) + msg = _LW('text') + LOG.warn(msg) + raise Exception(msg) + """, + 'expected_errors': [ + (3, 9, 'K007'), + ], + }, + { + 'code': """ + LOG = log.getLogger(__name__) + msg = _LW('text') + LOG.warn(msg) + msg = _('something else') + raise Exception(msg) + """, + 'expected_errors': [], + }, + { + 'code': """ + LOG = log.getLogger(__name__) + msg = _LW('hello %s') % 'world' + LOG.warn(msg) + raise Exception(msg) + """, + 'expected_errors': [ + (3, 9, 'K007'), + ], + }, + { + 'code': """ + LOG = log.getLogger(__name__) + msg = _LW('hello %s') % 'world' + LOG.warn(msg) + """, + 'expected_errors': [], + }, + ] diff --git a/keystone/tests/test_hacking_checks.py b/keystone/tests/test_hacking_checks.py index 3db26a3731..48d172ce0e 100644 --- a/keystone/tests/test_hacking_checks.py +++ b/keystone/tests/test_hacking_checks.py @@ -24,13 +24,16 @@ class BaseStyleCheck(testtools.TestCase): def setUp(self): super(BaseStyleCheck, self).setUp() - self.code_ex = self.useFixture(hacking_fixtures.HackingCode()) + self.code_ex = self.useFixture(self.get_fixture()) self.addCleanup(delattr, self, 'code_ex') def get_checker(self): """Returns the checker to be used for tests in this class.""" raise NotImplemented('subclasses must provide a real implementation') + def get_fixture(self): + return hacking_fixtures.HackingCode() + # We are patching pep8 so that only the check under test is actually # installed. @mock.patch('pep8._checks', @@ -83,13 +86,37 @@ class TestAssertingNoneEquality(BaseStyleCheck): self.assert_has_errors(code, expected_errors=errors) -class TestCheckForTranslationsInDebugLogging(BaseStyleCheck): +class TestCheckForDebugLoggingIssues(BaseStyleCheck): def get_checker(self): - return checks.CheckForTranslationsInDebugLogging + return checks.CheckForLoggingIssues - def test(self): + def test_for_translations(self): fixture = self.code_ex.assert_no_translations_for_debug_logging code = fixture['code'] errors = fixture['expected_errors'] self.assert_has_errors(code, expected_errors=errors) + + +class TestCheckForNonDebugLoggingIssues(BaseStyleCheck): + + def get_checker(self): + return checks.CheckForLoggingIssues + + def get_fixture(self): + return hacking_fixtures.HackingLogging() + + def test_for_translations(self): + for example in self.code_ex.examples: + code = self.code_ex.shared_imports + example['code'] + errors = example['expected_errors'] + self.assert_has_errors(code, expected_errors=errors) + + def assert_has_errors(self, code, expected_errors=None): + # pull out the parts of the error that we'll match against + actual_errors = (e[:3] for e in self.run_check(code)) + # adjust line numbers to make the fixure data more readable. + import_lines = len(self.code_ex.shared_imports.split('\n')) - 1 + actual_errors = [(e[0] - import_lines, e[1], e[2]) + for e in actual_errors] + self.assertEqual(expected_errors or [], actual_errors)