test_structured.py 6.8 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214
  1. # -*- coding: utf-8 -*-
  2. # Copyright 2019 The Matrix.org Foundation C.I.C.
  3. #
  4. # Licensed under the Apache License, Version 2.0 (the "License");
  5. # you may not use this file except in compliance with the License.
  6. # You may obtain a copy of the License at
  7. #
  8. # http://www.apache.org/licenses/LICENSE-2.0
  9. #
  10. # Unless required by applicable law or agreed to in writing, software
  11. # distributed under the License is distributed on an "AS IS" BASIS,
  12. # WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
  13. # See the License for the specific language governing permissions and
  14. # limitations under the License.
  15. import logging
  16. import os
  17. import os.path
  18. import shutil
  19. import sys
  20. import textwrap
  21. from twisted.logger import Logger, eventAsText, eventsFromJSONLogFile
  22. from synapse.config.logger import setup_logging
  23. from synapse.logging._structured import setup_structured_logging
  24. from synapse.logging.context import LoggingContext
  25. from tests.unittest import DEBUG, HomeserverTestCase
  26. class FakeBeginner(object):
  27. def beginLoggingTo(self, observers, **kwargs):
  28. self.observers = observers
  29. class StructuredLoggingTestBase(object):
  30. """
  31. Test base that registers a cleanup handler to reset the stdlib log handler
  32. to 'unset'.
  33. """
  34. def prepare(self, reactor, clock, hs):
  35. def _cleanup():
  36. logging.getLogger("synapse").setLevel(logging.NOTSET)
  37. self.addCleanup(_cleanup)
  38. class StructuredLoggingTestCase(StructuredLoggingTestBase, HomeserverTestCase):
  39. """
  40. Tests for Synapse's structured logging support.
  41. """
  42. def test_output_to_json_round_trip(self):
  43. """
  44. Synapse logs can be outputted to JSON and then read back again.
  45. """
  46. temp_dir = self.mktemp()
  47. os.mkdir(temp_dir)
  48. self.addCleanup(shutil.rmtree, temp_dir)
  49. json_log_file = os.path.abspath(os.path.join(temp_dir, "out.json"))
  50. log_config = {
  51. "drains": {"jsonfile": {"type": "file_json", "location": json_log_file}}
  52. }
  53. # Begin the logger with our config
  54. beginner = FakeBeginner()
  55. setup_structured_logging(
  56. self.hs, self.hs.config, log_config, logBeginner=beginner
  57. )
  58. # Make a logger and send an event
  59. logger = Logger(
  60. namespace="tests.logging.test_structured", observer=beginner.observers[0]
  61. )
  62. logger.info("Hello there, {name}!", name="wally")
  63. # Read the log file and check it has the event we sent
  64. with open(json_log_file, "r") as f:
  65. logged_events = list(eventsFromJSONLogFile(f))
  66. self.assertEqual(len(logged_events), 1)
  67. # The event pulled from the file should render fine
  68. self.assertEqual(
  69. eventAsText(logged_events[0], includeTimestamp=False),
  70. "[tests.logging.test_structured#info] Hello there, wally!",
  71. )
  72. def test_output_to_text(self):
  73. """
  74. Synapse logs can be outputted to text.
  75. """
  76. temp_dir = self.mktemp()
  77. os.mkdir(temp_dir)
  78. self.addCleanup(shutil.rmtree, temp_dir)
  79. log_file = os.path.abspath(os.path.join(temp_dir, "out.log"))
  80. log_config = {"drains": {"file": {"type": "file", "location": log_file}}}
  81. # Begin the logger with our config
  82. beginner = FakeBeginner()
  83. setup_structured_logging(
  84. self.hs, self.hs.config, log_config, logBeginner=beginner
  85. )
  86. # Make a logger and send an event
  87. logger = Logger(
  88. namespace="tests.logging.test_structured", observer=beginner.observers[0]
  89. )
  90. logger.info("Hello there, {name}!", name="wally")
  91. # Read the log file and check it has the event we sent
  92. with open(log_file, "r") as f:
  93. logged_events = f.read().strip().split("\n")
  94. self.assertEqual(len(logged_events), 1)
  95. # The event pulled from the file should render fine
  96. self.assertTrue(
  97. logged_events[0].endswith(
  98. " - tests.logging.test_structured - INFO - None - Hello there, wally!"
  99. )
  100. )
  101. def test_collects_logcontext(self):
  102. """
  103. Test that log outputs have the attached logging context.
  104. """
  105. log_config = {"drains": {}}
  106. # Begin the logger with our config
  107. beginner = FakeBeginner()
  108. publisher = setup_structured_logging(
  109. self.hs, self.hs.config, log_config, logBeginner=beginner
  110. )
  111. logs = []
  112. publisher.addObserver(logs.append)
  113. # Make a logger and send an event
  114. logger = Logger(
  115. namespace="tests.logging.test_structured", observer=beginner.observers[0]
  116. )
  117. with LoggingContext("testcontext", request="somereq"):
  118. logger.info("Hello there, {name}!", name="steve")
  119. self.assertEqual(len(logs), 1)
  120. self.assertEqual(logs[0]["request"], "somereq")
  121. class StructuredLoggingConfigurationFileTestCase(
  122. StructuredLoggingTestBase, HomeserverTestCase
  123. ):
  124. def make_homeserver(self, reactor, clock):
  125. tempdir = self.mktemp()
  126. os.mkdir(tempdir)
  127. log_config_file = os.path.abspath(os.path.join(tempdir, "log.config.yaml"))
  128. self.homeserver_log = os.path.abspath(os.path.join(tempdir, "homeserver.log"))
  129. config = self.default_config()
  130. config["log_config"] = log_config_file
  131. with open(log_config_file, "w") as f:
  132. f.write(
  133. textwrap.dedent(
  134. """\
  135. structured: true
  136. drains:
  137. file:
  138. type: file_json
  139. location: %s
  140. """
  141. % (self.homeserver_log,)
  142. )
  143. )
  144. self.addCleanup(self._sys_cleanup)
  145. return self.setup_test_homeserver(config=config)
  146. def _sys_cleanup(self):
  147. sys.stdout = sys.__stdout__
  148. sys.stderr = sys.__stderr__
  149. # Do not remove! We need the logging system to be set other than WARNING.
  150. @DEBUG
  151. def test_log_output(self):
  152. """
  153. When a structured logging config is given, Synapse will use it.
  154. """
  155. beginner = FakeBeginner()
  156. publisher = setup_logging(self.hs, self.hs.config, logBeginner=beginner)
  157. # Make a logger and send an event
  158. logger = Logger(namespace="tests.logging.test_structured", observer=publisher)
  159. with LoggingContext("testcontext", request="somereq"):
  160. logger.info("Hello there, {name}!", name="steve")
  161. with open(self.homeserver_log, "r") as f:
  162. logged_events = [
  163. eventAsText(x, includeTimestamp=False) for x in eventsFromJSONLogFile(f)
  164. ]
  165. logs = "\n".join(logged_events)
  166. self.assertTrue("***** STARTING SERVER *****" in logs)
  167. self.assertTrue("Hello there, steve!" in logs)