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

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,16 +175,29 @@ 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):
+    def safe_get_network_info(self, network_id):
-        """Enable DHCP for a network that meets enabling criteria."""
         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)
+            LOG.exception(_('Network %s info call failed.'), network_id)
-            return
+
+    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:
             return
@@ -208,11 +230,8 @@ class DhcpAgent(manager.Manager):
             # DHCP current not running for network.
             return self.enable_dhcp_helper(network_id)
 
-        try:
+        network = self.safe_get_network_info(network_id)
-            network = self.plugin_rpc.get_network_info(network_id)
+        if not network:
-        except Exception:
-            self.needs_resync = True
-            LOG.exception(_('Network %s RPC info call failed.'), network_id)
             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,
+        network = self.call(self.context,
-                             self.call(self.context,
                             self.make_msg('get_network_info',
                                           network_id=network_id,
                                           host=self.host),
-                                       topic=self.topic))
+                            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,
+        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))
+                         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."""

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)
+        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.

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()
+        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})
-
+            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])
 
+            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']:

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',

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
+        self.driver.return_value.foo.side_effect = exc or Exception
-        with mock.patch.object(dhcp_agent.LOG, 'exception') as log:
+        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: