Add a hacking rule for string interpolation at logging

String interpolation should be delayed to be handled
by the logging code, rather than being done
at the point of the logging call.
So add a hacking rule for it.

See the oslo i18n guideline.

* http://docs.openstack.org/developer/oslo.i18n/guidelines.html

Change-Id: I91e8d59d508c594256d5f74514e62f8f928d1df5
Closes-Bug: #1596829

HACKING.rst

@@ -28,6 +28,7 @@ Neutron Specific Commandments
 - [N334] Use unittest2 uniformly across Neutron.
 - [N340] Check usage of <module>.i18n (and neutron.i18n)
 - [N341] Check usage of _ from python builtins
+- [N342] String interpolation should be delayed at logging calls.
 
 Creating Unit Tests
 -------------------

neutron/agent/l3/agent.py

@@ -219,7 +219,7 @@ class L3NATAgent(ha.AgentMixin,
                                     'to retrieve service plugins enabled. '
                                     'Check connectivity to neutron server. '
                                     'Retrying... '
-                                    'Detailed message: %(msg)s.') % {'msg': e})
+                                    'Detailed message: %(msg)s.'), {'msg': e})
                     continue
             break
 

neutron/agent/linux/pd.py

@@ -230,7 +230,7 @@ class PrefixDelegation(object):
     def _lla_available(self, gw_ifname, ns_name, lla_with_mask):
         llas = self._get_llas(gw_ifname, ns_name)
         if self._is_lla_active(lla_with_mask, llas):
-            LOG.debug("LLA %s is active now" % lla_with_mask)
+            LOG.debug("LLA %s is active now", lla_with_mask)
             self.pd_update_cb()
             return True
 

neutron/api/v2/resource_helper.py

@@ -78,8 +78,8 @@ def build_resource_info(plural_mappings, resource_map, which_service,
     else:
         plugin = manager.NeutronManager.get_plugin()
     path_prefix = getattr(plugin, "path_prefix", "")
-    LOG.debug('Service %(service)s assigned prefix: %(prefix)s'
+    LOG.debug('Service %(service)s assigned prefix: %(prefix)s',
-              % {'service': which_service, 'prefix': path_prefix})
+              {'service': which_service, 'prefix': path_prefix})
     for collection_name in resource_map:
         resource_name = plural_mappings[collection_name]
         params = resource_map.get(collection_name, {})

neutron/db/dns_db.py

@@ -287,8 +287,8 @@ class DNSDbMixin(object):
             LOG.exception(_LE("Error deleting Floating IP data from external "
                               "DNS service. Name: '%(name)s'. Domain: "
                               "'%(domain)s'. IP addresses '%(ips)s'. DNS "
-                              "service driver message '%(message)s'")
+                              "service driver message '%(message)s'"),
-                          % {"name": dns_name,
+                          {"name": dns_name,
                            "domain": dns_domain,
                            "message": e.msg,
                            "ips": ', '.join(records)})
@@ -318,7 +318,7 @@ class DNSDbMixin(object):
             LOG.exception(_LE("Error publishing floating IP data in external "
                               "DNS service. Name: '%(name)s'. Domain: "
                               "'%(domain)s'. DNS service driver message "
-                              "'%(message)s'")
+                              "'%(message)s'"),
-                          % {"name": dns_name,
+                          {"name": dns_name,
                            "domain": dns_domain,
                            "message": e.msg})

neutron/db/quota/driver.py

@@ -151,7 +151,7 @@ class DbQuotaDriver(object):
         return dict((k, v) for k, v in quotas.items())
 
     def _handle_expired_reservations(self, context, tenant_id):
-        LOG.debug("Deleting expired reservations for tenant:%s" % tenant_id)
+        LOG.debug("Deleting expired reservations for tenant:%s", tenant_id)
         # Delete expired reservations (we don't want them to accrue
         # in the database)
         quota_api.remove_expired_reservations(

neutron/hacking/checks.py

@@ -64,6 +64,9 @@ def _regex_for_level(level, hint):
     }
 
 
+log_string_interpolation = re.compile(r".*LOG\.(?:error|warn|warning|info"
+                                      r"|critical|exception|debug)"
+                                      r"\([^,]*%[^,]*[,)]")
 log_translation_hint = re.compile(
     '|'.join('(?:%s)' % _regex_for_level(level, hint)
              for level, hint in six.iteritems(_all_log_levels)))
@@ -356,6 +359,28 @@ def check_unittest_imports(logical_line):
         yield (0, msg)
 
 
+@flake8ext
+def check_delayed_string_interpolation(logical_line, filename, noqa):
+    """N342 String interpolation should be delayed at logging calls.
+
+    N342: LOG.debug('Example: %s' % 'bad')
+    Okay: LOG.debug('Example: %s', 'good')
+    """
+    msg = ("N342 String interpolation should be delayed to be "
+           "handled by the logging code, rather than being done "
+           "at the point of the logging call. "
+           "Use ',' instead of '%'.")
+
+    if noqa:
+        return
+
+    if 'neutron/tests/' in filename:
+        return
+
+    if log_string_interpolation.match(logical_line):
+        yield(0, msg)
+
+
 def factory(register):
     register(validate_log_translations)
     register(use_jsonutils)
@@ -374,3 +399,4 @@ def factory(register):
     register(check_oslo_i18n_wrapper)
     register(check_builtins_gettext)
     register(check_unittest_imports)
+    register(check_delayed_string_interpolation)

neutron/plugins/ml2/drivers/openvswitch/agent/ovs_dvr_neutron_agent.py

@@ -570,8 +570,8 @@ class OVSDVRNeutronAgent(object):
         if local_vlan_map.network_type not in (constants.TUNNEL_NETWORK_TYPES
                                                + [p_const.TYPE_VLAN]):
             LOG.debug("DVR: Port %s is with network_type %s not supported"
-                      " for dvr plumbing" % (port.vif_id,
+                      " for dvr plumbing", port.vif_id,
-                                             local_vlan_map.network_type))
+                      local_vlan_map.network_type)
             return
 
         if (port.vif_id in self.local_ports and

neutron/plugins/ml2/extensions/dns_integration.py

@@ -248,8 +248,8 @@ def _send_data_to_external_dns_service(context, dns_driver, dns_domain,
     except (dns.DNSDomainNotFound, dns.DuplicateRecordSet) as e:
         LOG.exception(_LE("Error publishing port data in external DNS "
                           "service. Name: '%(name)s'. Domain: '%(domain)s'. "
-                          "DNS service driver message '%(message)s'")
+                          "DNS service driver message '%(message)s'"),
-                      % {"name": dns_name,
+                      {"name": dns_name,
                        "domain": dns_domain,
                        "message": e.msg})
 
@@ -262,8 +262,8 @@ def _remove_data_from_external_dns_service(context, dns_driver, dns_domain,
         LOG.exception(_LE("Error deleting port data from external DNS "
                           "service. Name: '%(name)s'. Domain: '%(domain)s'. "
                           "IP addresses '%(ips)s'. DNS service driver message "
-                          "'%(message)s'")
+                          "'%(message)s'"),
-                      % {"name": dns_name,
+                      {"name": dns_name,
                        "domain": dns_domain,
                        "message": e.msg,
                        "ips": ', '.join(records)})

neutron/tests/unit/hacking/test_checks.py

@@ -24,6 +24,9 @@ from neutron.hacking import checks
 from neutron.tests import base
 
 
+CREATE_DUMMY_MATCH_OBJECT = re.compile('a')
+
+
 class HackingTestCase(base.BaseTestCase):
 
     def assertLinePasses(self, func, line):
@@ -298,6 +301,38 @@ class HackingTestCase(base.BaseTestCase):
         self.assertLineFails(f, 'from unittest.TestSuite')
         self.assertLineFails(f, 'import unittest')
 
+    def test_check_delayed_string_interpolation(self):
+        dummy_noqa = CREATE_DUMMY_MATCH_OBJECT.search('a')
+
+        # In 'logical_line', Contents of strings replaced with
+        # "xxx" of same length.
+        fail_code1 = 'LOG.error(_LE("xxxxxxxxxxxxxxx") % value)'
+        fail_code2 = "LOG.warning(msg % 'xxxxx')"
+
+        self.assertEqual(
+            1, len(list(checks.check_delayed_string_interpolation(fail_code1,
+                                        "neutron/common/rpc.py", None))))
+        self.assertEqual(
+            1, len(list(checks.check_delayed_string_interpolation(fail_code2,
+                                        "neutron/common/rpc.py", None))))
+
+        pass_code1 = 'LOG.error(_LE("xxxxxxxxxxxxxxxxxx"), value)'
+        pass_code2 = "LOG.warning(msg, 'xxxxx')"
+        self.assertEqual(
+            0, len(list(checks.check_delayed_string_interpolation(pass_code1,
+                                        "neutron/common/rpc.py", None))))
+        self.assertEqual(
+            0, len(list(checks.check_delayed_string_interpolation(pass_code2,
+                                        "neutron/common/rpc.py", None))))
+        # check a file in neutron/tests
+        self.assertEqual(
+            0, len(list(checks.check_delayed_string_interpolation(fail_code1,
+                                        "neutron/tests/test_assert.py",
+                                        None))))
+        # check code including 'noqa'
+        self.assertEqual(
+            0, len(list(checks.check_delayed_string_interpolation(fail_code1,
+                                        "neutron/common/rpc.py", dummy_noqa))))
 
 # The following is borrowed from hacking/tests/test_doctest.py.
 # Tests defined in docstring is easier to understand