Explicitely print the result status of each playbook run

We are moving _emit_playbook_banner from zuul_stream to the
executor because the data that is meant to be printed inside
the banner is not available until v2_playbook_on_play_start which
is triggered on every play. This ensures that the banner is only
printed once per playbook, even if the playbook has multiple plays.

Additionally, we're also printing a 'footer' banner at the end of
each playbook in order to provide an explicit and easily parsable
result from the perspective of Ansible.

This will make it easier for people and systems to parse the job
output to find the result of particular playbooks.

For example, in Zuul v2, Elastic-Recheck would rely on the last lines
of the console to reliably tell when the job was completed and what was
it's status.
This new v3 approach allows increased granularity by providing the
ability to filter down to specific playbooks or even on a phase basis.

Change-Id: I7e34206d7968bf128e140468b9a222ecbce3a8f1

zuul/ansible/callback/zuul_stream.py

@@ -168,32 +168,8 @@ class CallbackModule(default.CallbackModule):
                 host=host.name,
                 filename=included_file._filename))
 
-    def _emit_playbook_banner(self):
-        # Get the hostvars from just one host - the vars we're looking for will
-        # be identical on all of them
-        hostvars = next(iter(self._play._variable_manager._hostvars.values()))
-        self._playbook_name = None
-
-        phase = hostvars.get('zuul_execution_phase', '')
-        playbook = hostvars.get('zuul_execution_canonical_name_and_path')
-        trusted = hostvars.get('zuul_execution_trusted')
-        trusted = 'trusted' if trusted == "True" else 'untrusted'
-        branch = hostvars.get('zuul_execution_branch')
-
-        if phase and phase != 'run':
-            phase = '{phase}-run'.format(phase=phase)
-        phase = phase.upper()
-
-        self._log("{phase} [{trusted} : {playbook}@{branch}]".format(
-            trusted=trusted, phase=phase, playbook=playbook, branch=branch))
-
     def v2_playbook_on_play_start(self, play):
         self._play = play
-
-        # We can't fill in this information until the first play
-        if self._playbook_name:
-            self._emit_playbook_banner()
-
         # Log an extra blank line to get space before each play
         self._log("")
 

zuul/executor/server.py

@@ -1740,6 +1740,37 @@ class AnsibleJob(object):
             self.RESULT_MAP[result], code))
         return result, code
 
+    def emitPlaybookBanner(self, playbook, step, phase, result=None):
+        # This is used to print a header and a footer, respectively at the
+        # beginning and the end of each playbook execution.
+        # We are doing it from the executor rather than from a callback because
+        # the parameters are not made available to the callback until it's too
+        # late.
+        phase = phase or ''
+        trusted = playbook.trusted
+        trusted = 'trusted' if trusted else 'untrusted'
+        branch = playbook.branch
+        playbook = playbook.canonical_name_and_path
+
+        if phase and phase != 'run':
+            phase = '{phase}-run'.format(phase=phase)
+        phase = phase.upper()
+
+        if result is not None:
+            result = self.RESULT_MAP[result]
+            msg = "{phase} {step} {result}: [{trusted} : {playbook}@{branch}]"
+            msg.format(phase=phase, step=step, result=result,
+                       trusted=trusted, playbook=playbook, branch=branch)
+        else:
+            msg = "{phase} {step}: [{trusted} : {playbook}@{branch}]"
+            msg.format(phase=phase, step=step, trusted=trusted,
+                       playbook=playbook, branch=branch)
+
+        with open(self.jobdir.job_output_file, 'a') as job_output:
+            job_output.write("{now} | {msg}".format(
+                now=datetime.datetime.now(),
+                msg=msg))
+
     def runAnsiblePlaybook(self, playbook, timeout, success=None,
                            phase=None, index=None):
         if self.executor_server.verbose:
@@ -1770,8 +1801,12 @@ class AnsibleJob(object):
         if self.executor_variables_file is not None:
             cmd.extend(['-e@%s' % self.executor_variables_file])
 
+        self.emitPlaybookBanner(playbook, 'START', phase)
+
         result, code = self.runAnsible(
             cmd=cmd, timeout=timeout, playbook=playbook)
         self.log.debug("Ansible complete, result %s code %s" % (
             self.RESULT_MAP[result], code))
+
+        self.emitPlaybookBanner(playbook, 'END', phase, result=result)
         return result, code