zuul_stream: handle non-string msg value

I noticed in some of our testing a construct like

 debug:
   msg: '{{ ansible_version }}'

was actually erroring out; you'll see in the console output if you're
looking

 Ansible output: b'TASK [Print ansible version msg={{ ansible_version }}] *************************'
 Ansible output: b'[WARNING]: Failure using method (v2_runner_on_ok) in callback plugin'
 Ansible output: b'(<ansible.plugins.callback.zuul_stream.CallbackModule object at'
 Ansible output: b"0x7f502760b490>): 'dict' object has no attribute 'startswith'"

and the job-output.txt will be empty for this task (this is detected
by by I9f569a411729f8a067de17d99ef6b9d74fc21543).

This is because the msg value here comes in as a dict, and in several
places we assume it is a string.  This changes places we inspect the
msg variable to use the standard Ansible way to make a text string
(to_text function) and ensures in the logging function it converts the
input to a string.

We test for this with updated tasks in the remote_zuul_stream tests.
It is slightly refactored to do partial matches so we can use the
version strings, which is where we saw the issue.

Change-Id: I6e6ed8dba2ba1fc74e7fc8361e8439ea6139279e

3 files changed, 50 insertions, 9 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 d737a1a9b..539db80b7 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
@@ -114,3 +114,17 @@
     - name: Command Not Found
       command: command-not-found
       failed_when: false
+
+- hosts: compute1
+  tasks:
+
+    - name: Debug raw variable in msg
+      debug:
+        msg: '{{ ansible_version }}'
+
+    - name: Debug raw variable in a loop
+      debug:
+        msg: '{{ ansible_version }}'
+      loop:
+        - 1
+        - 2
diff --git a/tests/remote/test_remote_zuul_stream.py b/tests/remote/test_remote_zuul_stream.py
index 03247b9ce..225c88e96 100644
--- a/tests/remote/test_remote_zuul_stream.py
+++ b/tests/remote/test_remote_zuul_stream.py
@@ -100,14 +100,20 @@ class FunctionalZuulStreamMixIn:
         with open(path) as f:
             return f.read()
 
-    def assertLogLine(self, line, log):
-        pattern = (r'^\d\d\d\d-\d\d-\d\d \d\d:\d\d\:\d\d\.\d\d\d\d\d\d \| %s$'
-                   % line)
+    def _assertLogLine(self, line, log, full_match=True):
+        pattern = (r'^\d\d\d\d-\d\d-\d\d \d\d:\d\d\:\d\d\.\d\d\d\d\d\d \| %s%s'
+                   % (line, '$' if full_match else ''))
         log_re = re.compile(pattern, re.MULTILINE)
         m = log_re.search(log)
         if m is None:
             raise Exception("'%s' not found in log" % (line,))
 
+    def assertLogLineStartsWith(self, line, log):
+        self._assertLogLine(line, log, full_match=False)
+
+    def assertLogLine(self, line, log):
+        self._assertLogLine(line, log, full_match=True)
+
     def _getLogTime(self, line, log):
         pattern = (r'^(\d\d\d\d-\d\d-\d\d \d\d:\d\d\:\d\d\.\d\d\d\d\d\d)'
                    r' \| %s\n'
@@ -142,6 +148,7 @@ class FunctionalZuulStreamMixIn:
             self.assertNotIn('[WARNING]: Failure using method', console_output)
 
             text = self._get_job_output(build)
+
             self.assertLogLine(
                 r'RUN START: \[untrusted : review.example.com/org/project/'
                 r'playbooks/command.yaml@master\]', text)
@@ -207,6 +214,20 @@ class FunctionalZuulStreamMixIn:
             self.assertLess((time2 - time1) / timedelta(milliseconds=1),
                             9000)
 
+            # This is from the debug: msg='{{ ansible_version }}'
+            # testing raw variable output.  To make it version
+            # agnostic, match just the start of
+            #  compute1 | ok: {'string': '2.9.27'...
+
+            # NOTE(ianw) 2022-08-24 : I don't know why the callback
+            # for debug: msg= doesn't put the hostname first like
+            # other output. Undetermined if bug or feature.
+            self.assertLogLineStartsWith(
+                r"""\{'string': '\d.""", text)
+            # ... handling loops is a different path, and that does
+            self.assertLogLineStartsWith(
+                r"""compute1 \| ok: \{'string': '\d.""", text)
+
     def test_module_exception(self):
         job = self._run_job('module_failure_exception')
         with self.jobLog(job):
diff --git a/zuul/ansible/base/callback/zuul_stream.py b/zuul/ansible/base/callback/zuul_stream.py
index 966d7d6fa..1d37fb3a8 100644
--- a/zuul/ansible/base/callback/zuul_stream.py
+++ b/zuul/ansible/base/callback/zuul_stream.py
@@ -43,6 +43,7 @@ import threading
 import time
 
 from ansible.plugins.callback import default
+from ansible.module_utils._text import to_text
 from zuul.ansible import paths
 
 from zuul.ansible import logconfig
@@ -492,8 +493,7 @@ class CallbackModule(default.CallbackModule):
         if result._task.loop and 'results' in result_dict:
             # items have their own events
             pass
-
-        elif result_dict.get('msg', '').startswith('MODULE FAILURE'):
+        elif to_text(result_dict.get('msg', '')).startswith('MODULE FAILURE'):
             self._log_module_failure(result, result_dict)
         elif result._task.action == 'debug':
             # this is a debug statement, handle it special
@@ -512,7 +512,7 @@ class CallbackModule(default.CallbackModule):
             # user provided. Note that msg may be a multi line block quote
             # so we handle that here as well.
             if keyname == 'msg':
-                msg_lines = result_dict['msg'].rstrip().split('\n')
+                msg_lines = to_text(result_dict['msg']).rstrip().split('\n')
                 for msg_line in msg_lines:
                     self._log(msg=msg_line)
             else:
@@ -562,7 +562,7 @@ class CallbackModule(default.CallbackModule):
         # changes.
         loop_var = result_dict.get('ansible_loop_var', 'item')
 
-        if result_dict.get('msg', '').startswith('MODULE FAILURE'):
+        if to_text(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'):
@@ -605,7 +605,7 @@ class CallbackModule(default.CallbackModule):
         # changes.
         loop_var = result_dict.get('ansible_loop_var', 'item')
 
-        if result_dict.get('msg', '').startswith('MODULE FAILURE'):
+        if to_text(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'):
@@ -738,7 +738,13 @@ class CallbackModule(default.CallbackModule):
             msg = result_dict['msg']
             result_dict = None
         if msg:
-            msg_lines = msg.rstrip().split('\n')
+            # ensure msg is a string; e.g.
+            #
+            # debug:
+            #   msg: '{{ var }}'
+            #
+            # may not be!
+            msg_lines = to_text(msg).rstrip().split('\n')
             if len(msg_lines) > 1:
                 self._log("{host} | {status}:".format(
                     host=hostname, status=status))