Merge lp:~cprov/launchpad/bug-404693-resuming-builder-with-timeout into lp:launchpad/db-devel

[Celso Providelo]

[Celso Providelo (cprov)]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

= Summary =

This branch fixes https://bugs.edge.launchpad.net/soyuz/+bug/404693. Resuming broken slaves will not block the buildd-manager anymore.

== Proposed fix ==

I've created `run_process_with_timeout` entry point in twistedsupport which uses the existing and tested `ProcessMonitorProtocolWithTimeout` and allows us to safely abort (SIGINT then SIGKILL) processes taking longer than expected.

== Implementation details ==

Originally we were using the script output when logging problems, I've removed it. Mainly because it doesn't add much and implementing the same behavior with the existing protocol would consume extra time that we don't have.

When integrating `run_process_with_timeout` in RecordingSlave.resumeHost, I've re-used the current 'socket_timeout' value from the buildmaster configuration.

I've done this simply because I didn't want to add another mysterious value to the already confusing configuration section. I'm happy to create one if it'd make things clearer.

== Tests ==

./bin/test -vv -t TestRecordingSlaves -t TestRunProcessWithTimeout

= Launchpad lint =

Checking for conflicts. and issues in doctests and templates.
Running jslint, xmllint, pyflakes, and pylint.
Using normal rules.

Linting changed files:
  lib/lp/buildmaster/tests/test_manager.py
  lib/canonical/twistedsupport/processmonitor.py
  lib/canonical/twistedsupport/tests/test_processmonitor.py
  lib/lp/buildmaster/manager.py
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.9 (GNU/Linux)

iEYEARECAAYFAkpsafEACgkQ7KBXuXyZSjDD3wCeOb3/lVEYnXW0N7jlEfjVo30I
rfQAnivz65cpO81BfOp0cCezptpBwnfB
=EJRw
-----END PGP SIGNATURE-----

[Michael Hudson-Doyle (mwhudson)]

Looks great.

review: Approve

[Christian Reis (kiko)]

On Mon, Jul 27, 2009 at 06:11:22PM -0000, Celso Providelo wrote:
> This branch fixes https://bugs.edge.launchpad.net/soyuz/+bug/404693.
> Resuming broken slaves will not block the buildd-manager anymore.

I like this patch, but it looks a bit dodgy for a last-minute RC. Can we
get some serious QA done on dogfood and then request a CP onto the right
box for proper deployment?
--
Christian Robottom Reis | [+55 16] 3376 0125 | http://launchpad.net/~kiko
                        | [+55 16] 9112 6430 | http://async.com.br/~kiko

=== modified file 'lib/canonical/twistedsupport/processmonitor.py'
--- lib/canonical/twistedsupport/processmonitor.py	2009-06-25 05:30:52 +0000
+++ lib/canonical/twistedsupport/processmonitor.py	2009-07-26 14:19:49 +0000
@@ -4,7 +4,11 @@
 """Helpers for running a child process and communicating things about it."""
 
 __metaclass__ = type
-__all__ = ['ProcessMonitorProtocol', 'ProcessMonitorProtocolWithTimeout']
+__all__ = [
+    'ProcessMonitorProtocol',
+    'ProcessMonitorProtocolWithTimeout',
+    'run_process_with_timeout',
+    ]
 
 
 from twisted.internet import defer, error, reactor
@@ -232,3 +236,20 @@
         self.setTimeout(None)
         ProcessMonitorProtocol.processEnded(self, reason)
 
+
+def run_process_with_timeout(args, timeout=5, clock=None):
+    """Run the given process with the specificed timeout.
+
+    :param args: tuple with the command-line arguments.
+    :param timeout: command timeout in seconds, defaults to 5.
+    :param clock: Passed to `ProcessMonitorProtocolWithTimeout.__init__`.
+
+    :return: a `Deferred` of the spawed process using
+        `ProcessMonitorProtocolWithTimeout`
+    """
+    assert isinstance(args, tuple), "'args' must be a tuple."
+    d = defer.Deferred()
+    p = ProcessMonitorProtocolWithTimeout(d, timeout, clock)
+    executable = args[0]
+    reactor.spawnProcess(p, executable, args)
+    return d

=== modified file 'lib/canonical/twistedsupport/tests/test_processmonitor.py'
--- lib/canonical/twistedsupport/tests/test_processmonitor.py	2009-06-25 05:30:52 +0000
+++ lib/canonical/twistedsupport/tests/test_processmonitor.py	2009-07-26 14:19:49 +0000
@@ -18,7 +18,7 @@
 from canonical.twistedsupport import suppress_stderr
 from canonical.twistedsupport.processmonitor import (
     ProcessMonitorProtocol, ProcessMonitorProtocolWithTimeout,
-    ProcessProtocolWithTwoStageKill)
+    ProcessProtocolWithTwoStageKill, run_process_with_timeout)
 
 
 def makeFailure(exception_factory, *args, **kwargs):
@@ -312,5 +312,48 @@
         deferred.callback(None)
         return self.termination_deferred
 
+
+class TestRunProcessWithTimeout(TrialTestCase):
+    """Tests for `run_process_with_timeout`."""
+
+    layer = TwistedLayer
+
+    def test_run_process_with_timeout_invalid_args(self):
+        # `run_process_with_timeout` expects the process 'args' to be a
+        # tuple.
+        self.assertRaises(
+            AssertionError, run_process_with_timeout, 'true')
+
+    def test_run_proces_with_timeout_success(self):
+        # On success, i.e process succeeded before the specified timeout,
+        # callback is fired with 'None'.
+        d = run_process_with_timeout(('true',))
+        def check_success_result(result):
+            self.assertEquals(result, None, "Success result is not None.")
+        d.addCallback(check_success_result)
+        return d
+
+    def test_run_process_with_timeout_failure(self):
+        # On failed process, the errback is fired with a `ProcessTerminated`
+        # failure.
+        d = run_process_with_timeout(('false',))
+        return self.assertFailure(d, error.ProcessTerminated)
+
+    def test_run_process_with_timeout_broken(self):
+        # On broken process, the errback is fired with a `ProcessTerminated`
+        # failure.
+        d = run_process_with_timeout(('does-not-exist',))
+        return self.assertFailure(d, error.ProcessTerminated)
+
+    def test_run_process_with_timeout_timeout(self):
+        # On process timeout, the errback is fired with `TimeoutError`
+        # failure.
+        clock = task.Clock()
+        d = run_process_with_timeout(
+            ('sleep', '2'), timeout=1, clock=clock)
+        clock.advance(2)
+        return self.assertFailure(d, error.TimeoutError)
+
+
 def test_suite():
     return unittest.TestLoader().loadTestsFromName(__name__)

=== modified file 'lib/lp/buildmaster/manager.py'
--- lib/lp/buildmaster/manager.py	2009-06-25 00:46:29 +0000
+++ lib/lp/buildmaster/manager.py	2009-07-26 14:19:49 +0000
@@ -15,11 +15,10 @@
     ]
 
 import logging
-import os
 import transaction
 
 from twisted.application import service
-from twisted.internet import reactor, utils, defer
+from twisted.internet import reactor, defer
 from twisted.protocols.policies import TimeoutMixin
 from twisted.python import log
 from twisted.python.failure import Failure
@@ -31,6 +30,7 @@
 from canonical.config import config
 from canonical.launchpad.webapp import urlappend
 from canonical.librarian.db import write_transaction
+from canonical.twistedsupport.processmonitor import run_process_with_timeout
 
 
 buildd_success_result_map = {
@@ -109,13 +109,17 @@
         Used the configuration command-line in the same way
         `BuilddSlave.resume` does.
 
+        Also use the builddmaster configuration 'socket_timeout' as
+        the process timeout.
+
         :return: a Deferred
         """
         resume_command = config.builddmaster.vm_resume_command % {
             'vm_host': self.vm_host}
         # Twisted API require string and the configuration provides unicode.
         resume_argv = [str(term) for term in resume_command.split()]
-        d = utils.getProcessOutputAndValue(resume_argv[0], resume_argv[1:])
+        d = run_process_with_timeout(
+            tuple(resume_argv), timeout=config.builddmaster.socket_timeout)
         return d
 
 
@@ -358,12 +362,11 @@
         If it failed, it returns a corresponding `ResetDispatchResult`
         dispatch result.
         """
-        out, err, code = response
-        if code == os.EX_OK:
+        if not isinstance(response, Failure):
             return None
 
         self.logger.error(
-            '%s resume failure:\nOUT: %s\nErr: %s' % (slave, out, err))
+            '%s resume failure: %s' % (slave, response.getErrorMessage()))
         self.slaveDone(slave)
         return self.reset_result(slave)
 

=== modified file 'lib/lp/buildmaster/tests/test_manager.py'
--- lib/lp/buildmaster/tests/test_manager.py	2009-06-25 00:46:29 +0000
+++ lib/lp/buildmaster/tests/test_manager.py	2009-07-26 14:19:49 +0000
@@ -8,7 +8,8 @@
 import unittest
 
 from twisted.internet import defer
-from twisted.internet.error import ConnectionClosed
+from twisted.internet.error import (
+    ConnectionClosed, ProcessTerminated, TimeoutError)
 from twisted.python.failure import Failure
 from twisted.trial.unittest import TestCase as TrialTestCase
 
@@ -43,14 +44,14 @@
         self.slave = RecordingSlave(
             'foo', 'http://foo:8221/rpc', 'foo.host')
 
-    def testInstantiation(self):
+    def test_representation(self):
         """`RecordingSlave` has a custom representation.
 
         It encloses builder name and xmlrpc url for debug purposes.
         """
         self.assertEqual('<foo:http://foo:8221/rpc>', repr(self.slave))
 
-    def testEnsurePresent(self):
+    def test_ensurepresent(self):
         """`RecordingSlave.ensurepresent` always succeeds.
 
         It returns the expected succeed code and records the interaction
@@ -63,7 +64,7 @@
             [('ensurepresent', ('boing', 'bar', 'baz'))],
             self.slave.calls)
 
-    def testBuild(self):
+    def test_build(self):
         """`RecordingSlave.build` always succeeds.
 
         It returns the expected succeed code and records the interaction
@@ -76,8 +77,8 @@
             [('build', ('boing', 'bar', 'baz'))],
             self.slave.calls)
 
-    def testResume(self):
-        """`RecordingSlave.resumeHost` returns a deferred resume request."""
+    def test_resume(self):
+        """`RecordingSlave.resume` always returns successs."""
         # Resume isn't requested in a just-instantiated RecordingSlave.
         self.assertFalse(self.slave.resume_requested)
 
@@ -86,38 +87,63 @@
         self.assertEqual(['', '', os.EX_OK], self.slave.resume())
         self.assertTrue(self.slave.resume_requested)
 
+    def test_resumeHost_success(self):
+        # On a successful resume resumeHost() fires the returned deferred
+        # callback with 'None'.
+
         # The configuration testing command-line.
         self.assertEqual(
             'echo %(vm_host)s', config.builddmaster.vm_resume_command)
 
-        # When executed it returns the expected output.
+        # On success the response is None.
         def check_resume_success(response):
-            out, err, code = response
-            self.assertEqual(os.EX_OK, code)
-            self.assertEqual('', err)
-            self.assertEqual('foo.host', out.strip())
+            self.assertEquals(None, response)
+        d = self.slave.resumeSlave()
+        d.addCallback(check_resume_success)
+        return d
 
-        d1 = self.slave.resumeSlave()
-        d1.addCallback(check_resume_success)
+    def test_resumeHost_failure(self):
+        # On a failed resume, 'resumeHost' fires the returned deferred
+        # errorback with the `ProcessTerminated` failure.
 
         # Override the configuration command-line with one that will fail.
         failed_config = """
         [builddmaster]
         vm_resume_command: test "%(vm_host)s = 'no-sir'"
         """
-        config.push('vm_resume_command', failed_config)
-
-        def check_resume_failure(response):
-            out, err, code = response
-            self.assertNotEqual(os.EX_OK, code)
-            self.assertEqual('', err)
-            self.assertEqual('', out)
-            config.pop('vm_resume_command')
-
-        d2 = self.slave.resumeSlave()
-        d2.addCallback(check_resume_failure)
-
-        return defer.DeferredList([d1, d2])
+        config.push('failed_resume_command', failed_config)
+
+        # On failures, the response is a twisted `Failure` object containing
+        # a `ProcessTerminated` error.
+        def check_resume_failure(failure):
+            self.assertIsInstance(failure, Failure)
+            self.assertIsInstance(failure.value, ProcessTerminated)
+            config.pop('failed_resume_command')
+        d = self.slave.resumeSlave()
+        d.addErrback(check_resume_failure)
+        return d
+
+    def test_resumeHost_timeout(self):
+        # On a resume timeouts, 'resumeHost' fires the returned deferred
+        # errorback with the `TimeoutError` failure.
+
+        # Override the configuration command-line with one that will timeout.
+        timeout_config = """
+        [builddmaster]
+        vm_resume_command: sleep 5
+        socket_timeout: 1
+        """
+        config.push('timeout_resume_command', timeout_config)
+
+        # On timeouts, the response is a twisted `Failure` object containing
+        # a `TimeoutError` error.
+        def check_resume_timeout(failure):
+            self.assertIsInstance(failure, Failure)
+            self.assertIsInstance(failure.value, TimeoutError)
+            config.pop('timeout_resume_command')
+        d = self.slave.resumeSlave()
+        d.addErrback(check_resume_timeout)
+        return d
 
 
 class TestingXMLRPCProxy: