Merge "Reduce the severity of dhcp related log traces"

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):
+    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
+
-        self.configure_dhcp_for_network(network)
+    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.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',
-                                       self.make_msg('get_network_info',
+                                          network_id=network_id,
-                                                     network_id=network_id,
+                                          host=self.host),
-                                                     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',
+                         self.make_msg('get_dhcp_port',
-                                                      network_id=network_id,
+                                       network_id=network_id,
-                                                      device_id=device_id,
+                                       device_id=device_id,
-                                                      host=self.host),
+                                       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)
-        interface_name = self.get_interface_name(network, port)
+        if port:
-        return ip_lib.IPDevice(interface_name,
+            interface_name = self.get_interface_name(network, port)
-                               self.root_helper,
+            return ip_lib.IPDevice(interface_name,
-                               network.namespace)
+                                   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()
-        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})
-
+            try:
-            network = plugin.get_network(context, network_id)
+                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']:

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: