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
This commit is contained in:
David Stanek 2014-09-03 19:18:10 +00:00
parent e709b98201
commit f8a588a6a9
3 changed files with 409 additions and 35 deletions

View File

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

View File

@ -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': [],
},
]

View File

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