123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279 |
- from typing import cast
- from twisted.internet import defer
- from twisted.test.proto_helpers import MemoryReactorClock
- from synapse.logging.context import (
- LoggingContext,
- make_deferred_yieldable,
- run_in_background,
- )
- from synapse.logging.opentracing import (
- start_active_span,
- start_active_span_follows_from,
- tag_args,
- trace_with_opname,
- )
- from synapse.util import Clock
- try:
- from synapse.logging.scopecontextmanager import LogContextScopeManager
- except ImportError:
- LogContextScopeManager = None
- try:
- import jaeger_client
- except ImportError:
- jaeger_client = None
- import logging
- from tests.unittest import TestCase
- logger = logging.getLogger(__name__)
- class LogContextScopeManagerTestCase(TestCase):
- """
- Test logging contexts and active opentracing spans.
- There's casts throughout this from generic opentracing objects (e.g.
- opentracing.Span) to the ones specific to Jaeger since they have additional
- properties that these tests depend on. This is safe since the only supported
- opentracing backend is Jaeger.
- """
- if LogContextScopeManager is None:
- skip = "Requires opentracing"
- if jaeger_client is None:
- skip = "Requires jaeger_client"
- def setUp(self) -> None:
-
-
-
- scope_manager = LogContextScopeManager()
- config = jaeger_client.config.Config(
- config={}, service_name="test", scope_manager=scope_manager
- )
- self._reporter = jaeger_client.reporter.InMemoryReporter()
- self._tracer = config.create_tracer(
- sampler=jaeger_client.ConstSampler(True),
- reporter=self._reporter,
- )
- def test_start_active_span(self) -> None:
-
- with LoggingContext("root context"):
- self.assertIsNone(self._tracer.active_span)
-
- scope = start_active_span("span", tracer=self._tracer)
- span = cast(jaeger_client.Span, scope.span)
- self.assertEqual(self._tracer.active_span, span)
- self.assertIsNotNone(span.start_time)
-
- with scope as ctx:
- self.assertIs(ctx, scope)
- self.assertEqual(self._tracer.active_span, span)
-
- self.assertIsNone(self._tracer.active_span)
- self.assertIsNotNone(span.end_time)
-
- self.assertEqual(self._reporter.get_spans(), [span])
- def test_nested_spans(self) -> None:
- """Starting two spans off inside each other should work"""
- with LoggingContext("root context"):
- with start_active_span("root span", tracer=self._tracer) as root_scope:
- self.assertEqual(self._tracer.active_span, root_scope.span)
- root_context = cast(jaeger_client.SpanContext, root_scope.span.context)
- scope1 = start_active_span(
- "child1",
- tracer=self._tracer,
- )
- self.assertEqual(
- self._tracer.active_span, scope1.span, "child1 was not activated"
- )
- context1 = cast(jaeger_client.SpanContext, scope1.span.context)
- self.assertEqual(context1.parent_id, root_context.span_id)
- scope2 = start_active_span_follows_from(
- "child2",
- contexts=(scope1,),
- tracer=self._tracer,
- )
- self.assertEqual(self._tracer.active_span, scope2.span)
- context2 = cast(jaeger_client.SpanContext, scope2.span.context)
- self.assertEqual(context2.parent_id, context1.span_id)
- with scope1, scope2:
- pass
-
- self.assertEqual(self._tracer.active_span, root_scope.span)
- span2 = cast(jaeger_client.Span, scope2.span)
- span1 = cast(jaeger_client.Span, scope1.span)
- self.assertIsNotNone(span2.end_time)
- self.assertIsNotNone(span1.end_time)
- self.assertIsNone(self._tracer.active_span)
-
- self.assertEqual(
- self._reporter.get_spans(), [scope2.span, scope1.span, root_scope.span]
- )
- def test_overlapping_spans(self) -> None:
- """Overlapping spans which are not neatly nested should work"""
- reactor = MemoryReactorClock()
- clock = Clock(reactor)
- scopes = []
- async def task(i: int) -> None:
- scope = start_active_span(
- f"task{i}",
- tracer=self._tracer,
- )
- scopes.append(scope)
- self.assertEqual(self._tracer.active_span, scope.span)
- await clock.sleep(4)
- self.assertEqual(self._tracer.active_span, scope.span)
- scope.close()
- async def root() -> None:
- with start_active_span("root span", tracer=self._tracer) as root_scope:
- self.assertEqual(self._tracer.active_span, root_scope.span)
- scopes.append(root_scope)
- d1 = run_in_background(task, 1)
- await clock.sleep(2)
- d2 = run_in_background(task, 2)
-
-
- self.assertEqual(self._tracer.active_span, root_scope.span)
- await make_deferred_yieldable(
- defer.gatherResults([d1, d2], consumeErrors=True)
- )
- self.assertEqual(self._tracer.active_span, root_scope.span)
- with LoggingContext("root context"):
-
- d1 = defer.ensureDeferred(root())
-
- reactor.pump((2,) * 8)
- self.successResultOf(d1)
- self.assertIsNone(self._tracer.active_span)
-
-
- self.assertEqual(
- self._reporter.get_spans(),
- [scopes[1].span, scopes[2].span, scopes[0].span],
- )
- def test_trace_decorator_sync(self) -> None:
- """
- Test whether we can use `@trace_with_opname` (`@trace`) and `@tag_args`
- with sync functions
- """
- with LoggingContext("root context"):
- @trace_with_opname("fixture_sync_func", tracer=self._tracer)
- @tag_args
- def fixture_sync_func() -> str:
- return "foo"
- result = fixture_sync_func()
- self.assertEqual(result, "foo")
-
- self.assertEqual(
- [span.operation_name for span in self._reporter.get_spans()],
- ["fixture_sync_func"],
- )
- def test_trace_decorator_deferred(self) -> None:
- """
- Test whether we can use `@trace_with_opname` (`@trace`) and `@tag_args`
- with functions that return deferreds
- """
- reactor = MemoryReactorClock()
- with LoggingContext("root context"):
- @trace_with_opname("fixture_deferred_func", tracer=self._tracer)
- @tag_args
- def fixture_deferred_func() -> "defer.Deferred[str]":
- d1: defer.Deferred[str] = defer.Deferred()
- d1.callback("foo")
- return d1
- result_d1 = fixture_deferred_func()
-
- reactor.pump((2,) * 8)
- self.assertEqual(self.successResultOf(result_d1), "foo")
-
- self.assertEqual(
- [span.operation_name for span in self._reporter.get_spans()],
- ["fixture_deferred_func"],
- )
- def test_trace_decorator_async(self) -> None:
- """
- Test whether we can use `@trace_with_opname` (`@trace`) and `@tag_args`
- with async functions
- """
- reactor = MemoryReactorClock()
- with LoggingContext("root context"):
- @trace_with_opname("fixture_async_func", tracer=self._tracer)
- @tag_args
- async def fixture_async_func() -> str:
- return "foo"
- d1 = defer.ensureDeferred(fixture_async_func())
-
- reactor.pump((2,) * 8)
- self.assertEqual(self.successResultOf(d1), "foo")
-
- self.assertEqual(
- [span.operation_name for span in self._reporter.get_spans()],
- ["fixture_async_func"],
- )
|