Структурированные логи: действительно видеть, что происходит в проде

Самый неприятный разговор на проде начинается так: «пользователь пишет, что платёж не прошёл». Вы открываете логи и видите там вот это:

Error: Request failed
    at processTicksAndRejections (node:internal/process/task_queues:95:5)

Какой пользователь? Какой запрос? Когда? Что он просил? Ничего. Логи есть, а пользы от них нет.

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

Строка текста против структурированной записи

Обычный лог выглядит так:

console.log(`Пользователь ${userId} создал заказ ${orderId}`)

Читать удобно. Но когда завтра вам понадобятся «все действия этого пользователя за сегодня», вы полезете искать grep'ом по тексту — и поиск сломается в тот момент, когда вы измените формат в одном месте.

Структурированный лог подходит иначе: каждая запись — это объект.

logger.info({ userId, orderId, amount }, 'заказ создан')

На выходе получается JSON:

{"level":"info","time":1789000000,"userId":"u_123","orderId":"o_456","amount":42000,"msg":"заказ создан"}

Разница в том, что теперь вы ищете не по тексту, а по полю. «Все записи, где userId равен u_123» — это однострочный запрос, не зависящий от формата.

В Node.js я использую pino: он быстрый и по умолчанию пишет JSON.

import pino from 'pino'

export const logger = pino({
  level: process.env.LOG_LEVEL ?? 'info',
})

Главный выигрыш: связывание запроса

Структурированный лог хорош сам по себе, но настоящая польза приходит от связывания.

Внутри одного HTTP-запроса появляются десятки записей: вход, аутентификация, три запроса к базе, вызов внешнего API, ответ. Если они не связаны между собой, вы будете вручную выуживать их из записей сотни других запросов.

Решение — выдать каждому запросу один идентификатор и добавлять его во все записи:

app.use((req, res, next) => {
  req.id = req.headers['x-request-id'] ?? crypto.randomUUID()
  req.log = logger.child({ requestId: req.id })
  res.setHeader('x-request-id', req.id)
  next()
})

Три строки кода. Результат большой: теперь поиск по одному идентификатору выдаёт всю историю запроса по порядку.

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

Если сервисов несколько, идентификатор передаётся и между ними — тем же заголовком x-request-id. Тогда логи связываются по всей цепочке.

Правильное использование уровней

Самая частая ошибка с уровнями — писать всё как info. Тогда уровень вообще перестаёт что-либо значить.

Я провожу границу так:

• error — нужно вмешательство человека. Работа не выполнена, пользователь пострадал. Этот уровень связан с алертами.
• warn — неожиданная ситуация, но система справилась сама. Например, внешний API не ответил с первой попытки, а со второй ответил.
• info — бизнес-событие. Заказ создан, пользователь зарегистрировался, отчёт сгенерирован.
• debug — технические подробности. В проде выключен, включается при разборе проблемы.

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

Называйте поля одинаково

Скучно, но в долгую это правило экономит больше всего времени.

Если в одном месте вы пишете userId, в другом user_id, в третьем uid, у вас появляется три варианта поиска и три способа ошибиться. Заведите в проекте один список и придерживайтесь его.

Мой обычный набор: requestId, userId, organizationId, durationMs, statusCode, route. Остальное добавляю по задаче.

Отдельный совет — длительность всегда пишите как durationMs и числом. Если записать текстом ("1.2s"), вы потом не сможете сделать запрос «все запросы медленнее 500 мс».

Что нельзя логировать никогда

Об этой части нужно думать не в конце, а в самом начале, потому что логи обычно хранятся долго и их видит много людей.

Никогда не пишите: пароли, токены, ключи сессий, данные карт, полный заголовок Authorization, номера личных документов.

Самый частый путь утечки — логирование целого объекта:

logger.info({ user }, 'пользователь вошёл')  // весь объект, включая хеш пароля

Правильная форма — явно выбрать нужные поля:

logger.info({ userId: user.id, role: user.role }, 'пользователь вошёл')

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

Как дополнительная защита, в pino можно автоматически скрывать поля:

pino({
  redact: ['req.headers.authorization', 'password', '*.token'],
})

Где хранить логи

На старте — нигде, и это нормально. Лог уходит в stdout, его собирает systemd или Docker, вы читаете через journalctl или docker logs.

Есть одно условие: не пишите в файл сами и не делайте ротацию руками. Это уже решённая задача, а неправильное решение забивает диск и останавливает сервер.

Когда нужна отдельная система сбора (Loki, Elastic и подобные)? Признаков два: появилось несколько серверов или контейнеров, и понадобилось искать по истории за несколько дней. Пока этих двух нет, journalctl | grep работает прекрасно.

Порядок внедрения

Если сейчас в проекте console.log, не пытайтесь заменить всё за день. Порядок такой:

1. Добавьте pino и экспортируйте один logger.
2. В middleware запроса создайте requestId и верните его в заголовке ответа.
3. Там, где обрабатываются ошибки, приведите в порядок уровень error — вычистите шум.
4. Запишите список имён полей.
5. Настройте скрытие чувствительных полей.

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