From 62d04a36ba2d744ee5fda62cf96e25d55369bf07 Mon Sep 17 00:00:00 2001 From: Mohab Usama Date: Fri, 13 Aug 2021 21:54:53 +0200 Subject: [PATCH] Add scope manager support (#55) --- README.rst | 75 +++++++++++- opentracing_utils/decorators.py | 26 ++++- opentracing_utils/libs/_django.py | 11 +- opentracing_utils/libs/_flask.py | 14 ++- opentracing_utils/libs/_requests.py | 13 ++- opentracing_utils/libs/_sqlalchemy.py | 35 +++++- opentracing_utils/span.py | 35 +++++- tests/test_django/app/views.py | 12 ++ tests/test_django/test_django_middleware.py | 26 +++++ tests/test_django/urls.py | 1 + tests/test_flask.py | 33 ++++++ tests/test_requests.py | 75 ++++++++++++ tests/test_span.py | 119 +++++++++++++++++++- tests/test_sqlalchemy.py | 110 ++++++++++++++++++ tests/test_trace.py | 78 +++++++++++++ 15 files changed, 637 insertions(+), 26 deletions(-) diff --git a/README.rst b/README.rst index 322055f..e3f6259 100644 --- a/README.rst +++ b/README.rst @@ -33,8 +33,9 @@ Features ``opentracing-utils`` should provide and aims at the following: * No external dependencies, only `opentracing-python `_. -* No threadlocals. Either pass spans explicitly or fallback to callstack frames inspection! +* No threadlocals. Either use tracer scoper manager, pass spans explicitly or fallback to callstack frames inspection! * Context agnostic, so no external **context implementation** dependency (no Tornado, Flask, Django etc ...). +* Support OpenTracing 2.0 API, with ``scope_manager`` (opentracing-utils>0.21.0). * Try to be less verbose - just add the ``@trace`` decorator. * Could be more verbose when needed, without complexity - just accept ``**kwargs`` and get the span passed to your traced functions via ``@trace(pass_span=True)``. * Support asyncio/async-await coroutines. (drop support for py2.7) @@ -201,8 +202,18 @@ Add ``lightstep`` to the ``dependencies.txt`` of your project. @trace decorator ---------------- +The ``@trace`` decorator supports OpenTracing ``scope_manager`` API (new in opentracing-utils > 0.21.0). + +The order of detecting a parent span goes as the following: + +1. Using ``span_extractor`` if exists. +2. Detect from passed kwargs. +3. Detect ``scope_manager`` active span (opentracing.tracer.active_span). +4. Detect using call stack frames. + .. code-block:: python + import opentracing from opentracing_utils import trace, extract_span_from_kwargs # decorate all your functions that require tracing @@ -243,6 +254,46 @@ Add ``lightstep`` to the ``dependencies.txt`` of your project. # trace_me will have ``epoch`` span as its parent. trace_me() + +@trace using scope_manager +-------------------------- + +In case you need to always use the ``scope_manager``, then you can pass ``use_scope_manager=True`` to ``@trace``. + +.. code-block:: python + + # ``use_scope_manager=True`` will always use scope_manager API for activating the new span. + @trace(operation_name='traced', use_scope_manager=True) + def trace_me_via_scope_manager(): + # @trace will activate the current span using the ``scope_manager``. + current_span = opentracing.tracer.active_span + assert current_span.operation_name == 'traced' + + # @trace will detect parent span from the ``scope_manager`` active span and automatically activate the new nested span. + @trace(operation_name='nested') + def trace_and_detect_scope(): + nested_span = opentracing.tracer.active_span + assert nested_span.operation_name == 'nested' + + trace_and_detect_scope() + + # current_span is back to be the active span. + assert current_span == opentracing.tracer.active_span + + + # If the ``scope_manager`` API is activating the parent span, @trace will detect it and use the ``scope_manager`` for the child span as well. + @trace() + def trace_and_detect_parent_scope(): + current_span = opentracing.tracer.active_span + assert current_span.operation_name == 'trace_and_detect_parent_scope' + + + with opentracing.tracer.start_active_span('top_span', finish_on_close=True): + + # the child span will depend on the ``scope_manager`` to detect the ``top_span`` as the parent span for the following function call. + trace_and_detect_parent_scope() + + Skip Spans ^^^^^^^^^^ @@ -275,7 +326,7 @@ In certain cases you might need to skip certain spans while using the ``@trace`` Broken traces ^^^^^^^^^^^^^ -If you plan to break nested traces, then it is recommended to pass the span to traced functions +If you plan to break nested traces, then it is recommended to pass the span to traced functions. .. code-block:: python @@ -306,6 +357,8 @@ Multiple traces If you plan to use multiple traces then it is better to always pass the span as it is safer/guaranteed. +Note: this should not be an issue if ``scope_manager`` is used. + .. code-block:: python first_span = opentracing.tracer.start_span(operation_name='first_trace') @@ -377,15 +430,18 @@ For tracing `Django `_ applications. You can use # Further options - # Add default tags to all incoming HTTP requests spans + # Add default tags to all incoming HTTP requests spans. OPENTRACING_UTILS_DEFAULT_TAGS = {'my-default-tag': 'tag-value'} - # Add error tag on 4XX responses (default is ``True``) + # Add error tag on 4XX responses (default is ``True``). OPENTRACING_UTILS_ERROR_4XX = False - # Override span operation_name (default is ``view_func.__name__``) + # Override span operation_name (default is ``view_func.__name__``). OPENTRACING_UTILS_OPERATION_NAME_CALLABLE = 'my_app.utils.span_operation_name' + # Use tracer scope manager (default is ``False``). + OPENTRACING_UTILS_USE_SCOPE_MANAGER = True + # Exclude certain requests from OpenTracing OPENTRACING_UTILS_SKIP_SPAN_CALLABLE = 'my_app.utils.skip_span' @@ -430,6 +486,9 @@ For tracing `Flask `_ applications. This utility functio trace_flask(app) + # You can use the ``scope_manager`` for managing all spans. + trace_flask(app, use_scope_manager=True) + # You can add default_tags or optionally treat 4xx responses as not an error (i.e no error tag in span) # trace_flask(app, default_tags={'always-there': True}, error_on_4xx=False) @@ -458,6 +517,9 @@ For tracing `requests `_ client library fo from opentracing_utils import trace_requests trace_requests() # noqa + # You can use the ``scope_manager`` for managing all spans. + trace_requests(use_scope_manager=True) # noqa + # In case you want to include default span tags to be sent with every outgoing request. # trace_requests(default_tags={'account_id': '123'}, set_error_tag=False) @@ -495,6 +557,9 @@ For tracing `SQLAlchemy `_ client librar from opentracing_utils import trace_sqlalchemy trace_sqlalchemy() + # You can use the ``scope_manager`` for managing all spans. + trace_sqlalchemy(use_scope_manager=True) + # You can customize the span operation_name via supplying a callable def get_sqlalchemy_span_op_name(conn, cursor, statement, parameters, context, executemany): # inspect statement and parameters etc... diff --git a/opentracing_utils/decorators.py b/opentracing_utils/decorators.py index e6942a4..d216fa5 100644 --- a/opentracing_utils/decorators.py +++ b/opentracing_utils/decorators.py @@ -1,13 +1,23 @@ import functools +import opentracing + from opentracing_utils.span import get_new_span, adjust_span, get_span_from_kwargs, remove_span_from_kwargs def trace(component=None, operation_name=None, tags=None, use_follows_from=False, pass_span=False, inspect_stack=True, - ignore_parent_span=False, span_extractor=None, skip_span=None): + ignore_parent_span=False, span_extractor=None, skip_span=None, use_scope_manager=False): """ Opentracing tracer decorator. Attempts to extract parent span and create a new span for the decorated function. + The order of parent span inspection: + + 1. Using ``span_extractor``. + 2. Detecting span in kwargs. + 3. Using ``opentracing.tracer.active_span`` managed by the tracer context manager. The new span will be using the + scope manager. + 4. Using call stack frames inspection. + :param commponent: commponent name. :type commponent: str @@ -40,6 +50,9 @@ def trace(component=None, operation_name=None, tags=None, use_follows_from=False :param skip_span: A callable which can be used to determine if the span should be skipped. :type skip_span: Callable[*args, **kwargs] + + :param use_scope_manager: Always use the scope manager when starting the span. + :type use_scope_manager: bool """ def trace_decorator(f): @@ -50,7 +63,7 @@ def wrapper(*args, **kwargs): # Get a new current span wrapping this traced function. # ``get_new_span`` should retrieve parent_span if any! - span_arg_name, current_span = get_new_span( + span_arg_name, using_scope_manager, current_span = get_new_span( f, args, kwargs, inspect_stack=inspect_stack, ignore_parent_span=ignore_parent_span, span_extractor=span_extractor, use_follows_from=use_follows_from) @@ -65,9 +78,16 @@ def wrapper(*args, **kwargs): current_span = adjust_span(current_span, operation_name, component, tags) - with current_span: + with _activate_span(current_span, using_scope_manager or use_scope_manager): return f(*args, **kwargs) return wrapper return trace_decorator + + +def _activate_span(current_span, using_scope_manager): + if using_scope_manager: + return opentracing.tracer.scope_manager.activate(current_span, finish_on_close=True) + + return current_span diff --git a/opentracing_utils/libs/_django.py b/opentracing_utils/libs/_django.py index 06e7f1e..9cd243a 100644 --- a/opentracing_utils/libs/_django.py +++ b/opentracing_utils/libs/_django.py @@ -47,6 +47,8 @@ def __init__(self, get_response=None): else: self._op_name_callable = import_string(op_name_str) if op_name_str else None + self.use_scope_manager = getattr(settings, 'OPENTRACING_UTILS_USE_SCOPE_MANAGER', False) + skip_span_str = getattr(settings, 'OPENTRACING_UTILS_SKIP_SPAN_CALLABLE', '') if callable(skip_span_str): self._skip_span_callable = skip_span_str @@ -81,6 +83,10 @@ def process_view(self, request, view_func, view_args, view_kwargs): except Exception: # pragma: no cover pass + if self.use_scope_manager: + scope = opentracing.tracer.scope_manager.activate(span, finish_on_close=True) + request.current_scope = scope + request.current_span = span def process_exception(self, request, exception): @@ -111,7 +117,10 @@ def _finish_tracing(self, request, response=None, exception=None): if response.status_code >= self._min_error_code: current_span.set_tag('error', True) - current_span.finish() + if hasattr(request, "current_scope"): + request.current_scope.close() + else: + current_span.finish() elif exception: current_span.set_tag('error', True) current_span.log_kv({ diff --git a/opentracing_utils/libs/_flask.py b/opentracing_utils/libs/_flask.py index 3382ee2..595df10 100644 --- a/opentracing_utils/libs/_flask.py +++ b/opentracing_utils/libs/_flask.py @@ -20,7 +20,7 @@ def trace_flask(app, request_attr=DEFUALT_REQUEST_ATTRIBUTES, response_attr=DEFUALT_RESPONSE_ATTRIBUTES, default_tags=None, error_on_4xx=True, mask_url_query=False, mask_url_path=False, operation_name=None, - skip_span=None): + skip_span=None, use_scope_manager=False): """ Add OpenTracing to Flask applications using ``before_request`` & ``after_request``. @@ -56,6 +56,9 @@ def trace_flask(app, request_attr=DEFUALT_REQUEST_ATTRIBUTES, response_attr=DEFU :param skip_span: Callable to determine whether to skip this request span. If returned ``True`` then span will be skipped. This is useful for excluding certain endpoints, like health checks. :type skip_span: Callable[*args, **kwargs] + + :param use_scope_manager: Always use the scope manager when starting the span. Default is ``False``. + :type use_scope_manager: bool """ min_error_code = 400 if error_on_4xx else 500 @@ -112,6 +115,10 @@ def trace_request(): span.set_tag(ot_tags.COMPONENT, 'flask') span.set_tag(ot_tags.SPAN_KIND, ot_tags.SPAN_KIND_RPC_SERVER) + if use_scope_manager: + scope = opentracing.tracer.scope_manager.activate(span, finish_on_close=True) + request.current_scope = scope + # Use ``flask.request`` as in process context. request.current_span = span @@ -130,7 +137,10 @@ def trace_response(response): if response.status_code >= min_error_code: request.current_span.set_tag('error', True) - request.current_span.finish() + if hasattr(request, "current_scope"): + request.current_scope.close() + else: + request.current_span.finish() finally: return response diff --git a/opentracing_utils/libs/_requests.py b/opentracing_utils/libs/_requests.py index 750be39..dab9c9b 100644 --- a/opentracing_utils/libs/_requests.py +++ b/opentracing_utils/libs/_requests.py @@ -28,7 +28,7 @@ def trace_requests(default_tags=None, set_error_tag=True, mask_url_query=True, - mask_url_path=False, ignore_url_patterns=None, span_extractor=None): + mask_url_path=False, ignore_url_patterns=None, span_extractor=None, use_scope_manager=False): """Patch requests library with OpenTracing support. :param default_tags: Default span tags to included with every outgoing request. @@ -48,6 +48,9 @@ def trace_requests(default_tags=None, set_error_tag=True, mask_url_query=True, :param span_extractor: Callable to return the parent span. :type span_extractor: Callable[*args, **kwargs] + + :param use_scope_manager: Always use the scope manager when starting the span. + :type use_scope_manager: bool """ def skip_span_matcher(http_adapter_obj, request, **kwargs): if ignore_url_patterns is None: @@ -58,7 +61,13 @@ def skip_span_matcher(http_adapter_obj, request, **kwargs): return False - @trace(pass_span=True, tags=default_tags, skip_span=skip_span_matcher, span_extractor=span_extractor) + @trace( + pass_span=True, + tags=default_tags, + skip_span=skip_span_matcher, + span_extractor=span_extractor, + use_scope_manager=use_scope_manager + ) def requests_send_wrapper(self, request, **kwargs): if ignore_url_patterns is not None: if any(re.match(pattern, request.url) for pattern in ignore_url_patterns): diff --git a/opentracing_utils/libs/_sqlalchemy.py b/opentracing_utils/libs/_sqlalchemy.py index f861568..d4c9239 100644 --- a/opentracing_utils/libs/_sqlalchemy.py +++ b/opentracing_utils/libs/_sqlalchemy.py @@ -10,7 +10,14 @@ from opentracing_utils.span import get_parent_span -def trace_sqlalchemy(operation_name=None, span_extractor=None, set_error_tag=False, skip_span=None, enrich_span=None): +def trace_sqlalchemy( + operation_name=None, + span_extractor=None, + set_error_tag=False, + skip_span=None, + enrich_span=None, + use_scope_manager=False +): """ Trace Sqlalchemy database queries. @@ -31,6 +38,9 @@ def trace_sqlalchemy(operation_name=None, span_extractor=None, set_error_tag=Fal :param enrich_span: Callable to enrich the span with additional data. :type enrich_span: Callable[span, conn, cursor, statement, parameters, context, executemany] + + :param use_scope_manager: Always use the scope manager when starting the span. + :type use_scope_manager: bool """ @listens_for(Engine, 'before_cursor_execute') @@ -38,9 +48,17 @@ def trace_before_cursor_execute(conn, cursor, statement, parameters, context, ex if callable(skip_span) and skip_span(conn, cursor, statement, parameters, context, executemany): return - if callable(span_extractor): + parent_span = None + using_scope_manager = False + try: + parent_span = opentracing.tracer.active_span + using_scope_manager = True if parent_span else False + except AttributeError: + pass + + if not parent_span and callable(span_extractor): parent_span = span_extractor(conn, cursor, statement, parameters, context, executemany) - else: + elif not parent_span: _, parent_span = get_parent_span() if context: @@ -60,11 +78,17 @@ def trace_before_cursor_execute(conn, cursor, statement, parameters, context, ex if callable(enrich_span): enrich_span(query_span, conn, cursor, statement, parameters, context, executemany) + if use_scope_manager or using_scope_manager: + scope = opentracing.tracer.scope_manager.activate(query_span, finish_on_close=True) + context._query_scope = scope + context._query_span = query_span @listens_for(Engine, 'after_cursor_execute') def tarce_after_cursor_execute(conn, cursor, statement, parameters, context, executemany): - if hasattr(context, '_query_span'): + if hasattr(context, '_query_scope'): + context._query_scope.close() + elif hasattr(context, '_query_span'): context._query_span.finish() @listens_for(Engine, 'handle_error') @@ -76,4 +100,7 @@ def trace_handle_error(exception_context): if set_error_tag: context._query_span.set_tag('error', True) + if hasattr(context, '_query_scope'): + context._query_scope.close() + else: context._query_span.finish() diff --git a/opentracing_utils/span.py b/opentracing_utils/span.py index 6d494eb..ceae10f 100644 --- a/opentracing_utils/span.py +++ b/opentracing_utils/span.py @@ -17,7 +17,8 @@ def get_new_span( f, func_args, func_kwargs, operation_name=None, inspect_stack=True, ignore_parent_span=False, span_extractor=None, use_follows_from=False): parent_span = None - span_arg_name = DEFAULT_SPAN_ARG_NAME + using_scope_manager = False + span_arg_name = None if not ignore_parent_span: if callable(span_extractor): @@ -27,7 +28,21 @@ def get_new_span( logger.exception('Failed to extract span from: {}'.format(span_extractor.__name__)) if not parent_span: - span_arg_name, parent_span = get_parent_span(inspect_stack=inspect_stack, **func_kwargs) + span_arg_name, parent_span = get_span_from_kwargs(**func_kwargs) + + if not parent_span: + try: + # We try inspecting ``active_span`` managed by ``tracer.scope_manager``. + parent_span = opentracing.tracer.active_span + using_scope_manager = True if parent_span else False + except AttributeError: + # Old opentracing lib! + pass + + # Finally, try to inspect call stack frames. + if not parent_span: + span_arg_name, parent_span = get_parent_span( + inspect_stack=inspect_stack, inspect_kwargs=False, **func_kwargs) op_name = f.__name__ if not operation_name else operation_name @@ -35,7 +50,13 @@ def get_new_span( if parent_span: references = [follows_from(parent_span.context)] if use_follows_from else [child_of(parent_span.context)] - return span_arg_name, opentracing.tracer.start_span(operation_name=op_name, references=references) + span_arg_name = span_arg_name or DEFAULT_SPAN_ARG_NAME + + return ( + span_arg_name, + using_scope_manager, + opentracing.tracer.start_span(operation_name=op_name, references=references) + ) def adjust_span(span, operation_name, component, tags): @@ -86,8 +107,12 @@ def inspect_span_from_stack(depth=100): return span -def get_parent_span(inspect_stack=True, **kwargs): - span_arg_name, parent_span = get_span_from_kwargs(**kwargs) +def get_parent_span(inspect_stack=True, inspect_kwargs=True, **kwargs): + span_arg_name = DEFAULT_SPAN_ARG_NAME + parent_span = None + + if inspect_kwargs: + span_arg_name, parent_span = get_span_from_kwargs(**kwargs) if not parent_span and inspect_stack: span_arg_name = DEFAULT_SPAN_ARG_NAME diff --git a/tests/test_django/app/views.py b/tests/test_django/app/views.py index 014c38b..07b67ee 100644 --- a/tests/test_django/app/views.py +++ b/tests/test_django/app/views.py @@ -1,5 +1,7 @@ from django.http import HttpResponse +import opentracing + from opentracing_utils import trace, extract_span_from_django_request, extract_span_from_kwargs @@ -25,3 +27,13 @@ def nested(request, *args, **kwargs): current_span.set_tag('nested', True) return HttpResponse('NESTED') + + +@trace(operation_name='nested_scope_call', pass_span=True) +def nested_scope(request, *args, **kwargs): + current_span = opentracing.tracer.active_span + + with opentracing.tracer.start_active_span("child_span", child_of=current_span.context): + pass + + return HttpResponse('NESTED SCOPE') diff --git a/tests/test_django/test_django_middleware.py b/tests/test_django/test_django_middleware.py index b1e61a1..68688fd 100644 --- a/tests/test_django/test_django_middleware.py +++ b/tests/test_django/test_django_middleware.py @@ -79,6 +79,32 @@ def test_request_nested(client): assert recorder.spans[0].parent_id == recorder.spans[1].context.span_id +@pytest.mark.skipif(six.PY2, reason='') +def test_request_nested_scope(client, settings): + recorder = get_recorder() + + settings.OPENTRACING_UTILS_USE_SCOPE_MANAGER = True + + response = client.get('/nested-scope') + assert response.content == b'NESTED SCOPE' + + assert len(recorder.spans) == 3 + + assert recorder.spans[2].operation_name == 'nested_scope' + assert recorder.spans[2].tags[tags.COMPONENT] == 'django' + assert recorder.spans[2].tags[tags.HTTP_URL] == '/nested-scope' + assert recorder.spans[2].tags[tags.HTTP_METHOD] == 'GET' + assert recorder.spans[2].tags[tags.HTTP_STATUS_CODE] == 200 + + assert recorder.spans[1].operation_name == 'nested_scope_call' + assert recorder.spans[1].context.trace_id == recorder.spans[2].context.trace_id + assert recorder.spans[1].parent_id == recorder.spans[2].context.span_id + + assert recorder.spans[0].operation_name == 'child_span' + assert recorder.spans[0].context.trace_id == recorder.spans[1].context.trace_id + assert recorder.spans[0].parent_id == recorder.spans[1].context.span_id + + @pytest.mark.skipif(six.PY2, reason='') def test_request_user(client): recorder = get_recorder() diff --git a/tests/test_django/urls.py b/tests/test_django/urls.py index dd76d0d..61a73f2 100644 --- a/tests/test_django/urls.py +++ b/tests/test_django/urls.py @@ -8,5 +8,6 @@ url(r'^user', views.user, name='user'), url(r'^error', views.error, name='error'), url(r'^bad', views.bad_request, name='bad'), + url(r'^nested-scope', views.nested_scope, name='nested_scope'), url(r'^nested', views.nested, name='nested'), ] diff --git a/tests/test_flask.py b/tests/test_flask.py index 823a076..720f4f0 100644 --- a/tests/test_flask.py +++ b/tests/test_flask.py @@ -67,6 +67,39 @@ def test_trace_flask(monkeypatch): assert recorder.spans[0].tags[ot_tags.HTTP_STATUS_CODE] == '200' +@pytest.mark.skipif(skip_flask, reason='Flask import failed - probably due to messed up futures dependency!') +def test_trace_flask_with_use_scope_manager(monkeypatch): + app = get_flask_app() + recorder = get_recorder() + + trace_flask(app, use_scope_manager=True) + + trace_id = '' + root_span_id = '' + + with app.app_context(): + def assert_scope_span(): + span = extract_span_from_flask_request() + assert span is not None + + assert opentracing.tracer.active_span is not None + assert opentracing.tracer.active_span == span + + return '{},{}'.format(span.context.trace_id, span.context.span_id) + + app.add_url_rule('/get-span', view_func=assert_scope_span) + + client = app.test_client() + + r = client.get('/get-span') + trace_id, root_span_id = r.get_data(as_text=True).split(',') + + assert len(recorder.spans) == 1 + + assert trace_id == str(recorder.spans[-1].context.trace_id) + assert root_span_id == str(recorder.spans[-1].context.span_id) + + @pytest.mark.skipif(skip_flask, reason='Flask import failed - probably due to messed up futures dependency!') def test_trace_flask_operation_name(monkeypatch): app = get_flask_app() diff --git a/tests/test_requests.py b/tests/test_requests.py index bd2ed77..0d8ca76 100644 --- a/tests/test_requests.py +++ b/tests/test_requests.py @@ -48,6 +48,13 @@ def send_request_mock(self, request, **kwargs): return send_request_mock +def assert_send_request_mock_scope_active(resp): + def send_request_mock(self, request, **kwargs): + assert opentracing.tracer.active_span is not None + return resp + return send_request_mock + + @pytest.mark.parametrize('status_code', (200, 302, 400, 500)) def test_trace_requests(monkeypatch, status_code): resp = Response() @@ -93,6 +100,51 @@ def f1(): assert recorder.spans[0].tags['error'] is True +@pytest.mark.parametrize('status_code', (200, 302, 400, 500)) +def test_trace_requests_scope_active(monkeypatch, status_code): + resp = Response() + resp.status_code = status_code + resp.url = URL + + monkeypatch.setattr('opentracing_utils.libs._requests.__requests_http_send', assert_send_request_mock(resp)) + + @trace() + def f1(): + pass + + recorder = Recorder() + t = BasicTracer(recorder=recorder) + t.register_required_propagators() + opentracing.tracer = t + + top_span = None + with opentracing.tracer.start_active_span(operation_name='top_span', finish_on_close=True) as top_scope: + top_span = top_scope.span + response = requests.get(URL, headers={CUSTOM_HEADER: CUSTOM_HEADER_VALUE}) + + f1() + + assert len(recorder.spans) == 3 + + assert recorder.spans[0].context.trace_id == top_span.context.trace_id + assert recorder.spans[0].parent_id == recorder.spans[-1].context.span_id + + assert recorder.spans[-1].operation_name == 'top_span' + + assert response.status_code == resp.status_code + assert recorder.spans[0].tags[tags.HTTP_STATUS_CODE] == resp.status_code + assert recorder.spans[0].tags[tags.HTTP_URL] == URL + assert recorder.spans[0].tags[tags.HTTP_METHOD] == 'GET' + assert recorder.spans[0].tags[tags.SPAN_KIND] == tags.SPAN_KIND_RPC_CLIENT + assert recorder.spans[0].tags[tags.PEER_HOSTNAME] == 'example.com' + assert recorder.spans[0].tags['timeout'] is None + assert recorder.spans[0].tags[tags.COMPONENT] == 'requests' + assert recorder.spans[0].operation_name == '{}_get'.format(OPERATION_NAME_PREFIX) + + if status_code >= 400: + assert recorder.spans[0].tags['error'] is True + + @pytest.mark.parametrize('timeout', (None, 5, (1, 10))) def test_trace_requests_timeout(monkeypatch, timeout): resp = Response() @@ -133,6 +185,29 @@ def test_trace_requests_with_ignore_url_pattern(monkeypatch): assert response.status_code == resp.status_code +def test_trace_requests_with_use_scope_manager(monkeypatch): + resp = Response() + resp.status_code = 200 + resp.url = URL + + recorder = Recorder() + t = BasicTracer(recorder=recorder) + t.register_required_propagators() + opentracing.tracer = t + + trace_requests(use_scope_manager=True) + + monkeypatch.setattr( + 'opentracing_utils.libs._requests.__requests_http_send', + assert_send_request_mock_scope_active(resp) + ) + + response = requests.get(URL, headers={CUSTOM_HEADER: CUSTOM_HEADER_VALUE}) + assert response.status_code == resp.status_code + + assert len(recorder.spans) == 1 + + def test_trace_requests_do_not_ignore_if_no_match(monkeypatch): resp = Response() resp.status_code = 200 diff --git a/tests/test_span.py b/tests/test_span.py index 061273d..26f7b59 100644 --- a/tests/test_span.py +++ b/tests/test_span.py @@ -18,19 +18,65 @@ import six +class NotActiveScopeManager(opentracing.ScopeManager): + @property + def active(self): + return None + + +class LegacyTracer(BasicTracer): + + @property + def active_span(self): + raise AttributeError + + def test_get_new_span(): + opentracing.tracer = BasicTracer(scope_manager=NotActiveScopeManager()) def f(): pass - span_arg_name, span = get_new_span(f, [], {}) + span_arg_name, using_scope_manager, span = get_new_span(f, [], {}) assert DEFAULT_SPAN_ARG_NAME == span_arg_name assert isinstance(span, opentracing.Span) + assert using_scope_manager is False -def test_get_new_span_with_extractor(): +def test_get_new_span_with_scope_manager(): + # BasicTracer comes with an "active" scope_manager. opentracing.tracer = BasicTracer() + + with opentracing.tracer.start_active_span("parent_span") as scope: + + def f(): + pass + + span_arg_name, using_scope_manager, span = get_new_span(f, [], {}) + + assert DEFAULT_SPAN_ARG_NAME == span_arg_name + assert isinstance(span, opentracing.Span) + assert span.parent_id == scope.span.context.span_id + assert using_scope_manager is True + + +def test_get_new_span_with_scope_manager_no_active_span(): + # BasicTracer comes with an "active" scope_manager. + opentracing.tracer = BasicTracer() + + def f(): + pass + + span_arg_name, using_scope_manager, span = get_new_span(f, [], {}) + + assert DEFAULT_SPAN_ARG_NAME == span_arg_name + assert isinstance(span, opentracing.Span) + assert using_scope_manager is False + + +def test_get_new_span_with_extractor(): + opentracing.tracer = BasicTracer(scope_manager=NotActiveScopeManager()) parent_span = opentracing.tracer.start_span() extractor = MagicMock() @@ -41,10 +87,13 @@ def test_get_new_span_with_extractor(): def f(ctx, extras=True): pass - span_arg_name, span = get_new_span(f, [ctx], {'extras': True}, span_extractor=extractor, inspect_stack=False) + span_arg_name, using_scope_manager, span = get_new_span( + f, [ctx], {'extras': True}, span_extractor=extractor, inspect_stack=False) assert DEFAULT_SPAN_ARG_NAME == span_arg_name assert span.parent_id == parent_span.context.span_id + assert using_scope_manager is False + extractor.assert_called_with(ctx, extras=True) @@ -55,10 +104,11 @@ def f(): def extractor(): raise RuntimeError('Failed') - span_arg_name, span = get_new_span(f, [], {}, span_extractor=extractor) + span_arg_name, using_scope_manager, span = get_new_span(f, [], {}, span_extractor=extractor) assert DEFAULT_SPAN_ARG_NAME == span_arg_name assert span.parent_id is None + assert using_scope_manager is False def test_adjust_span(monkeypatch): @@ -122,3 +172,64 @@ def test_inspect_span_from_stack_does_not_create_reference_cycle(): for previous_generation, current_generation in zip(previous_stats, stats): assert previous_generation['collected'] == current_generation['collected'] + + +def test_get_new_span_with_extractor_with_scope(): + opentracing.tracer = BasicTracer() + parent_span = opentracing.tracer.start_span() + + extractor = MagicMock() + extractor.return_value = parent_span + + ctx = '123' + + def f(ctx, extras=True): + pass + + with opentracing.tracer.start_active_span("ignored_parent", finish_on_close=True): + span_arg_name, using_scope_manager, span = get_new_span( + f, [ctx], {'extras': True}, span_extractor=extractor, inspect_stack=False) + + assert DEFAULT_SPAN_ARG_NAME == span_arg_name + # span_extractor takes precedence. + assert span.parent_id == parent_span.context.span_id + assert using_scope_manager is False + + extractor.assert_called_with(ctx, extras=True) + + +def test_get_new_span_kwargs_with_scope(monkeypatch): + opentracing.tracer = BasicTracer() + parent_span = opentracing.tracer.start_span() + + ctx = '123' + + def f(ctx, extras=True): + pass + + with opentracing.tracer.start_active_span("ignored_parent", finish_on_close=True): + span_arg_name, using_scope_manager, span = get_new_span( + f, [ctx], {'extras': True, 'span': parent_span}, inspect_stack=False) + + assert 'span' == span_arg_name + # span in kwargs takes precedence. + assert span.parent_id == parent_span.context.span_id + assert using_scope_manager is False + + +def test_get_new_span_with_legacy_tracer(): + # Does not have active_span + opentracing.tracer = LegacyTracer() + + with opentracing.tracer.start_span("parent_span") as parent_span: + + def f(): + pass + + span_arg_name, using_scope_manager, span = get_new_span(f, [], {}) + + assert DEFAULT_SPAN_ARG_NAME == span_arg_name + assert isinstance(span, opentracing.Span) + # detected via inspect_stack (i.e. fallback). + assert span.parent_id == parent_span.context.span_id + assert using_scope_manager is False diff --git a/tests/test_sqlalchemy.py b/tests/test_sqlalchemy.py index fa9ec3a..d6688a0 100644 --- a/tests/test_sqlalchemy.py +++ b/tests/test_sqlalchemy.py @@ -18,6 +18,13 @@ from opentracing_utils.libs._sqlalchemy import trace_sqlalchemy +class LegacyTracer(BasicTracer): + + @property + def active_span(self): + raise AttributeError + + Base = declarative_base() @@ -70,6 +77,16 @@ def recorder(): del(recorder) +@pytest.fixture +def legacy_recorder(): + recorder = Recorder() + recorder.spans = [] + # no scope manager support. + opentracing.tracer = LegacyTracer(recorder=recorder) + yield recorder + del(recorder) + + def test_trace_sqlalchemy(monkeypatch, session, recorder): trace_sqlalchemy() @@ -90,6 +107,28 @@ def test_trace_sqlalchemy(monkeypatch, session, recorder): assert_sqlalchemy_span(sql_span, operation_name='insert') +def test_trace_sqlalchemy_scope(monkeypatch, session, recorder): + trace_sqlalchemy() + + top_span = None + with opentracing.tracer.start_active_span(operation_name='top_span') as scope: + top_span = scope.span + user = User(name='Tracer', is_active=True) + session.add(user) + session.commit() + + assert top_span == opentracing.tracer.active_span + + assert len(recorder.spans) == 2 + + sql_span = recorder.spans[0] + assert sql_span.context.trace_id == top_span.context.trace_id + assert sql_span.parent_id == top_span.context.span_id + + assert sql_span.tags['db.statement'] == 'INSERT INTO users (name, is_active) VALUES (?, ?)' + assert_sqlalchemy_span(sql_span, operation_name='insert') + + def test_trace_sqlalchemy_nested(monkeypatch, session, recorder): trace_sqlalchemy() @@ -114,6 +153,33 @@ def create_user(): assert_sqlalchemy_span(sql_span, operation_name='insert') +def test_trace_sqlalchemy_nested_use_scope_manager(monkeypatch, session, recorder): + trace_sqlalchemy(use_scope_manager=True) + + @trace() + def create_user(): + user = User(name='Tracer') + assert opentracing.tracer.active_span.operation_name == 'create_user' + session.add(user) + session.commit() + + top_span = None + with opentracing.tracer.start_active_span(operation_name='top_span') as scope: + top_span = scope.span + create_user() + + assert top_span == opentracing.tracer.active_span + + assert len(recorder.spans) == 3 + + sql_span = recorder.spans[0] + assert sql_span.context.trace_id == top_span.context.trace_id + assert sql_span.parent_id == recorder.spans[1].context.span_id + + assert sql_span.tags['db.statement'] == 'INSERT INTO users (name, is_active) VALUES (?, ?)' + assert_sqlalchemy_span(sql_span, operation_name='insert') + + def test_trace_sqlalchemy_select(monkeypatch, session, recorder): trace_sqlalchemy() @@ -228,6 +294,31 @@ def test_trace_sqlalchemy_error(monkeypatch, session, recorder, error): assert span_error is error +@pytest.mark.parametrize('error', (False, True)) +def test_trace_sqlalchemy_error_scope_manager(monkeypatch, session, recorder, error): + trace_sqlalchemy(set_error_tag=error, use_scope_manager=True) + + top_span = opentracing.tracer.start_span(operation_name='top_span') + + with top_span: + user = User(name='Tracer', is_active=True) + session.add(user) + session.commit() + + with pytest.raises(IntegrityError): + user = User(name='Tracer', is_active=True) + session.add(user) + session.commit() + + # This is ugly but somehow overcomes the inconsistency of spans order! + span_error = False + for span in recorder.spans: + if 'error' in span.tags: + span_error = True + break + assert span_error is error + + def test_trace_sqlalchemy_operation_name(monkeypatch, session, recorder): def get_operation_name(conn, cursor, statement, parameters, context, executemany): @@ -294,3 +385,22 @@ def enrich_span(span, conn, cursor, statement, parameters, context, executemany) assert len(recorder.spans) == 1 assert parameters_tag in recorder.spans[0].tags assert recorder.spans[0].tags[parameters_tag] == (user_name, 1) + + +def test_trace_sqlalchemy_scope_legacy_tracer(monkeypatch, session, legacy_recorder): + trace_sqlalchemy() + + top_span = None + with opentracing.tracer.start_span(operation_name='top_span') as top_span: + user = User(name='Tracer', is_active=True) + session.add(user) + session.commit() + + assert len(legacy_recorder.spans) == 2 + + sql_span = legacy_recorder.spans[0] + assert sql_span.context.trace_id == top_span.context.trace_id + assert sql_span.parent_id == top_span.context.span_id + + assert sql_span.tags['db.statement'] == 'INSERT INTO users (name, is_active) VALUES (?, ?)' + assert_sqlalchemy_span(sql_span, operation_name='insert') diff --git a/tests/test_trace.py b/tests/test_trace.py index 382adb9..17993fd 100644 --- a/tests/test_trace.py +++ b/tests/test_trace.py @@ -425,3 +425,81 @@ def f1(skip_me): assert recorder.spans[0].context.trace_id == test_span.context.trace_id assert recorder.spans[0].parent_id == test_span.context.span_id + + +def test_trace_with_scope_active(): + @trace() + def f1(): + pass + + recorder = Recorder() + opentracing.tracer = BasicTracer(recorder=recorder) + + root_span = None + with opentracing.tracer.start_active_span(operation_name='test_trace', finish_on_close=True) as scope: + root_span = scope.span + f1() + f1() + f1() + + assert len(recorder.spans) == 4 + assert root_span is not None + for span in recorder.spans[:3]: + assert span.context.trace_id == root_span.context.trace_id + assert span.parent_id == root_span.context.span_id + + +def test_trace_with_use_scope_manager(): + + # Always use the scope manager + @trace(use_scope_manager=True) + def f1(): + assert opentracing.tracer.active_span is not None + + recorder = Recorder() + opentracing.tracer = BasicTracer(recorder=recorder) + + f1() + f1() + f1() + + assert len(recorder.spans) == 3 + + +def test_trace_generator_span_kwargs_with_scope_manager(): + + @trace() + def f1(): + list(l2_gen()) + + @trace() + def f2(): + pass + + @trace(pass_span=True) + def l2_gen(**kwargs): + s = extract_span_from_kwargs(**kwargs) + # passing span explicitly should build a correct tree. + f2(span=s) + for i in range(10): + yield i + + recorder = Recorder() + opentracing.tracer = BasicTracer(recorder=recorder) + + test_span = None + with opentracing.tracer.start_active_span(operation_name='test_trace') as scope: + test_span = scope.span + f1() + + assert len(recorder.spans) == 4 + + assert recorder.spans[0].context.trace_id == test_span.context.trace_id + assert recorder.spans[0].parent_id == recorder.spans[2].context.span_id + + # Inside generator takes generator as parent! + assert recorder.spans[1].context.trace_id == test_span.context.trace_id + assert recorder.spans[1].parent_id == recorder.spans[0].context.span_id + + assert recorder.spans[2].context.trace_id == test_span.context.trace_id + assert recorder.spans[2].parent_id == recorder.spans[3].context.span_id