← назад к разделу

Представьте ночной звонок. Пришёл алерт: доля ошибок на оформлении заказа выросла до четырёх процентов. Дальше начинается то, что знакомо каждому дежурному: одна вкладка с графиками, вторая с трассировкой, третья с логами — и полчаса перекладывания времени и идентификаторов из одной в другую руками.

Причина не в том, что инструменты плохие. Каждый из трёх сигналов настроен правильно и отвечает на свой вопрос: метрика — «сколько и как быстро», трассировка — «где именно», логи — «что произошло». Проблема в том, что между ними нет мостов, и дежурный работает этим мостом сам.

Мост делается один раз и стоит недорого: в Python-сервисе это один процессор structlog, один аргумент в вызове гистограммы и правильный тип ответа у /metrics. Дальше расследование, которое занимало полчаса, занимает три минуты — и это ровно та разница, которая в разборе аварии называется временем восстановления.

Обязательно

Общий идентификатор: то, без чего ничего не связывается

Всё держится на одной вещи — сквозном идентификаторе запроса. Он рождается на входе в систему, едет через все сервисы и попадает в каждый сигнал: в трассировку как идентификатор трейса, в каждую строку лога как поле, а при желании и в метрику.

Механика проброса разобрана отдельно: как контекст живёт внутри сервиса и попадает в логи и как он едет между сервисами в заголовке traceparent. Здесь важно следствие: если идентификатор есть везде, любой сигнал становится точкой входа в остальные два.

В Python мост между трассой и логом — процессор structlog, который читает текущий спан и дописывает поля в каждую запись:

import structlog
from opentelemetry import trace


def add_trace_context(logger, method_name, event_dict):
    span_context = trace.get_current_span().get_span_context()
    if span_context.is_valid:
        event_dict["trace_id"] = format(span_context.trace_id, "032x")
        event_dict["span_id"] = format(span_context.span_id, "016x")
    return event_dict


structlog.configure(
    processors=[
        structlog.contextvars.merge_contextvars,
        add_trace_context,
        structlog.processors.add_log_level,
        structlog.processors.TimeStamper(fmt="iso", utc=True),
        structlog.processors.JSONRenderer(),
    ],
)

Идентификаторы в OpenTelemetry — числа, и format(..., "032x") даёт те же тридцать два шестнадцатеричных знака, что лежат в заголовке traceparent и в хранилище трасс; без форматирования в журнал уйдёт десятичное число, по которому ничего не найдётся.

Два условия, без которых мост не работает. Первое: текущий спан живёт в contextvars, и процессор найдёт его только в том же контексте, где запрос обрабатывается. Задачи asyncio.create_task и asyncio.to_thread контекст копируют, а loop.run_in_executor — нет: запись из такого потока выйдет без идентификатора, пока контекст не передан явно. Второе: библиотеки пишут через стандартный logging, минуя процессоры structlog. Чтобы и их записи получили идентификатор, стандартный журнал пропускают через structlog.stdlib.ProcessorFormatter с тем же процессором — либо подключают LoggingInstrumentor из OpenTelemetry, который сам дописывает в каждую запись поля otelTraceID и otelSpanID. Во втором случае имя поля отличается, и его приводят к общему — см. ниже.

Проверить, что мост построен, можно за минуту. Возьмите любую строку лога боевого сервиса и попробуйте по её идентификатору найти трейс. Не нашли — дальше можно не читать, сначала надо починить это.

Две ошибки встречаются чаще всего. Первая — идентификатор есть не во всех сервисах: цепочка обрывается там, где кто-то не пробросил заголовок, и половина пути невидима. Вторая — поле называется по-разному: trace_id у structlog, otelTraceID у инструментации стандартного журнала, traceId у соседнего сервиса на другом языке. Написание стоит зафиксировать в общем стандарте — trace_id через подчёркивание, как пишет OpenTelemetry в своих спецификациях, — и привести к нему в процессоре, иначе поиск по логам всей системы превращается в угадывание.

Exemplars: клик из графика прямо в трейс

Общий идентификатор связывает трассировку и логи. Метрика остаётся в стороне — в ней по определению нет отдельных запросов, только агрегаты.

Мостик между графиком и трассировкой называется exemplar. Рядом со значением метрики прикладывается ссылка на один конкретный запрос, который в это значение попал. Смотрите на график задержки, видите всплеск — и проваливаетесь из точки на графике прямо в трейс того самого медленного запроса.

Выглядит это в выдаче метрик так:

http_request_duration_seconds_bucket{le="0.5",route="/orders"} 1027.0 # {trace_id="4bf92f3577b34da6a3ce929d0e0e4736",span_id="00f067aa0ba902b7"} 0.3 1791019593.433293

Всё, что после #, и есть exemplar: идентификаторы трейса и спана, затем само наблюдённое значение — здесь 0,3 секунды, длительность того самого запроса, — и отметка времени. Искать его надо именно в строках _bucket гистограммы и в счётчиках с суффиксом _total: у строки _count exemplar'ов не бывает.

Две вещи стоит знать заранее. Первая приятная: exemplar не увеличивает мощность метрики. Это не метка, а довесок к значению, поэтому опасность из статьи про метрики — не класть в метки идентификаторы — здесь не работает. Вторая практическая: prometheus_client сам exemplar не приложит, его передают явно в middleware метрик:

from opentelemetry import trace
from prometheus_client import Histogram

request_duration = Histogram("http_request_duration_seconds", "Длительность запроса", ["route", "method", "status"])


def observe(route: str, method: str, status: str, seconds: float) -> None:
    observer = request_duration.labels(route=route, method=method, status=status)
    span_context = trace.get_current_span().get_span_context()
    if span_context.is_valid and span_context.trace_flags.sampled:
        observer.observe(seconds, exemplar={
            "trace_id": format(span_context.trace_id, "032x"),
            "span_id": format(span_context.span_id, "016x"),
        })
        return
    observer.observe(seconds)

sampled здесь важен: exemplar должен ссылаться на трейс, который действительно записан, иначе ссылка ведёт в пустоту. У меток exemplar'а есть предел — 128 знаков на все имена и значения вместе, и prometheus_client падает с ValueError, если его превысить; два идентификатора в него умещаются, а третья метка с адресом уже нет. И нужен формат OpenMetrics в самом ответе /metrics — обычный текстовый формат Prometheus места для exemplar не имеет. make_asgi_app() отдаёт OpenMetrics сам, когда клиент его просит заголовком Accept; Prometheus просит, если у него включено хранение exemplar'ов (--enable-feature=exemplar-storage).

Проверяется одним запросом:

curl -H 'Accept: application/openmetrics-text; version=1.0.0' localhost:8081/metrics | grep '# {'

Если в ответе после значений появились комментарии с trace_id — мост работает.

Что именно включить в сервисе

Вся эта статья — про связи, и ставятся они несколькими строками, чтобы не собирать по четырём статьям:

from opentelemetry import trace
from opentelemetry.exporter.otlp.proto.http.trace_exporter import OTLPSpanExporter
from opentelemetry.instrumentation.fastapi import FastAPIInstrumentor
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import BatchSpanProcessor
from opentelemetry.sdk.trace.sampling import ParentBased, TraceIdRatioBased
from prometheus_client import make_asgi_app

provider = TracerProvider(sampler=ParentBased(TraceIdRatioBased(0.05)))
provider.add_span_processor(BatchSpanProcessor(OTLPSpanExporter()))
trace.set_tracer_provider(provider)

app.add_middleware(MetricsMiddleware)
FastAPIInstrumentor.instrument_app(app)
mgmt.mount("/metrics", make_asgi_app())

Инструментатор FastAPI ставит свой слой снаружи всех остальных, поэтому к моменту замера в MetricsMiddleware спан уже существует и exemplar есть к чему приложить. Экспортёр отправляет трассы в коллектор, адрес берётся из OTEL_EXPORTER_OTLP_ENDPOINT. И одно решение, которое к коду не относится, но важнее его: как называется поле идентификатора в журнале — trace_id для всех сервисов; если исторически разошлось, приводят к одному правилом на коллекторе, а не двадцатью выкатами.

Проверка, что всё сошлось, — три запроса подряд: в выдаче метрик есть комментарии с trace_id, в журнале есть то же поле с тем же значением, в хранилище трасс по этому значению открывается трасса. Любой не сошёлся — дальше настраивать бессмысленно, сначала этот.

Путь дежурного: четыре шага

Когда идентификатор сквозной, а exemplars включены, расследование становится последовательностью, а не поиском наугад.

алерт симптом и ссылка на панель панель когда началось, какой эндпоинт трейс exemplar: медленный span лог по trace_id: строка ошибки

Четыре перехода связывает один идентификатор трассы: из алерта на панель, с панели в трейс, из трейса в строку лога.

Шаг первый — что сломалось для клиента. Алерт называет симптом: выросли ошибки, выросла задержка, упала доступность. Первое, что нужно определить, — масштаб: это все запросы или один маршрут, все пользователи или один регион. График с разбивкой по route отвечает за минуту, и от ответа зависит всё остальное.

Шаг второй — какой запрос. Из точки на графике проваливаемся в exemplar и получаем конкретный трейс. Если exemplars не настроены, тот же результат достигается вручную: берём отрезок времени и ищем в трассировке самые медленные или упавшие запросы этого маршрута.

Шаг третий — где именно. Трейс показывает путь запроса по сервисам с временем каждого шага. Здесь обычно и находится ответ: восемьсот миллисекунд из девятисот ушли в один вызов, а остальное — шум. Полезно смотреть не только на длительность, но и на количество: двести спанов SELECT orders от инструментации SQLAlchemy внутри одного запроса — это выборка в цикле, только видно её сразу.

Шаг четвёртый — что произошло. По идентификатору трейса достаём все строки логов этого запроса со всех сервисов. Это тот момент, ради которого всё строилось: вместо «поищем ошибки за последние десять минут» — точный список того, что случилось именно в этом запросе, по порядку.

Когда идентификатор потерялся посередине

Идеальная картина — идентификатор во всех записях. Реальная — он теряется: один сервис не пробросил заголовок, запись сделала библиотека без контекста, сообщение ушло в брокер без заголовков, обработчик ушёл в пул потоков через run_in_executor без копии контекста. Расследование на этом останавливать не нужно: связывать можно ещё двумя способами.

По времени и сервису. Из трассы известно, что вызов к платёжному сервису шёл с 03:14:07.312 по 03:14:08.124. Значит, в журнале этого сервиса нужны записи за этот интервал, расширенный на пару секунд в обе стороны, уровня WARNING и выше. В ночной тишине такое окно содержит единицы записей.

По бизнес-идентификатору. Самый недооценённый приём: номер заказа, идентификатор платежа проставляют в записи журнала всегда, потому что они берутся не из контекста, а из самих данных. structlog.contextvars.bind_contextvars(order_id=order.id) в начале сценария — и каждая запись до конца запроса несёт номер заказа, а поиск по нему за сутки собирает всю его историю по всем сервисам, включая асинхронные шаги в других трассах.

Порядок попыток: идентификатор трассы → бизнес-ключ → окно времени плюс имя сервиса. Первый быстрее, третий работает всегда.

Дальше расследование уходит вглубь: в план запроса, если виновата база; в срез памяти, если сервис деградирует со временем; в разбор кода, если логика неверная.

Если трассировки нет

Путь выше предполагает, что трассировка настроена, а у многих сервисов её нет. Расследование всё равно работает — вместо трассы используются журналы, и шаг «где именно» делается иначе.

Что заменяет трассу. Идентификатор запроса в каждой строке журнала каждого сервиса. CorrelationIdMiddleware из asgi-correlation-id берёт его из заголовка X-Request-ID или создаёт новый, кладёт в contextvars и возвращает в ответе; merge_contextvars в structlog доносит его до каждой записи, а хук httpx на исходящие запросы пробрасывает дальше заголовком. Он даёт то же для связывания записей, но не даёт иерархии и точных длительностей шагов.

Что для этого нужно. Одна запись на границе каждого исходящего вызова с длительностью и результатом: log.info("external call", system="payment", op="charge", duration_ms=812, status=200). Такая строка заменяет спан почти полностью: по ней видно, кто медленный, и её можно агрегировать. То же на входе: одна запись в конце обработки с общим временем и кодом ответа — журнал доступа, только не текстовый от uvicorn, а свой, в JSON и с идентификатором; текстовый при этом выключают флагом --no-access-log.

Порядок расследования без трассировки. Из графика берём отрезок времени и маршрут. В журнале ищем записи этого маршрута с большой длительностью или ошибкой. Берём идентификатор запроса одной из них и запрашиваем все записи с этим значением — получаем последовательность шагов с временем.

Когда пора за трассировкой. Как только расследования начинают спотыкаться о цепочки глубже одного соседа, параллельные шаги и «двести запросов к базе внутри одного обращения». До этого место трассировки занимает дисциплина в журналах, и это честный первый шаг. Общее правило: дешёвое делают раньше дорогого. Идентификатор в журналах — день работы и ноль инфраструктуры; трассировка — коллектор, хранилище, сроки, выборка.

Что положить в сам алерт

Половина потерянного времени тратится ещё до первого графика — пока дежурный вспоминает, что это за сервис и куда смотреть.

Полезный алерт называет симптом со стороны клиента, а не техническую причину: «4 % ошибок на оформлении заказа» вместо rate(errors) > 0.04. Дальше — ссылка на нужный дашборд с уже выставленным временем. И ссылка на инструкцию: что это за срабатывание, какие бывают причины, что проверить в первую очередь. Про это же говорит статья про SLO и алерты: если реакция на срабатывание всегда «посмотрел и ничего не сделал», такой алерт лучше удалить.

Три ловушки

Выборка съела нужный трейс. TraceIdRatioBased(0.05) решает судьбу трассы в её начале, когда ещё не знает, кончится ли она ошибкой, — и тот единственный медленный запрос, ради которого всё затевалось, в выборку может не попасть. Лечится выборкой по хвосту на коллекторе: он дожидается всех спанов и оставляет все ошибочные и медленные плюс процент остальных. В сервисе при этом ставят ALWAYS_ON или высокий процент, а экономят на коллекторе.

Логи и трассировка живут разное время. Логи две недели, трассы три дня — через пять дней после аварии половина расследования недоступна. Сроки согласовывают, а для аварий сохраняют выборку отдельно, до разбора.

Часы разъехались. Когда время на серверах отличается на секунды, порядок событий в общем поиске по логам перестаёт соответствовать реальности. Проверяется одним запросом: взять свежую трассу, выбрать все записи журнала с её идентификатором и посмотреть на отметки по сервисам — у вложенного вызова запись «начали» не может быть раньше, чем у вызывающего. Расхождение в десятки миллисекунд — норма; секунды означают, что на машине не работает служба синхронизации времени.

Все три ловушки решаются в одном месте

У ловушек выше есть общее свойство: ни одна не лечится в коде приложения. Выборка по хвосту, сроки хранения, вырезание персональных данных и приведение имён полей к одному написанию — это настройки коллектора, отдельного процесса между сервисами и хранилищами. Приложение решает судьбу трассы в её начале; коллектор видит её целиком. Если в вашей схеме сервисы отправляют сигналы напрямую в хранилище, ни одну из трёх ловушек закрыть не получится. Устройство коллектора — в статье про трассировку.

Чем мерить, что стало лучше

Разницу «было полчаса, стало три минуты» стоит измерять — иначе улучшение остаётся ощущением.

Две величины по каждой аварии. Время до обнаружения — от начала проблемы до срабатывания тревоги (случаи, когда первой была жалоба пользователя, считают отдельно: это провал мониторинга). И время до диагноза — от тревоги до момента, когда дежурный понял причину. Второе — то, на что влияет всё, описанное в статье, и именно его обычно не считают, ограничиваясь временем восстановления.

Откуда берутся числа. Из разбора: в шаблоне хронологии стоят три обязательные отметки — начало проблемы, срабатывание тревоги, момент диагноза. Через квартал есть медиана и понятный ответ, помогает ли то, что вы строите. Как устроен сам разбор — в статье про разборы аварий.

Чего не надо делать с этими числами. Не сравнивать команды и не ставить целью: время до диагноза зависит от сложности аварии. Это показатель для себя: тренд за квартал и выбросы — инциденты, где диагноз занял часы.

Дополнительно: при первом чтении можно пропустить

Глубже: когда виновата база: от графика до EXPLAINрасширенное

В половине инцидентов лог говорит «медленно ответила база», и путь продолжается уже в PostgreSQL.

Сигнал. Тревога на p99 оформления заказа. На экране первой минуты трафик обычный, ошибок нет, а число выданных соединений пула SQLAlchemy упёрлось в pool_size + max_overflow, и в журнале появились QueuePool limit of size 5 overflow 10 reached, connection timed out: сервис ждёт базу.

Сейчас. pg_stat_activity показывает, чем заняты соединения в эту минуту: десятки сессий в одном и том же запросе с ожиданием ввода-вывода, или одна сессия держит блокировку, а остальные стоят за ней в Lock. Первое — тяжёлый запрос, второе — блокировка; как читать состояния, в статье про мониторинг PostgreSQL.

За период. Если проблема длится час, берут разницу снимков pg_stat_statements между «до» и «сейчас»: какой запрос набрал больше всего суммарного времени за интервал.

Запрос и план. Найденный запрос с реальными параметрами прогоняют через EXPLAIN (ANALYZE, BUFFERS): последовательное чтение таблицы, выросшей за месяц, или оценка в сто строк при фактических ста тысячах.

Правка и проверка. Индекс через CREATE INDEX CONCURRENTLY, переписанный запрос, statement_timeout на роль, чтобы один запрос не забирал пул. Правку видно на том же экране через минуту: пул отпустило, p99 вернулся. Алерт закрывают, когда цифра вернулась, а не когда правка применена.

Коротко

  • Три сигнала связываются одним сквозным идентификатором: в Python его кладёт в каждую запись процессор structlog, читающий текущий спан из contextvars; идентификаторы форматируют 032x и 016x, стандартный журнал пропускают через ProcessorFormatter или LoggingInstrumentor.
  • Exemplar — ссылка на конкретный запрос рядом со значением метрики: аргумент exemplar= у observe для сэмплированных трасс и формат OpenMetrics в ответе /metrics; мощность метрики не растёт, предел меток — 128 знаков.
  • Включается всё несколькими строками: провайдер с ParentBased(TraceIdRatioBased), BatchSpanProcessor с OTLPSpanExporter, FastAPIInstrumentor, процессор structlog, make_asgi_app на management-порту; поле зовётся trace_id во всех сервисах.
  • Путь дежурного: масштаб по графику с разбивкой по маршруту → конкретный запрос через exemplar → место в трассе → строки логов по идентификатору.
  • Когда идентификатор потерян, связывают по бизнес-ключу через bind_contextvars в каждой значимой записи, затем по окну времени и имени сервиса.
  • Без трассировки работает asgi-correlation-id плюс записи на границах вызовов с длительностью и свой JSON-журнал доступа; трассировку подключают, когда этого не хватает.
  • В алерте — симптом для клиента, ссылка на дашборд с временем и инструкция.
  • Ловушки: выборка в начале трассы теряет медленный запрос, разные сроки хранения, разъехавшиеся часы; все три лечатся на коллекторе, а не в сервисе.
  • Успех измеряют временем до обнаружения и временем до диагноза из хронологии разбора; путь в базу — пул SQLAlchemy, pg_stat_activity, pg_stat_statements, EXPLAIN (ANALYZE, BUFFERS).

Что почитать дальше