Один request_id через границы: как связать журнал без ложной трассировки

Симптом выглядит как три независимые ошибки: gateway вернул 502, API пишет о невалидном ответе адаптера, а worker сообщает о повторе операции. Время у строк близкое, но этого недостаточно: соседний запрос мог попасть в тот же промежуток. Цена угадывания — обвинить последний сервис в журнале, изменить таймаут и скрыть настоящую границу, где пропал контекст. Нужна не ещё одна строка, а способ доказать принадлежность записей одному запросу.

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

Сначала назначаем владельца идентификатора

Идентификатор нельзя генерировать в каждом модуле. Если gateway, контроллер и адаптер создадут по своему значению, журнал снова распадётся на части, хотя каждое сообщение формально структурировано. Владельцем становится первая граница, которая приняла запрос. Для HTTP это middleware или обработчик до роутинга. Он берёт входной X-Request-Id только если значение похоже на ожидаемый служебный формат; иначе создаёт новое и добавляет его в ответ для ручной проверки.

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

Передаём контекст как зависимость, а не через глобальную переменную

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

function isRequestId(value) {
  return typeof value === 'string' && /^req-demo-[0-9]{8}-[0-9]{2}$/.test(value);
}

function requestContext(baseLogger) {
  return function middleware(req, res, next) {
    const incoming = req.get('x-request-id');
    const requestId = isRequestId(incoming) ? incoming : 'req-demo-20200714-01';
    req.log = baseLogger.child({
      request_id: requestId,
      service: 'demo-gateway',
      environment: 'training'
    });
    res.setHeader('x-request-id', requestId);
    next();
  };
}

async function submitTrainingOrder(context, client) {
  context.log.info({ event: 'order.submit.started' }, 'Synthetic order submission started');
  await client.post('/training/orders', { headers: { 'x-request-id': context.request_id } });
}

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

У вложенных операций может появиться собственный operation_id, но он не заменяет request_id. Например, один запрос запускает несколько независимых попыток записи. Тогда request_id отвечает на вопрос «к какому входному действию относится строка?», а operation_id — «какая локальная попытка её создала?». Если в статье нет этого различия, повтор задачи легко ошибочно принять за второй пользовательский запрос. Начинать всё равно лучше с первого ключа; второй добавляют только при реальном вопросе диагностики.

Показываем путь одного синтетического запроса

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

{"timestamp":"2020-07-14T09:30:11.001Z","service":"demo-gateway","level":"info","event":"http.request.received","request_id":"req-demo-20200714-01","message":"Synthetic request accepted"}
{"timestamp":"2020-07-14T09:30:11.018Z","service":"demo-catalog-api","level":"info","event":"catalog.reserve.started","request_id":"req-demo-20200714-01","message":"Synthetic reservation started"}
{"timestamp":"2020-07-14T09:30:11.042Z","service":"demo-gateway","level":"info","event":"http.request.completed","request_id":"req-demo-20200714-01","message":"Synthetic request completed"}

# Учебный запрос: выбираем только события одного request_id, затем сортируем по времени.
jq -s 'map(select(.request_id == "req-demo-20200714-01")) | sort_by(.timestamp)' training.jsonl

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

Корреляция не равна причинности

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

Такое ограничение защищает текст от ложной уверенности. Можно честно показать один путь в JSONL, не рисуя систему так, будто она уже знает все связи. Внутренний заголовок тоже не делает интеграцию безопасной сам по себе: он должен быть ограничен форматом, не должен нести пользователя или секрет и не должен попадать в бизнес-ключ. Отражать его клиенту удобно для ручной проверки, но это не разрешение принимать произвольный внешний идентификатор без проверки.

Три места, где контекст теряется чаще всего

Первое место — исходящий HTTP-клиент. В контроллере есть дочерний логгер, но вызов клиента создаётся глубоко в адаптере и не получает заголовок. Симптом: на стороне gateway событие есть, на стороне API его нельзя найти по тому же ключу. Причина не в поисковом запросе, а в скрытой зависимости. Проверка проста: учебный клиент должен принимать контекст или request_id явно и записывать его в синтетический заголовок. Действие — передать этот объект в сигнатуру адаптера, а не получать «текущий запрос» из глобального состояния.

Второе место — обработчик ошибки. Код ловит исключение, создаёт новый логгер без базового контекста и пишет красивую error-строку. Симптом: именно самое важное событие оказывается без request_id. Причина — обработчик видит ошибку как отдельную операцию, хотя он всё ещё внутри исходного запроса. Проверка — добавить в учебный путь контролируемую ошибку и убедиться, что error.code, service и тот же ключ остаются на месте. Действие — передавать дочерний логгер в ветку catch и нормализовать причину вместо сериализации всего исключения.

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

Эти три случая показывают, почему корреляция — контракт границ, а не свойство библиотеки. Логгер может облегчить дочерний контекст, но не может сам угадать, куда код отправит HTTP-вызов, где обработает ошибку и что считается новой операцией. Пока каждая из этих границ названа, review видит место решения. Когда она скрыта, даже хороший JSON распадается на отдельные аккуратные, но бесполезные события.

Маршрут проверки перед расширением схемы

1. Выбрать одну входную границу и объявить её владельцем request_id.
2. Описать валидный формат и явное поведение для отсутствующего либо невалидного заголовка.
3. Создать дочерний логгер на границе и передавать контекст явно через исходящий клиент.
4. Сделать три синтетические записи от двух модулей с одним идентификатором.
5. Выполнить учебный JSONL-запрос и проверить, что потеря либо замена ключа заметна.
6. Отдельно решить, нужен ли operation_id; не добавлять trace-термины, если нет модели spans и их проверки.

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

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

• 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 — перечисляет данные, которые не следует писать в журнал, и предлагает проверять событие до записи