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

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

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

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

Обязательно

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

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

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

В Go мост между трассой и логом — обработчик slog, который читает контекст спана из ctx и дописывает поля в каждую запись:

type traceHandler struct{ slog.Handler }

func (h traceHandler) Handle(ctx context.Context, r slog.Record) error {
    if sc := trace.SpanContextFromContext(ctx); sc.IsValid() {
        r.AddAttrs(
            slog.String("trace_id", sc.TraceID().String()),
            slog.String("span_id", sc.SpanID().String()),
        )
    }
    return h.Handler.Handle(ctx, r)
}

func (h traceHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
    return traceHandler{h.Handler.WithAttrs(attrs)}
}

func (h traceHandler) WithGroup(name string) slog.Handler {
    return traceHandler{h.Handler.WithGroup(name)}
}

logger := slog.New(traceHandler{slog.NewJSONHandler(os.Stdout, nil)})
slog.SetDefault(logger)

Два условия, без которых мост не работает. Первое: писать надо slog.InfoContext(ctx, …), а не slog.Info(…) — без контекста обработчику неоткуда взять спан, и половина записей выйдет без идентификатора. Второе: WithAttrs и WithGroup обязаны вернуть обёртку, иначе logger.With("component", "orders") снимет её, и записи этого логгера идентификатор потеряют. Готовый мост есть в go.opentelemetry.io/contrib/bridges/otelslog, и если он подключён, своего писать не нужно.

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

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

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

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

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

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

http_request_duration_seconds_bucket{route="/orders",le="1"} 1027 # {trace_id="4bf92f",span_id="00f067"} 0.873 1713310767.908

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

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

func observe(ctx context.Context, route, method, status string, d time.Duration) {
    obs := reqDuration.WithLabelValues(route, method, status)
    if sc := trace.SpanContextFromContext(ctx); sc.IsSampled() {
        obs.(prometheus.ExemplarObserver).ObserveWithExemplar(d.Seconds(), prometheus.Labels{
            "trace_id": sc.TraceID().String(),
            "span_id":  sc.SpanID().String(),
        })
        return
    }
    obs.Observe(d.Seconds())
}

IsSampled здесь важен: exemplar должен ссылаться на трейс, который действительно записан, иначе ссылка ведёт в пустоту. И нужен формат OpenMetrics в самом ответе /metrics — обычный текстовый формат Prometheus места для exemplar не имеет:

mgmt.Handle("/metrics", promhttp.HandlerFor(reg, promhttp.HandlerOpts{EnableOpenMetrics: true}))

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

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

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

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

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

tp := sdktrace.NewTracerProvider(
    sdktrace.WithBatcher(exporter),
    sdktrace.WithSampler(sdktrace.ParentBased(sdktrace.TraceIDRatioBased(0.05))),
)
otel.SetTracerProvider(tp)
otel.SetTextMapPropagator(propagation.TraceContext{})

r.Use(otelhttp.NewMiddleware("order-service"))
r.Use(metrics.Middleware)
slog.SetDefault(slog.New(traceHandler{slog.NewJSONHandler(os.Stdout, nil)}))
mgmt.Handle("/metrics", promhttp.HandlerFor(reg, promhttp.HandlerOpts{EnableOpenMetrics: true}))

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

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

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

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

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

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

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

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

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

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

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

По бизнес-идентификатору. Самый недооценённый приём: номер заказа, идентификатор платежа проставляют в записи журнала всегда, потому что они берутся не из контекста, а из самих данных. slog.InfoContext(ctx, "payment declined", "order_id", o.ID) — и поиск по номеру заказа за сутки собирает всю его историю по всем сервисам, включая асинхронные шаги в других трассах.

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

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

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

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

Что заменяет трассу. Идентификатор запроса в каждой строке журнала каждого сервиса. middleware.RequestID из chi берёт его из заголовка X-Request-Id или создаёт новый; дальше он кладётся в контекст и в логи тем же обработчиком slog, что и trace_id, и пробрасывается в исходящие запросы заголовком. Он даёт то же для связывания записей, но не даёт иерархии и точных длительностей шагов.

Что для этого нужно. Одна запись на границе каждого исходящего вызова с длительностью и результатом: slog.InfoContext(ctx, "external call", "system", "payment", "op", "charge", "duration_ms", 812, "status", 200). Такая строка заменяет спан почти полностью: по ней видно, кто медленный, и её можно агрегировать. То же на входе: одна запись в конце обработки с общим временем и кодом ответа — журнал доступа, который middleware.Logger из chi пишет сам.

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

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

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

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

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

Три ловушки

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

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

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

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

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

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

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

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

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

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

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

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

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

Сигнал. Тревога на p99 оформления заказа. На экране первой минуты трафик обычный, ошибок нет, а pgx_pool_acquired_conns упёрся в MaxConns и растёт EmptyAcquireCount: сервис ждёт базу.

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

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

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

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

Коротко

  • Три сигнала связываются одним сквозным идентификатором: в Go его кладёт в каждую запись обработчик slog, читающий спан из ctx, поэтому пишут InfoContext, а WithAttrs и WithGroup сохраняют обёртку.
  • Exemplar — ссылка на конкретный запрос рядом со значением метрики: ObserveWithExemplar на гистограмме для сэмплированных трасс и EnableOpenMetrics у promhttp; мощность метрики не растёт.
  • Включается всё пятью строками: провайдер трасс с ParentBased(TraceIDRatioBased), otelhttp раньше метрик, обработчик slog, promhttp с OpenMetrics; поле зовётся trace_id во всех сервисах.
  • Путь дежурного: масштаб по графику с разбивкой по маршруту → конкретный запрос через exemplar → место в трассе → строки логов по идентификатору.
  • Когда идентификатор потерян, связывают по бизнес-ключу в каждой значимой записи, затем по окну времени и имени сервиса.
  • Без трассировки работает middleware.RequestID плюс записи на границах вызовов с длительностью; трассировку подключают, когда этого не хватает.
  • В алерте — симптом для клиента, ссылка на дашборд с временем и инструкция.
  • Ловушки: выборка в начале трассы теряет медленный запрос, разные сроки хранения, разъехавшиеся часы; все три лечатся на коллекторе, а не в сервисе.
  • Успех измеряют временем до обнаружения и временем до диагноза из хронологии разбора; путь в базу — пул, pg_stat_activity, pg_stat_statements, EXPLAIN (ANALYZE, BUFFERS).

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