From 21be3b2d4be943c8044ea2784f344eb270ddc5a7 Mon Sep 17 00:00:00 2001 From: "James E. Blair" Date: Thu, 19 Sep 2024 15:51:39 -0700 Subject: [PATCH] Fix console log stream delay on idempotent command The command module accepts "creates" or "deletes" arguments which cause it to internally skip running the command if the referenced path exists or not (as appropriate). This idempotency check is not implemented as a skipped task since it occurs inside the module itself. Instead, the module runs normally from Ansible's point of view and simply returns a message indicating it chose not to run the command. This change updates the zuul_stream callback to check for this message and, if found, terminate the streaming connection immediately without waiting for any data (as we do for skipped tasks). Without this, any command or shell task with a creates or deletes argument would wait 10 seconds for the log stream to terminate. Change-Id: I352f641368dcfc697be9634f26ce3a8393b96c1b --- .../git/org_project/playbooks/command.yaml | 22 ++++++++++++++ tests/remote/test_remote_zuul_stream.py | 30 +++++++++++++++++++ zuul/ansible/base/callback/zuul_stream.py | 13 ++++++-- 3 files changed, 63 insertions(+), 2 deletions(-) diff --git a/tests/fixtures/config/remote-zuul-stream/git/org_project/playbooks/command.yaml b/tests/fixtures/config/remote-zuul-stream/git/org_project/playbooks/command.yaml index c0178c898a..dc474a7ab7 100644 --- a/tests/fixtures/config/remote-zuul-stream/git/org_project/playbooks/command.yaml +++ b/tests/fixtures/config/remote-zuul-stream/git/org_project/playbooks/command.yaml @@ -69,6 +69,10 @@ - failed_in_loop1 - failed_in_loop2 + - name: Set testfile path name for later test + set_fact: + testfile: "/tmp/testfile-{{ zuul.build }}" + handlers: - name: test handler command: echo "This is a handler" @@ -106,6 +110,17 @@ - failed_in_loop1 - failed_in_loop2 ignore_errors: True + - name: Creates file that does not exist + command: "touch {{ testfile }}" + args: + creates: "{{ testfile }}" + +- hosts: controller + tasks: + - name: Creates file that already exists + command: "touch {{ testfile }}" + args: + creates: "{{ testfile }}" # Try transitive includes two different ways - hosts: compute1 @@ -145,3 +160,10 @@ loop: - 1 - 2 + +- hosts: all + tasks: + - name: Clean up tmpfile + file: + path: "{{ testfile }}" + state: absent diff --git a/tests/remote/test_remote_zuul_stream.py b/tests/remote/test_remote_zuul_stream.py index b12473bc27..9c5afd59a5 100644 --- a/tests/remote/test_remote_zuul_stream.py +++ b/tests/remote/test_remote_zuul_stream.py @@ -169,6 +169,21 @@ class FunctionalZuulStreamMixIn: result['stdout']) self.assertEqual("", result['stderr']) + # Find the "creates" tasks + create1_task = data[0]['plays'][4]['tasks'][3] + create1_host = create1_task['hosts']['compute1'] + self.assertIsNotNone(create1_host['delta']) + self.assertNotIn("Did not run command since", create1_host['msg']) + self.assertEqual("Creates file that does not exist", + create1_task['task']['name']) + create2_task = data[0]['plays'][5]['tasks'][0] + create2_host = create2_task['hosts']['controller'] + self.assertIsNone(create2_host['delta']) + self.assertIn("Did not run command since", create2_host['msg']) + self.assertEqual("Creates file that already exists", + create2_task['task']['name']) + self.assertLogLine(r'controller \| ok: Runtime: None', text) + self.assertLogLine( r'RUN START: \[untrusted : review.example.com/org/project/' r'playbooks/command.yaml@master\]', text) @@ -276,6 +291,21 @@ class FunctionalZuulStreamMixIn: self.assertEqual(token_stdout, result['stdout']) self.assertEqual(token_stderr, result['stderr']) + # Find the "creates" tasks + create1_task = data[0]['plays'][4]['tasks'][3] + create1_host = create1_task['hosts']['compute1'] + self.assertIsNotNone(create1_host['delta']) + self.assertNotIn("Did not run command since", create1_host['msg']) + self.assertEqual("Creates file that does not exist", + create1_task['task']['name']) + create2_task = data[0]['plays'][5]['tasks'][0] + create2_host = create2_task['hosts']['controller'] + self.assertIsNone(create2_host['delta']) + self.assertIn("Did not run command since", create2_host['msg']) + self.assertEqual("Creates file that already exists", + create2_task['task']['name']) + self.assertLogLine(r'controller \| ok: Runtime: None', text) + self.assertLogLine( r'RUN START: \[untrusted : review.example.com/org/project/' r'playbooks/command.yaml@master\]', text) diff --git a/zuul/ansible/base/callback/zuul_stream.py b/zuul/ansible/base/callback/zuul_stream.py index 53933986db..e0778c55be 100644 --- a/zuul/ansible/base/callback/zuul_stream.py +++ b/zuul/ansible/base/callback/zuul_stream.py @@ -606,12 +606,21 @@ class CallbackModule(default.CallbackModule): self._process_deferred(result) def v2_runner_on_ok(self, result): + result_dict = dict(result._result) + + if result._task.action in ('command', 'shell'): + # The command module has a small set of msgs it returns; + # we can use that to detect if decided not to execute the + # command: + # "Did/Would not run command since 'path' exists/does not exist" + # is the message we're looking for. + if 'not run command since' in result_dict.get('msg', ''): + self._stop_skipped_task_streamer(result._task) + if (self._play.strategy == 'free' and self._last_task_banner != result._task._uuid): self._print_task_banner(result._task) - result_dict = dict(result._result) - self._clean_results(result_dict, result._task.action) if '_zuul_nolog_return' in result_dict: # We have a custom zuul module that doesn't want the parameters