Merge lp:~allenap/maas/dns-timeout--bug-1672735 into lp:~maas-committers/maas/trunk

[Gavin Panella]

Suppress/ignore DNS time-outs when consuming neighbour events.

This also creates a new suppress function that is used instead of Failure.trap to suppress exceptions in a Deferred callback chain, and adds a testing helper callWithRunningService to make testing with Twisted services a little easier.

This branch contains some other, related, changes:

- Makes the module-local `suppress` function into a shared util.
  Previously I had used Failure.trap, but this returns the unwrapped
  exception when it matches, and this is then passed to the next
  callback in a Deferred. I don't think this has caused any harm, but
  it's a loose end that /may/ conceivably have caused problems, and will
  inevitably cause confusion some day.

- Creates a testing helper, callWithRunningService, that starts a
  Twisted service, calls a function, then stops the service again (akin
  to wrapping it in a try...finally). The result of calling the function
  is returned as the result of the Deferred.

[Mike Pontillo (mpontillo)]

Looks good; thanks for the fix.

Minor nit: I think some of your description deserves to be in the commit message.

review: Approve

=== modified file 'src/maasserver/listener.py'
--- src/maasserver/listener.py	2016-11-17 11:46:08 +0000
+++ src/maasserver/listener.py	2017-04-05 08:55:59 +0000
@@ -17,6 +17,7 @@
 from provisioningserver.utils.enum import map_enum
 from provisioningserver.utils.twisted import (
     callOut,
+    suppress,
     synchronous,
 )
 from twisted.application.service import Service
@@ -332,7 +333,7 @@
                 self.disconnecting.callback(None)
             else:
                 # Still connecting: cancel before disconnect.
-                self.connecting.addErrback(Failure.trap, CancelledError)
+                self.connecting.addErrback(suppress, CancelledError)
                 self.connecting.chainDeferred(self.disconnecting)
                 self.connecting.cancel()
 

=== modified file 'src/maasserver/regiondservices/reverse_dns.py'
--- src/maasserver/regiondservices/reverse_dns.py	2016-10-28 15:58:32 +0000
+++ src/maasserver/regiondservices/reverse_dns.py	2017-04-05 08:55:59 +0000
@@ -17,8 +17,9 @@
 from maasserver.utils.threads import deferToDatabase
 from provisioningserver.logger import LegacyLogger
 from provisioningserver.utils.network import reverseResolve
+from provisioningserver.utils.twisted import suppress
 from twisted.application.service import Service
-from twisted.internet.defer import inlineCallbacks
+from twisted.internet import defer
 
 
 log = LegacyLogger()
@@ -34,7 +35,7 @@
         # need to look it up every time a DNS entry changes.
         self.region = None
 
-    @inlineCallbacks
+    @defer.inlineCallbacks
     def startService(self):
         super().startService()
         self.region = yield deferToDatabase(
@@ -67,7 +68,7 @@
         """
         RDNS.objects.delete_current_entry(ip, self.region)
 
-    @inlineCallbacks
+    @defer.inlineCallbacks
     def consumeNeighbourEvent(self, action: str=None, cidr: str=None):
         """Given an event from the postgresListener, resolve RDNS for an IP.
 
@@ -85,7 +86,8 @@
             # the same IP address, and because an IP address might repeatedly
             # go back-and-forth between two MACs in the case of a duplicate IP
             # address.
-            results = yield reverseResolve(ip)
+            results = yield reverseResolve(ip).addErrback(
+                suppress, defer.TimeoutError, instead=None)
             if results is not None:
                 if len(results) > 0:
                     yield deferToDatabase(self.set_rdns_entry, ip, results)

=== modified file 'src/maasserver/regiondservices/tests/test_reverse_dns.py'
--- src/maasserver/regiondservices/tests/test_reverse_dns.py	2016-10-20 23:17:48 +0000
+++ src/maasserver/regiondservices/tests/test_reverse_dns.py	2017-04-05 08:55:59 +0000
@@ -15,6 +15,7 @@
 from maasserver.testing.testcase import MAASTransactionServerTestCase
 from maasserver.utils.threads import deferToDatabase
 from maastesting.matchers import MockCalledOnceWith
+from provisioningserver.utils.testing import callWithServiceRunning
 from provisioningserver.utils.tests.test_network import (
     TestReverseResolveMixIn,
 )
@@ -22,6 +23,7 @@
     Equals,
     Is,
 )
+from twisted.internet import defer
 from twisted.internet.defer import inlineCallbacks
 
 
@@ -109,3 +111,17 @@
         self.assertThat(listener.unregister, MockCalledOnceWith(
             'neighbour', service.consumeNeighbourEvent
         ))
+
+    @wait_for(30)
+    @inlineCallbacks
+    def test__ignores_timeouts_when_consuming_neighbour_event(self):
+        reverseResolve = self.patch(reverse_dns_module, "reverseResolve")
+        reverseResolve.return_value = defer.fail(defer.TimeoutError())
+        ip = factory.make_ip_address(ipv6=False)
+        service = ReverseDNSService()
+        yield callWithServiceRunning(
+            service, service.consumeNeighbourEvent,
+            "create", "%s/32" % ip)
+        self.assertThat(reverseResolve, MockCalledOnceWith(ip))
+        result = yield deferToDatabase(RDNS.objects.first)
+        self.assertThat(result, Is(None))

=== modified file 'src/maasserver/utils/async.py'
--- src/maasserver/utils/async.py	2016-11-01 09:18:42 +0000
+++ src/maasserver/utils/async.py	2017-04-05 08:55:59 +0000
@@ -20,6 +20,7 @@
     asynchronous,
     FOREVER,
     LONGTIME,
+    suppress,
     synchronous,
 )
 from twisted.internet import reactor
@@ -160,11 +161,6 @@
     return UseOnceIterator(queue.get, done)
 
 
-def suppress(failure, *exceptions):
-    """Used as a errback, suppress the given exceptions."""
-    failure.trap(*exceptions)
-
-
 class DeferredHooks(threading.local):
     """A utility class for managing hooks that are specified as Deferreds.
 

=== modified file 'src/provisioningserver/events.py'
--- src/provisioningserver/events.py	2017-02-17 14:23:04 +0000
+++ src/provisioningserver/events.py	2017-04-05 08:55:59 +0000
@@ -39,12 +39,12 @@
     callOut,
     DeferredValue,
     FOREVER,
+    suppress,
 )
 from twisted.internet.defer import (
     maybeDeferred,
     succeed,
 )
-from twisted.python.failure import Failure
 
 
 maaslog = get_maas_logger("events")
@@ -464,7 +464,7 @@
         # tracebacks telling us about it is not useful. Perhaps the region
         # should store these logs anyway. Then, if and when the node is
         # enlisted, logs prior to enlistment can be seen.
-        d.addErrback(Failure.trap, NoSuchNode)
+        d.addErrback(suppress, NoSuchNode)
 
         return d
 

=== modified file 'src/provisioningserver/rpc/clusterservice.py'
--- src/provisioningserver/rpc/clusterservice.py	2017-04-03 14:09:30 +0000
+++ src/provisioningserver/rpc/clusterservice.py	2017-04-05 08:55:59 +0000
@@ -100,6 +100,7 @@
     deferred,
     DeferredValue,
     makeDeferredWithProcessProtocol,
+    suppress,
 )
 from twisted import web
 from twisted.application.internet import TimerService
@@ -120,7 +121,6 @@
 )
 from twisted.internet.threads import deferToThread
 from twisted.protocols import amp
-from twisted.python.failure import Failure
 from twisted.python.reflect import fullyQualifiedName
 from twisted.web import http
 import twisted.web.client
@@ -651,7 +651,7 @@
                 executeScanNetworksSubprocess, scan_all=scan_all,
                 force_ping=force_ping, slow=slow, cidrs=cidrs, threads=threads,
                 interface=interface)
-            d.addErrback(Failure.trap, ProcessDone)  # Exited normally.
+            d.addErrback(suppress, ProcessDone)  # Exited normally.
             d.addErrback(log.err, 'Failed to scan all networks.')
             d.addBoth(callOut, lock.release)
         return {}

=== modified file 'src/provisioningserver/utils/services.py'
--- src/provisioningserver/utils/services.py	2017-03-24 15:28:07 +0000
+++ src/provisioningserver/utils/services.py	2017-04-05 08:55:59 +0000
@@ -32,6 +32,7 @@
 from provisioningserver.utils.twisted import (
     callOut,
     deferred,
+    suppress,
     terminateProcess,
 )
 from twisted.application.internet import TimerService
@@ -48,7 +49,6 @@
 )
 from twisted.internet.protocol import ProcessProtocol
 from twisted.internet.threads import deferToThread
-from twisted.python.failure import Failure
 
 
 maaslog = get_maas_logger("networks.monitor")
@@ -349,7 +349,7 @@
         # During the update, we might fail to get the interface monitoring
         # state from the region. We can safely ignore this, as it will be
         # retried shortly.
-        d.addErrback(Failure.trap, NoConnectionsAvailable)
+        d.addErrback(suppress, NoConnectionsAvailable)
         d.addErrback(failed)
         return d
 

=== modified file 'src/provisioningserver/utils/testing.py'
--- src/provisioningserver/utils/testing.py	2016-09-23 15:26:39 +0000
+++ src/provisioningserver/utils/testing.py	2017-04-05 08:55:59 +0000
@@ -4,6 +4,7 @@
 """Testing helpers for provisioningserver.utils."""
 
 __all__ = [
+    "callWithServiceRunning",
     "MAASIDFixture",
     "RegistryFixture",
 ]
@@ -11,6 +12,11 @@
 from fixtures import Fixture
 from provisioningserver.utils import env
 from provisioningserver.utils.registry import _registry
+from provisioningserver.utils.twisted import (
+    call,
+    callOut,
+)
+from twisted.internet import defer
 
 
 class RegistryFixture(Fixture):
@@ -34,3 +40,17 @@
         super(MAASIDFixture, self)._setUp()
         self.addCleanup(env.set_maas_id, env.get_maas_id())
         env.set_maas_id(self.system_id)
+
+
+def callWithServiceRunning(service, f, *args, **kwargs):
+    """Call `f` with `service` running.
+
+    The given service is a Twisted service. It is started, the given function
+    called with the given arguments, then the service is stopped.
+
+    Returns a `Deferred`, firing with the result of the call to `f`.
+    """
+    d = defer.maybeDeferred(service.startService)
+    d.addCallback(call, f, *args, **kwargs)
+    d.addBoth(callOut, service.stopService)
+    return d

=== modified file 'src/provisioningserver/utils/tests/test_network.py'
--- src/provisioningserver/utils/tests/test_network.py	2016-12-07 12:46:14 +0000
+++ src/provisioningserver/utils/tests/test_network.py	2017-04-05 08:55:59 +0000
@@ -1975,11 +1975,8 @@
         data = (rrset,)
         for hostname in hostnames:
             rr = Mock()
-            rr.payload = Mock()
-            rr.payload.name = Mock()
-            rr.payload.name.name = Mock()
-            rr.payload.name.name.decode = Mock()
-            rr.payload.name.name.decode.return_value = hostname
+            decode = rr.payload.name.name.decode
+            decode.return_value = hostname
             rrset.append(rr)
         self.reply = data
 

=== modified file 'src/provisioningserver/utils/tests/test_twisted.py'
--- src/provisioningserver/utils/tests/test_twisted.py	2017-03-30 22:10:58 +0000
+++ src/provisioningserver/utils/tests/test_twisted.py	2017-04-05 08:55:59 +0000
@@ -66,6 +66,7 @@
     reducedWebLogFormatter,
     retries,
     RPCFetcher,
+    suppress,
     synchronous,
     terminateProcess,
     ThreadPool,
@@ -304,6 +305,27 @@
             % (Something.__qualname__, a, b)))
 
 
+class TestSuppress(MAASTestCase):
+    """Tests for `suppress`."""
+
+    def test__suppresses_given_exception(self):
+        error_type = factory.make_exception_type()
+        failure = Failure(error_type())
+        self.assertThat(suppress(failure, error_type), Is(None))
+
+    def test__does_not_suppress_other_exceptions(self):
+        error_type = factory.make_exception_type()
+        failure = Failure(factory.make_exception())
+        self.assertThat(suppress(failure, error_type), Is(failure))
+
+    def test__returns_instead_value_when_suppressing(self):
+        error_type = factory.make_exception_type()
+        failure = Failure(error_type())
+        self.assertThat(
+            suppress(failure, error_type, instead=sentinel.instead),
+            Is(sentinel.instead))
+
+
 class TestRetries(MAASTestCase):
 
     def assertRetry(
@@ -1857,7 +1879,7 @@
         pid = process.pid
         # Terminate and wait for it to exit.
         self.terminateSignalPrinter(process, protocol)
-        yield protocol.done.addErrback(Failure.trap, ProcessTerminated)
+        yield protocol.done.addErrback(suppress, ProcessTerminated)
         # os.kill was called once then os.killpg was called twice because the
         # subprocess made itself a process group leader.
         self.assertThat(
@@ -1878,7 +1900,7 @@
         pid = process.pid
         # Terminate and wait for it to exit.
         self.terminateSignalPrinter(process, protocol)
-        yield protocol.done.addErrback(Failure.trap, ProcessTerminated)
+        yield protocol.done.addErrback(suppress, ProcessTerminated)
         # os.kill was called 3 times because the subprocess did not make
         # itself a process group leader.
         self.assertThat(

=== modified file 'src/provisioningserver/utils/twisted.py'
--- src/provisioningserver/utils/twisted.py	2017-03-30 22:10:58 +0000
+++ src/provisioningserver/utils/twisted.py	2017-04-05 08:55:59 +0000
@@ -22,6 +22,7 @@
     'pause',
     'reducedWebLogFormatter',
     'retries',
+    'suppress',
     'synchronous',
     'ThreadPool',
     'ThreadPoolLimiter',
@@ -246,6 +247,17 @@
     return wrapper
 
 
+def suppress(failure, *exceptions, instead=None):
+    """Used as a errback, suppress the given exceptions.
+
+    Returns the given `instead` value... instead.
+    """
+    if failure.check(*exceptions) is None:
+        return failure
+    else:
+        return instead
+
+
 def retries(timeout=30, intervals=1, clock=reactor):
     """Helper for retrying something, sleeping between attempts.