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

Оплата не прошла, на экране «Что-то пошло не так». Вы прикладываете скриншот — через день задача возвращается с пометкой «не воспроизводится». Скриншот показал, что пользователю плохо, но не сказал ни где, ни почему.

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

один клик «Оплатить» — три сервиса — три строки лога order-apiпринял POST /payments stock-apiрезерв товара payment-apiсписание денег req=7f3areq=7f3areq=7f3a 10:42:07INFOorder-apireq=7f3aзаказ 42 создан 10:42:07INFOstock-apireq=7f3aтовар зарезервирован 10:42:37ERRORpayment-apireq=7f3aтаймаут шлюза, 30 с на экране — «что-то пошло не так»в логе — какой сервис, в какую секунду и почему

Один клик проходит через три сервиса, и каждый пишет свою строку с общим идентификатором req=7f3a. По нему три лога собираются в одну нитку: две вехи INFO прошли, третья строка — ERROR от payment-api через тридцать секунд ожидания. Экран об этом сказал «что-то пошло не так», лог назвал сервис, секунду и причину.

Что даёт лог, чего не даёт экран

Экран показывает итог, лог — путь к нему. «Оплата не проходит» и «payment-api в 10:42:37 не дождался платёжного шлюза за тридцать секунд» — одна находка на двух уровнях доказательности, и вторая не возвращается с пометкой «не воспроизводится». Шаги воспроизведения она не заменяет: отвечает не на «как повторить», а на «что происходило внутри».

На отдельном стенде лог — файл, который читают tail -f и grep в терминале (минимум команд). Где сервисов много, файлы не читают: строки со всех машин стекаются в общее хранилище с поиском.

Уровни: DEBUG, INFO, WARN, ERROR

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

DEBUG — подробности для разработчика: значения переменных, тела запросов, ответы соседних систем. На стендах включают, на боевой системе обычно нет — и из-за объёма, и потому что в такие строки утекают чужие персональные данные. INFO — вехи сценария: «заказ 42 создан», «платёж отправлен»; по ним видно, докуда дошёл запрос. WARN — «странно, но живём»: повтор попытки, ответ дольше обычного, пустое поле, вместо которого подставили значение по умолчанию. Уровень недооценивают зря: WARN часто идёт за минуты до первого ERROR. ERROR — операция не выполнена, рядом лежит простыня со стеком вызовов: в отчёт её кладут целиком, а читают первую строку — там имя ошибки и сообщение.

Уровни вложены: поставили INFO — строк DEBUG нет вовсе, их не «отфильтровали», а не писали. Поэтому «включите на стенде DEBUG и повторите» — нормальная просьба.

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

Как найти свой запрос в общем потоке

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

Сузить поток помогают три зацепки. Время: записывайте секунду клика, а не «где-то в обед»; здесь же грабля — серверы живут в UTC, а часы у вас местные, и в Москве клик в 12:05 лежит в логе под 09:05. Сдвиг выясняют один раз. Свои данные: почта учётной записи или номер заказа, grep "order-42" app.log. Третья, самая точная, — идентификатор запроса.

Сквозной идентификатор: одна нитка через все сервисы

Клик по кнопке почти никогда не живёт в одном сервисе: заказ создаёт один, товар резервирует второй, деньги списывает третий, и лог у каждого свой. Найдя строку в первом, во втором вы снова в общем потоке. Для этого придуман сквозной идентификатор — случайная строка, которую выдаёт первый принявший запрос сервис и передаёт дальше заголовком, а остальные пишут её в каждую свою строку. Называют по-разному — request id, correlation id, trace id; в заголовках это X-Request-Id или стандартный traceparent. Смысл один: общий ключ, по которому логи сшиваются в один рассказ по времени.

Берут его во вкладке «Сеть»: открыть запрос, посмотреть заголовки ответа. Скопированная строка — пропуск в логи, в баг-репорт её кладут всегда. Нет идентификатора — отдельная находка.

Kibana на пальцах: где лежат собранные логи

Файлы на десяти машинах читать нечем, а после перезапуска контейнера файл исчезает с историей. Поэтому строки отправляют в одно хранилище с поиском — связку чаще всего называют ELK: Elasticsearch хранит и ищет, Logstash (или лёгкий сборщик Filebeat) забирает строки и раскладывает на поля, Kibana даёт экран для поиска. Бывают и другие сборки — Grafana Loki, OpenSearch, — приёмы там те же.

Дело решает окно времени в правом верхнем углу: пока оно стоит на «последние 15 минут», вчерашняя ошибка не найдётся никогда, экран покажет пустоту. Окно ставят до поиска.

Дальше — поиск по полю, а не по всему тексту. Строка разложена на поля level, service, message, request_id, и запрос выглядит как request_id: "7f3a" или service: "payment-api" and level: ERROR. Поиск по слову тоже работает, но шумит. Найденную строку раскрывают целиком, а рядом смотрят соседние.

Метрики и дашборды: зачем нужна Grafana

Лог отвечает про конкретный запрос. На вопрос «стало хуже или всегда так было» он не отвечает — нужны числа, снятые регулярно: запросов в секунду, доля ответов 5xx, время ответа по показателю p95, занятая память, длина очереди. Такое число называют метрикой, набор графиков по ним — дашбордом; рисует их обычно Grafana поверх хранилища метрик вроде Prometheus или Zabbix.

Разница простая: метрика показывает форму проблемы и её момент, лог — причину. Всплеск ошибок в 12:05 на графике — идёте в Kibana с окном 12:04–12:06 и уровнем ERROR. Ручным проверкам дашборд нужен на долгих сценариях: растёт ли время ответа от часа к часу, не течёт ли память.

Когда лог говорит, что дефект не здесь

Дефект летает между командами, пока никто не назвал границу, за которой он возник. Логи её и называют: последняя INFO говорит, кто отработал, первая ERROR — кто не смог.

  • Строк с вашим идентификатором нет вовсе. Запрос не доехал — вопрос к доступности стенда и сети, а не к коду.
  • ERROR у вашего сервиса, а внутри — чужой отказ: «таймаут вызова», «502 от соседа». Дефект на границе: в отчёт идут обе строки.
  • В логе ошибка, а пользователю ушёл статус 200. Это второй дефект: отказ скрыли.

Коротко

  • Лог отвечает не «как повторить», а «что происходило внутри»; строка с временем и сервисом снимает «не воспроизводится».
  • Уровни вложены: при INFO строк DEBUG нет вообще — их включают на стенде заранее.
  • WARN читают наравне с ERROR: он идёт за минуты до отказа.
  • Время в логе обычно в UTC — сдвиг выясняют один раз.
  • Сквозной идентификатор из заголовка ответа сшивает логи сервисов в одну нитку.
  • В Kibana сначала окно времени, потом поиск по полю; Grafana показывает форму проблемы, логи — причину.

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