From f79f17c6287019b928d871c0dd0b43397d4075e3 Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Fri, 4 Dec 2020 14:20:50 -0500 Subject: [PATCH 1/3] Avoid duplicated configuration code. --- tests/logging/test_terse_json.py | 44 ++++++++++++-------------------- 1 file changed, 17 insertions(+), 27 deletions(-) diff --git a/tests/logging/test_terse_json.py b/tests/logging/test_terse_json.py index 73f469b802e3..09bfd2a7e689 100644 --- a/tests/logging/test_terse_json.py +++ b/tests/logging/test_terse_json.py @@ -24,24 +24,28 @@ 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 +61,7 @@ def test_extra_data(self): """ 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 +69,7 @@ def test_extra_data(self): "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 +93,13 @@ def test_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(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 = [ From 5a60d3d8602fd9180df06e324b79cc8a80c422fd Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Wed, 2 Dec 2020 10:24:22 -0500 Subject: [PATCH 2/3] Add an additional test for JSON logging + logging contexts. --- tests/logging/test_terse_json.py | 29 +++++++++++++++++++++++++++++ 1 file changed, 29 insertions(+) diff --git a/tests/logging/test_terse_json.py b/tests/logging/test_terse_json.py index 09bfd2a7e689..f6e7e5fdaa8c 100644 --- a/tests/logging/test_terse_json.py +++ b/tests/logging/test_terse_json.py @@ -18,6 +18,7 @@ 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 @@ -109,3 +110,31 @@ def test_json_output(self): ] 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"]) From 24111450e04cbba73c0a60e1cb2a477846a22345 Mon Sep 17 00:00:00 2001 From: Patrick Cloke Date: Thu, 10 Dec 2020 08:23:11 -0500 Subject: [PATCH 3/3] Add changelog. --- changelog.d/8916.misc | 1 + 1 file changed, 1 insertion(+) create mode 100644 changelog.d/8916.misc diff --git a/changelog.d/8916.misc b/changelog.d/8916.misc new file mode 100644 index 000000000000..c71ef480e6cc --- /dev/null +++ b/changelog.d/8916.misc @@ -0,0 +1 @@ +Improve structured logging tests.