Merge "zuul_stream: handle non-string msg value"

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

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):

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
@@ -499,8 +500,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
@@ -519,7 +519,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:
@@ -569,7 +569,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'):
@@ -612,7 +612,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'):
@@ -745,7 +745,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))