test_logcontext.py 6.8 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199
  1. # Copyright 2014-2022 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 typing import Callable, Generator, cast
  15. import twisted.python.failure
  16. from twisted.internet import defer, reactor as _reactor
  17. from synapse.logging.context import (
  18. SENTINEL_CONTEXT,
  19. LoggingContext,
  20. PreserveLoggingContext,
  21. current_context,
  22. make_deferred_yieldable,
  23. nested_logging_context,
  24. run_in_background,
  25. )
  26. from synapse.types import ISynapseReactor
  27. from synapse.util import Clock
  28. from .. import unittest
  29. reactor = cast(ISynapseReactor, _reactor)
  30. class LoggingContextTestCase(unittest.TestCase):
  31. def _check_test_key(self, value: str) -> None:
  32. context = current_context()
  33. assert isinstance(context, LoggingContext)
  34. self.assertEqual(context.name, value)
  35. def test_with_context(self) -> None:
  36. with LoggingContext("test"):
  37. self._check_test_key("test")
  38. @defer.inlineCallbacks
  39. def test_sleep(self) -> Generator["defer.Deferred[object]", object, None]:
  40. clock = Clock(reactor)
  41. @defer.inlineCallbacks
  42. def competing_callback() -> Generator["defer.Deferred[object]", object, None]:
  43. with LoggingContext("competing"):
  44. yield clock.sleep(0)
  45. self._check_test_key("competing")
  46. reactor.callLater(0, competing_callback)
  47. with LoggingContext("one"):
  48. yield clock.sleep(0)
  49. self._check_test_key("one")
  50. def _test_run_in_background(self, function: Callable[[], object]) -> defer.Deferred:
  51. sentinel_context = current_context()
  52. callback_completed = False
  53. with LoggingContext("one"):
  54. # fire off function, but don't wait on it.
  55. d2 = run_in_background(function)
  56. def cb(res: object) -> object:
  57. nonlocal callback_completed
  58. callback_completed = True
  59. return res
  60. d2.addCallback(cb)
  61. self._check_test_key("one")
  62. # now wait for the function under test to have run, and check that
  63. # the logcontext is left in a sane state.
  64. d2 = defer.Deferred()
  65. def check_logcontext() -> None:
  66. if not callback_completed:
  67. reactor.callLater(0.01, check_logcontext)
  68. return
  69. # make sure that the context was reset before it got thrown back
  70. # into the reactor
  71. try:
  72. self.assertIs(current_context(), sentinel_context)
  73. d2.callback(None)
  74. except BaseException:
  75. d2.errback(twisted.python.failure.Failure())
  76. reactor.callLater(0.01, check_logcontext)
  77. # test is done once d2 finishes
  78. return d2
  79. def test_run_in_background_with_blocking_fn(self) -> defer.Deferred:
  80. @defer.inlineCallbacks
  81. def blocking_function() -> Generator["defer.Deferred[object]", object, None]:
  82. yield Clock(reactor).sleep(0)
  83. return self._test_run_in_background(blocking_function)
  84. def test_run_in_background_with_non_blocking_fn(self) -> defer.Deferred:
  85. @defer.inlineCallbacks
  86. def nonblocking_function() -> Generator["defer.Deferred[object]", object, None]:
  87. with PreserveLoggingContext():
  88. yield defer.succeed(None)
  89. return self._test_run_in_background(nonblocking_function)
  90. def test_run_in_background_with_chained_deferred(self) -> defer.Deferred:
  91. # a function which returns a deferred which looks like it has been
  92. # called, but is actually paused
  93. def testfunc() -> defer.Deferred:
  94. return make_deferred_yieldable(_chained_deferred_function())
  95. return self._test_run_in_background(testfunc)
  96. def test_run_in_background_with_coroutine(self) -> defer.Deferred:
  97. async def testfunc() -> None:
  98. self._check_test_key("one")
  99. d = Clock(reactor).sleep(0)
  100. self.assertIs(current_context(), SENTINEL_CONTEXT)
  101. await d
  102. self._check_test_key("one")
  103. return self._test_run_in_background(testfunc)
  104. def test_run_in_background_with_nonblocking_coroutine(self) -> defer.Deferred:
  105. async def testfunc() -> None:
  106. self._check_test_key("one")
  107. return self._test_run_in_background(testfunc)
  108. @defer.inlineCallbacks
  109. def test_make_deferred_yieldable(
  110. self,
  111. ) -> Generator["defer.Deferred[object]", object, None]:
  112. # a function which returns an incomplete deferred, but doesn't follow
  113. # the synapse rules.
  114. def blocking_function() -> defer.Deferred:
  115. d: defer.Deferred = defer.Deferred()
  116. reactor.callLater(0, d.callback, None)
  117. return d
  118. sentinel_context = current_context()
  119. with LoggingContext("one"):
  120. d1 = make_deferred_yieldable(blocking_function())
  121. # make sure that the context was reset by make_deferred_yieldable
  122. self.assertIs(current_context(), sentinel_context)
  123. yield d1
  124. # now it should be restored
  125. self._check_test_key("one")
  126. @defer.inlineCallbacks
  127. def test_make_deferred_yieldable_with_chained_deferreds(
  128. self,
  129. ) -> Generator["defer.Deferred[object]", object, None]:
  130. sentinel_context = current_context()
  131. with LoggingContext("one"):
  132. d1 = make_deferred_yieldable(_chained_deferred_function())
  133. # make sure that the context was reset by make_deferred_yieldable
  134. self.assertIs(current_context(), sentinel_context)
  135. yield d1
  136. # now it should be restored
  137. self._check_test_key("one")
  138. def test_nested_logging_context(self) -> None:
  139. with LoggingContext("foo"):
  140. nested_context = nested_logging_context(suffix="bar")
  141. self.assertEqual(nested_context.name, "foo-bar")
  142. # a function which returns a deferred which has been "called", but
  143. # which had a function which returned another incomplete deferred on
  144. # its callback list, so won't yet call any other new callbacks.
  145. def _chained_deferred_function() -> defer.Deferred:
  146. d = defer.succeed(None)
  147. def cb(res: object) -> defer.Deferred:
  148. d2: defer.Deferred = defer.Deferred()
  149. reactor.callLater(0, d2.callback, res)
  150. return d2
  151. d.addCallback(cb)
  152. return d