Log exceptions inside spawned functions

eventlet pool will discards all exception raised inside spawn(_n), it is
hard to discover problems inside spawned green-threads, it is better to
add a function wrapper to log the exceptions raised inside spawned
function.

Change-Id: I753df36c4614759f49134667a55f2a91f0c08317
Closes-bug: #1340708

diff --git a/neutron/agent/dhcp_agent.py b/neutron/agent/dhcp_agent.py
index 29119799e4215d497e7e009f1f48678159482040..0ec9a8446f7c3505b38452d25b74fcbc2c5f2543 100644 (file)
--- a/neutron/agent/dhcp_agent.py
+++ b/neutron/agent/dhcp_agent.py
@@ -176,6 +176,7 @@ class DhcpAgent(manager.Manager):
             self.schedule_resync(e)
             LOG.exception(_('Unable to sync network state.'))
 
+    @utils.exception_logger()
     def _periodic_resync_helper(self):
         """Resync the dhcp state at the configured interval."""
         while True:
@@ -210,6 +211,7 @@ class DhcpAgent(manager.Manager):
         if network:
             self.configure_dhcp_for_network(network)
 
+    @utils.exception_logger()
     def safe_configure_dhcp_for_network(self, network):
         try:
             self.configure_dhcp_for_network(network)

diff --git a/neutron/agent/l3_agent.py b/neutron/agent/l3_agent.py
index 9d7ec1219515fc501840afcf76db30ca24689b0a..ae0124a7874809270914505dd7b0a423ce5d5506 100644 (file)
--- a/neutron/agent/l3_agent.py
+++ b/neutron/agent/l3_agent.py
@@ -697,6 +697,7 @@ class L3NATAgent(firewall_l3_agent.FWaaSL3AgentRpcCallback, manager.Manager):
         ip_devs = ip_wrapper.get_devices(exclude_loopback=True)
         return [ip_dev.name for ip_dev in ip_devs]
 
+    @common_utils.exception_logger()
     def process_router(self, ri):
         # TODO(mrsmith) - we shouldn't need to check here
         if 'distributed' not in ri.router:

diff --git a/neutron/common/utils.py b/neutron/common/utils.py
index 8521ec7f92e4db5de5d772924adff2d1960fcea1..72aff70643414c32eaa88efb7996d5ac59759be4 100644 (file)
--- a/neutron/common/utils.py
+++ b/neutron/common/utils.py
@@ -33,6 +33,7 @@ from eventlet.green import subprocess
 from oslo.config import cfg
 
 from neutron.common import constants as q_const
+from neutron.openstack.common import excutils
 from neutron.openstack.common import lockutils
 from neutron.openstack.common import log as logging
 
@@ -308,3 +309,29 @@ def cpu_count():
         return multiprocessing.cpu_count()
     except NotImplementedError:
         return 1
+
+
+class exception_logger(object):
+    """Wrap a function and log raised exception
+
+    :param logger: the logger to log the exception default is LOG.exception
+
+    :returns: origin value if no exception raised; re-raise the exception if
+              any occurred
+
+    """
+    def __init__(self, logger=None):
+        self.logger = logger
+
+    def __call__(self, func):
+        if self.logger is None:
+            LOG = logging.getLogger(func.__module__)
+            self.logger = LOG.exception
+
+        def call(*args, **kwargs):
+            try:
+                return func(*args, **kwargs)
+            except Exception as e:
+                with excutils.save_and_reraise_exception():
+                    self.logger(e)
+        return call

diff --git a/neutron/tests/unit/test_common_utils.py b/neutron/tests/unit/test_common_utils.py
index 2bcd6b45ecf7999c035ff62e12a6c0c7bf8e0ad2..d42ce4e92620e329a18e372ceb036a25aa880b68 100644 (file)
--- a/neutron/tests/unit/test_common_utils.py
+++ b/neutron/tests/unit/test_common_utils.py
@@ -12,6 +12,7 @@
 #    License for the specific language governing permissions and limitations
 #    under the License.
 
+import eventlet
 import mock
 import testtools
 
@@ -381,3 +382,85 @@ class TestDict2Tuples(base.BaseTestCase):
         expected = ((42, 'baz'), ('aaa', 'zzz'), ('foo', 'bar'))
         output_tuple = utils.dict2tuple(input_dict)
         self.assertEqual(expected, output_tuple)
+
+
+class TestExceptionLogger(base.BaseTestCase):
+    def test_normal_call(self):
+        result = "Result"
+
+        @utils.exception_logger()
+        def func():
+            return result
+
+        self.assertEqual(result, func())
+
+    def test_raise(self):
+        result = "Result"
+
+        @utils.exception_logger()
+        def func():
+            raise RuntimeError(result)
+
+        self.assertRaises(RuntimeError, func)
+
+    def test_spawn_normal(self):
+        result = "Result"
+        logger = mock.Mock()
+
+        @utils.exception_logger(logger=logger)
+        def func():
+            return result
+
+        gt = eventlet.spawn(func)
+        self.assertEqual(result, gt.wait())
+        self.assertFalse(logger.called)
+
+    def test_spawn_raise(self):
+        result = "Result"
+        logger = mock.Mock()
+
+        @utils.exception_logger(logger=logger)
+        def func():
+            raise RuntimeError(result)
+
+        gt = eventlet.spawn(func)
+        self.assertRaises(RuntimeError, gt.wait)
+        self.assertTrue(logger.called)
+
+    def test_pool_spawn_normal(self):
+        logger = mock.Mock()
+        calls = mock.Mock()
+
+        @utils.exception_logger(logger=logger)
+        def func(i):
+            calls(i)
+
+        pool = eventlet.GreenPool(4)
+        for i in range(0, 4):
+            pool.spawn(func, i)
+        pool.waitall()
+
+        calls.assert_has_calls([mock.call(0), mock.call(1),
+                                mock.call(2), mock.call(3)],
+                               any_order=True)
+        self.assertFalse(logger.called)
+
+    def test_pool_spawn_raise(self):
+        logger = mock.Mock()
+        calls = mock.Mock()
+
+        @utils.exception_logger(logger=logger)
+        def func(i):
+            if i == 2:
+                raise RuntimeError(2)
+            else:
+                calls(i)
+
+        pool = eventlet.GreenPool(4)
+        for i in range(0, 4):
+            pool.spawn(func, i)
+        pool.waitall()
+
+        calls.assert_has_calls([mock.call(0), mock.call(1), mock.call(3)],
+                               any_order=True)
+        self.assertTrue(logger.called)