Add timestamps to multiline debug message logs

We special case ansible debug tasks with msg parameters to bypass normal
logging. This meant that multiline debug messages were passed through
verbatim and didn't get per line timestamps and log formatting. This is
not consistent with the rest of our logging so we update it to log each
line in a multi line debug message separately.

Change-Id: Iacb5a101b2a2b971f631e9a14caa51899495ea2d

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

@@ -391,9 +391,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),