Defer creation of router JSON in get_routers RPC

The get_routers method in the l3 RPC code has a log.debug
statement that formats all of the router data as indented
JSON. This method can be expensive if there are hundreds
of routers being synced and it happens even if debugging
is disabled since the function call result is the parameter
to the debug statement.

This patch adds and leverages a small helper class that takes a
callable and its args and defers calling it until the __str__ method
is called on it when it's actually trying to be rendered to a string.

Change-Id: I2bfceb286ce30f2a3595381b62bdc6dd71ed8483
Partial-Bug: #1445412

neutron/api/rpc/handlers/l3_rpc.py

@@ -85,7 +85,8 @@ class L3RpcCallback(object):
             self.plugin, constants.PORT_BINDING_EXT_ALIAS):
             self._ensure_host_set_on_ports(context, host, routers)
         LOG.debug("Routers returned to l3 agent:\n %s",
-                  jsonutils.dumps(routers, indent=5))
+                  utils.DelayedStringRenderer(jsonutils.dumps,
+                                              routers, indent=5))
         return routers
 
     def _ensure_host_set_on_ports(self, context, host, routers):

neutron/common/utils.py

@@ -405,3 +405,20 @@ def ip_version_from_int(ip_version_int):
     if ip_version_int == 6:
         return q_const.IPv6
     raise ValueError(_('Illegal IP version number'))
+
+
+class DelayedStringRenderer(object):
+    """Takes a callable and its args and calls when __str__ is called
+
+    Useful for when an argument to a logging statement is expensive to
+    create. This will prevent the callable from being called if it's
+    never converted to a string.
+    """
+
+    def __init__(self, function, *args, **kwargs):
+        self.function = function
+        self.args = args
+        self.kwargs = kwargs
+
+    def __str__(self):
+        return str(self.function(*self.args, **self.kwargs))

neutron/tests/unit/common/test_utils.py

@@ -24,6 +24,8 @@ from neutron.plugins.common import constants as p_const
 from neutron.plugins.common import utils as plugin_utils
 from neutron.tests import base
 
+from oslo_log import log as logging
+
 
 class TestParseMappings(base.BaseTestCase):
     def parse(self, mapping_list, unique_values=True):
@@ -632,3 +634,32 @@ class TestIpVersionFromInt(base.BaseTestCase):
         self.assertRaises(ValueError,
                           utils.ip_version_from_int,
                           8)
+
+
+class TestDelayedStringRederer(base.BaseTestCase):
+    def test_call_deferred_until_str(self):
+        my_func = mock.MagicMock(return_value='Brie cheese!')
+        delayed = utils.DelayedStringRenderer(my_func, 1, 2, key_arg=44)
+        self.assertFalse(my_func.called)
+        string = "Type: %s" % delayed
+        my_func.assert_called_once_with(1, 2, key_arg=44)
+        self.assertEqual("Type: Brie cheese!", string)
+
+    def test_not_called_with_low_log_level(self):
+        LOG = logging.getLogger(__name__)
+        # make sure we return logging to previous level
+        current_log_level = LOG.logger.getEffectiveLevel()
+        self.addCleanup(LOG.logger.setLevel, current_log_level)
+
+        my_func = mock.MagicMock()
+        delayed = utils.DelayedStringRenderer(my_func)
+
+        # set to warning so we shouldn't be logging debug messages
+        LOG.logger.setLevel(logging.logging.WARNING)
+        LOG.debug("Hello %s", delayed)
+        self.assertFalse(my_func.called)
+
+        # but it should be called with the debug level
+        LOG.logger.setLevel(logging.logging.DEBUG)
+        LOG.debug("Hello %s", delayed)
+        self.assertTrue(my_func.called)