Use lazy logging interpolation

There are a small number of examples of "eager" interpolation in
neutron:
  logging.debug("foo %s" % arg)

These should be converted to perform the interpolation lazily within
the logging function, since if the severity is below the logging level
then the interpolation can be skipped entirely.

This change addresses all such current examples found in neutron core
via a pylint test.  Vendor plugins and services are fixed elsewhere.

Change-Id: I823d8453cd76e4985cabd31ca6b939f43a80b36c
Partial-Bug: #1404788

neutron/agent/dhcp_agent.py

@@ -143,8 +143,8 @@ class DhcpAgent(manager.Manager):
                 or isinstance(e, exceptions.NetworkNotFound)):
                 LOG.warning(_LW("Network %s has been deleted."), network.id)
             else:
-                LOG.exception(_LE('Unable to %(action)s dhcp for %(net_id)s.')
-                              % {'net_id': network.id, 'action': action})
+                LOG.exception(_LE('Unable to %(action)s dhcp for %(net_id)s.'),
+                              {'net_id': network.id, 'action': action})
 
     def schedule_resync(self, reason, network=None):
         """Schedule a resync for a given network and reason. If no network is

neutron/agent/linux/dhcp.py

@@ -267,7 +267,7 @@ class DhcpLocalProcess(DhcpBase):
         except IOError:
             msg = _('Unable to access %s')
 
-        LOG.debug(msg % file_name)
+        LOG.debug(msg, file_name)
         return None
 
     @property

neutron/agent/linux/utils.py

@@ -161,7 +161,7 @@ def get_value_from_conf_file(cfg_root, uuid, cfg_file, converter=None):
     except IOError:
         msg = _('Unable to access %s')
 
-    LOG.debug(msg % file_name)
+    LOG.debug(msg, file_name)
     return None
 
 

neutron/api/rpc/handlers/l3_rpc.py

@@ -125,8 +125,8 @@ class L3RpcCallback(object):
                                         {'port': {portbindings.HOST_ID: host}})
             except exceptions.PortNotFound:
                 LOG.debug("Port %(port)s not found while updating "
-                          "agent binding for router %(router)s."
-                          % {"port": port['id'], "router": router_id})
+                          "agent binding for router %(router)s.",
+                          {"port": port['id'], "router": router_id})
         elif (port and
               port.get('device_owner') ==
               constants.DEVICE_OWNER_DVR_INTERFACE):

neutron/common/config.py

@@ -167,7 +167,7 @@ def setup_logging():
     LOG.info(_LI("%(prog)s version %(version)s"),
              {'prog': sys.argv[0],
               'version': version.version_info.release_string()})
-    LOG.debug("command line: %s" % " ".join(sys.argv))
+    LOG.debug("command line: %s", " ".join(sys.argv))
 
 
 def load_paste_app(app_name):

neutron/common/rpc.py

@@ -153,7 +153,7 @@ class Service(service.Service):
         super(Service, self).start()
 
         self.conn = create_connection(new=True)
-        LOG.debug("Creating Consumer connection for Service %s" %
+        LOG.debug("Creating Consumer connection for Service %s",
                   self.topic)
 
         endpoints = [self.manager]

neutron/db/agents_db.py

@@ -93,7 +93,7 @@ class AgentDbMixin(ext_agent.AgentPluginBase):
             agent = query.one()
         except exc.NoResultFound:
             LOG.debug('No enabled %(agent_type)s agent on host '
-                      '%(host)s' % {'agent_type': agent_type, 'host': host})
+                      '%(host)s', {'agent_type': agent_type, 'host': host})
             return
         if self.is_agent_down(agent.heartbeat_timestamp):
             LOG.warn(_LW('%(agent_type)s agent %(agent_id)s is not active'),

neutron/debug/commands.py

@@ -50,7 +50,7 @@ class CreateProbe(ProbeCommand):
         return parser
 
     def run(self, parsed_args):
-        self.log.debug('run(%s)' % parsed_args)
+        self.log.debug('run(%s)', parsed_args)
         debug_agent = self.get_debug_agent()
         probe_port = debug_agent.create_probe(parsed_args.id,
                                               parsed_args.device_owner)
@@ -70,7 +70,7 @@ class DeleteProbe(ProbeCommand):
         return parser
 
     def run(self, parsed_args):
-        self.log.debug('run(%s)' % parsed_args)
+        self.log.debug('run(%s)', parsed_args)
         debug_agent = self.get_debug_agent()
         debug_agent.delete_probe(parsed_args.id)
         self.log.info(_('Probe %s deleted'), parsed_args.id)
@@ -101,10 +101,10 @@ class ClearProbe(ProbeCommand):
     log = logging.getLogger(__name__ + '.ClearProbe')
 
     def run(self, parsed_args):
-        self.log.debug('run(%s)' % parsed_args)
+        self.log.debug('run(%s)', parsed_args)
         debug_agent = self.get_debug_agent()
         cleared_probes_count = debug_agent.clear_probes()
-        self.log.info(_LI('%d probe(s) deleted') % cleared_probes_count)
+        self.log.info(_LI('%d probe(s) deleted'), cleared_probes_count)
 
 
 class ExecProbe(ProbeCommand):
@@ -125,7 +125,7 @@ class ExecProbe(ProbeCommand):
         return parser
 
     def run(self, parsed_args):
-        self.log.debug('run(%s)' % parsed_args)
+        self.log.debug('run(%s)', parsed_args)
         debug_agent = self.get_debug_agent()
         result = debug_agent.exec_command(parsed_args.id, parsed_args.command)
         self.app.stdout.write(result + '\n')
@@ -149,7 +149,7 @@ class PingAll(ProbeCommand):
         return parser
 
     def run(self, parsed_args):
-        self.log.debug('run(%s)' % parsed_args)
+        self.log.debug('run(%s)', parsed_args)
         debug_agent = self.get_debug_agent()
         result = debug_agent.ping_all(parsed_args.id,
                                       timeout=parsed_args.timeout)

neutron/tests/unit/test_l3_plugin.py

@@ -2113,7 +2113,7 @@ class L3RpcCallbackTestCase(base.BaseTestCase):
         self.assertTrue(mock_log.call_count)
         expected_message = ('Port foo_port_id not found while updating '
                             'agent binding for router foo_router_id.')
-        actual_message = mock_log.call_args[0][0]
+        actual_message = mock_log.call_args[0][0] % mock_log.call_args[0][1]
         self.assertEqual(expected_message, actual_message)