Merge lp:~mpontillo/maas/dhcp-probe-log-spam--bug-1633717 into lp:~maas-committers/maas/trunk

[Mike Pontillo]

Fix extraneous logging in external DHCP detection.

 * No longer attempt to probe any interfaces without an IPv4
   address assigned (it will always fail anyway).
 * Add utility to determine if there is an IPv4 address on a specified
   interface, given the interfaces definition dictionary.
 * Fix error surfacing to include traceback.

[Lee Trager (ltrager)]

LGTM!

[Lee Trager (ltrager)]

review: Approve

=== modified file 'src/provisioningserver/rackdservices/dhcp_probe_service.py'
--- src/provisioningserver/rackdservices/dhcp_probe_service.py	2016-10-01 01:25:00 +0000
+++ src/provisioningserver/rackdservices/dhcp_probe_service.py	2016-10-21 19:00:29 +0000
@@ -15,7 +15,10 @@
 from provisioningserver.logger.log import get_maas_logger
 from provisioningserver.rpc.exceptions import NoConnectionsAvailable
 from provisioningserver.rpc.region import ReportForeignDHCPServer
-from provisioningserver.utils.network import get_all_interfaces_definition
+from provisioningserver.utils.network import (
+    get_all_interfaces_definition,
+    has_ipv4_address,
+)
 from provisioningserver.utils.twisted import (
     pause,
     retries,
@@ -50,8 +53,11 @@
         self.clock = reactor
         self.client_service = client_service
 
-    def log(self, string):
-        log.msg(string, system=type(self).__name__)
+    def log(self, *args, **kwargs):
+        log.msg(*args, **kwargs, system=type(self).__name__)
+
+    def err(self, *args, **kwargs):
+        log.err(*args, **kwargs, system=type(self).__name__)
 
     def _get_interfaces(self):
         """Return the interfaces for this rack controller."""
@@ -59,7 +65,13 @@
         d.addCallback(lambda interfaces: [
             name
             for name, info in interfaces.items()
-            if info["enabled"]
+            # No IPv4 address (unfortunately) means that MAAS cannot probe
+            # this interface. This is because ultimately the DHCP probe
+            # mechanism must send out a unicast UDP packet from the
+            # interface in order to receive a response, and the TCP/IP
+            # stack will drop packets coming back from the server if an
+            # unexpected address is used.
+            if info["enabled"] and has_ipv4_address(interfaces, name)
         ])
         return d
 
@@ -123,7 +135,7 @@
                     "'%s'." % interface)
                 if is_dev_environment():
                     error += " (Did you configure authbind per HACKING.txt?)"
-                log.err(e, error, system=type(self).__name__)
+                self.err(e, error)
                 continue
             else:
                 if len(servers) > 0:
@@ -146,5 +158,6 @@
             maaslog.error(
                 "Unable to probe for DHCP servers: %s",
                 str(error))
+            self.err(error, "Unable to probe for DHCP servers.")
         else:
             maaslog.debug("Finished periodic DHCP probe.")

=== modified file 'src/provisioningserver/rackdservices/tests/test_dhcp_probe_service.py'
--- src/provisioningserver/rackdservices/tests/test_dhcp_probe_service.py	2016-10-18 11:55:44 +0000
+++ src/provisioningserver/rackdservices/tests/test_dhcp_probe_service.py	2016-10-21 19:00:29 +0000
@@ -5,7 +5,6 @@
 
 __all__ = []
 
-
 from unittest.mock import (
     Mock,
     sentinel,
@@ -13,8 +12,10 @@
 
 from maastesting.factory import factory
 from maastesting.matchers import (
+    DocTestMatches,
     get_mock_calls,
     HasLength,
+    MockCalledOnce,
     MockCalledOnceWith,
     MockNotCalled,
 )
@@ -22,6 +23,7 @@
     MAASTestCase,
     MAASTwistedRunTest,
 )
+from maastesting.twisted import TwistedLoggerFixture
 from provisioningserver.rackdservices import dhcp_probe_service
 from provisioningserver.rackdservices.dhcp_probe_service import (
     DHCPProbeService,
@@ -81,6 +83,7 @@
         interfaces = {
             interface_name: {
                 "enabled": True,
+                "links": [{"address": "10.0.0.1/24"}]
             }
         }
 
@@ -118,6 +121,7 @@
         interfaces = {
             interface_name: {
                 "enabled": True,
+                "links": [{"address": "10.0.0.1/24"}]
             }
         }
 
@@ -130,11 +134,103 @@
         error_message = factory.make_string()
         self.patch(service, 'probe_dhcp').side_effect = Exception(
             error_message)
-        service.startService()
-        self.assertThat(
-            maaslog.error, MockCalledOnceWith(
-                "Unable to probe for DHCP servers: %s",
-                error_message))
+        with TwistedLoggerFixture() as logger:
+            service.startService()
+            self.assertThat(
+                maaslog.error, MockCalledOnceWith(
+                    "Unable to probe for DHCP servers: %s",
+                    error_message))
+            self.assertThat(logger.output, DocTestMatches(
+                "Unable to probe for DHCP servers.\n..."
+                "Traceback... "))
+
+    @inlineCallbacks
+    def test_skips_disabled_interfaces(self):
+        clock = Clock()
+        interface_name = factory.make_name("eth")
+        interfaces = {
+            interface_name: {
+                "enabled": False,
+                "links": [{"address": "10.0.0.1/24"}]
+            }
+        }
+        mock_interfaces = self.patch(
+            dhcp_probe_service, 'get_all_interfaces_definition')
+        mock_interfaces.return_value = interfaces
+        service = DHCPProbeService(
+            sentinel.service, clock)
+        try_get_client = self.patch(service, '_tryGetClient')
+        try_get_client.getClient = Mock()
+        probe_interface = self.patch(dhcp_probe_service, 'probe_interface')
+        yield service.startService()
+        yield service.stopService()
+        self.assertThat(probe_interface, MockNotCalled())
+
+    @inlineCallbacks
+    def test_probes_ipv4_interfaces(self):
+        clock = Clock()
+        interface_name = factory.make_name("eth")
+        interfaces = {
+            interface_name: {
+                "enabled": True,
+                "links": [{"address": "10.0.0.1/24"}]
+            }
+        }
+        mock_interfaces = self.patch(
+            dhcp_probe_service, 'get_all_interfaces_definition')
+        mock_interfaces.return_value = interfaces
+        service = DHCPProbeService(
+            sentinel.service, clock)
+        try_get_client = self.patch(service, '_tryGetClient')
+        try_get_client.getClient = Mock()
+        probe_interface = self.patch(dhcp_probe_service, 'probe_interface')
+        yield service.startService()
+        yield service.stopService()
+        self.assertThat(probe_interface, MockCalledOnce())
+
+    @inlineCallbacks
+    def test_skips_ipv6_interfaces(self):
+        clock = Clock()
+        interface_name = factory.make_name("eth")
+        interfaces = {
+            interface_name: {
+                "enabled": True,
+                "links": [{"address": "2001:db8::1/64"}]
+            }
+        }
+        mock_interfaces = self.patch(
+            dhcp_probe_service, 'get_all_interfaces_definition')
+        mock_interfaces.return_value = interfaces
+        service = DHCPProbeService(
+            sentinel.service, clock)
+        try_get_client = self.patch(service, '_tryGetClient')
+        try_get_client.getClient = Mock()
+        probe_interface = self.patch(dhcp_probe_service, 'probe_interface')
+        yield service.startService()
+        yield service.stopService()
+        self.assertThat(probe_interface, MockNotCalled())
+
+    @inlineCallbacks
+    def test_skips_unconfigured_interfaces(self):
+        clock = Clock()
+        interface_name = factory.make_name("eth")
+        interfaces = {
+            interface_name: {
+                "enabled": True,
+                "links": []
+            }
+        }
+        mock_interfaces = self.patch(
+            dhcp_probe_service, 'get_all_interfaces_definition')
+        mock_interfaces.return_value = interfaces
+        service = DHCPProbeService(
+            sentinel.service, clock)
+        try_get_client = self.patch(service, '_tryGetClient')
+        try_get_client.getClient = Mock()
+        probe_interface = self.patch(dhcp_probe_service, 'probe_interface')
+        yield service.startService()
+        yield service.stopService()
+        self.assertThat(probe_interface, MockNotCalled())
 
     @inlineCallbacks
     def test_reports_foreign_dhcp_servers_to_region(self):
@@ -143,6 +239,7 @@
         interfaces = {
             interface_name: {
                 "enabled": True,
+                "links": [{"address": "10.0.0.1/24"}]
             }
         }
 
@@ -182,6 +279,7 @@
         interfaces = {
             interface_name: {
                 "enabled": True,
+                "links": [{"address": "10.0.0.1/24"}]
             }
         }
 

=== modified file 'src/provisioningserver/utils/network.py'
--- src/provisioningserver/utils/network.py	2016-10-17 23:56:12 +0000
+++ src/provisioningserver/utils/network.py	2016-10-21 19:00:29 +0000
@@ -1171,6 +1171,23 @@
     return interfaces
 
 
+def has_ipv4_address(interfaces: dict, interface: str) -> bool:
+    """Returns True if the specified interface has an IPv4 address assigned.
+
+    If no addresses are assigned, or only addresses with other address families
+    are assigned (IPv6), returns False.
+
+    :param interfaces: The output of `get_all_interfaces_definition()`.
+    :param interface: The interface name to check.
+    """
+    links = interfaces[interface]["links"]
+    address_families = {
+        IPAddress(link['address'].split('/')[0]).version
+        for link in links
+    }
+    return 4 in address_families
+
+
 def is_loopback_address(hostname):
     """Determine if the given hostname appears to be a loopback address.
 

=== modified file 'src/provisioningserver/utils/tests/test_network.py'
--- src/provisioningserver/utils/tests/test_network.py	2016-10-17 17:34:28 +0000
+++ src/provisioningserver/utils/tests/test_network.py	2016-10-21 19:00:29 +0000
@@ -51,6 +51,7 @@
     get_eui_organization,
     get_interface_children,
     get_mac_organization,
+    has_ipv4_address,
     hex_str_to_bytes,
     inet_ntop,
     interface_children,
@@ -1472,6 +1473,49 @@
         self.assertInterfacesResult(ip_addr, iproute_info, {}, expected_result)
 
 
+class TestHasIPv4Address(MAASTestCase):
+    """Tests for `has_ipv4_address()`."""
+
+    def make_interfaces(self, name, address=None):
+        links = []
+        if address is not None:
+            links.append({
+                'address': address,
+                'mode': 'static'
+            })
+        return {
+            name: {
+                'enabled': True,
+                'links': links,
+                'mac_address': '52:54:00:e7:d9:2c',
+                'monitored': True,
+                'parents': [],
+                'source': 'ipaddr',
+                'type': 'physical'
+            }
+        }
+
+    def test__returns_false_for_no_ip_address(self):
+        ifname = factory.make_name('eth')
+        self.assertThat(
+            has_ipv4_address(self.make_interfaces(ifname), ifname),
+            Equals(False))
+
+    def test__returns_false_for_ipv6_address(self):
+        ifname = factory.make_name('eth')
+        address = "%s/64" % factory.make_ipv6_address()
+        self.assertThat(
+            has_ipv4_address(self.make_interfaces(ifname, address), ifname),
+            Equals(False))
+
+    def test__returns_true_for_ipv4_address(self):
+        ifname = factory.make_name('eth')
+        address = "%s/24" % factory.make_ipv4_address()
+        self.assertThat(
+            has_ipv4_address(self.make_interfaces(ifname, address), ifname),
+            Equals(True))
+
+
 class TestGetInterfaceChildren(MAASTestCase):
     """Tests for `get_interface_children()`."""