Merge ~blake-rouse/maas:cmd-timeout-service-monitor into maas:master

[Blake Rouse]

Add a 5 second timeout to execution of system monitor.

Also adds more debug logging inside the system monitor.

[Mike Pontillo (mpontillo)]

Looks good! I tested this branch and it seems to prevent the DHCP errors I've been seeing this cycle.

review: Approve

diff --git a/src/provisioningserver/utils/service_monitor.py b/src/provisioningserver/utils/service_monitor.py
index b43d49e..3f5e76f 100644
--- a/src/provisioningserver/utils/service_monitor.py
+++ b/src/provisioningserver/utils/service_monitor.py
@@ -35,8 +35,12 @@ from provisioningserver.utils import (
     typed,
 )
 from provisioningserver.utils.shell import get_env_with_bytes_locale
-from provisioningserver.utils.twisted import asynchronous
+from provisioningserver.utils.twisted import (
+    asynchronous,
+    deferWithTimeout,
+)
 from twisted.internet.defer import (
+    CancelledError,
     DeferredList,
     DeferredLock,
     inlineCallbacks,
@@ -406,6 +410,35 @@ class ServiceMonitor:
             raise ServiceActionError(error_msg)
         yield self._performServiceAction(service, "reload")
 
+    def _execCmd(self, cmd, env, timeout=5):
+
+        def decode(result):
+            out, err, code = result
+            return code, out.decode("utf-8"), err.decode("utf-8")
+
+        def log_code(result, cmd):
+            _, _, code = result
+            log.debug(
+                "Service monitor got exit code '{code}' from cmd: {cmd()}",
+                code=code, cmd=lambda: ' '.join(cmd))
+            return result
+
+        def handle_timeout(failure, timeout, cmd):
+            failure.trap(CancelledError)
+            raise ServiceActionError(
+                "Service monitor timed out after '%d' "
+                "seconds running cmd: %s" % (timeout, ' '.join(cmd)))
+
+        log.debug(
+            "Service monitor executing cmd: {cmd()}",
+            cmd=lambda: ' '.join(cmd))
+
+        d = deferWithTimeout(
+            timeout, getProcessOutputAndValue, cmd[0], cmd[1:], env=env)
+        d.addErrback(handle_timeout, timeout, cmd)
+        d.addCallback(log_code, cmd)
+        return d.addCallback(decode)
+
     @asynchronous
     def _execSystemDServiceAction(self, service_name, action, extra_opts=None):
         """Perform the action with the systemctl command.
@@ -417,13 +450,7 @@ class ServiceMonitor:
         if extra_opts is not None:
             cmd.extend(extra_opts)
         cmd.append(service_name)
-
-        def decode(result):
-            out, err, code = result
-            return code, out.decode("utf-8"), err.decode("utf-8")
-
-        d = getProcessOutputAndValue(cmd[0], cmd[1:], env=env)
-        return d.addCallback(decode)
+        return self._execCmd(cmd, env)
 
     @asynchronous
     def _execSupervisorServiceAction(self, service_name, action):
@@ -434,13 +461,7 @@ class ServiceMonitor:
         env = get_env_with_bytes_locale()
         cmd = os.path.join(snappy.get_snap_path(), "bin", "run-supervisorctl")
         cmd = (cmd, action, service_name)
-
-        def decode(result):
-            out, err, code = result
-            return code, out.decode("utf-8"), err.decode("utf-8")
-
-        d = getProcessOutputAndValue(cmd[0], cmd[1:], env=env)
-        return d.addCallback(decode)
+        return self._execCmd(cmd, env)
 
     @inlineCallbacks
     def _performServiceAction(self, service, action):
diff --git a/src/provisioningserver/utils/tests/test_service_monitor.py b/src/provisioningserver/utils/tests/test_service_monitor.py
index f40619b..969fb00 100644
--- a/src/provisioningserver/utils/tests/test_service_monitor.py
+++ b/src/provisioningserver/utils/tests/test_service_monitor.py
@@ -38,6 +38,7 @@ from provisioningserver.utils.service_monitor import (
     ToggleableService,
 )
 from provisioningserver.utils.shell import get_env_with_bytes_locale
+from provisioningserver.utils.twisted import pause
 from testscenarios import multiply_scenarios
 from testtools import ExpectedException
 from testtools.matchers import (
@@ -449,6 +450,14 @@ class TestServiceMonitor(MAASTestCase):
             yield service_monitor.reloadService(fake_service.name, if_on=True)
 
     @inlineCallbacks
+    def test___execCmd_times_out(self):
+        monitor = ServiceMonitor(make_fake_service())
+        with ExpectedException(ServiceActionError):
+            yield monitor._execCmd(["sleep", "0.3"], {}, timeout=0.1)
+        # Pause long enough for the reactor to cleanup the process.
+        yield pause(0.5)
+
+    @inlineCallbacks
     def test___execSystemDServiceAction_calls_systemctl(self):
         service_monitor = self.make_service_monitor()
         service_name = factory.make_name("service")