test_remote_handler.py 5.7 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168
  1. # Copyright 2019 The Matrix.org Foundation C.I.C.
  2. #
  3. # Licensed under the Apache License, Version 2.0 (the "License");
  4. # you may not use this file except in compliance with the License.
  5. # You may obtain a copy of the License at
  6. #
  7. # http://www.apache.org/licenses/LICENSE-2.0
  8. #
  9. # Unless required by applicable law or agreed to in writing, software
  10. # distributed under the License is distributed on an "AS IS" BASIS,
  11. # WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
  12. # See the License for the specific language governing permissions and
  13. # limitations under the License.
  14. from twisted.test.proto_helpers import AccumulatingProtocol
  15. from synapse.logging import RemoteHandler
  16. from tests.logging import LoggerCleanupMixin
  17. from tests.server import FakeTransport, get_clock
  18. from tests.unittest import TestCase
  19. def connect_logging_client(reactor, client_id):
  20. # This is essentially tests.server.connect_client, but disabling autoflush on
  21. # the client transport. This is necessary to avoid an infinite loop due to
  22. # sending of data via the logging transport causing additional logs to be
  23. # written.
  24. factory = reactor.tcpClients.pop(client_id)[2]
  25. client = factory.buildProtocol(None)
  26. server = AccumulatingProtocol()
  27. server.makeConnection(FakeTransport(client, reactor))
  28. client.makeConnection(FakeTransport(server, reactor, autoflush=False))
  29. return client, server
  30. class RemoteHandlerTestCase(LoggerCleanupMixin, TestCase):
  31. def setUp(self):
  32. self.reactor, _ = get_clock()
  33. def test_log_output(self):
  34. """
  35. The remote handler delivers logs over TCP.
  36. """
  37. handler = RemoteHandler("127.0.0.1", 9000, _reactor=self.reactor)
  38. logger = self.get_logger(handler)
  39. logger.info("Hello there, %s!", "wally")
  40. # Trigger the connection
  41. client, server = connect_logging_client(self.reactor, 0)
  42. # Trigger data being sent
  43. client.transport.flush()
  44. # One log message, with a single trailing newline
  45. logs = server.data.decode("utf8").splitlines()
  46. self.assertEqual(len(logs), 1)
  47. self.assertEqual(server.data.count(b"\n"), 1)
  48. # Ensure the data passed through properly.
  49. self.assertEqual(logs[0], "Hello there, wally!")
  50. def test_log_backpressure_debug(self):
  51. """
  52. When backpressure is hit, DEBUG logs will be shed.
  53. """
  54. handler = RemoteHandler(
  55. "127.0.0.1", 9000, maximum_buffer=10, _reactor=self.reactor
  56. )
  57. logger = self.get_logger(handler)
  58. # Send some debug messages
  59. for i in range(0, 3):
  60. logger.debug("debug %s" % (i,))
  61. # Send a bunch of useful messages
  62. for i in range(0, 7):
  63. logger.info("info %s" % (i,))
  64. # The last debug message pushes it past the maximum buffer
  65. logger.debug("too much debug")
  66. # Allow the reconnection
  67. client, server = connect_logging_client(self.reactor, 0)
  68. client.transport.flush()
  69. # Only the 7 infos made it through, the debugs were elided
  70. logs = server.data.splitlines()
  71. self.assertEqual(len(logs), 7)
  72. self.assertNotIn(b"debug", server.data)
  73. def test_log_backpressure_info(self):
  74. """
  75. When backpressure is hit, DEBUG and INFO logs will be shed.
  76. """
  77. handler = RemoteHandler(
  78. "127.0.0.1", 9000, maximum_buffer=10, _reactor=self.reactor
  79. )
  80. logger = self.get_logger(handler)
  81. # Send some debug messages
  82. for i in range(0, 3):
  83. logger.debug("debug %s" % (i,))
  84. # Send a bunch of useful messages
  85. for i in range(0, 10):
  86. logger.warning("warn %s" % (i,))
  87. # Send a bunch of info messages
  88. for i in range(0, 3):
  89. logger.info("info %s" % (i,))
  90. # The last debug message pushes it past the maximum buffer
  91. logger.debug("too much debug")
  92. # Allow the reconnection
  93. client, server = connect_logging_client(self.reactor, 0)
  94. client.transport.flush()
  95. # The 10 warnings made it through, the debugs and infos were elided
  96. logs = server.data.splitlines()
  97. self.assertEqual(len(logs), 10)
  98. self.assertNotIn(b"debug", server.data)
  99. self.assertNotIn(b"info", server.data)
  100. def test_log_backpressure_cut_middle(self):
  101. """
  102. When backpressure is hit, and no more DEBUG and INFOs cannot be culled,
  103. it will cut the middle messages out.
  104. """
  105. handler = RemoteHandler(
  106. "127.0.0.1", 9000, maximum_buffer=10, _reactor=self.reactor
  107. )
  108. logger = self.get_logger(handler)
  109. # Send a bunch of useful messages
  110. for i in range(0, 20):
  111. logger.warning("warn %s" % (i,))
  112. # Allow the reconnection
  113. client, server = connect_logging_client(self.reactor, 0)
  114. client.transport.flush()
  115. # The first five and last five warnings made it through, the debugs and
  116. # infos were elided
  117. logs = server.data.decode("utf8").splitlines()
  118. self.assertEqual(
  119. ["warn %s" % (i,) for i in range(5)]
  120. + ["warn %s" % (i,) for i in range(15, 20)],
  121. logs,
  122. )
  123. def test_cancel_connection(self):
  124. """
  125. Gracefully handle the connection being cancelled.
  126. """
  127. handler = RemoteHandler(
  128. "127.0.0.1", 9000, maximum_buffer=10, _reactor=self.reactor
  129. )
  130. logger = self.get_logger(handler)
  131. # Send a message.
  132. logger.info("Hello there, %s!", "wally")
  133. # Do not accept the connection and shutdown. This causes the pending
  134. # connection to be cancelled (and should not raise any exceptions).
  135. handler.close()