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

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

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)

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