Add log hacking rules

- [C312] Validate that logs are not translated.
- [H904] Delay string interpolations at logging calls. [1]

[1]https://docs.openstack.org/oslo.i18n/latest/user/guidelines.html#adding-variables-to-log-messages

Change-Id: I58930b6b42b00b28d80bda917834b077c380b0a0

HACKING.rst

@@ -1,12 +1,12 @@
 Blazar Style Commandments
-==========================
+=========================
 
 - Step 1: Read the OpenStack Style Commandments
   https://docs.openstack.org/hacking/latest/
 - Step 2: Read on
 
 Blazar Specific Commandments
------------------------------
-
-None so far
+----------------------------
 
+- [C312] Validate that logs are not translated.
+- [H904] Delay string interpolations at logging calls.

blazar/api/v1/utils.py

@@ -202,8 +202,8 @@ def get_request_args():
 
 def abort_and_log(status_code, descr, exc=None):
     """Process occurred errors."""
-    LOG.error(_("Request aborted with status code %(code)s and "
-                "message '%(msg)s'"), {'code': status_code, 'msg': descr})
+    LOG.error("Request aborted with status code %(code)s and "
+              "message '%(msg)s'", {'code': status_code, 'msg': descr})
 
     if exc is not None:
         LOG.error(traceback.format_exc())
@@ -227,8 +227,8 @@ def render_error_message(error_code, error_message, error_name):
 
 def internal_error(status_code, descr, exc=None):
     """Called if internal error occurred."""
-    LOG.error(_("Request aborted with status code %(code)s "
-                "and message '%(msg)s'"), {'code': status_code, 'msg': descr})
+    LOG.error("Request aborted with status code %(code)s "
+              "and message '%(msg)s'", {'code': status_code, 'msg': descr})
 
     if exc is not None:
         LOG.error(traceback.format_exc())

blazar/api/v2/controllers/__init__.py

@@ -46,7 +46,7 @@ class V2Controller(rest.RestController):
     def _log_missing_plugins(self, names):
         for name in names:
             if name not in self.extension_manager.names():
-                LOG.error(_("API Plugin %s was not loaded") % name)
+                LOG.error("API Plugin %s was not loaded", name)
 
     def __init__(self):
         extensions = []
@@ -68,7 +68,7 @@ def __init__(self):
             self._routes.update(ext.obj.extra_routes)
             extensions.append(ext.obj.name)
 
-        LOG.debug(_("Loaded extensions: {0}").format(extensions))
+        LOG.debug("Loaded extensions: {0}".format(extensions))
 
     @pecan.expose()
     def _route(self, args):
@@ -86,5 +86,5 @@ def _route(self, args):
             else:
                 args[0] = route
         except IndexError:
-            LOG.error(_("No args found on V2 controller"))
+            LOG.error("No args found on V2 controller")
         return super(V2Controller, self)._route(args)

blazar/db/sqlalchemy/api.py

@@ -28,7 +28,6 @@
 from blazar.db import exceptions as db_exc
 from blazar.db.sqlalchemy import facade_wrapper
 from blazar.db.sqlalchemy import models
-from blazar.i18n import _
 
 
 LOG = logging.getLogger(__name__)
@@ -60,7 +59,7 @@ def setup_db():
                                          sqlite_fk=True).get_engine()
         models.Lease.metadata.create_all(engine)
     except sa.exc.OperationalError as e:
-        LOG.error(_("Database registration exception: %s"), e)
+        LOG.error("Database registration exception: %s", e)
         return False
     return True
 
@@ -71,7 +70,7 @@ def drop_db():
                                          sqlite_fk=True).get_engine()
         models.Lease.metadata.drop_all(engine)
     except Exception as e:
-        LOG.error(_("Database shutdown exception: %s"), e)
+        LOG.error("Database shutdown exception: %s", e)
         return False
     return True
 

blazar/exceptions.py

@@ -43,9 +43,10 @@ def __init__(self, message=None, **kwargs):
             except KeyError:
                 # kwargs doesn't match a variable in the message
                 # log the issue and the kwargs
-                LOG.exception(_('Exception in string format operation'))
+                LOG.exception('Exception in string format operation')
                 for name, value in kwargs.iteritems():
-                    LOG.error("%s: %s" % (name, value))
+                    LOG.error("%(name)s: %(value)s",
+                              {'name': name, 'value': value})
 
                 message = self.msg_fmt
 

blazar/hacking/checks.py

@@ -0,0 +1,51 @@
+# Copyright (c) 2017 OpenStack Foundation.
+#
+# Licensed under the Apache License, Version 2.0 (the "License"); you may
+# not use this file except in compliance with the License. You may obtain
+# a copy of the License at
+#
+#      http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+# WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+# License for the specific language governing permissions and limitations
+# under the License.
+
+import re
+
+
+_all_log_levels = {'critical', 'error', 'exception', 'info',
+                   'warning', 'debug'}
+
+# Since _Lx() have been removed, we just need to check _()
+_all_hints = {'_'}
+
+_log_translation_hint = re.compile(
+    r".*LOG\.(%(levels)s)\(\s*(%(hints)s)\(" % {
+        'levels': '|'.join(_all_log_levels),
+        'hints': '|'.join(_all_hints),
+    })
+
+
+def no_translate_logs(logical_line):
+    """C312 - Don't translate logs.
+
+    Check for 'LOG.*(_('
+
+    Translators don't provide translations for log messages, and operators
+    asked not to translate them.
+
+    * This check assumes that 'LOG' is a logger.
+
+    :param logical_line: The logical line to check.
+    :returns: None if the logical line passes the check, otherwise a tuple
+    is yielded that contains the offending index in logical line and a
+    message describe the check validation failure.
+    """
+    if _log_translation_hint.match(logical_line):
+        yield (0, "C312: Log messages should not be translated!")
+
+
+def factory(register):
+    register(no_translate_logs)

blazar/manager/service.py

@@ -23,7 +23,6 @@
 from blazar.db import api as db_api
 from blazar.db import exceptions as db_ex
 from blazar import exceptions as common_ex
-from blazar.i18n import _
 from blazar import manager
 from blazar.manager import exceptions
 from blazar.notification import api as notification_api
@@ -156,7 +155,7 @@ def _event(self):
                                             events=['event.%s' % event_type])
             except Exception:
                 db_api.event_update(event['id'], {'status': 'ERROR'})
-                LOG.exception(_('Error occurred while event handling.'))
+                LOG.exception('Error occurred while event handling.')
 
     def _date_from_string(self, date_string, date_format=LEASE_DATE_FORMAT):
         try:
@@ -231,7 +230,7 @@ def create_lease(self, lease_values):
                     self._check_date_within_lease_limits(before_end_date,
                                                          lease_values)
                 except common_ex.BlazarException as e:
-                    LOG.error("Invalid before_end_date param. %s" % e.message)
+                    LOG.error("Invalid before_end_date param. %s", e.message)
                     raise e
             elif CONF.manager.minutes_before_end_lease > 0:
                 delta = datetime.timedelta(
@@ -349,7 +348,7 @@ def update_lease(self, lease_id, values):
                     self._check_date_within_lease_limits(before_end_date,
                                                          values)
                 except common_ex.BlazarException as e:
-                    LOG.error("Invalid before_end_date param. %s" % e.message)
+                    LOG.error("Invalid before_end_date param. %s", e.message)
                     raise e
 
             # TODO(frossigneux) rollback if an exception is raised
@@ -489,11 +488,9 @@ def _basic_action(self, lease_id, event_id, action_time,
                 )
             except common_ex.BlazarException:
                 LOG.exception("Failed to execute action %(action)s "
-                              "for lease %(lease)s"
-                              % {
-                                  'action': action_time,
-                                  'lease': lease_id,
-                              })
+                              "for lease %(lease)s",
+                              {'action': action_time,
+                               'lease': lease_id})
                 event_status = 'ERROR'
                 db_api.reservation_update(reservation['id'],
                                           {'status': 'error'})
@@ -537,9 +534,10 @@ def _update_before_end_event_date(self, event, before_end_date, lease):
         event['time'] = before_end_date
         if event['time'] < lease['start_date']:
             LOG.warning("Start_date greater than before_end_date. "
-                        "Setting before_end_date to %s for lease %s"
-                        % (lease['start_date'], lease.get('id',
-                           lease.get('name'))))
+                        "Setting before_end_date to %(start_date)s for "
+                        "lease %(id_name)s",
+                        {'start_date': lease['start_date'],
+                         'id_name': lease.get('id', lease.get('name'))})
             event['time'] = lease['start_date']
 
     def _update_before_end_event(self, old_lease, new_lease,

blazar/plugins/instances/instance_plugin.py

@@ -241,7 +241,7 @@ def reserve_resource(self, reservation_id, values):
             flavor, group, pool = self._create_resources(instance_reservation)
         except nova_exceptions.ClientException:
             LOG.exception("Failed to create Nova resources "
-                          "for reservation %s" % reservation_id)
+                          "for reservation %s", reservation_id)
             self.cleanup_resources(instance_reservation)
             raise mgr_exceptions.NovaClientError()
 
@@ -265,8 +265,10 @@ def on_start(self, resource_id):
             self.nova.flavor_access.add_tenant_access(reservation_id,
                                                       ctx.project_id)
         except nova_exceptions.ClientException:
-            LOG.info('Failed to associate flavor %s to project %s' %
-                     (reservation_id, ctx.project_id))
+            LOG.info('Failed to associate flavor %(reservation_id)s '
+                     'to project %(project_id)s',
+                     {'reservation_id': reservation_id,
+                      'project_id': ctx.project_id})
             raise mgr_exceptions.EventError()
 
         pool = nova.ReservationPool()

blazar/tests/db/migration/__init__.py

@@ -213,7 +213,7 @@ def setUp(self):
     def _load_config(self):
         # Load test databases from the config file. Only do this
         # once. No need to re-run this on each test...
-        LOG.debug('config_path is %s' % self.CONFIG_FILE_PATH)
+        LOG.debug('config_path is %s', self.CONFIG_FILE_PATH)
         if os.path.exists(self.CONFIG_FILE_PATH):
             cp = configparser.RawConfigParser()
             try:
@@ -373,7 +373,7 @@ class BaseWalkMigrationTestCase(BaseMigrationTestCase):
     def _load_config(self):
         # Load test databases from the config file. Only do this
         # once. No need to re-run this on each test...
-        LOG.debug('config_path is %s' % self.CONFIG_FILE_PATH)
+        LOG.debug('config_path is %s', self.CONFIG_FILE_PATH)
         if os.path.exists(self.CONFIG_FILE_PATH):
             cp = configparser.RawConfigParser()
             try:
@@ -468,7 +468,8 @@ def _alembic_command(self, alembic_command, engine, *args, **kwargs):
         CONF.set_override('connection', str(engine.url), group='database')
         getattr(command, alembic_command)(*args, **kwargs)
         res = buf.getvalue().strip()
-        LOG.debug('Alembic command `%s` returns: %s' % (alembic_command, res))
+        LOG.debug('Alembic command `%(command)s` returns: %(res)s',
+                  {'command': alembic_command, 'res': res})
         return res
 
     def _get_alembic_versions(self, engine):
@@ -600,6 +601,6 @@ def _migrate_up(self, engine, version, with_data=False):
                 if check:
                     check(engine, data)
         except Exception:
-            LOG.error("Failed to migrate to version %s on engine %s" %
-                      (version, engine))
+            LOG.error("Failed to migrate to version %(version)s on engine "
+                      "%(engine)s", {'version': version, 'engine': engine})
             raise

blazar/tests/hacking/test_hacking.py

@@ -0,0 +1,27 @@
+# Copyright (c) 2017 OpenStack Foundation.
+#
+# Licensed under the Apache License, Version 2.0 (the "License"); you may
+# not use this file except in compliance with the License. You may obtain
+# a copy of the License at
+#
+#      http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+# WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+# License for the specific language governing permissions and limitations
+# under the License.
+
+from blazar.hacking import checks
+from blazar import tests
+
+
+class HackingTestCase(tests.TestCase):
+    def test_no_log_translations(self):
+        for log in checks._all_log_levels:
+            for hint in checks._all_hints:
+                bad = 'LOG.%s(%s("Bad"))' % (log, hint)
+                self.assertEqual(1, len(list(checks.no_translate_logs(bad))))
+                # Catch abuses when used with a variable and not a literal
+                bad = 'LOG.%s(%s(msg))' % (log, hint)
+                self.assertEqual(1, len(list(checks.no_translate_logs(bad))))

blazar/utils/openstack/nova.py

@@ -254,8 +254,8 @@ def create(self, name=None, az=None, metadata=None):
 
         name = name or self._generate_aggregate_name()
 
-        LOG.debug('Creating pool aggregate: %s with Availability Zone %s'
-                  % (name, az))
+        LOG.debug('Creating pool aggregate: %(name)s with Availability Zone '
+                  '%(az)s', {'name': name, 'az': az})
         agg = self.nova.aggregates.create(name, az)
 
         try:
@@ -295,8 +295,8 @@ def delete(self, pool, force=True):
         except manager_exceptions.AggregateNotFound:
             raise manager_exceptions.NoFreePool()
         for host in hosts:
-            LOG.debug("Removing host '%s' from aggregate "
-                      "'%s')" % (host, agg.id))
+            LOG.debug("Removing host '%(host)s' from aggregate '%(id)s')",
+                      {'host': host, 'id': agg.id})
             self.nova.aggregates.remove_host(agg.id, host)
 
             if freepool_agg.id != agg.id and host not in freepool_agg.hosts:
@@ -348,14 +348,15 @@ def add_computehost(self, pool, host, stay_in=False):
             if host not in freepool_agg.hosts:
                 raise manager_exceptions.HostNotInFreePool(
                     host=host, freepool_name=freepool_agg.name)
-            LOG.info("removing host '%s' "
-                     "from aggregate freepool %s" % (host, freepool_agg.name))
+            LOG.info("removing host '%(host)s' from aggregate freepool "
+                     "%(name)s", {'host': host, 'name': freepool_agg.name})
             try:
                 self.remove_computehost(freepool_agg.id, host)
             except nova_exception.NotFound:
                 raise manager_exceptions.HostNotFound(host=host)
 
-        LOG.info("adding host '%s' to aggregate %s" % (host, agg.id))
+        LOG.info("adding host '%(host)s' to aggregate %(id)s",
+                 {'host': host, 'id': agg.id})
         try:
             return self.nova.aggregates.add_host(agg.id, host)
         except nova_exception.NotFound:

blazar/utils/service.py

@@ -23,7 +23,6 @@
 from oslo_service import service
 
 from blazar import context
-from blazar.i18n import _
 
 LOG = logging.getLogger(__name__)
 
@@ -79,8 +78,8 @@ def run_method(__ctx, **kwargs):
 
             return run_method
         except AttributeError:
-            LOG.error(_("No %(method)s method found implemented in "
-                        "%(class)s class"),
+            LOG.error("No %(method)s method found implemented in "
+                      "%(class)s class",
                       {'method': name, 'class': self.__endpoint})
 
 

contrib/tempest/tempest/scenario/resource_reservation_scenario.py

@@ -80,10 +80,11 @@ def check_lease_end():
                                       evt['status'] == 'DONE',
                                       events)) > 0
                 else:
-                    LOG.info("Lease with id %s is empty" % lease_id)
+                    LOG.info("Lease with id %s is empty", lease_id)
             except Exception as e:
-                LOG.info("Unable to find lease with id %s. Exception: %s"
-                         % (lease_id, e.message))
+                LOG.info("Unable to find lease with id %(lease_id)s. "
+                         "Exception: %(message)s",
+                         {'lease_id': lease_id, 'message': e.message})
             return True
 
         if not test_utils.call_until_true(
@@ -100,8 +101,9 @@ def remove_image_snapshot(self, image_name):
                            self.image_client.list())
             self.image_client.delete(image)
         except Exception as e:
-            LOG.info("Unable to delete %s snapshot. Exception: %s"
-                     % (image_name, e.message))
+            LOG.info("Unable to delete %(image_name)s snapshot. "
+                     "Exception: %(message)s",
+                     {'image_name': image_name, 'message': e.message})
 
     def is_flavor_enough(self, flavor_id, image_id):
         image = self.compute_images_client.show_image(image_id)['image']