diff --git a/changelog.d/8916.misc b/changelog.d/8916.misc new file mode 100644 index 000000000..c71ef480e --- /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 73f469b80..f6e7e5fda 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"])