|
| 1 | +# Copyright 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 | + |
| 15 | +from twisted.internet import defer |
| 16 | +from twisted.test.proto_helpers import MemoryReactorClock |
| 17 | + |
| 18 | +from synapse.logging.context import ( |
| 19 | + LoggingContext, |
| 20 | + make_deferred_yieldable, |
| 21 | + run_in_background, |
| 22 | +) |
| 23 | +from synapse.logging.opentracing import ( |
| 24 | + start_active_span, |
| 25 | + start_active_span_follows_from, |
| 26 | +) |
| 27 | +from synapse.util import Clock |
| 28 | + |
| 29 | +try: |
| 30 | + from synapse.logging.scopecontextmanager import LogContextScopeManager |
| 31 | +except ImportError: |
| 32 | + LogContextScopeManager = None # type: ignore |
| 33 | + |
| 34 | +try: |
| 35 | + import jaeger_client |
| 36 | +except ImportError: |
| 37 | + jaeger_client = None # type: ignore |
| 38 | + |
| 39 | +from tests.unittest import TestCase |
| 40 | + |
| 41 | + |
| 42 | +class LogContextScopeManagerTestCase(TestCase): |
| 43 | + if LogContextScopeManager is None: |
| 44 | + skip = "Requires opentracing" # type: ignore[unreachable] |
| 45 | + if jaeger_client is None: |
| 46 | + skip = "Requires jaeger_client" # type: ignore[unreachable] |
| 47 | + |
| 48 | + def setUp(self) -> None: |
| 49 | + # since this is a unit test, we don't really want to mess around with the |
| 50 | + # global variables that power opentracing. We create our own tracer instance |
| 51 | + # and test with it. |
| 52 | + |
| 53 | + scope_manager = LogContextScopeManager({}) |
| 54 | + config = jaeger_client.config.Config( |
| 55 | + config={}, service_name="test", scope_manager=scope_manager |
| 56 | + ) |
| 57 | + |
| 58 | + self._reporter = jaeger_client.reporter.InMemoryReporter() |
| 59 | + |
| 60 | + self._tracer = config.create_tracer( |
| 61 | + sampler=jaeger_client.ConstSampler(True), |
| 62 | + reporter=self._reporter, |
| 63 | + ) |
| 64 | + |
| 65 | + def test_start_active_span(self) -> None: |
| 66 | + # the scope manager assumes a logging context of some sort. |
| 67 | + with LoggingContext("root context"): |
| 68 | + self.assertIsNone(self._tracer.active_span) |
| 69 | + |
| 70 | + # start_active_span should start and activate a span. |
| 71 | + scope = start_active_span("span", tracer=self._tracer) |
| 72 | + span = scope.span |
| 73 | + self.assertEqual(self._tracer.active_span, span) |
| 74 | + self.assertIsNotNone(span.start_time) |
| 75 | + |
| 76 | + # entering the context doesn't actually do a whole lot. |
| 77 | + with scope as ctx: |
| 78 | + self.assertIs(ctx, scope) |
| 79 | + self.assertEqual(self._tracer.active_span, span) |
| 80 | + |
| 81 | + # ... but leaving it unsets the active span, and finishes the span. |
| 82 | + self.assertIsNone(self._tracer.active_span) |
| 83 | + self.assertIsNotNone(span.end_time) |
| 84 | + |
| 85 | + # the span should have been reported |
| 86 | + self.assertEqual(self._reporter.get_spans(), [span]) |
| 87 | + |
| 88 | + def test_nested_spans(self) -> None: |
| 89 | + """Starting two spans off inside each other should work""" |
| 90 | + |
| 91 | + with LoggingContext("root context"): |
| 92 | + with start_active_span("root span", tracer=self._tracer) as root_scope: |
| 93 | + self.assertEqual(self._tracer.active_span, root_scope.span) |
| 94 | + |
| 95 | + scope1 = start_active_span( |
| 96 | + "child1", |
| 97 | + tracer=self._tracer, |
| 98 | + ) |
| 99 | + self.assertEqual( |
| 100 | + self._tracer.active_span, scope1.span, "child1 was not activated" |
| 101 | + ) |
| 102 | + self.assertEqual( |
| 103 | + scope1.span.context.parent_id, root_scope.span.context.span_id |
| 104 | + ) |
| 105 | + |
| 106 | + scope2 = start_active_span_follows_from( |
| 107 | + "child2", |
| 108 | + contexts=(scope1,), |
| 109 | + tracer=self._tracer, |
| 110 | + ) |
| 111 | + self.assertEqual(self._tracer.active_span, scope2.span) |
| 112 | + self.assertEqual( |
| 113 | + scope2.span.context.parent_id, scope1.span.context.span_id |
| 114 | + ) |
| 115 | + |
| 116 | + with scope1, scope2: |
| 117 | + pass |
| 118 | + |
| 119 | + # the root scope should be restored |
| 120 | + self.assertEqual(self._tracer.active_span, root_scope.span) |
| 121 | + self.assertIsNotNone(scope2.span.end_time) |
| 122 | + self.assertIsNotNone(scope1.span.end_time) |
| 123 | + |
| 124 | + self.assertIsNone(self._tracer.active_span) |
| 125 | + |
| 126 | + # the spans should be reported in order of their finishing. |
| 127 | + self.assertEqual( |
| 128 | + self._reporter.get_spans(), [scope2.span, scope1.span, root_scope.span] |
| 129 | + ) |
| 130 | + |
| 131 | + def test_overlapping_spans(self) -> None: |
| 132 | + """Overlapping spans which are not neatly nested should work""" |
| 133 | + reactor = MemoryReactorClock() |
| 134 | + clock = Clock(reactor) |
| 135 | + |
| 136 | + scopes = [] |
| 137 | + |
| 138 | + async def task(i: int): |
| 139 | + scope = start_active_span( |
| 140 | + f"task{i}", |
| 141 | + tracer=self._tracer, |
| 142 | + ) |
| 143 | + scopes.append(scope) |
| 144 | + |
| 145 | + self.assertEqual(self._tracer.active_span, scope.span) |
| 146 | + await clock.sleep(4) |
| 147 | + self.assertEqual(self._tracer.active_span, scope.span) |
| 148 | + scope.close() |
| 149 | + |
| 150 | + async def root(): |
| 151 | + with start_active_span("root span", tracer=self._tracer) as root_scope: |
| 152 | + self.assertEqual(self._tracer.active_span, root_scope.span) |
| 153 | + scopes.append(root_scope) |
| 154 | + |
| 155 | + d1 = run_in_background(task, 1) |
| 156 | + await clock.sleep(2) |
| 157 | + d2 = run_in_background(task, 2) |
| 158 | + |
| 159 | + # because we did run_in_background, the active span should still be the |
| 160 | + # root. |
| 161 | + self.assertEqual(self._tracer.active_span, root_scope.span) |
| 162 | + |
| 163 | + await make_deferred_yieldable( |
| 164 | + defer.gatherResults([d1, d2], consumeErrors=True) |
| 165 | + ) |
| 166 | + |
| 167 | + self.assertEqual(self._tracer.active_span, root_scope.span) |
| 168 | + |
| 169 | + with LoggingContext("root context"): |
| 170 | + # start the test off |
| 171 | + d1 = defer.ensureDeferred(root()) |
| 172 | + |
| 173 | + # let the tasks complete |
| 174 | + reactor.pump((2,) * 8) |
| 175 | + |
| 176 | + self.successResultOf(d1) |
| 177 | + self.assertIsNone(self._tracer.active_span) |
| 178 | + |
| 179 | + # the spans should be reported in order of their finishing: task 1, task 2, |
| 180 | + # root. |
| 181 | + self.assertEqual( |
| 182 | + self._reporter.get_spans(), |
| 183 | + [scopes[1].span, scopes[2].span, scopes[0].span], |
| 184 | + ) |
0 commit comments