Handle non default loopvars in Ansible callback stream plugin

The Zuul Ansible callback stream plugin assumed that the ansible loop
var was always called 'item' in the result_dict. You can override this
value (and it is often necessary to do so to avoid collisions) to
something less generic. In those cases we would get errors like:

  b'[WARNING]: Failure using method (v2_runner_item_on_ok) in callback plugin'
  b'(<ansible.plugins.callback.zuul_stream.CallbackModule object at'
  b"0x7fbecc97c910>): 'item'"

And stream output would not include the info typically logged.

Address this by checking if ansible_loop_var is in the results_dict and
using that value for the loop var name instead. We still fall back to
'item' as I'm not sure that ansible_loop_var is always present.

Change-Id: I408e6d4af632f8097d63c04cbcb611d843086f6c

3 files changed, 35 insertions, 5 deletions

diff --git a/tests/fixtures/config/streamer/git/common-config/playbooks/python27.yaml b/tests/fixtures/config/streamer/git/common-config/playbooks/python27.yaml
index 8485b04ce..397439f61 100644
--- a/tests/fixtures/config/streamer/git/common-config/playbooks/python27.yaml
+++ b/tests/fixtures/config/streamer/git/common-config/playbooks/python27.yaml
@@ -11,6 +11,18 @@
           Debug Test Token String
           Message
 
+    # Logging of loops is special so we do a simple one iteration
+    # loop and check that we log things properly
+    - name: Override ansible_loop_var
+      set_fact:
+        _testing_fact: "{{ other_loop_var }}"
+      with_random_choice:
+        - "one"
+        - "two"
+        - "three"
+      loop_control:
+        loop_var: "other_loop_var"
+
      # Do not finish until test creates the flag file
     - wait_for:
         state: present
diff --git a/tests/unit/test_streaming.py b/tests/unit/test_streaming.py
index f323cd82a..ba3117f59 100644
--- a/tests/unit/test_streaming.py
+++ b/tests/unit/test_streaming.py
@@ -295,6 +295,11 @@ class TestStreaming(TestStreamingBase):
         match = r.search(self.streaming_data[None])
         self.assertNotEqual(match, None)
 
+        # Check that we logged loop_var contents properly
+        pattern = r'ok: "(one|two|three)"'
+        m = re.search(pattern, self.streaming_data[None])
+        self.assertNotEqual(m, None)
+
     def runWSClient(self, port, build_uuid):
         client = WSClient(port, build_uuid)
         client.event.wait()
diff --git a/zuul/ansible/base/callback/zuul_stream.py b/zuul/ansible/base/callback/zuul_stream.py
index 184dbe78f..720261cb2 100644
--- a/zuul/ansible/base/callback/zuul_stream.py
+++ b/zuul/ansible/base/callback/zuul_stream.py
@@ -502,6 +502,11 @@ class CallbackModule(default.CallbackModule):
         else:
             status = 'ok'
 
+        # This fallback may not be strictly necessary. 'item' is the
+        # default and we'll avoid problems in the common case if ansible
+        # changes.
+        loop_var = result_dict.get('ansible_loop_var', 'item')
+
         if result_dict.get('msg', '').startswith('MODULE FAILURE'):
             self._log_module_failure(result, result_dict)
         elif result._task.action not in ('command', 'shell',
@@ -512,7 +517,7 @@ class CallbackModule(default.CallbackModule):
             else:
                 self._log_message(
                     result=result,
-                    msg=json.dumps(result_dict['item'],
+                    msg=json.dumps(result_dict[loop_var],
                                    indent=2, sort_keys=True),
                     status=status)
         else:
@@ -521,10 +526,12 @@ class CallbackModule(default.CallbackModule):
                 hostname = self._get_hostname(result)
                 self._log("%s | %s " % (hostname, line))
 
-            if isinstance(result_dict['item'], str):
+            if isinstance(result_dict[loop_var], str):
                 self._log_message(
                     result,
-                    "Item: {item} Runtime: {delta}".format(**result_dict))
+                    "Item: {loop_var} Runtime: {delta}".format(
+                        loop_var=result_dict[loop_var],
+                        delta=result_dict['delta']))
             else:
                 self._log_message(
                     result,
@@ -538,13 +545,18 @@ class CallbackModule(default.CallbackModule):
         result_dict = dict(result._result)
         self._process_result_for_localhost(result, is_task=False)
 
+        # This fallback may not be strictly necessary. 'item' is the
+        # default and we'll avoid problems in the common case if ansible
+        # changes.
+        loop_var = result_dict.get('ansible_loop_var', 'item')
+
         if result_dict.get('msg', '').startswith('MODULE FAILURE'):
             self._log_module_failure(result, result_dict)
         elif result._task.action not in ('command', 'shell',
                                          'win_command', 'win_shell'):
             self._log_message(
                 result=result,
-                msg="Item: {item}".format(item=result_dict['item']),
+                msg="Item: {loop_var}".format(loop_var=result_dict[loop_var]),
                 status='ERROR',
                 result_dict=result_dict)
         else:
@@ -555,7 +567,8 @@ class CallbackModule(default.CallbackModule):
 
             # self._log("Result: %s" % (result_dict))
             self._log_message(
-                result, "Item: {item} Result: {rc}".format(**result_dict))
+                result, "Item: {loop_var} Result: {rc}".format(
+                    loop_var=result_dict[loop_var], rc=result_dict['rc']))
 
         if self._deferred_result:
             self._process_deferred(result)