Reduce the severity of dhcp related log traces

Due to timing issues, when the agent synchronizes
with the server wrt the representation of server's
and agent's networks, networks may have already
been deleted from the db. In such circumstances,
it is more appropriate to emit warnings rather than
full-blown exceptions as the agent handles these
circumstances just fine.

Close-bug: 1251874

Change-Id: I4b118b6087c7f42226f0d4265d2176c028d99f22

diff --git a/neutron/agent/dhcp_agent.py b/neutron/agent/dhcp_agent.py
index f58b577cdf9dd99bd0dac5ce492e840cb6aa6279..2cbd1494926d8146fca5ed991a8b040bc6da3439 100644 (file)
--- a/neutron/agent/dhcp_agent.py
+++ b/neutron/agent/dhcp_agent.py
@@ -27,6 +27,7 @@ from neutron.agent.linux import external_process
 from neutron.agent.linux import interface
 from neutron.agent import rpc as agent_rpc
 from neutron.common import constants
+from neutron.common import exceptions
 from neutron.common import legacy
 from neutron.common import topics
 from neutron.common import utils
@@ -35,6 +36,7 @@ from neutron import manager
 from neutron.openstack.common import importutils
 from neutron.openstack.common import log as logging
 from neutron.openstack.common import loopingcall
+from neutron.openstack.common.rpc import common
 from neutron.openstack.common.rpc import proxy
 from neutron.openstack.common import service
 from neutron import service as neutron_service
@@ -126,10 +128,17 @@ class DhcpAgent(manager.Manager):
             getattr(driver, action)(**action_kwargs)
             return True
 
-        except Exception:
+        except Exception as e:
             self.needs_resync = True
-            LOG.exception(_('Unable to %s dhcp.'), action)
+            if (isinstance(e, common.RemoteError)
+                and e.exc_type == 'NetworkNotFound'
+                or isinstance(e, exceptions.NetworkNotFound)):
+                LOG.warning(_("Network %s has been deleted."), network.id)
+            else:
+                LOG.exception(_('Unable to %(action)s dhcp for %(net_id)s.')
+                              % {'net_id': network.id, 'action': action})
 
+    @utils.synchronized('dhcp-agent')
     def sync_state(self):
         """Sync the local DHCP state with Neutron."""
         LOG.info(_('Synchronizing state'))
@@ -148,7 +157,7 @@ class DhcpAgent(manager.Manager):
                                     'network %s'), deleted_id)
 
             for network in active_networks:
-                pool.spawn_n(self.configure_dhcp_for_network, network)
+                pool.spawn_n(self.safe_configure_dhcp_for_network, network)
 
         except Exception:
             self.needs_resync = True
@@ -166,15 +175,28 @@ class DhcpAgent(manager.Manager):
         """Spawn a thread to periodically resync the dhcp state."""
         eventlet.spawn(self._periodic_resync_helper)
 
-    def enable_dhcp_helper(self, network_id):
-        """Enable DHCP for a network that meets enabling criteria."""
+    def safe_get_network_info(self, network_id):
         try:
             network = self.plugin_rpc.get_network_info(network_id)
+            if not network:
+                LOG.warn(_('Network %s has been deleted.'), network_id)
+            return network
         except Exception:
             self.needs_resync = True
-            LOG.exception(_('Network %s RPC info call failed.'), network_id)
-            return
-        self.configure_dhcp_for_network(network)
+            LOG.exception(_('Network %s info call failed.'), network_id)
+
+    def enable_dhcp_helper(self, network_id):
+        """Enable DHCP for a network that meets enabling criteria."""
+        network = self.safe_get_network_info(network_id)
+        if network:
+            self.configure_dhcp_for_network(network)
+
+    def safe_configure_dhcp_for_network(self, network):
+        try:
+            self.configure_dhcp_for_network(network)
+        except (exceptions.NetworkNotFound, RuntimeError):
+            LOG.warn(_('Network %s may have been deleted and its resources '
+                       'may have already been disposed.'), network.id)
 
     def configure_dhcp_for_network(self, network):
         if not network.admin_state_up:
@@ -208,11 +230,8 @@ class DhcpAgent(manager.Manager):
             # DHCP current not running for network.
             return self.enable_dhcp_helper(network_id)
 
-        try:
-            network = self.plugin_rpc.get_network_info(network_id)
-        except Exception:
-            self.needs_resync = True
-            LOG.exception(_('Network %s RPC info call failed.'), network_id)
+        network = self.safe_get_network_info(network_id)
+        if not network:
             return
 
         old_cidrs = set(s.cidr for s in old_network.subnets if s.enable_dhcp)
@@ -392,21 +411,24 @@ class DhcpPluginApi(proxy.RpcProxy):
 
     def get_network_info(self, network_id):
         """Make a remote process call to retrieve network info."""
-        return dhcp.NetModel(self.use_namespaces,
-                             self.call(self.context,
-                                       self.make_msg('get_network_info',
-                                                     network_id=network_id,
-                                                     host=self.host),
-                                       topic=self.topic))
+        network = self.call(self.context,
+                            self.make_msg('get_network_info',
+                                          network_id=network_id,
+                                          host=self.host),
+                            topic=self.topic)
+        if network:
+            return dhcp.NetModel(self.use_namespaces, network)
 
     def get_dhcp_port(self, network_id, device_id):
         """Make a remote process call to get the dhcp port."""
-        return dhcp.DictModel(self.call(self.context,
-                                        self.make_msg('get_dhcp_port',
-                                                      network_id=network_id,
-                                                      device_id=device_id,
-                                                      host=self.host),
-                              topic=self.topic))
+        port = self.call(self.context,
+                         self.make_msg('get_dhcp_port',
+                                       network_id=network_id,
+                                       device_id=device_id,
+                                       host=self.host),
+                         topic=self.topic)
+        if port:
+            return dhcp.DictModel(port)
 
     def create_dhcp_port(self, port):
         """Make a remote process call to create the dhcp port."""

diff --git a/neutron/agent/linux/dhcp.py b/neutron/agent/linux/dhcp.py
index fdb6c9b757d620c3c58a848122ac86f18ee462b6..6c4f09477d488cef2a8ded21a9c0ef6450217379 100644 (file)
--- a/neutron/agent/linux/dhcp.py
+++ b/neutron/agent/linux/dhcp.py
@@ -598,10 +598,13 @@ class DeviceManager(object):
         """Return DHCP ip_lib device for this host on the network."""
         device_id = self.get_device_id(network)
         port = self.plugin.get_dhcp_port(network.id, device_id)
-        interface_name = self.get_interface_name(network, port)
-        return ip_lib.IPDevice(interface_name,
-                               self.root_helper,
-                               network.namespace)
+        if port:
+            interface_name = self.get_interface_name(network, port)
+            return ip_lib.IPDevice(interface_name,
+                                   self.root_helper,
+                                   network.namespace)
+        else:
+            raise exceptions.NetworkNotFound(net_id=network.id)
 
     def _set_default_route(self, network):
         """Sets the default gateway for this dhcp namespace.

diff --git a/neutron/db/dhcp_rpc_base.py b/neutron/db/dhcp_rpc_base.py
index 2eacbbff4590f13be6393a7ec1c6c41ac3c2f89d..5953be136733a25cb8c4322c721a83e5966b45fb 100644 (file)
--- a/neutron/db/dhcp_rpc_base.py
+++ b/neutron/db/dhcp_rpc_base.py
@@ -18,9 +18,11 @@ from sqlalchemy.orm import exc
 
 from neutron.api.v2 import attributes
 from neutron.common import constants
+from neutron.common import exceptions as n_exc
 from neutron.common import utils
 from neutron.extensions import portbindings
 from neutron import manager
+from neutron.openstack.common.db import exception as db_exc
 from neutron.openstack.common import log as logging
 
 
@@ -82,8 +84,12 @@ class DhcpRpcCallbackMixin(object):
                     '%(host)s'), {'network_id': network_id,
                                   'host': host})
         plugin = manager.NeutronManager.get_plugin()
-        network = plugin.get_network(context, network_id)
-
+        try:
+            network = plugin.get_network(context, network_id)
+        except n_exc.NetworkNotFound:
+            LOG.warn(_("Network %s could not be found, it might have "
+                       "been deleted concurrently."), network_id)
+            return
         filters = dict(network_id=[network_id])
         network['subnets'] = plugin.get_subnets(context, filters=filters)
         network['ports'] = plugin.get_ports(context, filters=filters)
@@ -97,10 +103,6 @@ class DhcpRpcCallbackMixin(object):
         network state.
 
         """
-        # NOTE(arosen): This method is no longer used by the DHCP agent but is
-        # left so that neutron-dhcp-agents will still continue to work if
-        # neutron-server is upgraded and not the agent.
-
         host = kwargs.get('host')
         network_id = kwargs.get('network_id')
         device_id = kwargs.get('device_id')
@@ -146,8 +148,12 @@ class DhcpRpcCallbackMixin(object):
                       {'device_id': device_id,
                        'network_id': network_id,
                        'host': host})
-
-            network = plugin.get_network(context, network_id)
+            try:
+                network = plugin.get_network(context, network_id)
+            except n_exc.NetworkNotFound:
+                LOG.warn(_("Network %s could not be found, it might have "
+                           "been deleted concurrently."), network_id)
+                return
 
             port_dict = dict(
                 admin_state_up=True,
@@ -159,7 +165,14 @@ class DhcpRpcCallbackMixin(object):
                 device_owner='network:dhcp',
                 fixed_ips=[dict(subnet_id=s) for s in dhcp_enabled_subnet_ids])
 
-            retval = plugin.create_port(context, dict(port=port_dict))
+            try:
+                retval = plugin.create_port(context, dict(port=port_dict))
+            except (db_exc.DBError,
+                    n_exc.NetworkNotFound,
+                    n_exc.SubnetNotFound) as e:
+                LOG.warn(_("Port for network %(net_id)s could not be created: "
+                           "%(reason)s") % {"net_id": network_id, 'reason': e})
+                return
 
         # Convert subnet_id to subnet dict
         for fixed_ip in retval['fixed_ips']:

diff --git a/neutron/tests/unit/test_db_rpc_base.py b/neutron/tests/unit/test_db_rpc_base.py
index e878f0936fc9d87fa4be662a47eeab008d87cca7..9e7a3e87b8d744a35cc8b2d55267f27aa62af047 100644 (file)
--- a/neutron/tests/unit/test_db_rpc_base.py
+++ b/neutron/tests/unit/test_db_rpc_base.py
@@ -15,6 +15,7 @@
 
 import mock
 
+from neutron.common import exceptions as n_exc
 from neutron.db import dhcp_rpc_base
 from neutron.tests import base
 
@@ -49,6 +50,11 @@ class TestDhcpRpcCallackMixin(base.BaseTestCase):
 
         self.assertEqual(len(self.log.mock_calls), 1)
 
+    def test_get_network_info_return_none_on_not_found(self):
+        self.plugin.get_network.side_effect = n_exc.NetworkNotFound(net_id='a')
+        retval = self.callbacks.get_network_info(mock.Mock(), network_id='a')
+        self.assertIsNone(retval)
+
     def test_get_network_info(self):
         network_retval = dict(id='a')
 
@@ -101,6 +107,34 @@ class TestDhcpRpcCallackMixin(base.BaseTestCase):
                                         update_port=port_retval)
         self.assertEqual(len(self.log.mock_calls), 1)
 
+    def _test_get_dhcp_port_with_failures(self,
+                                          raise_get_network=None,
+                                          raise_create_port=None):
+        self.plugin.update_port.return_value = None
+        if raise_get_network:
+            self.plugin.get_network.side_effect = raise_get_network
+        else:
+            self.plugin.get_network.return_value = {'tenant_id': 'foo_tenant'}
+        if raise_create_port:
+            self.plugin.create_port.side_effect = raise_create_port
+        retval = self.callbacks.get_dhcp_port(mock.Mock(),
+                                              network_id='netid',
+                                              device_id='devid',
+                                              host='host')
+        self.assertIsNone(retval)
+
+    def test_get_dhcp_port_catch_not_found_on_get_network(self):
+        self._test_get_dhcp_port_with_failures(
+            raise_get_network=n_exc.NetworkNotFound(net_id='a'))
+
+    def test_get_dhcp_port_catch_network_not_found_on_create_port(self):
+        self._test_get_dhcp_port_with_failures(
+            raise_create_port=n_exc.NetworkNotFound(net_id='a'))
+
+    def test_get_dhcp_port_catch_subnet_not_found_on_create_port(self):
+        self._test_get_dhcp_port_with_failures(
+            raise_create_port=n_exc.SubnetNotFound(subnet_id='b'))
+
     def test_get_dhcp_port_create_new(self):
         self.plugin.get_network.return_value = dict(tenant_id='tenantid')
         create_spec = dict(tenant_id='tenantid', device_id='devid',

diff --git a/neutron/tests/unit/test_dhcp_agent.py b/neutron/tests/unit/test_dhcp_agent.py
index c799290bbc46d9fb8048f73f802df0a197e85b1b..cd7d0a2aade4e7b4d850b3a0e779a27748ede194 100644 (file)
--- a/neutron/tests/unit/test_dhcp_agent.py
+++ b/neutron/tests/unit/test_dhcp_agent.py
@@ -32,6 +32,7 @@ from neutron.agent.linux import dhcp
 from neutron.agent.linux import interface
 from neutron.common import constants as const
 from neutron.common import exceptions
+from neutron.openstack.common.rpc import common
 from neutron.tests import base
 
 
@@ -205,11 +206,11 @@ class TestDhcpAgent(base.BaseTestCase):
                                             mock.ANY,
                                             mock.ANY)
 
-    def test_call_driver_failure(self):
+    def _test_call_driver_failure(self, exc=None, trace_level='exception'):
         network = mock.Mock()
         network.id = '1'
-        self.driver.return_value.foo.side_effect = Exception
-        with mock.patch.object(dhcp_agent.LOG, 'exception') as log:
+        self.driver.return_value.foo.side_effect = exc or Exception
+        with mock.patch.object(dhcp_agent.LOG, trace_level) as log:
             dhcp = dhcp_agent.DhcpAgent(HOSTNAME)
             self.assertIsNone(dhcp.call_driver('foo', network))
             self.driver.assert_called_once_with(cfg.CONF,
@@ -220,6 +221,19 @@ class TestDhcpAgent(base.BaseTestCase):
             self.assertEqual(log.call_count, 1)
             self.assertTrue(dhcp.needs_resync)
 
+    def test_call_driver_failure(self):
+        self._test_call_driver_failure()
+
+    def test_call_driver_remote_error_net_not_found(self):
+        self._test_call_driver_failure(
+            exc=common.RemoteError(exc_type='NetworkNotFound'),
+            trace_level='warning')
+
+    def test_call_driver_network_not_found(self):
+        self._test_call_driver_failure(
+            exc=exceptions.NetworkNotFound(net_id='1'),
+            trace_level='warning')
+
     def _test_sync_state_helper(self, known_networks, active_networks):
         with mock.patch(DHCP_PLUGIN) as plug:
             mock_plugin = mock.Mock()
@@ -491,6 +505,16 @@ class TestDhcpAgentEventHandler(base.BaseTestCase):
         self.assertFalse(self.cache.called)
         self.assertFalse(self.external_process.called)
 
+    def test_enable_dhcp_helper_network_none(self):
+        self.plugin.get_network_info.return_value = None
+        with mock.patch.object(dhcp_agent.LOG, 'warn') as log:
+            self.dhcp.enable_dhcp_helper('fake_id')
+            self.plugin.assert_has_calls(
+                [mock.call.get_network_info('fake_id')])
+            self.assertFalse(self.call_driver.called)
+            self.assertTrue(log.called)
+            self.assertFalse(self.dhcp.needs_resync)
+
     def test_enable_dhcp_helper_exception_during_rpc(self):
         self.plugin.get_network_info.side_effect = Exception
         with mock.patch.object(dhcp_agent.LOG, 'exception') as log: