| # pylint: disable=C0103 |
| |
| """This class knows how to understand annotations. |
| |
| Here are a list of the currently supported annotations: |
| |
| @@@BUILD_STEP <stepname>@@@ |
| Add a new step <stepname>. End the current step, marking with last available |
| status. |
| |
| @@@STEP_LINK@<label>@<url>@@@ |
| Add a link with label <label> linking to <url> to the current stage. |
| |
| @@@STEP_WARNINGS@@@ |
| Mark the current step as having warnings (oragnge). |
| |
| @@@STEP_FAILURE@@@ |
| Mark the current step as having failed (red). |
| |
| @@@STEP_EXCEPTION@@@ |
| Mark the current step as having exceptions (magenta). |
| |
| @@@STEP_CLEAR@@@ |
| Reset the text description of the current step. |
| |
| @@@STEP_SUMMARY_CLEAR@@@ |
| Reset the text summary of the current step. |
| |
| @@@STEP_TEXT@<msg>@@@ |
| Append <msg> to the current step text. |
| |
| @@@STEP_SUMMARY_TEXT@<msg>@@@ |
| Append <msg> to the step summary (appears on top of the waterfall). |
| |
| @@@HALT_ON_FAILURE@@@ |
| Halt if exception or failure steps are encountered (default is not). |
| |
| @@@HONOR_ZERO_RETURN_CODE@@@ |
| Honor the return code being zero (success), even if steps have other results. |
| |
| Deprecated annotations: |
| TODO(bradnelson): drop these when all users have been tracked down. |
| |
| @@@BUILD_WARNINGS@@@ |
| Equivalent to @@@STEP_WARNINGS@@@ |
| |
| @@@BUILD_FAILED@@@ |
| Equivalent to @@@STEP_FAILURE@@@ |
| |
| @@@BUILD_EXCEPTION@@@ |
| Equivalent to @@@STEP_EXCEPTION@@@ |
| |
| @@@link@<label>@<url>@@@ |
| Equivalent to @@@STEP_LINK@<label>@<url>@@@ |
| """ |
| |
| import re |
| |
| from twisted.internet import defer |
| from twisted.internet import error |
| from twisted.python import failure |
| from twisted.python import log as logging |
| |
| from buildbot.process import buildstep |
| from buildbot.process import results |
| from buildbot.process import logobserver |
| |
| from buildbot.plugins import util |
| |
| from buildbot.util import asyncSleep |
| from buildbot.util.misc import deferredLocked |
| |
| if False: # for debugging |
| debuglog = logging.msg |
| else: |
| debuglog = lambda m: None |
| |
| class AnnotatedBuildStep(buildstep.BuildStep): |
| |
| def __init__(self, parent_step, *args, **kwargs): |
| self.parent_step = parent_step |
| buildstep.BuildStep.__init__(self, *args, **kwargs) |
| |
| # Step is really unpredictable |
| self.useProgress = False |
| |
| self.build = self.parent_step.build |
| self.master = self.parent_step.build.master |
| self.worker = self.parent_step.worker |
| |
| self.stdio_log = None |
| |
| self._loglines = [] |
| self._logLock = defer.DeferredLock() |
| |
| self._request_finish = False |
| |
| @defer.inlineCallbacks |
| def addStep(self): |
| debuglog("AnnotatedBuildStep: adding step '%s': buildid=%s" % ( |
| self.name, self.build.buildid)) |
| yield buildstep.BuildStep.addStep(self) |
| # Put ourselves into a list of processed steps of the build object. |
| self.build.executedSteps.append(self) |
| # Init result to SUCCESS by default. |
| self.results = results.SUCCESS |
| self.description = [self.name] |
| self.stdio_log = yield self.addLog('stdio') |
| |
| debuglog("AnnotatedBuildStep: added step '%s': stepid=%s, buildid=%s" % ( |
| self.name, self.stepid, self.build.buildid)) |
| |
| |
| @defer.inlineCallbacks |
| def finishStep(self): |
| hidden = False |
| debuglog("AnnotatedBuildStep: finish step '%s': stepid=%s, buildid=%s, results=%s" % ( |
| self.name, self.stepid, self.build.buildid, self.results)) |
| yield self.master.data.updates.finishStep(self.stepid, self.results, |
| hidden) |
| # finish unfinished logs |
| yield self.finishUnfinishedLogs() |
| |
| @defer.inlineCallbacks |
| def startStep(self, remote, done=False): |
| debuglog("AnnotatedBuildStep::startStep() starting '%s': " |
| "buildid=%s, done=%s" % ( |
| self.name, self.build.buildid, done)) |
| |
| try: |
| yield self.addStep() |
| |
| try: |
| self.realUpdateSummary() |
| # The "main" step has finished already. |
| # Do only necessary work. |
| #NOTE: we can get 'request finish' flag before the step started. |
| self._request_finish = self._request_finish or done |
| self._running = True |
| self.results = yield self.run() |
| finally: |
| self._running = False |
| |
| except buildstep.BuildStepCancelled: |
| self.results = results.CANCELLED |
| |
| except buildstep.BuildStepFailed: |
| self.results = results.FAILURE |
| |
| except error.ConnectionLost: |
| self.results = results.RETRY |
| |
| except Exception: |
| self.results = results.EXCEPTION |
| why = failure.Failure() |
| logging.err(why, "AnnotatedBuildStep.failed; traceback follows") |
| yield self.addLogWithFailure(why) |
| |
| finally: |
| # update the summary one last time, make sure that completes, |
| # and then don't update it any more. |
| self.realUpdateSummary() |
| yield self.realUpdateSummary.stop() |
| |
| # Update step status in the database. |
| yield self.finishStep() |
| |
| debuglog("AnnotatedBuildStep::startStep() completed '%s': " |
| "stepid=%s, buildid=%s, results=%s" % ( |
| self.name, self.stepid, self.build.buildid, self.results)) |
| |
| def requestFinish(self, status=None): |
| debuglog("AnnotatedBuildStep::requestFinish(%r): '%s': " |
| "stepid=%s, buildid=%s, results=%r" % ( |
| status, self.name, self.stepid, self.build.buildid, self.results)) |
| # Update the current step status with the worst result. |
| if status is not None: |
| self.updateStatus(status) |
| self._request_finish = True |
| |
| def setStepText(self, text=None): |
| if text is not None: |
| if self.description is not None: |
| self.description.append(text) |
| else: |
| self.description = [] |
| |
| self.updateSummary() |
| |
| def setStepSummary(self, text=None): |
| if text is not None: |
| if self.descriptionDone is not None: |
| self.descriptionDone.append(text) |
| else: |
| self.descriptionDone = [] |
| |
| self.updateSummary() |
| |
| @deferredLocked("_logLock") |
| def _flushLogs(self): |
| if self._loglines: |
| ll = "".join(self._loglines) |
| self._loglines = [] |
| self.stdio_log.addStdout(ll) |
| return defer.succeed(None) |
| |
| @deferredLocked("_logLock") |
| def _addLogs(self, text): |
| if text is not None: |
| self._loglines.append(text) |
| return defer.succeed(None) |
| |
| @defer.inlineCallbacks |
| def run(self): |
| debuglog("AnnotatedBuildStep::run() starting '%s' step: " |
| "stepid=%s, buildid=%s" % ( |
| self.name, self.stepid, self.build.buildid)) |
| |
| # Save previously collected log lines. |
| yield self._flushLogs() |
| |
| while not self._request_finish: |
| # Sleep for .1 second. Let arrive more logs. |
| yield asyncSleep(.1) |
| if self._loglines: |
| yield self._flushLogs() |
| |
| # and the last one time. |
| if self._loglines: |
| yield self._flushLogs() |
| |
| debuglog("AnnotatedBuildStep::run() exiting '%s' step: " |
| "stepid=%s, buildid=%s, results=%s" % ( |
| self.name, self.stepid, self.build.buildid, self.results)) |
| |
| return self.results |
| |
| @defer.inlineCallbacks |
| def scheduleStdout(self, text): |
| if text is None: |
| return |
| |
| # Not running yet, just store a log line. |
| if not self._running: |
| self._loglines.append(text) |
| return |
| |
| # Already executed, add the log line with locking. |
| yield self._addLogs(text=text) |
| |
| def updateStatus(self, status): |
| self.results = results.worst_status(self.results, status) |
| |
| |
| ALL_COMMANDS = list(range(11)) |
| STEP_LINK, STEP_WARNINGS, STEP_FAILURE, STEP_EXCEPTION, HALT_ON_FAILURE, HONOR_ZERO_RC, STEP_CLEAR, STEP_SUMMARY_CLEAR, STEP_TEXT, STEP_SUMMARY_TEXT, BUILD_STEP = ALL_COMMANDS |
| |
| class AnnotatedCommand(buildstep.ShellMixin, buildstep.BuildStep): |
| """Buildbot command that knows how to display annotations.""" |
| |
| _re_step_link = re.compile(r'^@@@(STEP_LINK|link)@(?P<link_label>.*)@(?P<link_url>.*)@@@', re.M) |
| _re_step_warnings = re.compile(r'^@@@(STEP_WARNINGS|BUILD_WARNINGS)@@@', re.M) |
| _re_step_failure = re.compile(r'^@@@(STEP_FAILURE|BUILD_FAILED)@@@', re.M) |
| _re_step_exception = re.compile(r'^@@@(STEP_EXCEPTION|BUILD_EXCEPTION)@@@', re.M) |
| _re_halt_on_failure = re.compile(r'^@@@HALT_ON_FAILURE@@@', re.M) |
| _re_honor_zero_rc = re.compile(r'^@@@HONOR_ZERO_RETURN_CODE@@@', re.M) |
| _re_step_clear = re.compile(r'^@@@STEP_CLEAR@@@', re.M) |
| _re_step_summary_clear = re.compile(r'^@@@STEP_SUMMARY_CLEAR@@@', re.M) |
| _re_step_text = re.compile(r'^@@@STEP_TEXT@(?P<text>.*)@@@', re.M) |
| _re_step_summary_step = re.compile(r'^@@@STEP_SUMMARY_TEXT@(?P<text>.*)@@@', re.M) |
| _re_build_step = re.compile(r'^@@@BUILD_STEP (?P<name>.*)@@@', re.M) |
| |
| _re_set = [ |
| # Support: @@@STEP_LINK@<name>@<url>@@@ (emit link) |
| # Also support depreceated @@@link@<name>@<url>@@@ |
| ( STEP_LINK, _re_step_link), |
| |
| # Support: @@@STEP_WARNINGS@@@ (warn on a stage) |
| # Also support deprecated @@@BUILD_WARNINGS@@@ |
| ( STEP_WARNINGS, _re_step_warnings ), |
| |
| # Support: @@@STEP_FAILURE@@@ (fail a stage) |
| # Also support deprecated @@@BUILD_FAILED@@@ |
| ( STEP_FAILURE, _re_step_failure ), |
| |
| # Support: @@@STEP_EXCEPTION@@@ (exception on a stage) |
| # Also support deprecated @@@BUILD_FAILED@@@ |
| ( STEP_EXCEPTION, _re_step_exception ), |
| |
| # Support: @@@HALT_ON_FAILURE@@@ (halt if a step fails immediately) |
| ( HALT_ON_FAILURE, _re_halt_on_failure ), |
| |
| # Support: @@@HONOR_ZERO_RETURN_CODE@@@ (succeed on 0 return, even if some |
| # steps have failed) |
| ( HONOR_ZERO_RC, _re_honor_zero_rc ), |
| |
| # Support: @@@STEP_CLEAR@@@ (reset step description) |
| ( STEP_CLEAR, _re_step_clear ), |
| |
| # Support: @@@STEP_SUMMARY_CLEAR@@@ (reset step summary) |
| ( STEP_SUMMARY_CLEAR, _re_step_summary_clear ), |
| |
| # Support: @@@STEP_TEXT@<msg>@@@ |
| ( STEP_TEXT, _re_step_text ), |
| |
| # Support: @@@STEP_SUMMARY_TEXT@<msg>@@@ |
| ( STEP_SUMMARY_TEXT, _re_step_summary_step ), |
| |
| # Support: @@@BUILD_STEP <step_name>@@@ (start a new section) |
| ( BUILD_STEP, _re_build_step ), |
| ] |
| |
| def __init__(self, **kwargs): |
| # Inject standard tags into the environment. |
| env = { |
| 'BUILDBOT_BLAMELIST': util.Interpolate('%(prop:blamelist:-[])s'), |
| 'BUILDBOT_BRANCH': util.Interpolate('%(prop:branch:-None)s'), |
| 'BUILDBOT_BUILDERNAME': util.Interpolate('%(prop:buildername:-None)s'), |
| 'BUILDBOT_BUILDNUMBER': util.Interpolate('%(prop:buildnumber:-None)s'), |
| 'BUILDBOT_CLOBBER': util.Interpolate('%(prop:clobber:+1)s'), |
| 'BUILDBOT_GOT_REVISION': util.Interpolate('%(prop:got_revision:-None)s'), |
| 'BUILDBOT_REVISION': util.Interpolate('%(prop:revision:-None)s'), |
| 'BUILDBOT_SCHEDULER': util.Interpolate('%(prop:scheduler:-None)s'), |
| 'BUILDBOT_SLAVENAME': util.Interpolate('%(prop:slavename:-None)s'), |
| 'BUILDBOT_MSAN_ORIGINS': util.Interpolate('%(prop:msan_origins:-)s'), |
| } |
| # Apply the passed in environment on top. |
| old_env = kwargs.get('env') or {} |
| env.update(old_env) |
| # Change passed in args (ok as a copy is made internally). |
| kwargs['env'] = env |
| |
| kwargs = self.setupShellMixin(kwargs) |
| super().__init__(**kwargs) |
| |
| self.addLogObserver('stdio', logobserver.LineConsumerLogObserver(self.processAnnotations)) |
| # A step log to store all logs, which we got before the first @@@BUILD_STEP @@@ command. |
| self.preamble_log = None |
| |
| self.annotate_status = results.SUCCESS |
| self.halt_on_failure = False |
| self.honor_zero_return_code = False |
| |
| self.annotated_steps = [] |
| # Use this lock to "run" the annotated steps. |
| self.initLock = defer.DeferredLock() |
| self._annotated_finished = False |
| |
| def _getLastAnnotatedStep(self): |
| return self.annotated_steps[-1] if self.annotated_steps else None |
| |
| def _updateLastAnnotatedStepStatus(self, status): |
| debuglog(">>> AnnotatedCommand::_updateLastAnnotatedStepStatus(%r)" % status) |
| |
| # Alway update the common annotate command status. |
| self.annotate_status = results.worst_status(self.annotate_status, status) |
| |
| s = self._getLastAnnotatedStep() |
| if s is not None: |
| s.updateStatus(status) |
| |
| if self.halt_on_failure and status in [results.FAILURE, results.EXCEPTION]: |
| if self.cmd: |
| self.cmd.interrupt("Failed annotated step") |
| |
| def _updateLastAnnotatedStepText(self, text = None): |
| """Updating a step text. None to clean up.""" |
| debuglog(">>> AnnotatedCommand::_updateLastAnnotatedStepText('%s')" % (text if text else '')) |
| |
| s = self._getLastAnnotatedStep() |
| if s is not None: |
| s.setStepText(text) |
| |
| def _updateLastAnnotatedStepSummaryInfo(self, text = None): |
| """Updating a step summary info. None to clean up.""" |
| debuglog(">>> AnnotatedCommand::_updateLastAnnotatedStepSummaryInfo('%s')" % (text if text else '')) |
| |
| s = self._getLastAnnotatedStep() |
| if s is not None: |
| s.setStepSummary(text) |
| |
| def _fixupActiveAnnotatedStep(self): |
| debuglog(">>> AnnotatedCommand::_fixupActiveAnnotatedStep()") |
| # Fixup the active step |
| s = self._getLastAnnotatedStep() |
| if s is not None: |
| # Finish the active step with its current status. |
| s.requestFinish() |
| |
| def _scheduleNewAnnotatedStep(self, name, logline): |
| debuglog(">>> AnnotatedCommand::_scheduleNewAnnotatedStep('%s')" % name) |
| |
| self._fixupActiveAnnotatedStep() |
| |
| s = AnnotatedBuildStep(parent_step=self, name=name) |
| # Doing this last so that @@@BUILD_STEP... occurs in the log of the new |
| # step. |
| s.scheduleStdout(logline) |
| # Make it ready to consume the logs and status updates. |
| self.annotated_steps.append(s) |
| |
| |
| @deferredLocked("initLock") |
| @defer.inlineCallbacks |
| def _execStep(self, step, done): |
| yield step.startStep(remote=None, done=done) |
| |
| @defer.inlineCallbacks |
| def _walkOverScheduledAnnotatedSteps(self): |
| debuglog(">>> AnnotatedCommand::_walkOverScheduledAnnotatedSteps: started") |
| |
| while self.annotated_steps or not self._annotated_finished: |
| if self.annotated_steps: |
| yield self._execStep(self.annotated_steps[0], done=self._annotated_finished) |
| last_step = self.annotated_steps.pop(0) |
| if last_step.results == results.EXCEPTION: |
| raise Exception("Annotated step exception") |
| |
| if not self._annotated_finished: |
| yield asyncSleep(.1) |
| |
| debuglog(">>> AnnotatedCommand::_walkOverScheduledAnnotatedSteps: finished") |
| |
| def run(self): |
| return self.runAnnotatedCommands() |
| |
| @defer.inlineCallbacks |
| def runAnnotatedCommands(self): |
| try: |
| # Create a preamble log for primary annotate step. |
| self.preamble_log = yield self.addLog('preamble') |
| |
| cmd = yield self.makeRemoteShellCommand(command=self.command, |
| stdioLogName='stdio') |
| |
| d1 = self.runCommand(cmd) |
| d2 = defer.maybeDeferred(self._walkOverScheduledAnnotatedSteps) |
| |
| @d1.addBoth |
| def cb(r): |
| self._annotated_finished = True |
| try: |
| # In some cases we can get the empty queue after the check. |
| # Just catch and pass the exception. |
| if self.annotated_steps: |
| # Current processing step. |
| last_step = self.annotated_steps[0] |
| cmd_results = cmd.results() |
| # We can get CANCELLED for two cases: |
| # 1. when UI stop button was pressed. In that case just pass this status |
| # into the annotated step as the result status. |
| # 2. and when the remote command was canceled because of failed annotated step. |
| # For that situation we finish the annotated step with its current status. |
| if cmd_results == results.CANCELLED and last_step.results in [results.FAILURE, results.EXCEPTION]: |
| # Finish the annotated step with its current status. |
| last_step.requestFinish() |
| else: |
| last_step.requestFinish(cmd_results) |
| except IndexError: |
| pass |
| return r |
| |
| @d2.addErrback |
| def cbErrback(r): |
| debuglog("+++ AnnotatedCommand::runAnnotatedCommands(): error callback with exception. " |
| "Terminate remote command.") |
| self.annotate_status = results.EXCEPTION |
| if self.cmd: |
| self.cmd.interrupt("Annotated step exception") |
| return r |
| |
| # Wait until both -- the remote command and the annotated step processing loop -- get finished. |
| yield defer.DeferredList([d1, d2]) |
| |
| except Exception: |
| why = failure.Failure() |
| logging.err(why, "AnnotatedCommand.failed; traceback follows") |
| yield self.addLogWithFailure(why) |
| |
| # This case when the remote command has been canceled by failed annotated command. |
| if cmd.results() == results.CANCELLED and self.annotate_status in [results.FAILURE, results.EXCEPTION]: |
| return self.annotate_status |
| # Regular case. |
| return results.worst_status(cmd.results(), self.annotate_status) |
| |
| def processAnnotations(self): |
| |
| while True: |
| try: |
| stream, ln = yield |
| # Add \n if not there, which seems to be the case for log lines from |
| # windows agents, but not others. |
| if not ln.endswith('\n'): |
| ln += '\n' |
| |
| self.processAnnotatedCommand(ln) |
| except GeneratorExit: |
| return |
| |
| def processAnnotatedCommand(self, line): |
| #pylint: disable=too-many-branches |
| |
| # returns: op, args |
| def parse_annotate_cmd(ln): |
| for ancmd, anre in AnnotatedCommand._re_set: |
| ro = anre.search(ln) |
| if ro is not None: |
| # Get the regex named group values. |
| # We can get the empty set, but it is ok. |
| args = ro.groupdict() or {} |
| # Store the current log line within the arguments. |
| # We will need to save it in some cases. |
| args['logline'] = ln |
| return ancmd, args |
| return None, None |
| |
| ancmd, args = parse_annotate_cmd(line) |
| |
| if ancmd: |
| debuglog(">>> AnnotatedCommand::processAnnotatedCommand(): %s, %r" % (ancmd, args)) |
| |
| try: |
| if ancmd == STEP_LINK: |
| s = self._getLastAnnotatedStep() |
| if s is not None: |
| s.addURL(args['link_label'], args['link_url']) |
| else: |
| logging.msg("Warning: missed link for annotated step. " |
| "No active steps. (%s/%s)" % (args['link_label'], args['link_url'])) |
| |
| elif ancmd == STEP_WARNINGS: |
| self._updateLastAnnotatedStepStatus(results.WARNINGS) |
| elif ancmd == STEP_FAILURE: |
| self._updateLastAnnotatedStepStatus(results.FAILURE) |
| elif ancmd == STEP_EXCEPTION: |
| self._updateLastAnnotatedStepStatus(results.EXCEPTION) |
| elif ancmd == HALT_ON_FAILURE: |
| self.halt_on_failure = True |
| elif ancmd == HONOR_ZERO_RC: |
| self.honor_zero_return_code = True |
| elif ancmd == STEP_CLEAR: |
| self._updateLastAnnotatedStepText() |
| elif ancmd == STEP_SUMMARY_CLEAR: |
| self._updateLastAnnotatedStepSummaryInfo() |
| elif ancmd == STEP_TEXT: |
| self._updateLastAnnotatedStepText(text=args['text']) |
| elif ancmd == STEP_SUMMARY_TEXT: |
| self._updateLastAnnotatedStepSummaryInfo(text=args['text']) |
| elif ancmd == BUILD_STEP: |
| self._scheduleNewAnnotatedStep(name=args['name'].strip(), |
| logline=args['logline']) |
| else: |
| # Regular log line, forward it to the active step. |
| s = self._getLastAnnotatedStep() |
| if s is None and self.preamble_log is not None: |
| self.preamble_log.addStdout(line) |
| else: |
| s.scheduleStdout(line) |
| |
| except Exception: |
| logging.err(failure.Failure(), 'error while processing annotgated command log:') |
