From 3af0672350965b4fddf3aad2904795bbd0199c30 Mon Sep 17 00:00:00 2001
From: Patrick Cloke <clokep@users.noreply.github.com>
Date: Fri, 11 Dec 2020 07:25:01 -0500
Subject: [PATCH] Improve tests for structured logging. (#8916)

---
 changelog.d/8916.misc            |  1 +
 tests/logging/test_terse_json.py | 73 ++++++++++++++++++++------------
 2 files changed, 47 insertions(+), 27 deletions(-)
 create mode 100644 changelog.d/8916.misc

diff --git a/changelog.d/8916.misc b/changelog.d/8916.misc
new file mode 100644
index 0000000000..c71ef480e6
--- /dev/null
+++ b/changelog.d/8916.misc
@@ -0,0 +1 @@
+Improve structured logging tests.
diff --git a/tests/logging/test_terse_json.py b/tests/logging/test_terse_json.py
index 73f469b802..f6e7e5fdaa 100644
--- a/tests/logging/test_terse_json.py
+++ b/tests/logging/test_terse_json.py
@@ -18,30 +18,35 @@ import logging
 from io import StringIO
 
 from synapse.logging._terse_json import JsonFormatter, TerseJsonFormatter
+from synapse.logging.context import LoggingContext, LoggingContextFilter
 
 from tests.logging import LoggerCleanupMixin
 from tests.unittest import TestCase
 
 
 class TerseJsonTestCase(LoggerCleanupMixin, TestCase):
+    def setUp(self):
+        self.output = StringIO()
+
+    def get_log_line(self):
+        # One log message, with a single trailing newline.
+        data = self.output.getvalue()
+        logs = data.splitlines()
+        self.assertEqual(len(logs), 1)
+        self.assertEqual(data.count("\n"), 1)
+        return json.loads(logs[0])
+
     def test_terse_json_output(self):
         """
         The Terse JSON formatter converts log messages to JSON.
         """
-        output = StringIO()
-
-        handler = logging.StreamHandler(output)
+        handler = logging.StreamHandler(self.output)
         handler.setFormatter(TerseJsonFormatter())
         logger = self.get_logger(handler)
 
         logger.info("Hello there, %s!", "wally")
 
-        # One log message, with a single trailing newline.
-        data = output.getvalue()
-        logs = data.splitlines()
-        self.assertEqual(len(logs), 1)
-        self.assertEqual(data.count("\n"), 1)
-        log = json.loads(logs[0])
+        log = self.get_log_line()
 
         # The terse logger should give us these keys.
         expected_log_keys = [
@@ -57,9 +62,7 @@ class TerseJsonTestCase(LoggerCleanupMixin, TestCase):
         """
         Additional information can be included in the structured logging.
         """
-        output = StringIO()
-
-        handler = logging.StreamHandler(output)
+        handler = logging.StreamHandler(self.output)
         handler.setFormatter(TerseJsonFormatter())
         logger = self.get_logger(handler)
 
@@ -67,12 +70,7 @@ class TerseJsonTestCase(LoggerCleanupMixin, TestCase):
             "Hello there, %s!", "wally", extra={"foo": "bar", "int": 3, "bool": True}
         )
 
-        # One log message, with a single trailing newline.
-        data = output.getvalue()
-        logs = data.splitlines()
-        self.assertEqual(len(logs), 1)
-        self.assertEqual(data.count("\n"), 1)
-        log = json.loads(logs[0])
+        log = self.get_log_line()
 
         # The terse logger should give us these keys.
         expected_log_keys = [
@@ -96,20 +94,13 @@ class TerseJsonTestCase(LoggerCleanupMixin, TestCase):
         """
         The Terse JSON formatter converts log messages to JSON.
         """
-        output = StringIO()
-
-        handler = logging.StreamHandler(output)
+        handler = logging.StreamHandler(self.output)
         handler.setFormatter(JsonFormatter())
         logger = self.get_logger(handler)
 
         logger.info("Hello there, %s!", "wally")
 
-        # One log message, with a single trailing newline.
-        data = output.getvalue()
-        logs = data.splitlines()
-        self.assertEqual(len(logs), 1)
-        self.assertEqual(data.count("\n"), 1)
-        log = json.loads(logs[0])
+        log = self.get_log_line()
 
         # The terse logger should give us these keys.
         expected_log_keys = [
@@ -119,3 +110,31 @@ class TerseJsonTestCase(LoggerCleanupMixin, TestCase):
         ]
         self.assertCountEqual(log.keys(), expected_log_keys)
         self.assertEqual(log["log"], "Hello there, wally!")
+
+    def test_with_context(self):
+        """
+        The logging context should be added to the JSON response.
+        """
+        handler = logging.StreamHandler(self.output)
+        handler.setFormatter(JsonFormatter())
+        handler.addFilter(LoggingContextFilter(request=""))
+        logger = self.get_logger(handler)
+
+        with LoggingContext() as context_one:
+            context_one.request = "test"
+            logger.info("Hello there, %s!", "wally")
+
+        log = self.get_log_line()
+
+        # The terse logger should give us these keys.
+        expected_log_keys = [
+            "log",
+            "level",
+            "namespace",
+            "request",
+            "scope",
+        ]
+        self.assertCountEqual(log.keys(), expected_log_keys)
+        self.assertEqual(log["log"], "Hello there, wally!")
+        self.assertEqual(log["request"], "test")
+        self.assertIsNone(log["scope"])