Merge "Add timestamps to multiline debug message logs"

tests/fixtures/config/streamer/git/common-config/playbooks/python27.yaml

@@ -5,6 +5,12 @@
   tasks:
     - debug: var=waitpath
 
+    - debug:
+        msg: |
+          Multiline
+          Debug Test Token String
+          Message
+
      # Do not finish until test creates the flag file
     - wait_for:
         state: present

tests/unit/test_streaming.py

@@ -19,6 +19,7 @@ import logging
 import json
 import os
 import os.path
+import re
 import socket
 import tempfile
 import testtools
@@ -198,6 +199,13 @@ class TestStreaming(tests.base.AnsibleZuulTestCase):
         self.log.debug("\n\nStreamed: %s\n\n", self.streaming_data)
         self.assertEqual(file_contents, self.streaming_data)
 
+        # Check that we logged a multiline debug message
+        pattern = (r'^\d\d\d\d-\d\d-\d\d \d\d:\d\d\:\d\d\.\d\d\d\d\d\d \| '
+                   r'Debug Test Token String$')
+        r = re.compile(pattern, re.MULTILINE)
+        match = r.search(self.streaming_data)
+        self.assertNotEqual(match, None)
+
     def runWSClient(self, port, build_uuid):
         client = WSClient(port, build_uuid)
         client.event.wait()

zuul/ansible/callback/zuul_stream.py

@@ -397,9 +397,12 @@ class CallbackModule(default.CallbackModule):
             #    msg: Some debug text the user was looking for
             #
             # So we log it with self._log to get just the raw string the
-            # user provided.
+            # user provided. Note that msg may be a multi line block quote
+            # so we handle that here as well.
             if keyname == 'msg':
-                self._log(msg=result_dict['msg'])
+                msg_lines = result_dict['msg'].rstrip().split('\n')
+                for msg_line in msg_lines:
+                    self._log(msg=msg_line)
             else:
                 self._log_message(
                     msg=json.dumps(result_dict, indent=2, sort_keys=True),