From 720c6c8bb557f559339ecfdec023e451683122cf Mon Sep 17 00:00:00 2001 From: Chris AtLee Date: Wed, 11 Aug 2010 22:01:12 -0400 Subject: [PATCH] Fixes for interrupting builds before steps have started. Added methods to BaseLock class to stop waiting on a lock, and to determine if an object is an owner of the lock. stopBuild will now stop the build properly even if it's waiting for a lock. Moved call to build_status.buildStarted(self) to before the call to acquireLocks so that the build now shows up in the waterfall and database. Removed logging of acquire/releaseLocks if there are no locks configured. Add current step display to the per-build web status, which will also indicate if the build is waiting for a lock. Fixes: #389 --- master/buildbot/locks.py | 9 + master/buildbot/process/base.py | 30 ++- master/buildbot/process/buildstep.py | 50 +++- master/buildbot/status/builder.py | 8 + master/buildbot/status/web/build.py | 30 ++- master/buildbot/status/web/builder.py | 11 +- master/buildbot/status/web/files/default.css | 2 +- .../buildbot/status/web/templates/build.html | 2 + .../buildbot/test/unit/test_process_base.py | 235 ++++++++++++++++++ 9 files changed, 348 insertions(+), 29 deletions(-) create mode 100644 master/buildbot/test/unit/test_process_base.py diff --git a/master/buildbot/locks.py b/master/buildbot/locks.py index 28d65c671f9..8eed10a0ddd 100644 --- a/master/buildbot/locks.py +++ b/master/buildbot/locks.py @@ -115,6 +115,15 @@ def waitUntilMaybeAvailable(self, owner, access): self.waiting.append((access, d)) return d + def stopWaitingUntilAvailable(self, owner, access, d): + debuglog("%s stopWaitingUntilAvailable(%s)" % (self, owner)) + assert isinstance(access, LockAccess) + assert (access, d) in self.waiting + self.waiting.remove( (access, d) ) + + def isOwner(self, owner, access): + return (owner, access) in self.owners + class RealMasterLock(BaseLock): def __init__(self, lockid): diff --git a/master/buildbot/process/base.py b/master/buildbot/process/base.py index 7045bf4c726..3037fcd0b27 100644 --- a/master/buildbot/process/base.py +++ b/master/buildbot/process/base.py @@ -60,6 +60,8 @@ def __init__(self, requests): self.terminate = False + self._acquiringLock = None + def setBuilder(self, builder): """ Set the given builder as our builder. @@ -229,18 +231,23 @@ def _release_slave(res, slave, bs): d.callback(self) return d + self.build_status.buildStarted(self) self.acquireLocks().addCallback(self._startBuild_2) return d def acquireLocks(self, res=None): - log.msg("acquireLocks(step %s, locks %s)" % (self, self.locks)) + self._acquiringLock = None if not self.locks: return defer.succeed(None) + if self.stopped: + return defer.succeed(None) + log.msg("acquireLocks(build %s, locks %s)" % (self, self.locks)) for lock, access in self.locks: if not lock.isAvailable(access): log.msg("Build %s waiting for lock %s" % (self, lock)) d = lock.waitUntilMaybeAvailable(self, access) d.addCallback(self.acquireLocks) + self._acquiringLock = (lock, access, d) return d # all locks are available, claim them all for lock, access in self.locks: @@ -248,7 +255,6 @@ def acquireLocks(self, res=None): return defer.succeed(None) def _startBuild_2(self, res): - self.build_status.buildStarted(self) self.startNextStep() def setupBuild(self, expectations): @@ -427,7 +433,16 @@ def stopBuild(self, reason=""): # TODO: include 'reason' in this point event self.builder.builder_status.addPointEvent(['interrupt']) self.stopped = True - self.currentStep.interrupt(reason) + if self.currentStep: + self.currentStep.interrupt(reason) + + self.result = FAILURE + self.text.append("Interrupted") + + if self._acquiringLock: + lock, access, d = self._acquiringLock + lock.stopWaitingUntilAvailable(self, access, d) + d.callback(None) def allStepsDone(self): if self.result == FAILURE: @@ -476,9 +491,14 @@ def buildFinished(self, text, results): self.deferred = None def releaseLocks(self): - log.msg("releaseLocks(%s): %s" % (self, self.locks)) + if self.locks: + log.msg("releaseLocks(%s): %s" % (self, self.locks)) for lock, access in self.locks: - lock.release(self, access) + if lock.isOwner(self, access): + lock.release(self, access) + else: + # This should only happen if we've been interrupted + assert self.stopped # IBuildControl diff --git a/master/buildbot/process/buildstep.py b/master/buildbot/process/buildstep.py index fa761b0d0dc..1b9ee770dd5 100644 --- a/master/buildbot/process/buildstep.py +++ b/master/buildbot/process/buildstep.py @@ -618,6 +618,9 @@ def __init__(self, **kwargs): raise TypeError(why) self._pendingLogObservers = [] + self._acquiringLock = None + self.stopped = False + def describe(self, done=False): return [self.name] @@ -713,33 +716,45 @@ def startStep(self, remote): log.msg("Hey, lock %s is claimed by both a Step (%s) and the" " parent Build (%s)" % (l, self, self.build)) raise RuntimeError("lock claimed by both Step and Build") + + # Set the step's text here so that the stepStarted notification sees + # the correct description + self.step_status.setText(self.describe(False)) + self.step_status.stepStarted() + d = self.acquireLocks() d.addCallback(self._startStep_2) return self.deferred def acquireLocks(self, res=None): - log.msg("acquireLocks(step %s, locks %s)" % (self, self.locks)) + self._acquiringLock = None if not self.locks: return defer.succeed(None) + if self.stopped: + return defer.succeed(None) + log.msg("acquireLocks(step %s, locks %s)" % (self, self.locks)) for lock, access in self.locks: if not lock.isAvailable(access): + self.step_status.setWaitingForLocks(True) log.msg("step %s waiting for lock %s" % (self, lock)) d = lock.waitUntilMaybeAvailable(self, access) d.addCallback(self.acquireLocks) + self._acquiringLock = (lock, access, d) return d # all locks are available, claim them all for lock, access in self.locks: lock.claim(self, access) + self.step_status.setWaitingForLocks(False) return defer.succeed(None) def _startStep_2(self, res): + if self.stopped: + self.finished(FAILURE) + return + if self.progress: self.progress.start() - # Set the step's text here so that the stepStarted notification sees - # the correct description - self.step_status.setText(self.describe(False)) - self.step_status.stepStarted() try: skip = None if isinstance(self.doStepIf, bool): @@ -827,12 +842,20 @@ def interrupt(self, reason): local processing should be skipped, and the Step completed with an error status. The results text should say something useful like ['step', 'interrupted'] or ['remote', 'lost']""" - pass + self.stopped = True + if self._acquiringLock: + lock, access, d = self._acquiringLock + lock.stopWaitingUntilAvailable(self, access, d) + d.callback(None) def releaseLocks(self): log.msg("releaseLocks(%s): %s" % (self, self.locks)) for lock, access in self.locks: - lock.release(self, access) + if lock.isOwner(self, access): + lock.release(self, access) + else: + # This should only happen if we've been interrupted + assert self.stopped def finished(self, results): if self.progress: @@ -986,6 +1009,7 @@ class LoggingBuildStep(BuildStep): logfiles = {} parms = BuildStep.parms + ['logfiles', 'lazylogfiles'] + cmd = None def __init__(self, logfiles={}, lazylogfiles=False, *args, **kwargs): BuildStep.__init__(self, *args, **kwargs) @@ -1061,9 +1085,15 @@ def interrupt(self, reason): # TODO: consider adding an INTERRUPTED or STOPPED status to use # instead of FAILURE, might make the text a bit more clear. # 'reason' can be a Failure, or text - self.addCompleteLog('interrupt', str(reason)) - d = self.cmd.interrupt(reason) - return d + BuildStep.interrupt(self, reason) + if self.step_status.isWaitingForLocks(): + self.addCompleteLog('interrupt while waiting for locks', str(reason)) + else: + self.addCompleteLog('interrupt', str(reason)) + + if self.cmd: + d = self.cmd.interrupt(reason) + return d def checkDisconnect(self, f): f.trap(error.ConnectionLost) diff --git a/master/buildbot/status/builder.py b/master/buildbot/status/builder.py index 8b2859b99af..ad0565bf434 100644 --- a/master/buildbot/status/builder.py +++ b/master/buildbot/status/builder.py @@ -827,6 +827,8 @@ def __init__(self, parent): self.finishedWatchers = [] self.statistics = {} + self.waitingForLocks = False + def getName(self): """Returns a short string with the name of this step. This string may have spaces in it.""" @@ -1046,6 +1048,12 @@ def checkLogfiles(self): # filter out logs that have been deleted self.logs = [ l for l in self.logs if l.hasContents() ] + def isWaitingForLocks(self): + return self.waitingForLocks + + def setWaitingForLocks(self, waiting): + self.waitingForLocks = waiting + # persistence def __getstate__(self): diff --git a/master/buildbot/status/web/build.py b/master/buildbot/status/web/build.py index 1b2ad50d0ce..2f20849827c 100644 --- a/master/buildbot/status/web/build.py +++ b/master/buildbot/status/web/build.py @@ -33,25 +33,33 @@ def content(self, req, cxt): cxt['b'] = b cxt['path_to_builder'] = path_to_builder(req, b.getBuilder()) - + if not b.isFinished(): + step = b.getCurrentStep() + if not step: + cxt['current_step'] = "[waiting for Lock]" + else: + if step.isWaitingForLocks(): + cxt['current_step'] = "%s [waiting for Lock]" % step.getName() + else: + cxt['current_step'] = step.getName() when = b.getETA() if when is not None: cxt['when'] = util.formatInterval(when) cxt['when_time'] = time.strftime("%H:%M:%S", time.localtime(time.time() + when)) - - else: + + else: cxt['result_css'] = css_classes[b.getResults()] if b.getTestResults(): cxt['tests_link'] = req.childLink("tests") - + ss = cxt['ss'] = b.getSourceStamp() - + if ss.branch is None and ss.revision is None and ss.patch is None and not ss.changes: cxt['most_recent_rev_build'] = True - - + + got_revision = None try: got_revision = b.getProperty("got_revision") @@ -76,8 +84,12 @@ def content(self, req, cxt): (start, end) = s.getTimes() step['time_to_run'] = util.formatInterval(end - start) elif s.isStarted(): - step['css_class'] = "running" - step['time_to_run'] = "running" + if s.isWaitingForLocks(): + step['css_class'] = "waiting" + step['time_to_run'] = "waiting for locks" + else: + step['css_class'] = "running" + step['time_to_run'] = "running" else: step['css_class'] = "not_started" step['time_to_run'] = "" diff --git a/master/buildbot/status/web/builder.py b/master/buildbot/status/web/builder.py index 91d86644abf..cd9a83e9d30 100644 --- a/master/buildbot/status/web/builder.py +++ b/master/buildbot/status/web/builder.py @@ -38,11 +38,14 @@ def builder(self, build, req): time.localtime(time.time() + when)) step = build.getCurrentStep() - if step: - b['current_step'] = step.getName() - else: + # TODO: is this necessarily the case? + if not step: b['current_step'] = "[waiting for Lock]" - # TODO: is this necessarily the case? + else: + if step.isWaitingForLocks(): + b['current_step'] = "%s [waiting for Lock]" % step.getName() + else: + b['current_step'] = step.getName() b['stop_url'] = path_to_build(req, build) + '/stop' diff --git a/master/buildbot/status/web/files/default.css b/master/buildbot/status/web/files/default.css index 58b6f95b3b5..545c19d34fe 100644 --- a/master/buildbot/status/web/files/default.css +++ b/master/buildbot/status/web/files/default.css @@ -360,7 +360,7 @@ div.BuildWaterfall { border-color: #ACA0B3; } -.start,.running,td.building { +.start,.running,.waiting,td.building { color: #666666; background-color: #ff6; border-color: #C5C56D; diff --git a/master/buildbot/status/web/templates/build.html b/master/buildbot/status/web/templates/build.html index afdeb5c269b..471ceb9660c 100644 --- a/master/buildbot/status/web/templates/build.html +++ b/master/buildbot/status/web/templates/build.html @@ -17,6 +17,8 @@

Build In Progress:

{% if when_time %}

ETA: {{ when_time }} [{{ when }}]

{% endif %} + + {{ current_step }} {% if authz.advertiseAction('stopBuild') %}

Stop Build

diff --git a/master/buildbot/test/unit/test_process_base.py b/master/buildbot/test/unit/test_process_base.py new file mode 100644 index 00000000000..6da578d2482 --- /dev/null +++ b/master/buildbot/test/unit/test_process_base.py @@ -0,0 +1,235 @@ +from twisted.trial import unittest +from twisted.internet import defer + +from buildbot.process.base import Build +from buildbot.process.properties import Properties +from buildbot.buildrequest import BuildRequest +from buildbot.status.builder import FAILURE, SUCCESS +from buildbot.locks import SlaveLock, RealSlaveLock +from buildbot.process.buildstep import BuildStep, LoggingBuildStep + +from mock import Mock + +class FakeChange: + properties = Properties() + who = "me" + +class FakeSource: + changes = [FakeChange()] + branch = None + revision = "12345" + repository = None + project = None + +class FakeRequest: + startCount = 0 + source = FakeSource() + reason = "Because" + properties = Properties() + + def mergeWith(self, others): + return self.source + + def mergeReasons(self, others): + return self.reason + +class FakeMaster: + locks = {} + parent = Mock() + def getLockByID(self, lockid): + if not lockid in self.locks: + self.locks[lockid] = lockid.lockClass(lockid) + return self.locks[lockid] + +class TestBuild(unittest.TestCase): + def testRunSuccessfulBuild(self): + r = FakeRequest() + + b = Build([r]) + b.setBuilder(Mock()) + + step = Mock() + step.return_value = step + step.startStep.return_value = SUCCESS + b.setStepFactories([(step, {})]) + + slavebuilder = Mock() + status = Mock() + + b.startBuild(status, None, slavebuilder) + + self.assertEqual(b.result, SUCCESS) + self.assert_( ('startStep', (b.remote,), {}) in step.method_calls) + + def testStopBuild(self): + r = FakeRequest() + + b = Build([r]) + b.setBuilder(Mock()) + + step = Mock() + step.return_value = step + b.setStepFactories([(step, {})]) + + slavebuilder = Mock() + status = Mock() + + def startStep(*args, **kw): + # Now interrupt the build + b.stopBuild("stop it") + return defer.Deferred() + step.startStep = startStep + + b.startBuild(status, None, slavebuilder) + + self.assert_("Interrupted" in b.text) + self.assertEqual(b.result, FAILURE) + + self.assert_( ('interrupt', ('stop it',), {}) in step.method_calls) + + def testBuildLocksAcquired(self): + r = FakeRequest() + + b = Build([r]) + b.setBuilder(Mock()) + b.builder.botmaster = FakeMaster() + slavebuilder = Mock() + status = Mock() + + l = SlaveLock('lock') + claimCount = [0] + lock_access = l.access('counting') + l.access = lambda mode: lock_access + real_lock = b.builder.botmaster.getLockByID(l).getLock(slavebuilder) + def claim(owner, access): + claimCount[0] += 1 + return real_lock.old_claim(owner, access) + real_lock.old_claim = real_lock.claim + real_lock.claim = claim + b.setLocks([l]) + + step = Mock() + step.return_value = step + step.startStep.return_value = SUCCESS + b.setStepFactories([(step, {})]) + + b.startBuild(status, None, slavebuilder) + + self.assertEqual(b.result, SUCCESS) + self.assert_( ('startStep', (b.remote,), {}) in step.method_calls) + self.assertEquals(claimCount[0], 1) + + def testBuildWaitingForLocks(self): + r = FakeRequest() + + b = Build([r]) + b.setBuilder(Mock()) + b.builder.botmaster = FakeMaster() + slavebuilder = Mock() + status = Mock() + + l = SlaveLock('lock') + claimCount = [0] + lock_access = l.access('counting') + l.access = lambda mode: lock_access + real_lock = b.builder.botmaster.getLockByID(l).getLock(slavebuilder) + def claim(owner, access): + claimCount[0] += 1 + return real_lock.old_claim(owner, access) + real_lock.old_claim = real_lock.claim + real_lock.claim = claim + b.setLocks([l]) + + step = Mock() + step.return_value = step + step.startStep.return_value = SUCCESS + b.setStepFactories([(step, {})]) + + real_lock.claim(Mock(), l.access('counting')) + + b.startBuild(status, None, slavebuilder) + + self.assert_( ('startStep', (b.remote,), {}) not in step.method_calls) + self.assertEquals(claimCount[0], 1) + self.assert_(b.currentStep is None) + self.assert_(b._acquiringLock is not None) + + def testStopBuildWaitingForLocks(self): + r = FakeRequest() + + b = Build([r]) + b.setBuilder(Mock()) + b.builder.botmaster = FakeMaster() + slavebuilder = Mock() + status = Mock() + + l = SlaveLock('lock') + claimCount = [0] + lock_access = l.access('counting') + l.access = lambda mode: lock_access + real_lock = b.builder.botmaster.getLockByID(l).getLock(slavebuilder) + b.setLocks([l]) + + step = Mock() + step.return_value = step + step.startStep.return_value = SUCCESS + b.setStepFactories([(step, {})]) + + real_lock.claim(Mock(), l.access('counting')) + + def acquireLocks(res=None): + retval = Build.acquireLocks(b, res) + b.stopBuild('stop it') + return retval + b.acquireLocks = acquireLocks + + b.startBuild(status, None, slavebuilder) + + self.assert_( ('startStep', (b.remote,), {}) not in step.method_calls) + self.assert_(b.currentStep is None) + self.assert_("Interrupted" in b.text, b.text) + self.assertEqual(b.result, FAILURE) + self.assert_( ('interrupt', ('stop it',), {}) not in step.method_calls) + + def testStopBuildWaitingForStepLocks(self): + r = FakeRequest() + + b = Build([r]) + b.setBuilder(Mock()) + b.builder.botmaster = FakeMaster() + slavebuilder = Mock() + status = Mock() + + l = SlaveLock('lock') + claimCount = [0] + lock_access = l.access('counting') + l.access = lambda mode: lock_access + real_lock = b.builder.botmaster.getLockByID(l).getLock(slavebuilder) + + step = LoggingBuildStep(locks=[lock_access]) + def factory(*args): + return step + b.setStepFactories([(factory, {})]) + + real_lock.claim(Mock(), l.access('counting')) + + gotLocks = [False] + + def acquireLocks(res=None): + gotLocks[0] = True + retval = LoggingBuildStep.acquireLocks(step, res) + self.assert_(b.currentStep is step) + b.stopBuild('stop it') + return retval + step.acquireLocks = acquireLocks + step.setStepStatus = Mock() + step.step_status = Mock() + step.step_status.addLog().chunkSize = 10 + step.step_status.getLogs.return_value = [] + + b.startBuild(status, None, slavebuilder) + + self.assertEqual(gotLocks, [True]) + self.assert_(('stepStarted', (), {}) in step.step_status.method_calls) + self.assert_("Interrupted" in b.text, b.text) + self.assertEqual(b.result, FAILURE)