2019-07-18 08:06:54 -06:00
|
|
|
# Copyright 2019 The Matrix.org Foundation C.I.C.
|
2019-07-11 03:36:03 -06:00
|
|
|
#
|
|
|
|
# Licensed under the Apache License, Version 2.0 (the "License");
|
|
|
|
# you may not use this file except in compliance with the License.
|
|
|
|
# You may obtain a copy of the License at
|
|
|
|
#
|
|
|
|
# http://www.apache.org/licenses/LICENSE-2.0
|
|
|
|
#
|
|
|
|
# Unless required by applicable law or agreed to in writing, software
|
|
|
|
# distributed under the License is distributed on an "AS IS" BASIS,
|
|
|
|
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
|
|
|
|
# See the License for the specific language governing permissions and
|
2019-07-23 06:31:16 -06:00
|
|
|
# limitations under the License.
|
2019-07-11 03:36:03 -06:00
|
|
|
|
|
|
|
|
|
|
|
# NOTE
|
|
|
|
# This is a small wrapper around opentracing because opentracing is not currently
|
|
|
|
# packaged downstream (specifically debian). Since opentracing instrumentation is
|
|
|
|
# fairly invasive it was awkward to make it optional. As a result we opted to encapsulate
|
|
|
|
# all opentracing state in these methods which effectively noop if opentracing is
|
|
|
|
# not present. We should strongly consider encouraging the downstream distributers
|
|
|
|
# to package opentracing and making opentracing a full dependency. In order to facilitate
|
|
|
|
# this move the methods have work very similarly to opentracing's and it should only
|
|
|
|
# be a matter of few regexes to move over to opentracing's access patterns proper.
|
|
|
|
|
2019-07-22 04:15:21 -06:00
|
|
|
"""
|
|
|
|
============================
|
|
|
|
Using OpenTracing in Synapse
|
|
|
|
============================
|
|
|
|
|
|
|
|
Python-specific tracing concepts are at https://opentracing.io/guides/python/.
|
|
|
|
Note that Synapse wraps OpenTracing in a small module (this one) in order to make the
|
|
|
|
OpenTracing dependency optional. That means that the access patterns are
|
|
|
|
different to those demonstrated in the OpenTracing guides. However, it is
|
|
|
|
still useful to know, especially if OpenTracing is included as a full dependency
|
|
|
|
in the future or if you are modifying this module.
|
|
|
|
|
|
|
|
|
|
|
|
OpenTracing is encapsulated so that
|
|
|
|
no span objects from OpenTracing are exposed in Synapse's code. This allows
|
|
|
|
OpenTracing to be easily disabled in Synapse and thereby have OpenTracing as
|
|
|
|
an optional dependency. This does however limit the number of modifiable spans
|
|
|
|
at any point in the code to one. From here out references to `opentracing`
|
|
|
|
in the code snippets refer to the Synapses module.
|
2019-08-20 06:56:03 -06:00
|
|
|
Most methods provided in the module have a direct correlation to those provided
|
|
|
|
by opentracing. Refer to docs there for a more in-depth documentation on some of
|
|
|
|
the args and methods.
|
2019-07-22 04:15:21 -06:00
|
|
|
|
|
|
|
Tracing
|
|
|
|
-------
|
|
|
|
|
|
|
|
In Synapse it is not possible to start a non-active span. Spans can be started
|
|
|
|
using the ``start_active_span`` method. This returns a scope (see
|
|
|
|
OpenTracing docs) which is a context manager that needs to be entered and
|
|
|
|
exited. This is usually done by using ``with``.
|
|
|
|
|
|
|
|
.. code-block:: python
|
|
|
|
|
|
|
|
from synapse.logging.opentracing import start_active_span
|
|
|
|
|
|
|
|
with start_active_span("operation name"):
|
|
|
|
# Do something we want to tracer
|
|
|
|
|
|
|
|
Forgetting to enter or exit a scope will result in some mysterious and grievous log
|
|
|
|
context errors.
|
|
|
|
|
|
|
|
At anytime where there is an active span ``opentracing.set_tag`` can be used to
|
|
|
|
set a tag on the current active span.
|
|
|
|
|
|
|
|
Tracing functions
|
|
|
|
-----------------
|
|
|
|
|
2019-08-20 06:56:03 -06:00
|
|
|
Functions can be easily traced using decorators. The name of
|
2019-07-22 04:15:21 -06:00
|
|
|
the function becomes the operation name for the span.
|
|
|
|
|
|
|
|
.. code-block:: python
|
|
|
|
|
2019-08-20 06:56:03 -06:00
|
|
|
from synapse.logging.opentracing import trace
|
2019-07-22 04:15:21 -06:00
|
|
|
|
2019-08-20 06:56:03 -06:00
|
|
|
# Start a span using 'interesting_function' as the operation name
|
2019-07-22 04:15:21 -06:00
|
|
|
@trace
|
2019-08-20 06:56:03 -06:00
|
|
|
def interesting_function(*args, **kwargs):
|
2019-07-22 04:15:21 -06:00
|
|
|
# Does all kinds of cool and expected things
|
|
|
|
return something_usual_and_useful
|
|
|
|
|
|
|
|
|
2022-07-19 12:14:30 -06:00
|
|
|
Operation names can be explicitly set for a function by using ``trace_with_opname``:
|
2019-07-22 04:15:21 -06:00
|
|
|
|
|
|
|
.. code-block:: python
|
|
|
|
|
2022-07-19 12:14:30 -06:00
|
|
|
from synapse.logging.opentracing import trace_with_opname
|
2019-07-22 04:15:21 -06:00
|
|
|
|
2022-07-19 12:14:30 -06:00
|
|
|
@trace_with_opname("a_better_operation_name")
|
2019-08-20 06:56:03 -06:00
|
|
|
def interesting_badly_named_function(*args, **kwargs):
|
2019-07-22 04:15:21 -06:00
|
|
|
# Does all kinds of cool and expected things
|
|
|
|
return something_usual_and_useful
|
|
|
|
|
2019-08-20 06:56:03 -06:00
|
|
|
Setting Tags
|
|
|
|
------------
|
|
|
|
|
|
|
|
To set a tag on the active span do
|
|
|
|
|
|
|
|
.. code-block:: python
|
|
|
|
|
|
|
|
from synapse.logging.opentracing import set_tag
|
|
|
|
|
|
|
|
set_tag(tag_name, tag_value)
|
|
|
|
|
|
|
|
There's a convenient decorator to tag all the args of the method. It uses
|
|
|
|
inspection in order to use the formal parameter names prefixed with 'ARG_' as
|
|
|
|
tag names. It uses kwarg names as tag names without the prefix.
|
|
|
|
|
|
|
|
.. code-block:: python
|
|
|
|
|
|
|
|
from synapse.logging.opentracing import tag_args
|
|
|
|
|
|
|
|
@tag_args
|
|
|
|
def set_fates(clotho, lachesis, atropos, father="Zues", mother="Themis"):
|
|
|
|
pass
|
|
|
|
|
|
|
|
set_fates("the story", "the end", "the act")
|
|
|
|
# This will have the following tags
|
|
|
|
# - ARG_clotho: "the story"
|
|
|
|
# - ARG_lachesis: "the end"
|
|
|
|
# - ARG_atropos: "the act"
|
|
|
|
# - father: "Zues"
|
|
|
|
# - mother: "Themis"
|
2019-07-22 04:15:21 -06:00
|
|
|
|
|
|
|
Contexts and carriers
|
|
|
|
---------------------
|
|
|
|
|
|
|
|
There are a selection of wrappers for injecting and extracting contexts from
|
|
|
|
carriers provided. Unfortunately OpenTracing's three context injection
|
|
|
|
techniques are not adequate for our inject of OpenTracing span-contexts into
|
|
|
|
Twisted's http headers, EDU contents and our database tables. Also note that
|
|
|
|
the binary encoding format mandated by OpenTracing is not actually implemented
|
|
|
|
by jaeger_client v4.0.0 - it will silently noop.
|
|
|
|
Please refer to the end of ``logging/opentracing.py`` for the available
|
|
|
|
injection and extraction methods.
|
|
|
|
|
|
|
|
Homeserver whitelisting
|
|
|
|
-----------------------
|
|
|
|
|
|
|
|
Most of the whitelist checks are encapsulated in the modules's injection
|
|
|
|
and extraction method but be aware that using custom carriers or crossing
|
|
|
|
unchartered waters will require the enforcement of the whitelist.
|
|
|
|
``logging/opentracing.py`` has a ``whitelisted_homeserver`` method which takes
|
|
|
|
in a destination and compares it to the whitelist.
|
|
|
|
|
2019-08-22 11:21:10 -06:00
|
|
|
Most injection methods take a 'destination' arg. The context will only be injected
|
|
|
|
if the destination matches the whitelist or the destination is None.
|
|
|
|
|
2019-07-22 04:15:21 -06:00
|
|
|
=======
|
|
|
|
Gotchas
|
|
|
|
=======
|
|
|
|
|
|
|
|
- Checking whitelists on span propagation
|
|
|
|
- Inserting pii
|
|
|
|
- Forgetting to enter or exit a scope
|
|
|
|
- Span source: make sure that the span you expect to be active across a
|
|
|
|
function call really will be that one. Does the current function have more
|
|
|
|
than one caller? Will all of those calling functions have be in a context
|
|
|
|
with an active span?
|
|
|
|
"""
|
2019-07-18 08:06:54 -06:00
|
|
|
import contextlib
|
2022-06-30 07:05:06 -06:00
|
|
|
import enum
|
2019-07-23 06:31:16 -06:00
|
|
|
import inspect
|
2019-07-18 08:06:54 -06:00
|
|
|
import logging
|
|
|
|
import re
|
|
|
|
from functools import wraps
|
2022-05-27 04:17:33 -06:00
|
|
|
from typing import (
|
|
|
|
TYPE_CHECKING,
|
|
|
|
Any,
|
|
|
|
Callable,
|
|
|
|
Collection,
|
2022-08-09 13:32:33 -06:00
|
|
|
ContextManager,
|
2022-05-27 04:17:33 -06:00
|
|
|
Dict,
|
|
|
|
Generator,
|
|
|
|
Iterable,
|
|
|
|
List,
|
|
|
|
Optional,
|
|
|
|
Pattern,
|
|
|
|
Type,
|
|
|
|
TypeVar,
|
|
|
|
Union,
|
2022-07-21 06:01:52 -06:00
|
|
|
cast,
|
|
|
|
overload,
|
2022-05-27 04:17:33 -06:00
|
|
|
)
|
2019-07-18 08:06:54 -06:00
|
|
|
|
2020-06-17 07:13:41 -06:00
|
|
|
import attr
|
2022-05-27 04:17:33 -06:00
|
|
|
from typing_extensions import ParamSpec
|
2019-07-23 06:31:16 -06:00
|
|
|
|
2019-07-18 08:06:54 -06:00
|
|
|
from twisted.internet import defer
|
2021-12-20 10:45:03 -07:00
|
|
|
from twisted.web.http import Request
|
2021-06-18 04:43:22 -06:00
|
|
|
from twisted.web.http_headers import Headers
|
2019-07-18 08:06:54 -06:00
|
|
|
|
|
|
|
from synapse.config import ConfigError
|
2020-08-20 08:32:33 -06:00
|
|
|
from synapse.util import json_decoder, json_encoder
|
2019-07-18 08:06:54 -06:00
|
|
|
|
2020-04-29 09:23:08 -06:00
|
|
|
if TYPE_CHECKING:
|
2020-07-03 12:02:19 -06:00
|
|
|
from synapse.http.site import SynapseRequest
|
2020-07-05 09:32:02 -06:00
|
|
|
from synapse.server import HomeServer
|
2020-04-29 09:23:08 -06:00
|
|
|
|
2019-08-22 11:08:07 -06:00
|
|
|
# Helper class
|
|
|
|
|
2022-09-09 10:30:06 -06:00
|
|
|
# Matches the number suffix in an instance name like "matrix.org client_reader-8"
|
|
|
|
STRIP_INSTANCE_NUMBER_SUFFIX_REGEX = re.compile(r"[_-]?\d+$")
|
|
|
|
|
2019-08-22 11:08:07 -06:00
|
|
|
|
2020-09-04 04:54:56 -06:00
|
|
|
class _DummyTagNames:
|
2019-08-22 11:08:07 -06:00
|
|
|
"""wrapper of opentracings tags. We need to have them if we
|
|
|
|
want to reference them without opentracing around. Clearly they
|
|
|
|
should never actually show up in a trace. `set_tags` overwrites
|
|
|
|
these with the correct ones."""
|
|
|
|
|
|
|
|
INVALID_TAG = "invalid-tag"
|
|
|
|
COMPONENT = INVALID_TAG
|
|
|
|
DATABASE_INSTANCE = INVALID_TAG
|
|
|
|
DATABASE_STATEMENT = INVALID_TAG
|
|
|
|
DATABASE_TYPE = INVALID_TAG
|
|
|
|
DATABASE_USER = INVALID_TAG
|
|
|
|
ERROR = INVALID_TAG
|
|
|
|
HTTP_METHOD = INVALID_TAG
|
|
|
|
HTTP_STATUS_CODE = INVALID_TAG
|
|
|
|
HTTP_URL = INVALID_TAG
|
|
|
|
MESSAGE_BUS_DESTINATION = INVALID_TAG
|
|
|
|
PEER_ADDRESS = INVALID_TAG
|
|
|
|
PEER_HOSTNAME = INVALID_TAG
|
|
|
|
PEER_HOST_IPV4 = INVALID_TAG
|
|
|
|
PEER_HOST_IPV6 = INVALID_TAG
|
|
|
|
PEER_PORT = INVALID_TAG
|
|
|
|
PEER_SERVICE = INVALID_TAG
|
|
|
|
SAMPLING_PRIORITY = INVALID_TAG
|
|
|
|
SERVICE = INVALID_TAG
|
|
|
|
SPAN_KIND = INVALID_TAG
|
|
|
|
SPAN_KIND_CONSUMER = INVALID_TAG
|
|
|
|
SPAN_KIND_PRODUCER = INVALID_TAG
|
|
|
|
SPAN_KIND_RPC_CLIENT = INVALID_TAG
|
|
|
|
SPAN_KIND_RPC_SERVER = INVALID_TAG
|
|
|
|
|
|
|
|
|
2019-07-11 03:36:03 -06:00
|
|
|
try:
|
|
|
|
import opentracing
|
2021-12-23 04:47:24 -07:00
|
|
|
import opentracing.tags
|
2019-08-22 11:08:07 -06:00
|
|
|
|
|
|
|
tags = opentracing.tags
|
2019-07-11 03:36:03 -06:00
|
|
|
except ImportError:
|
2021-12-20 05:18:09 -07:00
|
|
|
opentracing = None # type: ignore[assignment]
|
|
|
|
tags = _DummyTagNames # type: ignore[assignment]
|
2019-07-11 03:36:03 -06:00
|
|
|
try:
|
|
|
|
from jaeger_client import Config as JaegerConfig
|
2020-07-05 09:32:02 -06:00
|
|
|
|
2019-07-11 03:36:03 -06:00
|
|
|
from synapse.logging.scopecontextmanager import LogContextScopeManager
|
|
|
|
except ImportError:
|
2019-09-12 10:29:55 -06:00
|
|
|
JaegerConfig = None # type: ignore
|
|
|
|
LogContextScopeManager = None # type: ignore
|
2019-07-11 03:36:03 -06:00
|
|
|
|
|
|
|
|
2020-06-17 07:13:41 -06:00
|
|
|
try:
|
|
|
|
from rust_python_jaeger_reporter import Reporter
|
|
|
|
|
2021-09-13 06:54:01 -06:00
|
|
|
# jaeger-client 4.7.0 requires that reporters inherit from BaseReporter, which
|
|
|
|
# didn't exist before that version.
|
|
|
|
try:
|
|
|
|
from jaeger_client.reporter import BaseReporter
|
|
|
|
except ImportError:
|
|
|
|
|
|
|
|
class BaseReporter: # type: ignore[no-redef]
|
|
|
|
pass
|
|
|
|
|
2022-01-19 05:39:11 -07:00
|
|
|
@attr.s(slots=True, frozen=True, auto_attribs=True)
|
2021-09-13 06:54:01 -06:00
|
|
|
class _WrappedRustReporter(BaseReporter):
|
2020-06-17 07:13:41 -06:00
|
|
|
"""Wrap the reporter to ensure `report_span` never throws."""
|
|
|
|
|
2022-01-13 06:49:28 -07:00
|
|
|
_reporter: Reporter = attr.Factory(Reporter)
|
2020-06-17 07:13:41 -06:00
|
|
|
|
2022-06-30 07:05:06 -06:00
|
|
|
def set_process(self, *args: Any, **kwargs: Any) -> None:
|
2020-06-17 07:13:41 -06:00
|
|
|
return self._reporter.set_process(*args, **kwargs)
|
|
|
|
|
2022-05-27 04:17:33 -06:00
|
|
|
def report_span(self, span: "opentracing.Span") -> None:
|
2020-06-17 07:13:41 -06:00
|
|
|
try:
|
|
|
|
return self._reporter.report_span(span)
|
|
|
|
except Exception:
|
|
|
|
logger.exception("Failed to report span")
|
|
|
|
|
2021-07-15 04:02:43 -06:00
|
|
|
RustReporter: Optional[Type[_WrappedRustReporter]] = _WrappedRustReporter
|
2020-06-17 07:13:41 -06:00
|
|
|
except ImportError:
|
|
|
|
RustReporter = None
|
|
|
|
|
|
|
|
|
2019-07-11 03:36:03 -06:00
|
|
|
logger = logging.getLogger(__name__)
|
|
|
|
|
|
|
|
|
2021-04-01 10:08:21 -06:00
|
|
|
class SynapseTags:
|
2022-12-06 02:52:55 -07:00
|
|
|
# The message ID of any to_device EDU processed
|
|
|
|
TO_DEVICE_EDU_ID = "to_device.edu_id"
|
|
|
|
|
|
|
|
# Details about to-device messages
|
|
|
|
TO_DEVICE_TYPE = "to_device.type"
|
|
|
|
TO_DEVICE_SENDER = "to_device.sender"
|
|
|
|
TO_DEVICE_RECIPIENT = "to_device.recipient"
|
|
|
|
TO_DEVICE_RECIPIENT_DEVICE = "to_device.recipient_device"
|
|
|
|
TO_DEVICE_MSGID = "to_device.msgid" # client-generated ID
|
2021-04-01 10:08:21 -06:00
|
|
|
|
|
|
|
# Whether the sync response has new data to be returned to the client.
|
|
|
|
SYNC_RESULT = "sync.new_data"
|
|
|
|
|
2022-09-09 10:31:37 -06:00
|
|
|
INSTANCE_NAME = "instance_name"
|
|
|
|
|
2021-05-28 09:14:08 -06:00
|
|
|
# incoming HTTP request ID (as written in the logs)
|
|
|
|
REQUEST_ID = "request_id"
|
|
|
|
|
|
|
|
# HTTP request tag (used to distinguish full vs incremental syncs, etc)
|
|
|
|
REQUEST_TAG = "request_tag"
|
|
|
|
|
2021-06-03 09:31:56 -06:00
|
|
|
# Text description of a database transaction
|
|
|
|
DB_TXN_DESC = "db.txn_desc"
|
|
|
|
|
|
|
|
# Uniqueish ID of a database transaction
|
|
|
|
DB_TXN_ID = "db.txn_id"
|
|
|
|
|
2022-04-07 06:18:29 -06:00
|
|
|
# The name of the external cache
|
|
|
|
CACHE_NAME = "cache.name"
|
|
|
|
|
2023-01-31 05:43:20 -07:00
|
|
|
# Boolean. Present on /v2/send_join requests, omitted from all others.
|
|
|
|
# True iff partial state was requested and we provided (or intended to provide)
|
|
|
|
# partial state in the response.
|
|
|
|
SEND_JOIN_RESPONSE_IS_PARTIAL_STATE = "send_join.partial_state_response"
|
|
|
|
|
2022-08-16 11:39:40 -06:00
|
|
|
# Used to tag function arguments
|
|
|
|
#
|
|
|
|
# Tag a named arg. The name of the argument should be appended to this prefix.
|
|
|
|
FUNC_ARG_PREFIX = "ARG."
|
|
|
|
# Tag extra variadic number of positional arguments (`def foo(first, second, *extras)`)
|
|
|
|
FUNC_ARGS = "args"
|
|
|
|
# Tag keyword args
|
|
|
|
FUNC_KWARGS = "kwargs"
|
|
|
|
|
|
|
|
# Some intermediate result that's interesting to the function. The label for
|
|
|
|
# the result should be appended to this prefix.
|
|
|
|
RESULT_PREFIX = "RESULT."
|
|
|
|
|
2021-04-01 10:08:21 -06:00
|
|
|
|
2021-06-16 04:41:15 -06:00
|
|
|
class SynapseBaggage:
|
|
|
|
FORCE_TRACING = "synapse-force-tracing"
|
|
|
|
|
|
|
|
|
2019-07-23 06:31:16 -06:00
|
|
|
# Block everything by default
|
|
|
|
# A regex which matches the server_names to expose traces for.
|
|
|
|
# None means 'block everything'.
|
2021-07-15 04:02:43 -06:00
|
|
|
_homeserver_whitelist: Optional[Pattern[str]] = None
|
2019-07-11 03:36:03 -06:00
|
|
|
|
2019-07-23 06:31:16 -06:00
|
|
|
# Util methods
|
2019-07-11 03:36:03 -06:00
|
|
|
|
2022-06-30 07:05:06 -06:00
|
|
|
|
|
|
|
class _Sentinel(enum.Enum):
|
|
|
|
# defining a sentinel in this way allows mypy to correctly handle the
|
|
|
|
# type of a dictionary lookup.
|
|
|
|
sentinel = object()
|
2021-06-16 04:41:15 -06:00
|
|
|
|
2019-07-11 03:36:03 -06:00
|
|
|
|
2022-05-27 04:17:33 -06:00
|
|
|
P = ParamSpec("P")
|
|
|
|
R = TypeVar("R")
|
2022-07-21 06:01:52 -06:00
|
|
|
T = TypeVar("T")
|
2022-05-27 04:17:33 -06:00
|
|
|
|
|
|
|
|
|
|
|
def only_if_tracing(func: Callable[P, R]) -> Callable[P, Optional[R]]:
|
2019-09-05 10:33:29 -06:00
|
|
|
"""Executes the function only if we're tracing. Otherwise returns None."""
|
2019-07-11 03:36:03 -06:00
|
|
|
|
|
|
|
@wraps(func)
|
2022-05-27 04:17:33 -06:00
|
|
|
def _only_if_tracing_inner(*args: P.args, **kwargs: P.kwargs) -> Optional[R]:
|
2019-07-11 03:36:03 -06:00
|
|
|
if opentracing:
|
|
|
|
return func(*args, **kwargs)
|
|
|
|
else:
|
2022-05-27 04:17:33 -06:00
|
|
|
return None
|
2019-07-11 03:36:03 -06:00
|
|
|
|
|
|
|
return _only_if_tracing_inner
|
|
|
|
|
|
|
|
|
2022-07-21 06:01:52 -06:00
|
|
|
@overload
|
|
|
|
def ensure_active_span(
|
|
|
|
message: str,
|
|
|
|
) -> Callable[[Callable[P, R]], Callable[P, Optional[R]]]:
|
|
|
|
...
|
|
|
|
|
|
|
|
|
|
|
|
@overload
|
|
|
|
def ensure_active_span(
|
|
|
|
message: str, ret: T
|
|
|
|
) -> Callable[[Callable[P, R]], Callable[P, Union[T, R]]]:
|
|
|
|
...
|
|
|
|
|
|
|
|
|
|
|
|
def ensure_active_span(
|
|
|
|
message: str, ret: Optional[T] = None
|
|
|
|
) -> Callable[[Callable[P, R]], Callable[P, Union[Optional[T], R]]]:
|
2019-09-05 10:33:29 -06:00
|
|
|
"""Executes the operation only if opentracing is enabled and there is an active span.
|
|
|
|
If there is no active span it logs message at the error level.
|
|
|
|
|
|
|
|
Args:
|
2022-06-30 07:05:06 -06:00
|
|
|
message: Message which fills in "There was no active span when trying to %s"
|
2019-09-05 10:33:29 -06:00
|
|
|
in the error log if there is no active span and opentracing is enabled.
|
2022-07-21 06:01:52 -06:00
|
|
|
ret: return value if opentracing is None or there is no active span.
|
2019-09-05 10:33:29 -06:00
|
|
|
|
2022-07-21 06:01:52 -06:00
|
|
|
Returns:
|
|
|
|
The result of the func, falling back to ret if opentracing is disabled or there
|
2019-09-05 10:33:29 -06:00
|
|
|
was no active span.
|
|
|
|
"""
|
|
|
|
|
2022-07-21 06:01:52 -06:00
|
|
|
def ensure_active_span_inner_1(
|
|
|
|
func: Callable[P, R]
|
|
|
|
) -> Callable[P, Union[Optional[T], R]]:
|
2019-09-05 10:33:29 -06:00
|
|
|
@wraps(func)
|
2022-07-21 06:01:52 -06:00
|
|
|
def ensure_active_span_inner_2(
|
|
|
|
*args: P.args, **kwargs: P.kwargs
|
|
|
|
) -> Union[Optional[T], R]:
|
2019-09-05 10:33:29 -06:00
|
|
|
if not opentracing:
|
|
|
|
return ret
|
|
|
|
|
|
|
|
if not opentracing.tracer.active_span:
|
|
|
|
logger.error(
|
|
|
|
"There was no active span when trying to %s."
|
|
|
|
" Did you forget to start one or did a context slip?",
|
|
|
|
message,
|
2021-10-05 05:23:25 -06:00
|
|
|
stack_info=True,
|
2019-09-05 10:33:29 -06:00
|
|
|
)
|
|
|
|
|
|
|
|
return ret
|
|
|
|
|
|
|
|
return func(*args, **kwargs)
|
|
|
|
|
|
|
|
return ensure_active_span_inner_2
|
|
|
|
|
|
|
|
return ensure_active_span_inner_1
|
|
|
|
|
|
|
|
|
2019-07-23 06:31:16 -06:00
|
|
|
# Setup
|
2019-07-11 03:36:03 -06:00
|
|
|
|
|
|
|
|
2022-05-27 04:17:33 -06:00
|
|
|
def init_tracer(hs: "HomeServer") -> None:
|
2019-07-11 03:36:03 -06:00
|
|
|
"""Set the whitelists and initialise the JaegerClient tracer"""
|
|
|
|
global opentracing
|
2021-09-24 05:25:21 -06:00
|
|
|
if not hs.config.tracing.opentracer_enabled:
|
2019-07-11 03:36:03 -06:00
|
|
|
# We don't have a tracer
|
2021-12-20 05:18:09 -07:00
|
|
|
opentracing = None # type: ignore[assignment]
|
2019-07-11 03:36:03 -06:00
|
|
|
return
|
|
|
|
|
2019-07-18 08:06:54 -06:00
|
|
|
if not opentracing or not JaegerConfig:
|
|
|
|
raise ConfigError(
|
|
|
|
"The server has been configured to use opentracing but opentracing is not "
|
|
|
|
"installed."
|
2019-07-11 03:36:03 -06:00
|
|
|
)
|
|
|
|
|
2019-07-23 08:46:04 -06:00
|
|
|
# Pull out the jaeger config if it was given. Otherwise set it to something sensible.
|
|
|
|
# See https://github.com/jaegertracing/jaeger-client-python/blob/master/jaeger_client/config.py
|
|
|
|
|
2021-09-24 05:25:21 -06:00
|
|
|
set_homeserver_whitelist(hs.config.tracing.opentracer_whitelist)
|
2019-07-23 08:46:04 -06:00
|
|
|
|
2021-06-04 02:25:33 -06:00
|
|
|
from jaeger_client.metrics.prometheus import PrometheusMetricsFactory
|
|
|
|
|
2022-09-09 10:30:06 -06:00
|
|
|
# Instance names are opaque strings but by stripping off the number suffix,
|
|
|
|
# we can get something that looks like a "worker type", e.g.
|
|
|
|
# "client_reader-1" -> "client_reader" so we don't spread the traces across
|
|
|
|
# so many services.
|
|
|
|
instance_name_by_type = re.sub(
|
|
|
|
STRIP_INSTANCE_NUMBER_SUFFIX_REGEX, "", hs.get_instance_name()
|
|
|
|
)
|
|
|
|
|
2020-06-17 07:13:41 -06:00
|
|
|
config = JaegerConfig(
|
2021-09-24 05:25:21 -06:00
|
|
|
config=hs.config.tracing.jaeger_config,
|
2022-09-09 10:30:06 -06:00
|
|
|
service_name=f"{hs.config.server.server_name} {instance_name_by_type}",
|
2022-06-30 07:05:06 -06:00
|
|
|
scope_manager=LogContextScopeManager(),
|
2021-06-04 02:25:33 -06:00
|
|
|
metrics_factory=PrometheusMetricsFactory(),
|
2020-06-17 07:13:41 -06:00
|
|
|
)
|
|
|
|
|
|
|
|
# If we have the rust jaeger reporter available let's use that.
|
|
|
|
if RustReporter:
|
|
|
|
logger.info("Using rust_python_jaeger_reporter library")
|
2021-09-13 06:54:01 -06:00
|
|
|
assert config.sampler is not None
|
2020-06-17 07:13:41 -06:00
|
|
|
tracer = config.create_tracer(RustReporter(), config.sampler)
|
|
|
|
opentracing.set_global_tracer(tracer)
|
|
|
|
else:
|
|
|
|
config.initialize_tracer()
|
2019-07-11 03:36:03 -06:00
|
|
|
|
|
|
|
|
2019-07-23 06:31:16 -06:00
|
|
|
# Whitelisting
|
|
|
|
|
|
|
|
|
|
|
|
@only_if_tracing
|
2022-05-27 04:17:33 -06:00
|
|
|
def set_homeserver_whitelist(homeserver_whitelist: Iterable[str]) -> None:
|
2019-07-23 06:31:16 -06:00
|
|
|
"""Sets the homeserver whitelist
|
2019-07-11 03:36:03 -06:00
|
|
|
|
2019-07-23 06:31:16 -06:00
|
|
|
Args:
|
2022-05-27 04:17:33 -06:00
|
|
|
homeserver_whitelist: regexes specifying whitelisted homeservers
|
2019-07-23 06:31:16 -06:00
|
|
|
"""
|
|
|
|
global _homeserver_whitelist
|
|
|
|
if homeserver_whitelist:
|
|
|
|
# Makes a single regex which accepts all passed in regexes in the list
|
|
|
|
_homeserver_whitelist = re.compile(
|
|
|
|
"({})".format(")|(".join(homeserver_whitelist))
|
|
|
|
)
|
|
|
|
|
|
|
|
|
|
|
|
@only_if_tracing
|
2022-05-27 04:17:33 -06:00
|
|
|
def whitelisted_homeserver(destination: str) -> bool:
|
2019-07-23 06:31:16 -06:00
|
|
|
"""Checks if a destination matches the whitelist
|
|
|
|
|
|
|
|
Args:
|
2022-05-27 04:17:33 -06:00
|
|
|
destination
|
2019-07-23 06:31:16 -06:00
|
|
|
"""
|
2019-09-05 07:46:04 -06:00
|
|
|
|
2019-07-23 06:31:16 -06:00
|
|
|
if _homeserver_whitelist:
|
2022-05-27 04:17:33 -06:00
|
|
|
return _homeserver_whitelist.match(destination) is not None
|
2019-07-23 06:31:16 -06:00
|
|
|
return False
|
|
|
|
|
|
|
|
|
|
|
|
# Start spans and scopes
|
2019-07-11 03:36:03 -06:00
|
|
|
|
|
|
|
# Could use kwargs but I want these to be explicit
|
|
|
|
def start_active_span(
|
2022-06-30 07:05:06 -06:00
|
|
|
operation_name: str,
|
|
|
|
child_of: Optional[Union["opentracing.Span", "opentracing.SpanContext"]] = None,
|
|
|
|
references: Optional[List["opentracing.Reference"]] = None,
|
|
|
|
tags: Optional[Dict[str, str]] = None,
|
|
|
|
start_time: Optional[float] = None,
|
|
|
|
ignore_active_span: bool = False,
|
|
|
|
finish_on_close: bool = True,
|
2022-02-02 15:41:57 -07:00
|
|
|
*,
|
2022-06-30 07:05:06 -06:00
|
|
|
tracer: Optional["opentracing.Tracer"] = None,
|
2022-07-21 06:01:52 -06:00
|
|
|
) -> "opentracing.Scope":
|
2022-02-02 15:41:57 -07:00
|
|
|
"""Starts an active opentracing span.
|
|
|
|
|
|
|
|
Records the start time for the span, and sets it as the "active span" in the
|
|
|
|
scope manager.
|
|
|
|
|
2019-07-11 03:36:03 -06:00
|
|
|
Args:
|
|
|
|
See opentracing.tracer
|
|
|
|
Returns:
|
2022-05-27 04:17:33 -06:00
|
|
|
scope (Scope) or contextlib.nullcontext
|
2019-07-11 03:36:03 -06:00
|
|
|
"""
|
2019-07-23 06:31:16 -06:00
|
|
|
|
2019-07-11 03:36:03 -06:00
|
|
|
if opentracing is None:
|
2022-05-27 04:17:33 -06:00
|
|
|
return contextlib.nullcontext() # type: ignore[unreachable]
|
2019-07-23 06:31:16 -06:00
|
|
|
|
2022-02-02 15:41:57 -07:00
|
|
|
if tracer is None:
|
|
|
|
# use the global tracer by default
|
|
|
|
tracer = opentracing.tracer
|
|
|
|
|
|
|
|
return tracer.start_active_span(
|
2019-09-05 10:33:29 -06:00
|
|
|
operation_name,
|
|
|
|
child_of=child_of,
|
|
|
|
references=references,
|
|
|
|
tags=tags,
|
|
|
|
start_time=start_time,
|
|
|
|
ignore_active_span=ignore_active_span,
|
|
|
|
finish_on_close=finish_on_close,
|
|
|
|
)
|
2019-07-11 03:36:03 -06:00
|
|
|
|
|
|
|
|
2021-06-16 04:41:15 -06:00
|
|
|
def start_active_span_follows_from(
|
2022-02-02 15:41:57 -07:00
|
|
|
operation_name: str,
|
|
|
|
contexts: Collection,
|
2022-06-30 07:05:06 -06:00
|
|
|
child_of: Optional[Union["opentracing.Span", "opentracing.SpanContext"]] = None,
|
2022-02-03 05:29:16 -07:00
|
|
|
start_time: Optional[float] = None,
|
2022-02-02 15:41:57 -07:00
|
|
|
*,
|
2022-06-30 07:05:06 -06:00
|
|
|
inherit_force_tracing: bool = False,
|
|
|
|
tracer: Optional["opentracing.Tracer"] = None,
|
2022-07-21 06:01:52 -06:00
|
|
|
) -> "opentracing.Scope":
|
2021-06-16 04:41:15 -06:00
|
|
|
"""Starts an active opentracing span, with additional references to previous spans
|
|
|
|
|
|
|
|
Args:
|
|
|
|
operation_name: name of the operation represented by the new span
|
|
|
|
contexts: the previous spans to inherit from
|
2022-02-03 05:29:16 -07:00
|
|
|
|
|
|
|
child_of: optionally override the parent span. If unset, the currently active
|
|
|
|
span will be the parent. (If there is no currently active span, the first
|
|
|
|
span in `contexts` will be the parent.)
|
|
|
|
|
|
|
|
start_time: optional override for the start time of the created span. Seconds
|
|
|
|
since the epoch.
|
|
|
|
|
2021-06-16 04:41:15 -06:00
|
|
|
inherit_force_tracing: if set, and any of the previous contexts have had tracing
|
|
|
|
forced, the new span will also have tracing forced.
|
2022-02-02 15:41:57 -07:00
|
|
|
tracer: override the opentracing tracer. By default the global tracer is used.
|
2021-06-16 04:41:15 -06:00
|
|
|
"""
|
2019-07-23 06:31:16 -06:00
|
|
|
if opentracing is None:
|
2022-05-27 04:17:33 -06:00
|
|
|
return contextlib.nullcontext() # type: ignore[unreachable]
|
2019-09-05 10:33:29 -06:00
|
|
|
|
|
|
|
references = [opentracing.follows_from(context) for context in contexts]
|
2022-02-02 15:41:57 -07:00
|
|
|
scope = start_active_span(
|
|
|
|
operation_name,
|
2022-02-03 05:29:16 -07:00
|
|
|
child_of=child_of,
|
2022-02-02 15:41:57 -07:00
|
|
|
references=references,
|
2022-02-03 05:29:16 -07:00
|
|
|
start_time=start_time,
|
2022-02-02 15:41:57 -07:00
|
|
|
tracer=tracer,
|
|
|
|
)
|
2021-06-16 04:41:15 -06:00
|
|
|
|
|
|
|
if inherit_force_tracing and any(
|
|
|
|
is_context_forced_tracing(ctx) for ctx in contexts
|
|
|
|
):
|
|
|
|
force_tracing(scope.span)
|
|
|
|
|
2019-09-05 10:33:29 -06:00
|
|
|
return scope
|
2019-07-11 03:36:03 -06:00
|
|
|
|
|
|
|
|
2019-07-23 06:31:16 -06:00
|
|
|
def start_active_span_from_edu(
|
2022-05-27 04:17:33 -06:00
|
|
|
edu_content: Dict[str, Any],
|
|
|
|
operation_name: str,
|
|
|
|
references: Optional[List["opentracing.Reference"]] = None,
|
2022-06-30 07:05:06 -06:00
|
|
|
tags: Optional[Dict[str, str]] = None,
|
2022-05-27 04:17:33 -06:00
|
|
|
start_time: Optional[float] = None,
|
|
|
|
ignore_active_span: bool = False,
|
|
|
|
finish_on_close: bool = True,
|
|
|
|
) -> "opentracing.Scope":
|
2019-07-23 06:31:16 -06:00
|
|
|
"""
|
|
|
|
Extracts a span context from an edu and uses it to start a new active span
|
|
|
|
|
|
|
|
Args:
|
2022-05-27 04:17:33 -06:00
|
|
|
edu_content: an edu_content with a `context` field whose value is
|
2019-07-23 06:31:16 -06:00
|
|
|
canonical json for a dict which contains opentracing information.
|
|
|
|
|
|
|
|
For the other args see opentracing.tracer
|
|
|
|
"""
|
2021-04-08 15:38:54 -06:00
|
|
|
references = references or []
|
2019-07-23 06:31:16 -06:00
|
|
|
|
|
|
|
if opentracing is None:
|
2022-05-27 04:17:33 -06:00
|
|
|
return contextlib.nullcontext() # type: ignore[unreachable]
|
2019-07-23 06:31:16 -06:00
|
|
|
|
2020-08-19 05:26:03 -06:00
|
|
|
carrier = json_decoder.decode(edu_content.get("context", "{}")).get(
|
|
|
|
"opentracing", {}
|
|
|
|
)
|
2019-07-23 06:31:16 -06:00
|
|
|
context = opentracing.tracer.extract(opentracing.Format.TEXT_MAP, carrier)
|
|
|
|
_references = [
|
|
|
|
opentracing.child_of(span_context_from_string(x))
|
|
|
|
for x in carrier.get("references", [])
|
|
|
|
]
|
|
|
|
|
|
|
|
# For some reason jaeger decided not to support the visualization of multiple parent
|
2020-09-14 09:46:58 -06:00
|
|
|
# spans or explicitly show references. I include the span context as a tag here as
|
2019-07-23 06:31:16 -06:00
|
|
|
# an aid to people debugging but it's really not an ideal solution.
|
|
|
|
|
|
|
|
references += _references
|
|
|
|
|
|
|
|
scope = opentracing.tracer.start_active_span(
|
|
|
|
operation_name,
|
|
|
|
child_of=context,
|
|
|
|
references=references,
|
|
|
|
tags=tags,
|
|
|
|
start_time=start_time,
|
|
|
|
ignore_active_span=ignore_active_span,
|
|
|
|
finish_on_close=finish_on_close,
|
|
|
|
)
|
|
|
|
|
|
|
|
scope.span.set_tag("references", carrier.get("references", []))
|
|
|
|
return scope
|
|
|
|
|
|
|
|
|
|
|
|
# Opentracing setters for tags, logs, etc
|
2021-06-16 04:41:15 -06:00
|
|
|
@only_if_tracing
|
2022-05-27 04:17:33 -06:00
|
|
|
def active_span() -> Optional["opentracing.Span"]:
|
2021-06-16 04:41:15 -06:00
|
|
|
"""Get the currently active span, if any"""
|
|
|
|
return opentracing.tracer.active_span
|
2019-07-23 06:31:16 -06:00
|
|
|
|
|
|
|
|
2019-09-05 10:33:29 -06:00
|
|
|
@ensure_active_span("set a tag")
|
2022-05-27 04:17:33 -06:00
|
|
|
def set_tag(key: str, value: Union[str, bool, int, float]) -> None:
|
2019-07-23 06:31:16 -06:00
|
|
|
"""Sets a tag on the active span"""
|
2021-12-20 05:18:09 -07:00
|
|
|
assert opentracing.tracer.active_span is not None
|
2019-07-23 06:31:16 -06:00
|
|
|
opentracing.tracer.active_span.set_tag(key, value)
|
|
|
|
|
|
|
|
|
2019-09-05 10:33:29 -06:00
|
|
|
@ensure_active_span("log")
|
2022-05-27 04:17:33 -06:00
|
|
|
def log_kv(key_values: Dict[str, Any], timestamp: Optional[float] = None) -> None:
|
2019-07-23 06:31:16 -06:00
|
|
|
"""Log to the active span"""
|
2021-12-20 05:18:09 -07:00
|
|
|
assert opentracing.tracer.active_span is not None
|
2019-07-23 06:31:16 -06:00
|
|
|
opentracing.tracer.active_span.log_kv(key_values, timestamp)
|
|
|
|
|
|
|
|
|
2019-09-05 10:33:29 -06:00
|
|
|
@ensure_active_span("set the traces operation name")
|
2022-05-27 04:17:33 -06:00
|
|
|
def set_operation_name(operation_name: str) -> None:
|
2019-07-23 06:31:16 -06:00
|
|
|
"""Sets the operation name of the active span"""
|
2021-12-20 05:18:09 -07:00
|
|
|
assert opentracing.tracer.active_span is not None
|
2019-07-23 06:31:16 -06:00
|
|
|
opentracing.tracer.active_span.set_operation_name(operation_name)
|
|
|
|
|
|
|
|
|
2021-06-16 04:41:15 -06:00
|
|
|
@only_if_tracing
|
2022-06-30 07:05:06 -06:00
|
|
|
def force_tracing(
|
|
|
|
span: Union["opentracing.Span", _Sentinel] = _Sentinel.sentinel
|
|
|
|
) -> None:
|
2021-06-16 04:41:15 -06:00
|
|
|
"""Force sampling for the active/given span and its children.
|
|
|
|
|
|
|
|
Args:
|
|
|
|
span: span to force tracing for. By default, the active span.
|
|
|
|
"""
|
2022-06-30 07:05:06 -06:00
|
|
|
if isinstance(span, _Sentinel):
|
|
|
|
span_to_trace = opentracing.tracer.active_span
|
|
|
|
else:
|
|
|
|
span_to_trace = span
|
|
|
|
if span_to_trace is None:
|
2021-06-16 04:41:15 -06:00
|
|
|
logger.error("No active span in force_tracing")
|
|
|
|
return
|
|
|
|
|
2022-06-30 07:05:06 -06:00
|
|
|
span_to_trace.set_tag(opentracing.tags.SAMPLING_PRIORITY, 1)
|
2021-06-16 04:41:15 -06:00
|
|
|
|
|
|
|
# also set a bit of baggage, so that we have a way of figuring out if
|
|
|
|
# it is enabled later
|
2022-06-30 07:05:06 -06:00
|
|
|
span_to_trace.set_baggage_item(SynapseBaggage.FORCE_TRACING, "1")
|
2021-06-16 04:41:15 -06:00
|
|
|
|
|
|
|
|
2022-05-27 04:17:33 -06:00
|
|
|
def is_context_forced_tracing(
|
|
|
|
span_context: Optional["opentracing.SpanContext"],
|
|
|
|
) -> bool:
|
2021-06-16 04:41:15 -06:00
|
|
|
"""Check if sampling has been force for the given span context."""
|
|
|
|
if span_context is None:
|
|
|
|
return False
|
|
|
|
return span_context.baggage.get(SynapseBaggage.FORCE_TRACING) is not None
|
|
|
|
|
|
|
|
|
2019-07-23 06:31:16 -06:00
|
|
|
# Injection and extraction
|
|
|
|
|
|
|
|
|
2021-06-09 04:33:00 -06:00
|
|
|
@ensure_active_span("inject the span into a header dict")
|
|
|
|
def inject_header_dict(
|
|
|
|
headers: Dict[bytes, List[bytes]],
|
|
|
|
destination: Optional[str] = None,
|
|
|
|
check_destination: bool = True,
|
|
|
|
) -> None:
|
2019-07-11 03:36:03 -06:00
|
|
|
"""
|
2021-06-09 04:33:00 -06:00
|
|
|
Injects a span context into a dict of HTTP headers
|
2019-07-11 03:36:03 -06:00
|
|
|
|
|
|
|
Args:
|
2021-06-09 04:33:00 -06:00
|
|
|
headers: the dict to inject headers into
|
|
|
|
destination: address of entity receiving the span context. Must be given unless
|
|
|
|
check_destination is False. The context will only be injected if the
|
|
|
|
destination matches the opentracing whitelist
|
2022-11-16 08:25:24 -07:00
|
|
|
check_destination: If false, destination will be ignored and the context
|
2019-09-05 07:22:15 -06:00
|
|
|
will always be injected.
|
2019-07-11 03:36:03 -06:00
|
|
|
|
|
|
|
Note:
|
|
|
|
The headers set by the tracer are custom to the tracer implementation which
|
|
|
|
should be unique enough that they don't interfere with any headers set by
|
|
|
|
synapse or twisted. If we're still using jaeger these headers would be those
|
|
|
|
here:
|
|
|
|
https://github.com/jaegertracing/jaeger-client-python/blob/master/jaeger_client/constants.py
|
|
|
|
"""
|
2021-06-09 04:33:00 -06:00
|
|
|
if check_destination:
|
|
|
|
if destination is None:
|
|
|
|
raise ValueError(
|
|
|
|
"destination must be given unless check_destination is False"
|
|
|
|
)
|
|
|
|
if not whitelisted_homeserver(destination):
|
|
|
|
return
|
2019-07-11 03:36:03 -06:00
|
|
|
|
|
|
|
span = opentracing.tracer.active_span
|
|
|
|
|
2021-07-15 04:02:43 -06:00
|
|
|
carrier: Dict[str, str] = {}
|
2021-12-20 05:18:09 -07:00
|
|
|
assert span is not None
|
2021-06-01 01:40:26 -06:00
|
|
|
opentracing.tracer.inject(span.context, opentracing.Format.HTTP_HEADERS, carrier)
|
2019-07-11 03:36:03 -06:00
|
|
|
|
|
|
|
for key, value in carrier.items():
|
|
|
|
headers[key.encode()] = [value.encode()]
|
|
|
|
|
|
|
|
|
2021-06-18 04:43:22 -06:00
|
|
|
def inject_response_headers(response_headers: Headers) -> None:
|
|
|
|
"""Inject the current trace id into the HTTP response headers"""
|
|
|
|
if not opentracing:
|
|
|
|
return
|
|
|
|
span = opentracing.tracer.active_span
|
|
|
|
if not span:
|
|
|
|
return
|
|
|
|
|
|
|
|
# This is a bit implementation-specific.
|
|
|
|
#
|
|
|
|
# Jaeger's Spans have a trace_id property; other implementations (including the
|
|
|
|
# dummy opentracing.span.Span which we use if init_tracer is not called) do not
|
|
|
|
# expose it
|
|
|
|
trace_id = getattr(span, "trace_id", None)
|
|
|
|
|
|
|
|
if trace_id is not None:
|
|
|
|
response_headers.addRawHeader("Synapse-Trace-Id", f"{trace_id:x}")
|
|
|
|
|
|
|
|
|
2022-07-21 06:01:52 -06:00
|
|
|
@ensure_active_span(
|
|
|
|
"get the active span context as a dict", ret=cast(Dict[str, str], {})
|
|
|
|
)
|
2022-05-27 04:17:33 -06:00
|
|
|
def get_active_span_text_map(destination: Optional[str] = None) -> Dict[str, str]:
|
2019-08-22 11:21:10 -06:00
|
|
|
"""
|
|
|
|
Gets a span context as a dict. This can be used instead of manually
|
|
|
|
injecting a span into an empty carrier.
|
|
|
|
|
|
|
|
Args:
|
2022-05-27 04:17:33 -06:00
|
|
|
destination: the name of the remote server.
|
2019-08-22 11:21:10 -06:00
|
|
|
|
|
|
|
Returns:
|
2022-11-16 08:25:24 -07:00
|
|
|
the active span's context if opentracing is enabled, otherwise empty.
|
2019-08-22 11:21:10 -06:00
|
|
|
"""
|
|
|
|
|
2019-09-05 10:33:29 -06:00
|
|
|
if destination and not whitelisted_homeserver(destination):
|
2019-08-22 11:21:10 -06:00
|
|
|
return {}
|
|
|
|
|
2021-07-15 04:02:43 -06:00
|
|
|
carrier: Dict[str, str] = {}
|
2021-12-20 05:18:09 -07:00
|
|
|
assert opentracing.tracer.active_span is not None
|
2019-08-22 11:21:10 -06:00
|
|
|
opentracing.tracer.inject(
|
2021-06-01 01:40:26 -06:00
|
|
|
opentracing.tracer.active_span.context, opentracing.Format.TEXT_MAP, carrier
|
2019-08-22 11:21:10 -06:00
|
|
|
)
|
|
|
|
|
|
|
|
return carrier
|
|
|
|
|
|
|
|
|
2019-09-05 10:33:29 -06:00
|
|
|
@ensure_active_span("get the span context as a string.", ret={})
|
2022-05-27 04:17:33 -06:00
|
|
|
def active_span_context_as_string() -> str:
|
2019-07-23 06:31:16 -06:00
|
|
|
"""
|
|
|
|
Returns:
|
|
|
|
The active span context encoded as a string.
|
|
|
|
"""
|
2021-07-15 04:02:43 -06:00
|
|
|
carrier: Dict[str, str] = {}
|
2019-07-23 06:31:16 -06:00
|
|
|
if opentracing:
|
2021-12-20 05:18:09 -07:00
|
|
|
assert opentracing.tracer.active_span is not None
|
2019-07-23 06:31:16 -06:00
|
|
|
opentracing.tracer.inject(
|
2021-06-01 01:40:26 -06:00
|
|
|
opentracing.tracer.active_span.context, opentracing.Format.TEXT_MAP, carrier
|
2019-07-23 06:31:16 -06:00
|
|
|
)
|
2020-08-20 08:32:33 -06:00
|
|
|
return json_encoder.encode(carrier)
|
2019-07-23 06:31:16 -06:00
|
|
|
|
|
|
|
|
2021-12-20 10:45:03 -07:00
|
|
|
def span_context_from_request(request: Request) -> "Optional[opentracing.SpanContext]":
|
|
|
|
"""Extract an opentracing context from the headers on an HTTP request
|
|
|
|
|
|
|
|
This is useful when we have received an HTTP request from another part of our
|
|
|
|
system, and want to link our spans to those of the remote system.
|
|
|
|
"""
|
|
|
|
if not opentracing:
|
|
|
|
return None
|
|
|
|
header_dict = {
|
|
|
|
k.decode(): v[0].decode() for k, v in request.requestHeaders.getAllRawHeaders()
|
|
|
|
}
|
|
|
|
return opentracing.tracer.extract(opentracing.Format.HTTP_HEADERS, header_dict)
|
|
|
|
|
|
|
|
|
2019-07-23 06:31:16 -06:00
|
|
|
@only_if_tracing
|
2022-05-27 04:17:33 -06:00
|
|
|
def span_context_from_string(carrier: str) -> Optional["opentracing.SpanContext"]:
|
2019-07-23 06:31:16 -06:00
|
|
|
"""
|
|
|
|
Returns:
|
|
|
|
The active span context decoded from a string.
|
|
|
|
"""
|
2022-05-27 04:17:33 -06:00
|
|
|
payload: Dict[str, str] = json_decoder.decode(carrier)
|
|
|
|
return opentracing.tracer.extract(opentracing.Format.TEXT_MAP, payload)
|
2019-07-23 06:31:16 -06:00
|
|
|
|
|
|
|
|
|
|
|
@only_if_tracing
|
2022-05-27 04:17:33 -06:00
|
|
|
def extract_text_map(carrier: Dict[str, str]) -> Optional["opentracing.SpanContext"]:
|
2019-07-23 06:31:16 -06:00
|
|
|
"""
|
|
|
|
Wrapper method for opentracing's tracer.extract for TEXT_MAP.
|
|
|
|
Args:
|
2022-05-27 04:17:33 -06:00
|
|
|
carrier: a dict possibly containing a span context.
|
2019-07-23 06:31:16 -06:00
|
|
|
|
|
|
|
Returns:
|
|
|
|
The active span context extracted from carrier.
|
|
|
|
"""
|
|
|
|
return opentracing.tracer.extract(opentracing.Format.TEXT_MAP, carrier)
|
|
|
|
|
|
|
|
|
|
|
|
# Tracing decorators
|
|
|
|
|
|
|
|
|
2022-08-09 13:32:33 -06:00
|
|
|
def _custom_sync_async_decorator(
|
|
|
|
func: Callable[P, R],
|
|
|
|
wrapping_logic: Callable[[Callable[P, R], Any, Any], ContextManager[None]],
|
|
|
|
) -> Callable[P, R]:
|
2019-07-23 06:31:16 -06:00
|
|
|
"""
|
2022-08-09 13:32:33 -06:00
|
|
|
Decorates a function that is sync or async (coroutines), or that returns a Twisted
|
|
|
|
`Deferred`. The custom business logic of the decorator goes in `wrapping_logic`.
|
|
|
|
|
|
|
|
Example usage:
|
|
|
|
```py
|
|
|
|
# Decorator to time the function and log it out
|
|
|
|
def duration(func: Callable[P, R]) -> Callable[P, R]:
|
|
|
|
@contextlib.contextmanager
|
|
|
|
def _wrapping_logic(func: Callable[P, R], *args: P.args, **kwargs: P.kwargs) -> Generator[None, None, None]:
|
|
|
|
start_ts = time.time()
|
|
|
|
try:
|
|
|
|
yield
|
|
|
|
finally:
|
|
|
|
end_ts = time.time()
|
|
|
|
duration = end_ts - start_ts
|
|
|
|
logger.info("%s took %s seconds", func.__name__, duration)
|
|
|
|
return _custom_sync_async_decorator(func, _wrapping_logic)
|
|
|
|
```
|
2022-07-19 12:14:30 -06:00
|
|
|
|
2022-08-09 13:32:33 -06:00
|
|
|
Args:
|
|
|
|
func: The function to be decorated
|
|
|
|
wrapping_logic: The business logic of your custom decorator.
|
|
|
|
This should be a ContextManager so you are able to run your logic
|
|
|
|
before/after the function as desired.
|
2019-07-23 06:31:16 -06:00
|
|
|
"""
|
|
|
|
|
2022-08-09 13:32:33 -06:00
|
|
|
if inspect.iscoroutinefunction(func):
|
2019-07-23 06:31:16 -06:00
|
|
|
|
2022-08-09 13:32:33 -06:00
|
|
|
@wraps(func)
|
|
|
|
async def _wrapper(*args: P.args, **kwargs: P.kwargs) -> R:
|
|
|
|
with wrapping_logic(func, *args, **kwargs):
|
|
|
|
return await func(*args, **kwargs) # type: ignore[misc]
|
2019-07-23 06:31:16 -06:00
|
|
|
|
2022-08-09 13:32:33 -06:00
|
|
|
else:
|
|
|
|
# The other case here handles both sync functions and those
|
|
|
|
# decorated with inlineDeferred.
|
|
|
|
@wraps(func)
|
|
|
|
def _wrapper(*args: P.args, **kwargs: P.kwargs) -> R:
|
|
|
|
scope = wrapping_logic(func, *args, **kwargs)
|
|
|
|
scope.__enter__()
|
2019-07-23 06:31:16 -06:00
|
|
|
|
2022-08-09 13:32:33 -06:00
|
|
|
try:
|
|
|
|
result = func(*args, **kwargs)
|
|
|
|
if isinstance(result, defer.Deferred):
|
|
|
|
|
|
|
|
def call_back(result: R) -> R:
|
|
|
|
scope.__exit__(None, None, None)
|
|
|
|
return result
|
2021-10-12 04:23:46 -06:00
|
|
|
|
2022-08-09 13:32:33 -06:00
|
|
|
def err_back(result: R) -> R:
|
2020-07-17 11:32:01 -06:00
|
|
|
scope.__exit__(None, None, None)
|
2022-08-09 13:32:33 -06:00
|
|
|
return result
|
2019-07-23 06:31:16 -06:00
|
|
|
|
2022-08-09 13:32:33 -06:00
|
|
|
result.addCallbacks(call_back, err_back)
|
2019-07-23 06:31:16 -06:00
|
|
|
|
2022-08-09 13:32:33 -06:00
|
|
|
else:
|
|
|
|
if inspect.isawaitable(result):
|
|
|
|
logger.error(
|
|
|
|
"@trace may not have wrapped %s correctly! "
|
|
|
|
"The function is not async but returned a %s.",
|
|
|
|
func.__qualname__,
|
|
|
|
type(result).__name__,
|
|
|
|
)
|
2019-07-23 06:31:16 -06:00
|
|
|
|
2022-08-09 13:32:33 -06:00
|
|
|
scope.__exit__(None, None, None)
|
2019-07-23 06:31:16 -06:00
|
|
|
|
2022-08-09 13:32:33 -06:00
|
|
|
return result
|
|
|
|
|
|
|
|
except Exception as e:
|
|
|
|
scope.__exit__(type(e), None, e.__traceback__)
|
|
|
|
raise
|
|
|
|
|
|
|
|
return _wrapper # type: ignore[return-value]
|
|
|
|
|
|
|
|
|
|
|
|
def trace_with_opname(
|
|
|
|
opname: str,
|
|
|
|
*,
|
|
|
|
tracer: Optional["opentracing.Tracer"] = None,
|
|
|
|
) -> Callable[[Callable[P, R]], Callable[P, R]]:
|
|
|
|
"""
|
|
|
|
Decorator to trace a function with a custom opname.
|
|
|
|
See the module's doc string for usage examples.
|
|
|
|
"""
|
|
|
|
|
|
|
|
# type-ignore: mypy bug, see https://github.com/python/mypy/issues/12909
|
|
|
|
@contextlib.contextmanager # type: ignore[arg-type]
|
|
|
|
def _wrapping_logic(
|
|
|
|
func: Callable[P, R], *args: P.args, **kwargs: P.kwargs
|
|
|
|
) -> Generator[None, None, None]:
|
|
|
|
with start_active_span(opname, tracer=tracer):
|
|
|
|
yield
|
|
|
|
|
|
|
|
def _decorator(func: Callable[P, R]) -> Callable[P, R]:
|
|
|
|
if not opentracing:
|
|
|
|
return func
|
|
|
|
|
|
|
|
return _custom_sync_async_decorator(func, _wrapping_logic)
|
|
|
|
|
|
|
|
return _decorator
|
2022-07-19 12:14:30 -06:00
|
|
|
|
|
|
|
|
|
|
|
def trace(func: Callable[P, R]) -> Callable[P, R]:
|
|
|
|
"""
|
|
|
|
Decorator to trace a function.
|
|
|
|
Sets the operation name to that of the function's name.
|
|
|
|
See the module's doc string for usage examples.
|
|
|
|
"""
|
|
|
|
|
|
|
|
return trace_with_opname(func.__name__)(func)
|
2019-07-23 06:31:16 -06:00
|
|
|
|
|
|
|
|
2022-05-27 04:17:33 -06:00
|
|
|
def tag_args(func: Callable[P, R]) -> Callable[P, R]:
|
2019-07-23 06:31:16 -06:00
|
|
|
"""
|
2022-08-09 13:32:33 -06:00
|
|
|
Decorator to tag all of the args to the active span.
|
Fix `@tag_args` being off-by-one (ahead) (#13452)
Fix @tag_args being off-by-one (ahead)
Example:
```
argspec.args=[
'self',
'room_id'
]
args=(
<synapse.storage.databases.main.DataStore object at 0x10d0b8d00>,
'!HBehERstyQBxyJDLfR:my.synapse.server'
)
```
---
The previous logic was also flawed and we can end up in a situation like this:
```
argspec.args=['self', 'dest', 'room_id', 'limit', 'extremities']
args=(<synapse.federation.federation_client.FederationClient object at 0x7f1651c18160>, 'hs1', '!jAEHKIubyIfuLOdfpY:hs1')
```
From this source:
```py
async def backfill(
self, dest: str, room_id: str, limit: int, extremities: Collection[str]
) -> Optional[List[EventBase]]:
```
And this usage:
```py
events = await self._federation_client.backfill(
dest, room_id, limit=limit, extremities=extremities
)
```
which would previously cause this error:
```
synapse_main | 2022-08-04 06:13:12,051 - synapse.handlers.federation - 424 - ERROR - GET-5 - Failed to backfill from hs1 because tuple index out of range
synapse_main | Traceback (most recent call last):
synapse_main | File "/usr/local/lib/python3.9/site-packages/synapse/handlers/federation.py", line 392, in try_backfill
synapse_main | await self._federation_event_handler.backfill(
synapse_main | File "/usr/local/lib/python3.9/site-packages/synapse/logging/tracing.py", line 828, in _wrapper
synapse_main | return await func(*args, **kwargs)
synapse_main | File "/usr/local/lib/python3.9/site-packages/synapse/handlers/federation_event.py", line 593, in backfill
synapse_main | events = await self._federation_client.backfill(
synapse_main | File "/usr/local/lib/python3.9/site-packages/synapse/logging/tracing.py", line 828, in _wrapper
synapse_main | return await func(*args, **kwargs)
synapse_main | File "/usr/local/lib/python3.9/site-packages/synapse/logging/tracing.py", line 827, in _wrapper
synapse_main | with wrapping_logic(func, *args, **kwargs):
synapse_main | File "/usr/local/lib/python3.9/contextlib.py", line 119, in __enter__
synapse_main | return next(self.gen)
synapse_main | File "/usr/local/lib/python3.9/site-packages/synapse/logging/tracing.py", line 922, in _wrapping_logic
synapse_main | set_attribute("ARG_" + arg, str(args[i + 1])) # type: ignore[index]
synapse_main | IndexError: tuple index out of range
```
2022-08-04 13:29:41 -06:00
|
|
|
|
|
|
|
Args:
|
|
|
|
func: `func` is assumed to be a method taking a `self` parameter, or a
|
|
|
|
`classmethod` taking a `cls` parameter. In either case, a tag is not
|
|
|
|
created for this parameter.
|
2019-07-23 06:31:16 -06:00
|
|
|
"""
|
|
|
|
|
|
|
|
if not opentracing:
|
|
|
|
return func
|
|
|
|
|
2022-08-09 13:32:33 -06:00
|
|
|
# type-ignore: mypy bug, see https://github.com/python/mypy/issues/12909
|
|
|
|
@contextlib.contextmanager # type: ignore[arg-type]
|
|
|
|
def _wrapping_logic(
|
|
|
|
func: Callable[P, R], *args: P.args, **kwargs: P.kwargs
|
|
|
|
) -> Generator[None, None, None]:
|
2021-01-28 06:34:19 -07:00
|
|
|
argspec = inspect.getfullargspec(func)
|
Fix `@tag_args` being off-by-one (ahead) (#13452)
Fix @tag_args being off-by-one (ahead)
Example:
```
argspec.args=[
'self',
'room_id'
]
args=(
<synapse.storage.databases.main.DataStore object at 0x10d0b8d00>,
'!HBehERstyQBxyJDLfR:my.synapse.server'
)
```
---
The previous logic was also flawed and we can end up in a situation like this:
```
argspec.args=['self', 'dest', 'room_id', 'limit', 'extremities']
args=(<synapse.federation.federation_client.FederationClient object at 0x7f1651c18160>, 'hs1', '!jAEHKIubyIfuLOdfpY:hs1')
```
From this source:
```py
async def backfill(
self, dest: str, room_id: str, limit: int, extremities: Collection[str]
) -> Optional[List[EventBase]]:
```
And this usage:
```py
events = await self._federation_client.backfill(
dest, room_id, limit=limit, extremities=extremities
)
```
which would previously cause this error:
```
synapse_main | 2022-08-04 06:13:12,051 - synapse.handlers.federation - 424 - ERROR - GET-5 - Failed to backfill from hs1 because tuple index out of range
synapse_main | Traceback (most recent call last):
synapse_main | File "/usr/local/lib/python3.9/site-packages/synapse/handlers/federation.py", line 392, in try_backfill
synapse_main | await self._federation_event_handler.backfill(
synapse_main | File "/usr/local/lib/python3.9/site-packages/synapse/logging/tracing.py", line 828, in _wrapper
synapse_main | return await func(*args, **kwargs)
synapse_main | File "/usr/local/lib/python3.9/site-packages/synapse/handlers/federation_event.py", line 593, in backfill
synapse_main | events = await self._federation_client.backfill(
synapse_main | File "/usr/local/lib/python3.9/site-packages/synapse/logging/tracing.py", line 828, in _wrapper
synapse_main | return await func(*args, **kwargs)
synapse_main | File "/usr/local/lib/python3.9/site-packages/synapse/logging/tracing.py", line 827, in _wrapper
synapse_main | with wrapping_logic(func, *args, **kwargs):
synapse_main | File "/usr/local/lib/python3.9/contextlib.py", line 119, in __enter__
synapse_main | return next(self.gen)
synapse_main | File "/usr/local/lib/python3.9/site-packages/synapse/logging/tracing.py", line 922, in _wrapping_logic
synapse_main | set_attribute("ARG_" + arg, str(args[i + 1])) # type: ignore[index]
synapse_main | IndexError: tuple index out of range
```
2022-08-04 13:29:41 -06:00
|
|
|
# We use `[1:]` to skip the `self` object reference and `start=1` to
|
|
|
|
# make the index line up with `argspec.args`.
|
|
|
|
#
|
2022-08-09 13:32:33 -06:00
|
|
|
# FIXME: We could update this to handle any type of function by ignoring the
|
Fix `@tag_args` being off-by-one (ahead) (#13452)
Fix @tag_args being off-by-one (ahead)
Example:
```
argspec.args=[
'self',
'room_id'
]
args=(
<synapse.storage.databases.main.DataStore object at 0x10d0b8d00>,
'!HBehERstyQBxyJDLfR:my.synapse.server'
)
```
---
The previous logic was also flawed and we can end up in a situation like this:
```
argspec.args=['self', 'dest', 'room_id', 'limit', 'extremities']
args=(<synapse.federation.federation_client.FederationClient object at 0x7f1651c18160>, 'hs1', '!jAEHKIubyIfuLOdfpY:hs1')
```
From this source:
```py
async def backfill(
self, dest: str, room_id: str, limit: int, extremities: Collection[str]
) -> Optional[List[EventBase]]:
```
And this usage:
```py
events = await self._federation_client.backfill(
dest, room_id, limit=limit, extremities=extremities
)
```
which would previously cause this error:
```
synapse_main | 2022-08-04 06:13:12,051 - synapse.handlers.federation - 424 - ERROR - GET-5 - Failed to backfill from hs1 because tuple index out of range
synapse_main | Traceback (most recent call last):
synapse_main | File "/usr/local/lib/python3.9/site-packages/synapse/handlers/federation.py", line 392, in try_backfill
synapse_main | await self._federation_event_handler.backfill(
synapse_main | File "/usr/local/lib/python3.9/site-packages/synapse/logging/tracing.py", line 828, in _wrapper
synapse_main | return await func(*args, **kwargs)
synapse_main | File "/usr/local/lib/python3.9/site-packages/synapse/handlers/federation_event.py", line 593, in backfill
synapse_main | events = await self._federation_client.backfill(
synapse_main | File "/usr/local/lib/python3.9/site-packages/synapse/logging/tracing.py", line 828, in _wrapper
synapse_main | return await func(*args, **kwargs)
synapse_main | File "/usr/local/lib/python3.9/site-packages/synapse/logging/tracing.py", line 827, in _wrapper
synapse_main | with wrapping_logic(func, *args, **kwargs):
synapse_main | File "/usr/local/lib/python3.9/contextlib.py", line 119, in __enter__
synapse_main | return next(self.gen)
synapse_main | File "/usr/local/lib/python3.9/site-packages/synapse/logging/tracing.py", line 922, in _wrapping_logic
synapse_main | set_attribute("ARG_" + arg, str(args[i + 1])) # type: ignore[index]
synapse_main | IndexError: tuple index out of range
```
2022-08-04 13:29:41 -06:00
|
|
|
# first argument only if it's named `self` or `cls`. This isn't fool-proof
|
|
|
|
# but handles the idiomatic cases.
|
2022-09-30 10:36:28 -06:00
|
|
|
for i, arg in enumerate(args[1:], start=1):
|
2022-08-16 11:39:40 -06:00
|
|
|
set_tag(SynapseTags.FUNC_ARG_PREFIX + argspec.args[i], str(arg))
|
2022-09-30 10:36:28 -06:00
|
|
|
set_tag(SynapseTags.FUNC_ARGS, str(args[len(argspec.args) :]))
|
2022-08-16 11:39:40 -06:00
|
|
|
set_tag(SynapseTags.FUNC_KWARGS, str(kwargs))
|
2022-08-09 13:32:33 -06:00
|
|
|
yield
|
2019-07-23 06:31:16 -06:00
|
|
|
|
2022-08-09 13:32:33 -06:00
|
|
|
return _custom_sync_async_decorator(func, _wrapping_logic)
|
2019-07-23 06:31:16 -06:00
|
|
|
|
|
|
|
|
2020-07-03 12:02:19 -06:00
|
|
|
@contextlib.contextmanager
|
2022-05-27 04:17:33 -06:00
|
|
|
def trace_servlet(
|
|
|
|
request: "SynapseRequest", extract_context: bool = False
|
|
|
|
) -> Generator[None, None, None]:
|
2020-07-03 12:02:19 -06:00
|
|
|
"""Returns a context manager which traces a request. It starts a span
|
|
|
|
with some servlet specific tags such as the request metrics name and
|
|
|
|
request information.
|
2019-07-11 03:36:03 -06:00
|
|
|
|
2019-08-22 11:08:07 -06:00
|
|
|
Args:
|
2020-07-03 12:02:19 -06:00
|
|
|
request
|
|
|
|
extract_context: Whether to attempt to extract the opentracing
|
2019-08-22 11:08:07 -06:00
|
|
|
context from the request the servlet is handling.
|
|
|
|
"""
|
|
|
|
|
2020-07-03 12:02:19 -06:00
|
|
|
if opentracing is None:
|
2021-12-20 05:18:09 -07:00
|
|
|
yield # type: ignore[unreachable]
|
2020-07-03 12:02:19 -06:00
|
|
|
return
|
2019-10-11 04:22:36 -06:00
|
|
|
|
2020-07-03 12:02:19 -06:00
|
|
|
request_tags = {
|
2021-05-28 09:14:08 -06:00
|
|
|
SynapseTags.REQUEST_ID: request.get_request_id(),
|
2020-07-03 12:02:19 -06:00
|
|
|
tags.SPAN_KIND: tags.SPAN_KIND_RPC_SERVER,
|
|
|
|
tags.HTTP_METHOD: request.get_method(),
|
|
|
|
tags.HTTP_URL: request.get_redacted_uri(),
|
2022-05-04 12:11:21 -06:00
|
|
|
tags.PEER_HOST_IPV6: request.getClientAddress().host,
|
2020-07-03 12:02:19 -06:00
|
|
|
}
|
2019-10-11 04:22:36 -06:00
|
|
|
|
2020-07-03 12:02:19 -06:00
|
|
|
request_name = request.request_metrics.name
|
2021-12-20 10:45:03 -07:00
|
|
|
context = span_context_from_request(request) if extract_context else None
|
|
|
|
|
|
|
|
# we configure the scope not to finish the span immediately on exit, and instead
|
|
|
|
# pass the span into the SynapseRequest, which will finish it once we've finished
|
|
|
|
# sending the response to the client.
|
|
|
|
scope = start_active_span(request_name, child_of=context, finish_on_close=False)
|
|
|
|
request.set_opentracing_span(scope.span)
|
2019-07-23 06:31:16 -06:00
|
|
|
|
2020-07-03 12:02:19 -06:00
|
|
|
with scope:
|
2021-06-18 04:43:22 -06:00
|
|
|
inject_response_headers(request.responseHeaders)
|
2020-07-03 12:02:19 -06:00
|
|
|
try:
|
|
|
|
yield
|
|
|
|
finally:
|
|
|
|
# We set the operation name again in case its changed (which happens
|
|
|
|
# with JsonResource).
|
|
|
|
scope.span.set_operation_name(request.request_metrics.name)
|
2019-07-23 06:31:16 -06:00
|
|
|
|
2021-05-28 09:14:08 -06:00
|
|
|
request_tags[
|
|
|
|
SynapseTags.REQUEST_TAG
|
|
|
|
] = request.request_metrics.start_context.tag
|
|
|
|
|
2022-09-09 10:31:37 -06:00
|
|
|
# set the tags *after* the servlet completes, in case it decided to
|
|
|
|
# prioritise the span (tags will get dropped on unprioritised spans)
|
2021-05-28 09:14:08 -06:00
|
|
|
for k, v in request_tags.items():
|
|
|
|
scope.span.set_tag(k, v)
|