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)