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 @@ def call_driver(self, action, network, **action_kwargs):
                 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 @@ def _get_value_from_conf_file(self, kind, converter=None):
         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 @@ def _ensure_host_set_on_port(self, context, host, port, router_id=None):
                                         {'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 @@ def start(self):
         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 @@ def get_enabled_agent_on_host(self, context, agent_type, host):
             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 @@ def get_parser(self, prog_name):
         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 @@ def get_parser(self, prog_name):
         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 @@ def get_parser(self, prog_name):
         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 @@ def get_parser(self, prog_name):
         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 @@ def test__ensure_host_set_on_port_update_on_concurrent_delete(self):
         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)