From a15f2fa2fe2b724b1fd4169329db9ce555068f0c Mon Sep 17 00:00:00 2001 From: armando-migliaccio Date: Sat, 16 Nov 2013 10:07:31 -0800 Subject: [PATCH] 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 | 72 +++++++++++++++++--------- neutron/agent/linux/dhcp.py | 11 ++-- neutron/db/dhcp_rpc_base.py | 31 +++++++---- neutron/tests/unit/test_db_rpc_base.py | 34 ++++++++++++ neutron/tests/unit/test_dhcp_agent.py | 30 +++++++++-- 5 files changed, 137 insertions(+), 41 deletions(-) diff --git a/neutron/agent/dhcp_agent.py b/neutron/agent/dhcp_agent.py index f58b577cdf..2cbd149492 100644 --- 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 fdb6c9b757..6c4f09477d 100644 --- 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 2eacbbff45..5953be1367 100644 --- 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 e878f0936f..9e7a3e87b8 100644 --- 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 c799290bbc..cd7d0a2aad 100644 --- 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: