From 10fa3339a55af7e81b768ef7a163b5a6fb97c694 Mon Sep 17 00:00:00 2001
From: Clark Boylan <clark.boylan@gmail.com>
Date: Wed, 6 Jun 2018 10:32:18 -0700
Subject: [PATCH] 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
---
 .../streamer/git/common-config/playbooks/python27.yaml    | 6 ++++++
 tests/unit/test_streaming.py                              | 8 ++++++++
 zuul/ansible/callback/zuul_stream.py                      | 7 +++++--
 3 files changed, 19 insertions(+), 2 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 753e7e2e26..f45e337de1 100644
--- a/tests/fixtures/config/streamer/git/common-config/playbooks/python27.yaml
+++ b/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
diff --git a/tests/unit/test_streaming.py b/tests/unit/test_streaming.py
index f96f7fd7c2..65de60d64a 100644
--- a/tests/unit/test_streaming.py
+++ b/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()
diff --git a/zuul/ansible/callback/zuul_stream.py b/zuul/ansible/callback/zuul_stream.py
index 58564bd56a..0fada2bb9d 100644
--- a/zuul/ansible/callback/zuul_stream.py
+++ b/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),