Enforce log hints

This change enforces log hints use and removes debug level log
translation, modifications are validated through a hacking rule
and the change respects logging guidelines.

Change-Id: Ia4e6659b8b59732d88cd603b0e6c630fad37aae5
Closes-bug: #1320867
This commit is contained in:
Cedric Brandily 2014-12-07 21:35:16 +01:00
parent 7bdbd6f334
commit 32ef5da488
11 changed files with 82 additions and 148 deletions

View File

@ -32,7 +32,7 @@ class NeutronKeystoneContext(wsgi.Middleware):
# Determine the user ID
user_id = req.headers.get('X_USER_ID')
if not user_id:
LOG.debug(_("X_USER_ID is not found in request"))
LOG.debug("X_USER_ID is not found in request")
return webob.exc.HTTPUnauthorized()
# Determine the tenant

View File

@ -80,8 +80,7 @@ class ContextBase(common_context.RequestContext):
# Log only once the context has been configured to prevent
# format errors.
if kwargs:
LOG.debug(_('Arguments dropped when creating '
'context: %s'), kwargs)
LOG.debug('Arguments dropped when creating context: %s', kwargs)
@property
def project_id(self):

View File

@ -31,8 +31,6 @@ Guidelines for writing new hacking checks
"""
log_translation = re.compile(
r"(.)*LOG\.(audit|error|info|warn|warning|critical|exception)\(\s*('|\")")
author_tag_re = (re.compile("^\s*#\s*@?(a|A)uthor"),
re.compile("^\.\.\s+moduleauthor::"))
_all_hints = set(['_', '_LI', '_LE', '_LW', '_LC'])
@ -55,64 +53,17 @@ for level, hint in _all_log_levels.iteritems():
log_translation_hints.append(re.compile(r))
def _directory_to_check_translation(filename):
# In order to try and speed up the integration of this we will
# do it on a directory by directory basis. The last patch of the
# series will remove this and the entire code base will be validated.
dirs = ["neutron/agent",
"neutron/api",
"neutron/cmd",
"neutron/common",
"neutron/db",
"neutron/debug",
"neutron/extensions",
"neutron/hacking",
"neutron/locale",
"neutron/notifiers",
"neutron/openstack",
"neutron/scheduler",
"neutron/server",
"neutron/services",
#"neutron/plugins",
"neutron/plugins/bigswitch",
"neutron/plugins/brocade",
"neutron/plugins/cisco",
"neutron/plugins/common",
"neutron/plugins/embrane",
"neutron/plugins/hyperv",
"neutron/plugins/ibm",
"neutron/plugins/linuxbridge",
"neutron/plugins/metaplugin",
"neutron/plugins/midonet",
"neutron/plugins/ml2",
"neutron/plugins/mlnx",
"neutron/plugins/nec",
"neutron/plugins/nuage",
"neutron/plugins/ofagent",
"neutron/plugins/oneconvergence",
"neutron/plugins/opencontrail",
"neutron/plugins/openvswitch",
"neutron/plugins/plumgrid",
"neutron/plugins/sriovnicagent",
"neutron/plugins/vmware"]
return any([dir in filename for dir in dirs])
def validate_log_translations(logical_line, physical_line, filename):
# Translations are not required in the test directory
if "neutron/tests" in filename:
return
if pep8.noqa(physical_line):
return
msg = "N320: Log messages require translations!"
if log_translation.match(logical_line):
yield (0, msg)
if _directory_to_check_translation(filename):
msg = "N320: Log messages require translation hints!"
for log_translation_hint in log_translation_hints:
if log_translation_hint.match(logical_line):
yield (0, msg)
msg = "N320: Log messages require translation hints!"
for log_translation_hint in log_translation_hints:
if log_translation_hint.match(logical_line):
yield (0, msg)
def use_jsonutils(logical_line, filename):
@ -156,10 +107,9 @@ def no_translate_debug_logs(logical_line, filename):
* This check assumes that 'LOG' is a logger.
N319
"""
if _directory_to_check_translation(filename):
for hint in _all_hints:
if logical_line.startswith("LOG.debug(%s(" % hint):
yield(0, "N319 Don't translate debug level logs")
for hint in _all_hints:
if logical_line.startswith("LOG.debug(%s(" % hint):
yield(0, "N319 Don't translate debug level logs")
def check_assert_called_once_with(logical_line, filename):

View File

@ -20,6 +20,7 @@ from oslo import messaging
from oslo.utils import importutils
from neutron.common import utils
from neutron.i18n import _LE, _LI
from neutron.openstack.common import log as logging
from neutron.openstack.common import periodic_task
from neutron.plugins.common import constants
@ -109,7 +110,7 @@ class NeutronManager(object):
# intentionally to allow v2 plugins to be monitored
# for performance metrics.
plugin_provider = cfg.CONF.core_plugin
LOG.info(_("Loading core plugin: %s"), plugin_provider)
LOG.info(_LI("Loading core plugin: %s"), plugin_provider)
self.plugin = self._get_plugin_instance('neutron.core_plugins',
plugin_provider)
msg = validate_post_plugin_load()
@ -134,14 +135,14 @@ class NeutronManager(object):
try:
plugin_class = importutils.import_class(plugin_provider)
except ImportError as e2:
LOG.exception(_("Error loading plugin by name, %s"), e1)
LOG.exception(_("Error loading plugin by class, %s"), e2)
LOG.exception(_LE("Error loading plugin by name, %s"), e1)
LOG.exception(_LE("Error loading plugin by class, %s"), e2)
raise ImportError(_("Plugin not found."))
return plugin_class()
def _load_services_from_core_plugin(self):
"""Puts core plugin in service_plugins for supported services."""
LOG.debug(_("Loading services supported by the core plugin"))
LOG.debug("Loading services supported by the core plugin")
# supported service types are derived from supported extensions
for ext_alias in getattr(self.plugin,
@ -149,7 +150,7 @@ class NeutronManager(object):
if ext_alias in constants.EXT_TO_SERVICE_MAPPING:
service_type = constants.EXT_TO_SERVICE_MAPPING[ext_alias]
self.service_plugins[service_type] = self.plugin
LOG.info(_("Service %s is supported by the core plugin"),
LOG.info(_LI("Service %s is supported by the core plugin"),
service_type)
def _load_service_plugins(self):
@ -162,12 +163,12 @@ class NeutronManager(object):
self._load_services_from_core_plugin()
plugin_providers = cfg.CONF.service_plugins
LOG.debug(_("Loading service plugins: %s"), plugin_providers)
LOG.debug("Loading service plugins: %s", plugin_providers)
for provider in plugin_providers:
if provider == '':
continue
LOG.info(_("Loading Plugin: %s"), provider)
LOG.info(_LI("Loading Plugin: %s"), provider)
plugin_inst = self._get_plugin_instance('neutron.service_plugins',
provider)
@ -187,8 +188,8 @@ class NeutronManager(object):
hasattr(plugin_inst, 'agent_notifiers')):
self.plugin.agent_notifiers.update(plugin_inst.agent_notifiers)
LOG.debug(_("Successfully loaded %(type)s plugin. "
"Description: %(desc)s"),
LOG.debug("Successfully loaded %(type)s plugin. "
"Description: %(desc)s",
{"type": plugin_inst.get_plugin_type(),
"desc": plugin_inst.get_plugin_description()})

View File

@ -168,8 +168,8 @@ def _build_subattr_match_rule(attr_name, attr, action, target):
return
data = validate[key[0]]
if not isinstance(data, dict):
LOG.debug(_("Attribute type descriptor is not a dict. Unable to "
"generate any sub-attr policy rule for %s."),
LOG.debug("Attribute type descriptor is not a dict. Unable to "
"generate any sub-attr policy rule for %s.",
attr_name)
return
sub_attr_rules = [policy.RuleCheck('rule', '%s:%s:%s' %
@ -275,7 +275,7 @@ class OwnerCheck(policy.Check):
parent_res, parent_field = do_split(separator)
break
except ValueError:
LOG.debug(_("Unable to find ':' as separator in %s."),
LOG.debug("Unable to find ':' as separator in %s.",
self.target_field)
else:
# If we are here split failed with both separators
@ -346,10 +346,9 @@ class FieldCheck(policy.Check):
target_value = target_dict.get(self.field)
# target_value might be a boolean, explicitly compare with None
if target_value is None:
LOG.debug(_("Unable to find requested field: %(field)s in "
"target: %(target_dict)s"),
{'field': self.field,
'target_dict': target_dict})
LOG.debug("Unable to find requested field: %(field)s in target: "
"%(target_dict)s",
{'field': self.field, 'target_dict': target_dict})
return False
return target_value == self.value

View File

@ -21,6 +21,7 @@ from oslo.utils import importutils
import webob
from neutron.common import exceptions
from neutron.i18n import _LI, _LW
from neutron.openstack.common import log as logging
LOG = logging.getLogger(__name__)
@ -223,12 +224,12 @@ class QuotaEngine(object):
QUOTA_DB_MODULE not in sys.modules):
# If quotas table is not loaded, force config quota driver.
_driver_class = QUOTA_CONF_DRIVER
LOG.info(_("ConfDriver is used as quota_driver because the "
"loaded plugin does not support 'quotas' table."))
LOG.info(_LI("ConfDriver is used as quota_driver because the "
"loaded plugin does not support 'quotas' table."))
if isinstance(_driver_class, basestring):
_driver_class = importutils.import_object(_driver_class)
self._driver = _driver_class
LOG.info(_('Loaded quota_driver: %s.'), _driver_class)
LOG.info(_LI('Loaded quota_driver: %s.'), _driver_class)
return self._driver
def __contains__(self, resource):
@ -237,7 +238,7 @@ class QuotaEngine(object):
def register_resource(self, resource):
"""Register a resource."""
if resource.name in self._resources:
LOG.warn(_('%s is already registered.'), resource.name)
LOG.warn(_LW('%s is already registered.'), resource.name)
return
self._resources[resource.name] = resource

View File

@ -27,6 +27,7 @@ from neutron.common import config
from neutron.common import rpc as n_rpc
from neutron import context
from neutron.db import api as session
from neutron.i18n import _LE, _LI
from neutron import manager
from neutron.openstack.common import log as logging
from neutron.openstack.common import loopingcall
@ -102,8 +103,8 @@ def serve_wsgi(cls):
service.start()
except Exception:
with excutils.save_and_reraise_exception():
LOG.exception(_('Unrecoverable error: please check log '
'for details.'))
LOG.exception(_LE('Unrecoverable error: please check log '
'for details.'))
return service
@ -141,11 +142,11 @@ def serve_rpc():
# simpler to check this up front by testing whether the plugin supports
# multiple RPC workers.
if not plugin.rpc_workers_supported():
LOG.debug(_("Active plugin doesn't implement start_rpc_listeners"))
LOG.debug("Active plugin doesn't implement start_rpc_listeners")
if 0 < cfg.CONF.rpc_workers:
msg = _("'rpc_workers = %d' ignored because start_rpc_listeners "
"is not implemented.")
LOG.error(msg, cfg.CONF.rpc_workers)
LOG.error(_LE("'rpc_workers = %d' ignored because "
"start_rpc_listeners is not implemented."),
cfg.CONF.rpc_workers)
raise NotImplementedError()
try:
@ -160,23 +161,22 @@ def serve_rpc():
return launcher
except Exception:
with excutils.save_and_reraise_exception():
LOG.exception(_('Unrecoverable error: please check log '
'for details.'))
LOG.exception(_LE('Unrecoverable error: please check log for '
'details.'))
def _run_wsgi(app_name):
app = config.load_paste_app(app_name)
if not app:
LOG.error(_('No known API applications configured.'))
LOG.error(_LE('No known API applications configured.'))
return
server = wsgi.Server("Neutron")
server.start(app, cfg.CONF.bind_port, cfg.CONF.bind_host,
workers=cfg.CONF.api_workers)
# Dump all option values here after all options are parsed
cfg.CONF.log_opt_values(LOG, std_logging.DEBUG)
LOG.info(_("Neutron service started, listening on %(host)s:%(port)s"),
{'host': cfg.CONF.bind_host,
'port': cfg.CONF.bind_port})
LOG.info(_LI("Neutron service started, listening on %(host)s:%(port)s"),
{'host': cfg.CONF.bind_host, 'port': cfg.CONF.bind_port})
return server
@ -275,8 +275,7 @@ class Service(n_rpc.Service):
try:
x.stop()
except Exception:
LOG.exception(_("Exception occurs when timer stops"))
pass
LOG.exception(_LE("Exception occurs when timer stops"))
self.timers = []
def wait(self):
@ -285,8 +284,7 @@ class Service(n_rpc.Service):
try:
x.wait()
except Exception:
LOG.exception(_("Exception occurs when waiting for timer"))
pass
LOG.exception(_LE("Exception occurs when waiting for timer"))
def periodic_tasks(self, raise_on_error=False):
"""Tasks to be run at a periodic interval."""

View File

@ -67,8 +67,8 @@ class HTTPConnectionMock(object):
self.response = HTTPResponseMock500(None, errmsg=errmsg)
def request(self, action, uri, body, headers):
LOG.debug(_("Request: action=%(action)s, uri=%(uri)r, "
"body=%(body)s, headers=%(headers)s"),
LOG.debug("Request: action=%(action)s, uri=%(uri)r, "
"body=%(body)s, headers=%(headers)s",
{'action': action, 'uri': uri,
'body': body, 'headers': headers})
if self.broken and "ExceptOnBadServer" in uri:

View File

@ -75,7 +75,7 @@ class StubOFCDriver(ofc_driver_base.OFCDriverBase):
if self.autocheck:
raise Exception(_('(delete_tenant) OFC tenant %s not found')
% ofc_tenant_id)
LOG.debug(_('delete_tenant: SUCCEED'))
LOG.debug('delete_tenant: SUCCEED')
@call_log.log
def create_network(self, ofc_tenant_id, description, network_id=None):
@ -100,7 +100,7 @@ class StubOFCDriver(ofc_driver_base.OFCDriverBase):
% ofc_network_id)
data = {'description': description}
self.ofc_network_dict[ofc_network_id].update(data)
LOG.debug(_('update_network: SUCCEED'))
LOG.debug('update_network: SUCCEED')
@call_log.log
def delete_network(self, ofc_network_id):
@ -110,7 +110,7 @@ class StubOFCDriver(ofc_driver_base.OFCDriverBase):
if self.autocheck:
raise Exception(_('(delete_network) OFC network %s not found')
% ofc_network_id)
LOG.debug(_('delete_network: SUCCEED'))
LOG.debug('delete_network: SUCCEED')
@call_log.log
def create_port(self, ofc_network_id, info, port_id=None, filters=None):
@ -136,7 +136,7 @@ class StubOFCDriver(ofc_driver_base.OFCDriverBase):
if self.autocheck:
raise Exception(_('(delete_port) OFC port %s not found')
% ofc_port_id)
LOG.debug(_('delete_port: SUCCEED'))
LOG.debug('delete_port: SUCCEED')
@classmethod
def filter_supported(cls):
@ -190,7 +190,7 @@ class StubOFCDriver(ofc_driver_base.OFCDriverBase):
if self.autocheck:
raise Exception(_('(delete_router) OFC router %s not found')
% ofc_router_id)
LOG.debug(_('delete_router: SUCCEED'))
LOG.debug('delete_router: SUCCEED')
@call_log.log
def add_router_interface(self, ofc_router_id, ofc_net_id,
@ -213,7 +213,7 @@ class StubOFCDriver(ofc_driver_base.OFCDriverBase):
'network_id': ofc_net_id,
'ip_address': ip_address,
'mac_address': mac_address}
LOG.debug(_('add_router_interface: SUCCEED (if_id=%s)'), if_id)
LOG.debug('add_router_interface: SUCCEED (if_id=%s)', if_id)
return if_id
@call_log.log
@ -230,7 +230,7 @@ class StubOFCDriver(ofc_driver_base.OFCDriverBase):
inf.update({'ip_address': ip_address})
if mac_address:
inf.update({'mac_address': mac_address})
LOG.debug(_('update_router_route: SUCCEED'))
LOG.debug('update_router_route: SUCCEED')
@call_log.log
def delete_router_interface(self, ofc_router_inf_id):
@ -241,7 +241,7 @@ class StubOFCDriver(ofc_driver_base.OFCDriverBase):
raise Exception(_('(delete_router_interface) '
'OFC router interface %s not found')
% ofc_router_inf_id)
LOG.debug(_('delete_router_interface: SUCCEED'))
LOG.debug('delete_router_interface: SUCCEED')
@call_log.log
def add_router_route(self, ofc_router_id, destination, nexthop):
@ -261,7 +261,7 @@ class StubOFCDriver(ofc_driver_base.OFCDriverBase):
self.ofc_router_route_dict[route_id] = {'router_id': ofc_router_id,
'destination': destination,
'nexthop': nexthop}
LOG.debug(_('add_router_route: SUCCEED (route_id=%s)'), route_id)
LOG.debug('add_router_route: SUCCEED (route_id=%s)', route_id)
return route_id
@call_log.log
@ -272,7 +272,7 @@ class StubOFCDriver(ofc_driver_base.OFCDriverBase):
if self.autocheck:
raise Exception(_('(delete_router_route) OFC router route %s '
'not found') % ofc_router_route_id)
LOG.debug(_('delete_router_route: SUCCEED'))
LOG.debug('delete_router_route: SUCCEED')
@call_log.log
def list_router_routes(self, ofc_router_id):
@ -285,5 +285,5 @@ class StubOFCDriver(ofc_driver_base.OFCDriverBase):
'nexthop': v['nexthop']}
for k, v in self.ofc_router_route_dict.items()
if v['router_id'] == ofc_router_id]
LOG.debug(_('list_router_routes: routes=%s'), routes)
LOG.debug('list_router_routes: routes=%s', routes)
return routes

View File

@ -27,8 +27,6 @@ class HackingTestCase(base.BaseTestCase):
'exception': '_LE',
}
logs = expected_marks.keys()
levels = ['_LI', '_LW', '_LE', '_LC']
all_marks = levels + ['_']
debug = "LOG.debug('OK')"
self.assertEqual(
0, len(list(checks.validate_log_translations(debug, debug, 'f'))))
@ -36,35 +34,25 @@ class HackingTestCase(base.BaseTestCase):
bad = 'LOG.%s("Bad")' % log
self.assertEqual(
1, len(list(checks.validate_log_translations(bad, bad, 'f'))))
ok = "LOG.%s(_('OK'))" % log
self.assertEqual(
0, len(list(checks.validate_log_translations(ok, ok, 'f'))))
ok = "LOG.%s('OK') # noqa" % log
self.assertEqual(
0, len(list(checks.validate_log_translations(ok, ok, 'f'))))
ok = "LOG.%s(variable)" % log
self.assertEqual(
0, len(list(checks.validate_log_translations(ok, ok, 'f'))))
for level in levels:
ok = "LOG.%s(%s('OK'))" % (log, level)
self.assertEqual(
0, len(list(checks.validate_log_translations(ok,
ok, 'f'))))
filename = 'neutron/agent/f'
for mark in all_marks:
for mark in checks._all_hints:
stmt = "LOG.%s(%s('test'))" % (log, mark)
self.assertEqual(
0 if expected_marks[log] == mark else 1,
len(list(checks.validate_log_translations(stmt,
stmt,
filename))))
len(list(checks.validate_log_translations(stmt, stmt,
'f'))))
def test_no_translate_debug_logs(self):
filename = 'neutron/agent/f'
for hint in checks._all_hints:
bad = "LOG.debug(%s('bad'))" % hint
self.assertEqual(
1, len(list(checks.no_translate_debug_logs(bad, filename))))
1, len(list(checks.no_translate_debug_logs(bad, 'f'))))
def test_use_jsonutils(self):
def __get_msg(fun):

View File

@ -38,6 +38,7 @@ import webob.exc
from neutron.common import exceptions as exception
from neutron import context
from neutron.db import api
from neutron.i18n import _LE, _LI
from neutron.openstack.common import log as logging
from neutron.openstack.common import service as common_service
from neutron.openstack.common import systemd
@ -126,7 +127,7 @@ class Server(object):
family = info[0]
bind_addr = info[-1]
except Exception:
LOG.exception(_("Unable to listen on %(host)s:%(port)s"),
LOG.exception(_LE("Unable to listen on %(host)s:%(port)s"),
{'host': host, 'port': port})
sys.exit(1)
@ -334,7 +335,7 @@ class Request(webob.Request):
def get_content_type(self):
allowed_types = ("application/json")
if "Content-Type" not in self.headers:
LOG.debug(_("Missing Content-Type"))
LOG.debug("Missing Content-Type")
return None
_type = self.content_type
if _type in allowed_types:
@ -512,23 +513,23 @@ class RequestDeserializer(object):
try:
content_type = request.best_match_content_type()
except exception.InvalidContentType:
LOG.debug(_("Unrecognized Content-Type provided in request"))
LOG.debug("Unrecognized Content-Type provided in request")
return {}
if content_type is None:
LOG.debug(_("No Content-Type provided in request"))
LOG.debug("No Content-Type provided in request")
return {}
if not len(request.body) > 0:
LOG.debug(_("Empty body provided in request"))
LOG.debug("Empty body provided in request")
return {}
try:
deserializer = self.get_body_deserializer(content_type)
except exception.InvalidContentType:
with excutils.save_and_reraise_exception():
LOG.debug(_("Unable to deserialize body as provided "
"Content-Type"))
LOG.debug("Unable to deserialize body as provided "
"Content-Type")
return deserializer.deserialize(request.body, action)
@ -759,27 +760,27 @@ class Resource(Application):
def __call__(self, request):
"""WSGI method that controls (de)serialization and method dispatch."""
LOG.info(_("%(method)s %(url)s"), {"method": request.method,
"url": request.url})
LOG.info(_LI("%(method)s %(url)s"),
{"method": request.method, "url": request.url})
try:
action, args, accept = self.deserializer.deserialize(request)
except exception.InvalidContentType:
msg = _("Unsupported Content-Type")
LOG.exception(_("InvalidContentType: %s"), msg)
LOG.exception(_LE("InvalidContentType: %s"), msg)
return Fault(webob.exc.HTTPBadRequest(explanation=msg))
except exception.MalformedRequestBody:
msg = _("Malformed request body")
LOG.exception(_("MalformedRequestBody: %s"), msg)
LOG.exception(_LE("MalformedRequestBody: %s"), msg)
return Fault(webob.exc.HTTPBadRequest(explanation=msg))
try:
action_result = self.dispatch(request, action, args)
except webob.exc.HTTPException as ex:
LOG.info(_("HTTP exception thrown: %s"), unicode(ex))
LOG.info(_LI("HTTP exception thrown: %s"), ex)
action_result = Fault(ex, self._fault_body_function)
except Exception:
LOG.exception(_("Internal error"))
LOG.exception(_LE("Internal error"))
# Do not include the traceback to avoid returning it to clients.
action_result = Fault(webob.exc.HTTPServerError(),
self._fault_body_function)
@ -792,13 +793,11 @@ class Resource(Application):
response = action_result
try:
msg_dict = dict(url=request.url, status=response.status_int)
msg = _("%(url)s returned with HTTP %(status)d") % msg_dict
LOG.info(_LI("%(url)s returned with HTTP %(status)d"),
dict(url=request.url, status=response.status_int))
except AttributeError as e:
msg_dict = dict(url=request.url, exception=e)
msg = _("%(url)s returned a fault: %(exception)s") % msg_dict
LOG.info(msg)
LOG.info(_LI("%(url)s returned a fault: %(exception)s"),
dict(url=request.url, exception=e))
return response
@ -889,9 +888,8 @@ class Controller(object):
response = webob.Response(status=status,
content_type=content_type,
body=body)
msg_dict = dict(url=req.url, status=response.status_int)
msg = _("%(url)s returned with HTTP %(status)d") % msg_dict
LOG.debug(msg)
LOG.debug("%(url)s returned with HTTP %(status)d",
dict(url=req.url, status=response.status_int))
return response
else:
return result