Структурированные логи: сначала контракт одного события

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

В июле 2020 я бы не начинал с большой платформы наблюдаемости. Достаточно договориться о контракте одного события и провести через приложение один request_id. Тогда у записи есть известные поля, у запроса — один ключ поиска, а у ревью — конкретный объект проверки. Цель этой практики скромнее полной распределённой трассировки: собрать последовательность событий одного учебного HTTP-запроса и не потерять смысл при сериализации.

Событие — это контракт, а не оформленная строка

Структурированный лог — JSON-объект с устойчивыми именами полей. Его сообщение остаётся коротким объяснением для человека, но поиск и группировка опираются не на порядок слов, а на event, уровень, сервис и идентификатор запроса. RFC 5424 разделяет заголовок и структурированные данные именно потому, что отдельные значения должны быть распознаваемыми. JSON не делает событие полезным автоматически: полезность появляется, когда поля имеют владельца и одинаковый смысл в каждом модуле.

Я разделяю обязательные и локальные поля. Обязательные пишутся на каждом значимом событии HTTP-обработки: время, уровень, сервис, среда, имя события, идентификатор запроса и краткое сообщение. Локальные поля добавляет владелец операции: маршрут, код ответа, имя адаптера или длительность конкретного шага. Не стоит помещать в базовый объект целый req, ответ базы или объект пользователя. Такой объект плохо читается, имеет случайную форму и почти наверняка приносит данные, которые журналу не нужны.

Собираем запись до того, как она попадёт в stdout

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

const required = [
  'timestamp', 'level', 'service', 'environment',
  'event', 'request_id', 'message'
];

function buildTrainingEvent(base, local) {
  const event = { ...base, ...local };
  const missing = required.filter((name) => event[name] === undefined);
  if (missing.length) throw new Error('missing log fields: ' + missing.join(', '));
  return event;
}

const entry = buildTrainingEvent(
  {
    timestamp: '2020-07-14T09:30:11.042Z',
    level: 'info', service: 'demo-catalog-api', environment: 'training',
    event: 'http.request.completed', request_id: 'req-demo-20200714-01',
    message: 'Synthetic request completed'
  },
  { http: { method: 'POST', route: '/training/orders/:orderId', status_code: 202 } }
);
process.stdout.write(JSON.stringify(entry) + "\n");

Здесь route — шаблон, а не полный URL с параметром. Это сразу ограничивает кардинальность: для ста заказов остаётся один маршрут, а не сто новых значений. event тоже выбирается из небольшого словаря, например http.request.received, order.validation.failed, http.request.completed. Если имя события собирается из текста ошибки или номера заказа, его нельзя надёжно считать и сравнивать.

Не надо подменять контракт декоративной вложенностью. Поля timestamp и request_id нужны в одном и том же месте, потому что по ним читается любая запись. Вложенный http нужен только HTTP-событиям. У воркера вместо него может быть job; у интеграции — adapter. Общий корень остаётся одним, но контекст не превращается в плоский список из пятидесяти пустых полей.

Проверяем один синтетический запрос целиком

Все идентификаторы, маршруты и значения в примерах ниже учебные и синтетические. Это не журнал реального пользователя и не отчёт о production-инциденте.

{"timestamp":"2020-07-14T09:30:11.001Z","level":"info","service":"demo-gateway","environment":"training","event":"http.request.received","request_id":"req-demo-20200714-01","message":"Synthetic request accepted","http":{"method":"POST","route":"/training/orders/:orderId"}}
{"timestamp":"2020-07-14T09:30:11.021Z","level":"info","service":"demo-catalog-api","environment":"training","event":"order.validation.completed","request_id":"req-demo-20200714-01","message":"Synthetic order passed validation","order":{"state":"accepted"}}
{"timestamp":"2020-07-14T09:30:11.042Z","level":"info","service":"demo-gateway","environment":"training","event":"http.request.completed","request_id":"req-demo-20200714-01","message":"Synthetic request completed","http":{"status_code":202,"duration_ms":41}}

# Учебный поиск по одному запросу, файл training.jsonl не является production-журналом:
jq -c 'select(.request_id == "req-demo-20200714-01")' training.jsonl

Проверка отвечает на узкий вопрос: есть ли три ожидаемые записи с одинаковым request_id и различными владельцами? Она не доказывает, что запрос прошёл все возможные сервисы, и не заменяет трассу критического пути. Если второй сервис не пишет запись, диагноз звучит конкретно: контекст не был передан через эту границу или событие не было добавлено. Это лучше, чем искать по минуте и надеяться, что порядок строк совпал.

Неизбежные ограничения контракта

Поле request_id высококардинально: почти каждый запрос даёт новое значение. Это нормально для поиска конкретной истории, но плохая причина использовать его как измерение в агрегате или как часть имени события. Похожая ошибка — писать user_id, адрес почты, полный query string или текст входного тела «на всякий случай». Они не помогают базовой проверке одного запроса и расширяют поверхность приватных данных. В минимальном контракте их нет.

Чувствительные ключи нужно редактировать до сериализации и тестировать отдельно. Маска в интерфейсе просмотра недостаточна: строка уже могла попасть в файл, транспорт или резервную копию. В этой партии учебный fixture заменяет authorization и cookie на [REDACTED]; он не использует реальные токены. Список путей redaction зависит от формы объекта, поэтому его надо держать рядом с кодом, который формирует запись, а не надеяться на память автора запроса.

Проверяем контракт как часть изменения, а не после поиска

Контракт ломается тихо: новый обработчик пишет requestId вместо request_id, забывает environment или собирает event из текста исключения. JSON при этом остаётся валидным, поэтому парсер не жалуется. Нужна более предметная проверка. Для каждого учебного события тест строит объект, сверяет обязательные ключи, проверяет формат идентификатора и сравнивает имя события с разрешённым словарём. Это не заменяет типы и не требует отдельного сервиса схем, но ловит расхождение до того, как оно станет привычкой в соседних модулях.

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

Словарь событий тоже стоит ревьюить как API. Имя http.request.completed говорит о факте, а не о конкретной реализации; postgres.timeout.42 смешивает компонент, причину и случайный номер. Когда событие приходится переименовать, старое значение не нужно оставлять «на всякий случай» во всех ветках. Лучше явно обозначить переход и обновить учебный запрос. Иначе поиск начнёт возвращать два почти одинаковых набора, а следующая статья снова будет объяснять, почему журнал нельзя читать автоматически.

Граница с числовыми сигналами

Лог отвечает на вопрос о конкретном случае: что происходило с req-demo-20200714-01? Числовой сигнал отвечает на другой вопрос: как часто повторяется известный вид события? В этом месяце достаточно не смешивать эти роли. Уникальный request_id полезен в JSONL, но не должен становиться ключом для подсчёта. Напротив, ограниченное event и service можно позднее использовать для простого числа случаев. Такое разделение предотвращает два симметричных дефекта: попытку искать один запрос в агрегате и попытку хранить бесконечный набор уникальных значений ради красивого графика.

Из этого следует практическое правило для автора события. Сначала он спрашивает: «мне нужно найти одну историю или сравнить повторяющиеся случаи?» В первом ответе добавляет request_id и локальный контекст. Во втором выбирает небольшой словарь имён и нормализованный код. Если требуется оба ответа, поля существуют рядом, но их назначение не смешивается. Никакой готовой платформы здесь не предполагается: договорённость уже работает в одном файле JSONL и не мешает более зрелому инструменту появиться позже.

Маршрут внедрения без большой переделки

1. Выбрать один HTTP-маршрут для учебной проверки и выписать его владельцев.
2. Зафиксировать семь обязательных полей и словарь из трёх–пяти имён событий.
3. Добавить request_id на входной границе и передать дочерний логгер в следующий модуль.
4. Сгенерировать только синтетический запрос и проверить поиск всех его записей по одному идентификатору.
5. Добавить redaction для известных чувствительных ключей, затем проверить, что fixture не выпускает их значение.
6. Только после этого повторить схему на соседнем маршруте; не переносить сырые объекты ради скорости внедрения.

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

Проверяемые источники

• RFC 5424: The Syslog Protocol — задаёт отдельные поля заголовка и формат STRUCTURED-DATA; это полезный контрпример строке, которую затем приходится разбирать регулярным выражением
• RFC 8259: The JavaScript Object Notation (JSON) Data Interchange Format — фиксирует правила JSON-значений и строк; логгер должен выдавать валидную запись, а не склеивать псевдо-JSON вручную
• Pino: API documentation — документирует дочерние логгеры и параметр redact; перед применением нужно сверить эти возможности с версией, установленной в конкретном проекте
• OWASP Logging Cheat Sheet — перечисляет данные, которые не следует писать в журнал, и предлагает проверять событие до записи