Merge lp:~cjwatson/launchpad/buildmaster-cancel-properly into lp:launchpad

[Colin Watson]

Cancel builds by sending an "abort" command to the build slave, with a three-minute timeout after which we give up and rescue the builder. This should now work even on non-virtualised builders.

This is the second half of the master side of build cancellation, following on from the first half of the master side in https://code.launchpad.net/~cjwatson/launchpad/buildstatus-aborted/+merge/176990, and the slave side in https://code.launchpad.net/~cjwatson/launchpad-buildd/fix-abort/+merge/177003 (both those branches must be landed first). With a working slave side we mainly just need to remove previous restrictions and arrange for a timeout in the event that the builder entirely fails to abort.

The bug that had previously led test_abort to be disabled should be fixed by using scan-for-processes on the slave rather than killing a specific process.

We should be able to get rid of most of BuilderStatus.ABORTED once this is all deployed and working.

For QA, we should test on dogfood with both virtualised and non-virtualised builders, using builds that (a) hang "normally" but are reasonably killable and (b) attempt to spawn processes faster than scan-for-processes can kill them. It might also be a good idea to attempt some kind of fake slave that can be told to enter the ABORTED state without the master asking it to do so.

[William Grant (wgrant)]

59 + self.logger.info("Build '%s' failed to cancel" % build.title)

I'd mention the builder here to make logs searchable.

80 + builder.requestAbort()
81 + self.date_cancel = self._clock.seconds() + self.CANCEL_TIMEOUT
82 + return defer.succeed(False)

requestAbort returns a Deferred that you might want to handle.

Additionally, what will happen if I restart buildd-manager while the builder is ABORTING? It'll attempt to call requestAbort again, which will probably fail, but it'll be ignored because you don't handle the Deferred.

review: Approve (code)

=== modified file 'lib/lp/buildmaster/interactor.py'
--- lib/lp/buildmaster/interactor.py	2013-08-29 04:58:10 +0000
+++ lib/lp/buildmaster/interactor.py	2013-08-29 12:10:56 +0000
@@ -364,16 +364,6 @@
             # the job.
             if (status == 'BuilderStatus.ABORTED'
                     and self.builder.currentjob is None):
-                if not self.builder.virtualized:
-                    # We can't reset non-virtual builders reliably as the
-                    # abort() function doesn't kill the actual build job,
-                    # only the sbuild process!  All we can do here is fail
-                    # the builder with a message indicating the problem and
-                    # wait for an admin to reboot it.
-                    self.builder.failBuilder(
-                        "Non-virtual builder in ABORTED state, requires admin "
-                        "to restart")
-                    return "dummy status"
                 if logger is not None:
                     logger.info(
                         "Builder '%s' being cleaned up from ABORTED" %

=== modified file 'lib/lp/buildmaster/manager.py'
--- lib/lp/buildmaster/manager.py	2013-08-29 04:28:50 +0000
+++ lib/lp/buildmaster/manager.py	2013-08-29 12:10:56 +0000
@@ -1,4 +1,4 @@
-# Copyright 2009-2012 Canonical Ltd.  This software is licensed under the
+# Copyright 2009-2013 Canonical Ltd.  This software is licensed under the
 # GNU Affero General Public License version 3 (see the file LICENSE).
 
 """Soyuz buildd slave manager logic."""
@@ -114,13 +114,25 @@
     # algorithm for polling.
     SCAN_INTERVAL = 15
 
-    def __init__(self, builder_name, logger):
+    # The time before deciding that a cancelling builder has failed, in
+    # seconds.  This should normally be a multiple of SCAN_INTERVAL, and
+    # greater than abort_timeout in launchpad-buildd's slave BuildManager.
+    CANCEL_TIMEOUT = 180
+
+    def __init__(self, builder_name, logger, clock=None):
         self.builder_name = builder_name
         self.logger = logger
+        # Use the clock if provided, so that tests can advance it.  Use the
+        # reactor by default.
+        if clock is None:
+            clock = reactor
+        self._clock = clock
+        self.date_cancel = None
 
     def startCycle(self):
         """Scan the builder and dispatch to it or deal with failures."""
         self.loop = LoopingCall(self.singleCycle)
+        self.loop.clock = self._clock
         self.stopping_deferred = self.loop.start(self.SCAN_INTERVAL)
         return self.stopping_deferred
 
@@ -172,32 +184,53 @@
                 exc_info=True)
             transaction.abort()
 
+    @defer.inlineCallbacks
     def checkCancellation(self, builder):
         """See if there is a pending cancellation request.
 
         If the current build is in status CANCELLING then terminate it
         immediately.
 
-        :return: A deferred whose value is True if we cancelled the build.
+        :return: A deferred whose value is True if we recovered the builder
+            by resuming a slave host, so that there is no need to update its
+            status.
         """
-        if not builder.virtualized:
-            return defer.succeed(False)
         buildqueue = self.builder.getBuildQueue()
         if not buildqueue:
-            return defer.succeed(False)
+            self.date_cancel = None
+            defer.returnValue(False)
         build = buildqueue.specific_job.build
         if build.status != BuildStatus.CANCELLING:
-            return defer.succeed(False)
-
-        def resume_done(ignored):
-            return defer.succeed(True)
-
-        self.logger.info("Cancelling build '%s'" % build.title)
-        buildqueue.cancel()
-        transaction.commit()
-        d = self.interactor.resumeSlaveHost()
-        d.addCallback(resume_done)
-        return d
+            self.date_cancel = None
+            defer.returnValue(False)
+
+        try:
+            if self.date_cancel is None:
+                self.logger.info("Cancelling build '%s'" % build.title)
+                yield self.interactor.requestAbort()
+                self.date_cancel = self._clock.seconds() + self.CANCEL_TIMEOUT
+                defer.returnValue(False)
+            else:
+                # The BuildFarmJob will normally set the build's status to
+                # something other than CANCELLING once the builder responds to
+                # the cancel request.  This timeout is in case it doesn't.
+                if self._clock.seconds() < self.date_cancel:
+                    self.logger.info(
+                        "Waiting for build '%s' to cancel" % build.title)
+                    defer.returnValue(False)
+                else:
+                    raise BuildSlaveFailure(
+                        "Build '%s' cancellation timed out" % build.title)
+        except Exception as e:
+            self.logger.info(
+                "Build '%s' on %s failed to cancel" %
+                (build.title, self.builder.name))
+            self.date_cancel = None
+            buildqueue.cancel()
+            transaction.commit()
+            value = yield self.interactor.resetOrFail(self.logger, e)
+            # value is not None if we resumed a slave host.
+            defer.returnValue(value is not None)
 
     def scan(self):
         """Probe the builder and update/dispatch/collect as appropriate.

=== modified file 'lib/lp/buildmaster/tests/mock_slaves.py'
--- lib/lp/buildmaster/tests/mock_slaves.py	2013-08-29 04:27:12 +0000
+++ lib/lp/buildmaster/tests/mock_slaves.py	2013-08-29 12:10:56 +0000
@@ -1,4 +1,4 @@
-# Copyright 2009-2011 Canonical Ltd.  This software is licensed under the
+# Copyright 2009-2013 Canonical Ltd.  This software is licensed under the
 # GNU Affero General Public License version 3 (see the file LICENSE).
 
 """Mock Build objects for tests soyuz buildd-system."""
@@ -222,6 +222,10 @@
         self.call_log.append('abort')
         return defer.fail(xmlrpclib.Fault(8002, "Could not abort"))
 
+    def resume(self):
+        self.call_log.append('resume')
+        return defer.succeed(("", "", 0))
+
 
 class BrokenSlave:
     """A mock slave that reports that it is broken."""

=== modified file 'lib/lp/buildmaster/tests/test_builder.py'
--- lib/lp/buildmaster/tests/test_builder.py	2013-08-29 04:12:56 +0000
+++ lib/lp/buildmaster/tests/test_builder.py	2013-08-29 12:10:56 +0000
@@ -1,4 +1,4 @@
-# Copyright 2009-2010 Canonical Ltd.  This software is licensed under the
+# Copyright 2009-2013 Canonical Ltd.  This software is licensed under the
 # GNU Affero General Public License version 3 (see the file LICENSE).
 
 """Test Builder features."""
@@ -359,18 +359,17 @@
         return d.addCallback(check_slave_calls)
 
     def test_recovery_of_aborted_nonvirtual_slave(self):
-        # Nonvirtual slaves in the ABORTED state cannot be reliably
-        # cleaned since the sbuild process doesn't properly kill the
-        # build job.  We test that the builder is marked failed.
+        # If a nonvirtual slave is in the ABORTED state,
+        # rescueBuilderIfLost should clean it if we don't think it's
+        # currently building anything.
         aborted_slave = AbortedSlave()
-        builder = MockBuilder(virtualized=False, builderok=True)
+        builder = MockBuilder(virtualized=False, builderok=False)
         d = BuilderInteractor(builder, aborted_slave).rescueIfLost()
 
-        def check_failed(ignored):
-            self.assertFalse(builder.builderok)
-            self.assertNotIn('clean', aborted_slave.call_log)
+        def check_slave_calls(ignored):
+            self.assertIn('clean', aborted_slave.call_log)
 
-        return d.addCallback(check_failed)
+        return d.addCallback(check_slave_calls)
 
     def test_recover_ok_slave(self):
         # An idle slave is not rescued.
@@ -885,10 +884,7 @@
         super(TestSlave, self).setUp()
         self.slave_helper = self.useFixture(SlaveTestHelpers())
 
-    # XXX 2010-10-06 Julian bug=655559
-    # This is failing on buildbot but not locally; it's trying to abort
-    # before the build has started.
-    def disabled_test_abort(self):
+    def test_abort(self):
         slave = self.slave_helper.getClientSlave()
         # We need to be in a BUILDING state before we can abort.
         d = self.slave_helper.triggerGoodBuild(slave)

=== modified file 'lib/lp/buildmaster/tests/test_manager.py'
--- lib/lp/buildmaster/tests/test_manager.py	2013-08-27 09:17:07 +0000
+++ lib/lp/buildmaster/tests/test_manager.py	2013-08-29 12:10:56 +0000
@@ -1,4 +1,4 @@
-# Copyright 2009-2010 Canonical Ltd.  This software is licensed under the
+# Copyright 2009-2013 Canonical Ltd.  This software is licensed under the
 # GNU Affero General Public License version 3 (see the file LICENSE).
 
 """Tests for the renovated slave scanner aka BuilddManager."""
@@ -42,6 +42,7 @@
 from lp.buildmaster.tests.mock_slaves import (
     BrokenSlave,
     BuildingSlave,
+    LostBuildingBrokenSlave,
     make_publisher,
     OkSlave,
     )
@@ -112,14 +113,14 @@
         self.assertEqual(build.status, BuildStatus.BUILDING)
         self.assertEqual(job.logtail, logtail)
 
-    def _getScanner(self, builder_name=None):
+    def _getScanner(self, builder_name=None, clock=None):
         """Instantiate a SlaveScanner object.
 
         Replace its default logging handler by a testing version.
         """
         if builder_name is None:
             builder_name = BOB_THE_BUILDER_NAME
-        scanner = SlaveScanner(builder_name, BufferLogger())
+        scanner = SlaveScanner(builder_name, BufferLogger(), clock=clock)
         scanner.logger.name = 'slave-scanner'
 
         return scanner
@@ -395,19 +396,14 @@
 
         return d.addCallback(check)
 
+    @defer.inlineCallbacks
     def test_cancelling_a_build(self):
         # When scanning an in-progress build, if its state is CANCELLING
-        # then the build should be stopped and moved to the CANCELLED state.
-
-        # Set up a building slave with a fake resume method so we can see
-        # if it got called later.
-        slave = BuildingSlave(build_id="8-1")
-        call_counter = FakeMethod()
-
-        def fake_resume():
-            call_counter()
-            return defer.succeed((None, None, 0))
-        slave.resume = fake_resume
+        # then the build should be aborted, and eventually stopped and moved
+        # to the CANCELLED state if it does not abort by itself.
+
+        # Set up a mock building slave.
+        slave = BuildingSlave()
 
         # Set the sample data builder building with the slave from above.
         builder = getUtility(IBuilderSet)[BOB_THE_BUILDER_NAME]
@@ -420,6 +416,7 @@
         transaction.commit()
         login(ANONYMOUS)
         buildqueue = builder.currentjob
+        slave.build_id = buildqueue.specific_job.generateSlaveBuildCookie()
         self.assertBuildingJob(buildqueue, builder)
 
         # Now set the build to CANCELLING.
@@ -428,18 +425,28 @@
 
         # Run 'scan' and check its results.
         switch_dbuser(config.builddmaster.dbuser)
-        scanner = self._getScanner()
-        d = scanner.scan()
-
-        # The build state should be cancelled and we should have also
-        # called the resume() method on the slave that resets the virtual
-        # machine.
-        def check_cancelled(ignore, builder, buildqueue):
-            self.assertEqual(1, call_counter.call_count)
-            self.assertEqual(BuildStatus.CANCELLED, build.status)
-
-        d.addCallback(check_cancelled, builder, buildqueue)
-        return d
+        clock = task.Clock()
+        scanner = self._getScanner(clock=clock)
+        yield scanner.scan()
+
+        # An abort request should be sent.
+        self.assertEqual(1, slave.call_log.count("abort"))
+        self.assertEqual(BuildStatus.CANCELLING, build.status)
+
+        # Advance time a little.  Nothing much should happen.
+        clock.advance(1)
+        yield scanner.scan()
+        self.assertEqual(1, slave.call_log.count("abort"))
+        self.assertEqual(BuildStatus.CANCELLING, build.status)
+
+        # Advance past the timeout.  The build state should be cancelled and
+        # we should have also called the resume() method on the slave that
+        # resets the virtual machine.
+        clock.advance(SlaveScanner.CANCEL_TIMEOUT)
+        yield scanner.scan()
+        self.assertEqual(1, slave.call_log.count("abort"))
+        self.assertEqual(1, slave.call_log.count("resume"))
+        self.assertEqual(BuildStatus.CANCELLED, build.status)
 
 
 class TestCancellationChecking(TestCaseWithFactory):
@@ -453,15 +460,18 @@
         builder_name = BOB_THE_BUILDER_NAME
         self.builder = getUtility(IBuilderSet)[builder_name]
         self.builder.virtualized = True
-        self.scanner = SlaveScanner(builder_name, BufferLogger())
-        self.scanner.builder = self.builder
-        self.scanner.interactor = BuilderInteractor(self.builder)
-        self.scanner.logger.name = 'slave-scanner'
+
+    def _getScanner(self, clock=None):
+        scanner = SlaveScanner(None, BufferLogger(), clock=clock)
+        scanner.builder = self.builder
+        scanner.interactor = BuilderInteractor(self.builder)
+        scanner.logger.name = 'slave-scanner'
+        return scanner
 
     def test_ignores_nonvirtual(self):
         # If the builder is nonvirtual make sure we return False.
         self.builder.virtualized = False
-        d = self.scanner.checkCancellation(self.builder)
+        d = self._getScanner().checkCancellation(self.builder)
         return d.addCallback(self.assertFalse)
 
     def test_ignores_no_buildqueue(self):
@@ -469,37 +479,52 @@
         # make sure we return False.
         buildqueue = self.builder.currentjob
         buildqueue.reset()
-        d = self.scanner.checkCancellation(self.builder)
+        d = self._getScanner().checkCancellation(self.builder)
         return d.addCallback(self.assertFalse)
 
     def test_ignores_build_not_cancelling(self):
         # If the active build is not in a CANCELLING state, ignore it.
-        d = self.scanner.checkCancellation(self.builder)
+        d = self._getScanner().checkCancellation(self.builder)
         return d.addCallback(self.assertFalse)
 
+    @defer.inlineCallbacks
     def test_cancelling_build_is_cancelled(self):
-        # If a build is CANCELLING, make sure True is returned and the
-        # slave was resumed.
-        call_counter = FakeMethod()
-
-        def fake_resume():
-            call_counter()
-            return defer.succeed((None, None, 0))
+        # If a build is CANCELLING and the cancel timeout expires, make sure
+        # True is returned and the slave was resumed.
         slave = OkSlave()
-        slave.resume = fake_resume
-        self.builder.vm_host = "fake_vm_host"
-        self.patch(BuilderSlave, 'makeBuilderSlave', FakeMethod(slave))
-        buildqueue = self.builder.currentjob
-        build = getUtility(IBinaryPackageBuildSet).getByQueueEntry(buildqueue)
-        build.updateStatus(BuildStatus.CANCELLING)
-
-        def check(result):
-            self.assertEqual(1, call_counter.call_count)
-            self.assertTrue(result)
-            self.assertEqual(BuildStatus.CANCELLED, build.status)
-
-        d = self.scanner.checkCancellation(self.builder)
-        return d.addCallback(check)
+        self.builder.vm_host = "fake_vm_host"
+        self.patch(BuilderSlave, 'makeBuilderSlave', FakeMethod(slave))
+        buildqueue = self.builder.currentjob
+        build = getUtility(IBinaryPackageBuildSet).getByQueueEntry(buildqueue)
+        build.updateStatus(BuildStatus.CANCELLING)
+        clock = task.Clock()
+        scanner = self._getScanner(clock=clock)
+
+        result = yield scanner.checkCancellation(self.builder)
+        self.assertNotIn("resume", slave.call_log)
+        self.assertFalse(result)
+        self.assertEqual(BuildStatus.CANCELLING, build.status)
+
+        clock.advance(SlaveScanner.CANCEL_TIMEOUT)
+        result = yield scanner.checkCancellation(self.builder)
+        self.assertEqual(1, slave.call_log.count("resume"))
+        self.assertTrue(result)
+        self.assertEqual(BuildStatus.CANCELLED, build.status)
+
+    @defer.inlineCallbacks
+    def test_lost_build_is_cancelled(self):
+        # If the builder reports a fault while attempting to abort it, then
+        # immediately resume the slave as if the cancel timeout had expired.
+        slave = LostBuildingBrokenSlave()
+        self.builder.vm_host = "fake_vm_host"
+        self.patch(BuilderSlave, 'makeBuilderSlave', FakeMethod(slave))
+        buildqueue = self.builder.currentjob
+        build = getUtility(IBinaryPackageBuildSet).getByQueueEntry(buildqueue)
+        build.updateStatus(BuildStatus.CANCELLING)
+        result = yield self._getScanner().checkCancellation(self.builder)
+        self.assertEqual(1, slave.call_log.count("resume"))
+        self.assertTrue(result)
+        self.assertEqual(BuildStatus.CANCELLED, build.status)
 
 
 class TestBuilddManager(TestCase):

=== modified file 'lib/lp/soyuz/model/binarypackagebuild.py'
--- lib/lp/soyuz/model/binarypackagebuild.py	2013-08-28 04:40:32 +0000
+++ lib/lp/soyuz/model/binarypackagebuild.py	2013-08-29 12:10:56 +0000
@@ -1,4 +1,4 @@
-# Copyright 2009-2012 Canonical Ltd.  This software is licensed under the
+# Copyright 2009-2013 Canonical Ltd.  This software is licensed under the
 # GNU Affero General Public License version 3 (see the file LICENSE).
 
 __metaclass__ = type
@@ -381,8 +381,6 @@
         """See `IBuild`."""
         if not self.buildqueue_record:
             return False
-        if self.buildqueue_record.virtualized is False:
-            return False
 
         cancellable_statuses = [
             BuildStatus.BUILDING,