1
0

test_terse_json.py 7.1 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234
  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 json
  16. from collections import Counter
  17. from twisted.logger import Logger
  18. from synapse.logging._structured import setup_structured_logging
  19. from tests.server import connect_client
  20. from tests.unittest import HomeserverTestCase
  21. from .test_structured import FakeBeginner, StructuredLoggingTestBase
  22. class TerseJSONTCPTestCase(StructuredLoggingTestBase, HomeserverTestCase):
  23. def test_log_output(self):
  24. """
  25. The Terse JSON outputter delivers simplified structured logs over TCP.
  26. """
  27. log_config = {
  28. "drains": {
  29. "tersejson": {
  30. "type": "network_json_terse",
  31. "host": "127.0.0.1",
  32. "port": 8000,
  33. }
  34. }
  35. }
  36. # Begin the logger with our config
  37. beginner = FakeBeginner()
  38. setup_structured_logging(
  39. self.hs, self.hs.config, log_config, logBeginner=beginner
  40. )
  41. logger = Logger(
  42. namespace="tests.logging.test_terse_json", observer=beginner.observers[0]
  43. )
  44. logger.info("Hello there, {name}!", name="wally")
  45. # Trigger the connection
  46. self.pump()
  47. _, server = connect_client(self.reactor, 0)
  48. # Trigger data being sent
  49. self.pump()
  50. # One log message, with a single trailing newline
  51. logs = server.data.decode("utf8").splitlines()
  52. self.assertEqual(len(logs), 1)
  53. self.assertEqual(server.data.count(b"\n"), 1)
  54. log = json.loads(logs[0])
  55. # The terse logger should give us these keys.
  56. expected_log_keys = [
  57. "log",
  58. "time",
  59. "level",
  60. "log_namespace",
  61. "request",
  62. "scope",
  63. "server_name",
  64. "name",
  65. ]
  66. self.assertEqual(set(log.keys()), set(expected_log_keys))
  67. # It contains the data we expect.
  68. self.assertEqual(log["name"], "wally")
  69. def test_log_backpressure_debug(self):
  70. """
  71. When backpressure is hit, DEBUG logs will be shed.
  72. """
  73. log_config = {
  74. "loggers": {"synapse": {"level": "DEBUG"}},
  75. "drains": {
  76. "tersejson": {
  77. "type": "network_json_terse",
  78. "host": "127.0.0.1",
  79. "port": 8000,
  80. "maximum_buffer": 10,
  81. }
  82. },
  83. }
  84. # Begin the logger with our config
  85. beginner = FakeBeginner()
  86. setup_structured_logging(
  87. self.hs,
  88. self.hs.config,
  89. log_config,
  90. logBeginner=beginner,
  91. redirect_stdlib_logging=False,
  92. )
  93. logger = Logger(
  94. namespace="synapse.logging.test_terse_json", observer=beginner.observers[0]
  95. )
  96. # Send some debug messages
  97. for i in range(0, 3):
  98. logger.debug("debug %s" % (i,))
  99. # Send a bunch of useful messages
  100. for i in range(0, 7):
  101. logger.info("test message %s" % (i,))
  102. # The last debug message pushes it past the maximum buffer
  103. logger.debug("too much debug")
  104. # Allow the reconnection
  105. _, server = connect_client(self.reactor, 0)
  106. self.pump()
  107. # Only the 7 infos made it through, the debugs were elided
  108. logs = server.data.splitlines()
  109. self.assertEqual(len(logs), 7)
  110. def test_log_backpressure_info(self):
  111. """
  112. When backpressure is hit, DEBUG and INFO logs will be shed.
  113. """
  114. log_config = {
  115. "loggers": {"synapse": {"level": "DEBUG"}},
  116. "drains": {
  117. "tersejson": {
  118. "type": "network_json_terse",
  119. "host": "127.0.0.1",
  120. "port": 8000,
  121. "maximum_buffer": 10,
  122. }
  123. },
  124. }
  125. # Begin the logger with our config
  126. beginner = FakeBeginner()
  127. setup_structured_logging(
  128. self.hs,
  129. self.hs.config,
  130. log_config,
  131. logBeginner=beginner,
  132. redirect_stdlib_logging=False,
  133. )
  134. logger = Logger(
  135. namespace="synapse.logging.test_terse_json", observer=beginner.observers[0]
  136. )
  137. # Send some debug messages
  138. for i in range(0, 3):
  139. logger.debug("debug %s" % (i,))
  140. # Send a bunch of useful messages
  141. for i in range(0, 10):
  142. logger.warn("test warn %s" % (i,))
  143. # Send a bunch of info messages
  144. for i in range(0, 3):
  145. logger.info("test message %s" % (i,))
  146. # The last debug message pushes it past the maximum buffer
  147. logger.debug("too much debug")
  148. # Allow the reconnection
  149. client, server = connect_client(self.reactor, 0)
  150. self.pump()
  151. # The 10 warnings made it through, the debugs and infos were elided
  152. logs = list(map(json.loads, server.data.decode("utf8").splitlines()))
  153. self.assertEqual(len(logs), 10)
  154. self.assertEqual(Counter([x["level"] for x in logs]), {"WARN": 10})
  155. def test_log_backpressure_cut_middle(self):
  156. """
  157. When backpressure is hit, and no more DEBUG and INFOs cannot be culled,
  158. it will cut the middle messages out.
  159. """
  160. log_config = {
  161. "loggers": {"synapse": {"level": "DEBUG"}},
  162. "drains": {
  163. "tersejson": {
  164. "type": "network_json_terse",
  165. "host": "127.0.0.1",
  166. "port": 8000,
  167. "maximum_buffer": 10,
  168. }
  169. },
  170. }
  171. # Begin the logger with our config
  172. beginner = FakeBeginner()
  173. setup_structured_logging(
  174. self.hs,
  175. self.hs.config,
  176. log_config,
  177. logBeginner=beginner,
  178. redirect_stdlib_logging=False,
  179. )
  180. logger = Logger(
  181. namespace="synapse.logging.test_terse_json", observer=beginner.observers[0]
  182. )
  183. # Send a bunch of useful messages
  184. for i in range(0, 20):
  185. logger.warn("test warn", num=i)
  186. # Allow the reconnection
  187. client, server = connect_client(self.reactor, 0)
  188. self.pump()
  189. # The first five and last five warnings made it through, the debugs and
  190. # infos were elided
  191. logs = list(map(json.loads, server.data.decode("utf8").splitlines()))
  192. self.assertEqual(len(logs), 10)
  193. self.assertEqual(Counter([x["level"] for x in logs]), {"WARN": 10})
  194. self.assertEqual([0, 1, 2, 3, 4, 15, 16, 17, 18, 19], [x["num"] for x in logs])