From 0e2489a4cd61f46824bd3c05d58fe67b7c3e3872 Mon Sep 17 00:00:00 2001 From: Monty Taylor Date: Tue, 10 Oct 2017 11:57:29 -0500 Subject: [PATCH] Grab json log contents for final post playbook failures If the final post playbook fails, something has gone wrong with log uploading, which means it's very hard to debug. Grab the contents of the json log file, extract the log for the last playbook and add it to the executor log. Change-Id: Ia930311e121c350e73e41b20e9b742b2eac9c9f6 --- .../playbooks/job-output-failure-post.yaml | 4 ++ .../job-output/git/common-config/zuul.yaml | 11 ++++++ .../config/job-output/git/org_project2/README | 1 + tests/fixtures/config/job-output/main.yaml | 1 + tests/unit/test_v3.py | 38 ++++++++++++++++++- zuul/executor/server.py | 28 ++++++++++++++ 6 files changed, 82 insertions(+), 1 deletion(-) create mode 100644 tests/fixtures/config/job-output/git/common-config/playbooks/job-output-failure-post.yaml create mode 100644 tests/fixtures/config/job-output/git/org_project2/README diff --git a/tests/fixtures/config/job-output/git/common-config/playbooks/job-output-failure-post.yaml b/tests/fixtures/config/job-output/git/common-config/playbooks/job-output-failure-post.yaml new file mode 100644 index 0000000000..bd46718f08 --- /dev/null +++ b/tests/fixtures/config/job-output/git/common-config/playbooks/job-output-failure-post.yaml @@ -0,0 +1,4 @@ +- hosts: all + tasks: + - shell: echo "Failure test {{ zuul.executor.src_root }}" + - shell: exit 1 diff --git a/tests/fixtures/config/job-output/git/common-config/zuul.yaml b/tests/fixtures/config/job-output/git/common-config/zuul.yaml index a83f0bc778..f182d8dece 100644 --- a/tests/fixtures/config/job-output/git/common-config/zuul.yaml +++ b/tests/fixtures/config/job-output/git/common-config/zuul.yaml @@ -20,8 +20,19 @@ parent: base name: job-output +- job: + name: job-output-failure + run: playbooks/job-output + post-run: playbooks/job-output-failure-post + - project: name: org/project check: jobs: - job-output + +- project: + name: org/project2 + check: + jobs: + - job-output-failure diff --git a/tests/fixtures/config/job-output/git/org_project2/README b/tests/fixtures/config/job-output/git/org_project2/README new file mode 100644 index 0000000000..9daeafb986 --- /dev/null +++ b/tests/fixtures/config/job-output/git/org_project2/README @@ -0,0 +1 @@ +test diff --git a/tests/fixtures/config/job-output/main.yaml b/tests/fixtures/config/job-output/main.yaml index 208e274b13..14b382fe08 100644 --- a/tests/fixtures/config/job-output/main.yaml +++ b/tests/fixtures/config/job-output/main.yaml @@ -6,3 +6,4 @@ - common-config untrusted-projects: - org/project + - org/project2 diff --git a/tests/unit/test_v3.py b/tests/unit/test_v3.py index 327d457f96..99c87e07e3 100755 --- a/tests/unit/test_v3.py +++ b/tests/unit/test_v3.py @@ -14,7 +14,9 @@ # License for the specific language governing permissions and limitations # under the License. +import io import json +import logging import os import textwrap import gc @@ -1844,7 +1846,8 @@ class TestJobOutput(AnsibleZuulTestCase): return f.read() def test_job_output(self): - # Verify that command standard output appears in the job output + # Verify that command standard output appears in the job output, + # and that failures in the final playbook get logged. # This currently only verifies we receive output from # localhost. Notably, it does not verify we receive output @@ -1869,3 +1872,36 @@ class TestJobOutput(AnsibleZuulTestCase): self.assertIn(token, self._get_file(self.history[0], 'work/logs/job-output.txt')) + + def test_job_output_failure_log(self): + logger = logging.getLogger('zuul.AnsibleJob') + output = io.StringIO() + logger.addHandler(logging.StreamHandler(output)) + + # Verify that a failure in the last post playbook emits the contents + # of the json output to the log + self.executor_server.keep_jobdir = True + A = self.fake_gerrit.addFakeChange('org/project2', 'master', 'A') + self.fake_gerrit.addEvent(A.getPatchsetCreatedEvent(1)) + self.waitUntilSettled() + self.assertHistory([ + dict(name='job-output-failure', + result='POST_FAILURE', changes='1,1'), + ], ordered=False) + + token = 'Standard output test %s' % (self.history[0].jobdir.src_root) + j = json.loads(self._get_file(self.history[0], + 'work/logs/job-output.json')) + self.assertEqual(token, + j[0]['plays'][0]['tasks'][0] + ['hosts']['localhost']['stdout']) + + print(self._get_file(self.history[0], + 'work/logs/job-output.json')) + self.assertIn(token, + self._get_file(self.history[0], + 'work/logs/job-output.txt')) + + log_output = output.getvalue() + self.assertIn('Final playbook failed', log_output) + self.assertIn('Failure test', log_output) diff --git a/zuul/executor/server.py b/zuul/executor/server.py index 459a554e07..b22be60863 100644 --- a/zuul/executor/server.py +++ b/zuul/executor/server.py @@ -1229,8 +1229,36 @@ class AnsibleJob(object): # precedence over the post result. if not pre_failed: result = 'POST_FAILURE' + if (index + 1) == len(self.jobdir.post_playbooks): + self._logFinalPlaybookError() + return result + def _logFinalPlaybookError(self): + # Failures in the final post playbook can include failures + # uploading logs, which makes diagnosing issues difficult. + # Grab the output from the last playbook from the json + # file and log it. + json_output = self.jobdir.job_output_file.replace('txt', 'json') + self.log.debug("Final playbook failed") + if not os.path.exists(json_output): + self.log.debug("JSON logfile {logfile} is missing".format( + logfile=json_output)) + return + try: + output = json.load(open(json_output, 'r')) + last_playbook = output[-1] + # Transform json to yaml - because it's easier to read and given + # the size of the data it'll be extra-hard to read this as an + # all on one line stringified nested dict. + yaml_out = yaml.safe_dump(last_playbook, default_flow_style=False) + for line in yaml_out.split('\n'): + self.log.debug(line) + except Exception: + self.log.exception( + "Could not decode json from {logfile}".format( + logfile=json_output)) + def getHostList(self, args): hosts = [] for node in args['nodes']: