Updated the step completition detection for annotated steps.

[vvereschaka]

Summary

Process the completed step statuses properly in case when we consume the annotated log faster than operating with the buildbot api.

[gkistanova]

Thanks, Vlad!
Looks good with a nitpick.

zorg/buildbot/commands/AnnotatedCommand.py

127

Could you use the str.format() interface here and in the other change below instead, please?

We are Python 3.x only now. No need to keep the backward compatibility.

[vvereschaka]

OK, it is not a problem.
I'll prepare another patch with the string formatting fixes.

zorg/buildbot/commands/AnnotatedCommand.py

def finishStep(self):
         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):
+    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
 
class AnnotatedBuildStep(buildstep.BuildStep):
     @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()
def _scheduleNewAnnotatedStep(self, name, logline):
         # 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):
-        yield step.startStep(remote=None)
+    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:
-                if self._annotated_finished:
-                    # Reset a status for all unprocessed annotated steps to
-                    # the common annotate status.
-                    self.annotated_steps[0].updateStatus(self.annotate_status)
-                yield self._execStep(self.annotated_steps[0])
+                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):
def processAnnotations(self):
                 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:
-                # Done with log, the last active annotated step should get everything we got.
-                # Just stop it and let the "main" step get completed.
-                self._fixupActiveAnnotatedStep()
                 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: