От алерта до строки лога: как связать три сигнала

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

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

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

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

Вот как выглядит то же ночное расследование, когда мост уже построен.

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

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

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

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

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

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

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

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

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

http_server_requests_seconds_bucket{uri="/orders",le="1.0"} 1027 # {trace_id="4bf92f",span_id="00f067"} 0.873 1713310767.908

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

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

Вторая практическая: одного формата мало. Чтобы exemplars вообще появились, со стороны сервиса нужны три вещи — включённая гистограмма (percentiles-histogram для нужной метрики), трассировка в сборке (без неё нечего и прикладывать) и формат OpenMetrics в самом запросе. Это расширение обычного текстового формата Prometheus: строки метрик те же, но после значения разрешён комментарий с trace_id, а в старом формате такого места нет, поэтому exemplar'ы туда не помещаются. Проверяется одним запросом:

curl -H 'Accept: application/openmetrics-text; version=1.0.0' localhost:8081/actuator/prometheus

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

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

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

management:
  endpoints:
    web:
      exposure:
        include: health,info,metrics,prometheus
  prometheus:
    metrics:
      export:
        descriptions: true
  metrics:
    distribution:
      percentiles-histogram:
        http.server.requests: true     # без гистограммы exemplar'ов не будет
    tags:
      service: ${spring.application.name}
      env: ${ENV:dev}
  tracing:
    sampling:
      probability: 0.05
  otlp:
    tracing:
      endpoint: http://otel-collector.observability:4318/v1/traces

logging:
  structured:
    format:
      console: ecs                     # Spring Boot 3.4+: JSON без сторонней библиотеки

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

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

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

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

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

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

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

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

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

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

По времени и сервису. Из трассы известно, что вызов к платёжному сервису шёл с 03:14:07.312 по 03:14:08.124. Значит, в журнале этого сервиса нужны записи за этот интервал, расширенный на пару секунд в обе стороны. Запрос выглядит как «сервис = payment, время в окне, уровень WARN и выше» — и в ночной тишине такое окно обычно содержит единицы записей, среди которых нужная видна сразу. На нагруженном сервисе окно дополняют вторым признаком: тем же идентификатором заказа, кодом ответа, именем операции.

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

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

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

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

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

Что заменяет трассу. Идентификатор запроса (requestId) в каждой строке журнала каждого сервиса. Он даёт ровно то же, что идентификатор трассы, для связывания записей: по нему собираются все строки одного запроса со всех сервисов. Чего не даёт — иерархии и точных длительностей шагов; их приходится восстанавливать по отметкам времени соседних записей.

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

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

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

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

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

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

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

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

Три ловушки

Выборка съела нужный трейс. Трассировка обычно пишет не все запросы, а часть — иначе объём неподъёмный. И тот единственный медленный запрос, ради которого всё затевалось, вполне может в выборку не попасть. Лечится настройкой, при которой ошибочные и медленные запросы записываются всегда, а обычные — по проценту.

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

Часы разъехались. Когда время на серверах отличается на секунды, порядок событий в общем поиске по логам перестаёт соответствовать реальности, и расследование уводит не туда. Синхронизация времени — скучная инфраструктурная вещь, о которой вспоминают ровно в такие моменты.

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

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

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

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

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

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

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

Во вступлении обещана разница: было полчаса, стало три минуты. Её стоит измерять — иначе улучшение остаётся ощущением, а разговор о том, стоило ли всё это, превращается в спор.

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

Различать диагноз и восстановление важно: починка может быть долгой по объективным причинам (перелив данных, ожидание поставщика), а поиск причины — это про инструменты. Если из сорока минут инцидента тридцать пять ушло на «понять, где сломалось», работать надо с мостами, а не с процедурами.

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

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

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

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

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

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

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

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

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

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

После. В разбор попадает не «добавили индекс», а «почему не заметили рост таблицы»: тревога на время самого запроса в pg_stat_statements, проверка планов на снимке прода при росте данных, автовакуум для таблицы. Для этого нужны те же снимки статистики, что и для отчёта, собранные заранее; в момент инцидента их уже не соберёшь.

Коротко

• Три сигнала связываются одним сквозным идентификатором запроса: он должен быть в трассировке, в каждой строке лога и называться везде одинаково. Проверка моста занимает минуту: взять строку лога и найти по ней трейс.
• Exemplar — ссылка на конкретный запрос рядом со значением метрики; он не увеличивает мощность и требует формата OpenMetrics.
• Путь дежурного: масштаб по графику → конкретный запрос через exemplar или поиск → место в трассировке → строки логов по идентификатору.
• В алерте должны быть симптом со стороны клиента, ссылка на дашборд с нужным временем и инструкция.
• Ловушки: выборка не сохранила нужный трейс, разные сроки хранения логов и трейсов, разъехавшиеся часы.
• Путь в базу: пул упёрся на экране, pg_stat_activity сейчас, разница снимков pg_stat_statements за период, EXPLAIN (ANALYZE, BUFFERS) найденного запроса, правка индексом или таймаутом, проверка по тому же графику, тревога на время запроса в разборе.
• Включается это несколькими настройками (гистограмма, трассировка с адресом коллектора, структурный журнал) и одним решением — единым написанием поля идентификатора для всех сервисов.
• Без трассировки расследование работает на идентификаторе запроса в журналах плюс записи на границах вызовов с длительностью; трассировку подключают, когда этого начинает не хватать.
• Когда идентификатор потерян посередине, связывают по бизнес-ключу (номер заказа в каждой значимой записи), а затем по окну времени и имени сервиса.
• Успех измеряют временем до обнаружения и временем до диагноза, а не только временем восстановления; числа берут из хронологии разбора и смотрят тренд, не сравнивая команды.

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

• Проброс контекста — как идентификатор переезжает между сервисами через HTTP и брокеры.
• SLO и алерты — на что вообще стоит будить дежурного.
• Профилирование и утечки памяти — куда идти, когда трейс показал деградацию во времени.
• Метрики — почему идентификаторы нельзя класть в метки, а в exemplars можно.