Логи и контекст запроса

У «Пульса» есть путь API → PostgreSQL → worker, но отдельные строки stdout трудно связать с одним запросом. Добавим структурированные логи и локальный контекст. Вместо свободной фразы создадим событие с устойчивым именем и ограниченным набором полей. Оно должно отвечать на вопрос «какой переход произошёл», не копируя входной запрос, токен или параметры SQL.

Во втором состоянии SDK ещё не создаёт traces. Корреляция внутри одного процесса будет опираться на request ID, передаваемый через AsyncLocalStorage. Он не переносится автоматически в другой процесс и не является полноценным distributed trace. Этот промежуточный шаг помогает увидеть механизм контекста до появления span ID и trace ID. В следующем уроке мы заменим локальную связь стандартным контекстом OpenTelemetry.

Событие вместо свободной строки

Событие report.accepted означает, что INSERT успешно завершился и API принял задание. request.completed содержит шаблон маршрута и класс статуса. Это разные факты: событие принятия не должно возникать перед фиксацией базы, а событие завершения полезно и при отказе. Если сначала написать «готово», а затем выполнить SQL, журнал будет противоречить данным при ошибке соединения.

Формат JSON удобен тем, что поля не нужно извлекать регулярным выражением из произвольной фразы. time задаёт время события, event — устойчивое имя, request_id — связь внутри текущего процесса. Для технической ошибки используем код из заранее определённого набора. Текст исключения не переносим автоматически: он может содержать connection string, SQL, путь или значение, которое пользователь прислал в запросе.

Полный файл telemetry.mjs состояния 02:

import { AsyncLocalStorage } from 'node:async_hooks';
import { randomUUID } from 'node:crypto';
const requests=new AsyncLocalStorage();
export async function inSpan(name,options,work){
  return requests.getStore()?work():requests.run({request_id:randomUUID()},work);
}
export function currentCarrier(){return {};}
export function extracted(carrier){return undefined;}
export function observeRequest(){}
export function queueAge(){}
export function event(name,attributes={}) {
  const allowed=new Set(['route','status_class','error_code','outcome','attempt']);
  const safe=Object.fromEntries(Object.entries(attributes).filter(([key])=>allowed.has(key)));
  console.log(JSON.stringify({time:new Date().toISOString(),event:name,...safe,...requests.getStore()}));
}
export async function shutdown(){}

AsyncLocalStorage хранит объект контекста для асинхронного выполнения. Внешний вызов inSpan() во втором состоянии создаёт локальный request ID, а вложенный вызов для SQL использует уже существующий store. Поэтому параллельные запросы не обязаны обмениваться глобальной переменной currentRequest. Глобальная переменная была бы перезаписана следующим запросом до завершения первого и создала бы ложную корреляцию.

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

Где записывать лог

В API есть события после принятия задания и после окончания обработки HTTP. В worker события обозначают старт и завершение работы. Пока локальный контекст этих двух процессов независим. Даже совпадение UUID задания само по себе не формирует временную иерархию. Не будем маскировать этот разрыв: четвёртая глава явно сохранит переносимый trace context рядом с очередью, а worker восстановит его перед обработкой.

В модуле базы не логируем полный SQL. Название операции INSERT либо UPDATE достаточно для первичного сопоставления. Диагностика конкретного плана запроса выполняется отдельно в контролируемой среде. Выгрузка SQL с параметрами во внешнюю телеметрию может раскрыть значения пользователя и credentials; позже инструментирование базы сохранит ограниченные атрибуты операции без её содержимого.

Логи полезно ставить на переходах ответственности, а не на каждой строке. Принятие HTTP, фиксация задания и окончание worker описывают разные границы. Десятки сообщений «вошли в функцию» увеличивают стоимость и затрудняют поиск, не объясняя результат. Если нужна длительность вложенного действия, лучше создать span. Если нужен общий масштаб, лучше метрика. Выбор сигнала зависит от вопроса, а не от привычки добавлять console.log.

Безопасные поля и уровни

Разрешённые поля в текущем проекте имеют серверные значения: шаблон маршрута, класс статуса, код ошибки, исход операции и номер попытки. Полный URL не сохраняется, потому что query может содержать токен или данные поиска. Тело запроса не сохраняется даже при ошибке parser. Authorization не попадает ни в body события, ни в attributes. Скрыть секрет в интерфейсе Grafana после записи было бы слишком поздно.

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

Текущий wrapper пишет в stdout и не гарантирует долговременное сохранение. После перезапуска терминала или контейнера строки могут быть потеряны по правилам среды. В седьмом уроке появится OTLP logs exporter, а в восьмом Loki. При этом JSON stdout останется полезным локальным представлением. Два пути журналирования не должны случайно удваиваться в одном backend, если среда одновременно собирает stdout и прямой OTLP.

Как читать ожидаемую последовательность

Для одного успешного запроса ожидаются report.accepted и request.completed с одним локальным request ID. Для другого параллельного запроса ожидается другое значение. Внутренний SQL-вызов не создаёт новую идентичность текущего HTTP. Поскольку пример не исполнялся, конкретные UUID и отметки времени не представлены как наблюдённый вывод; проверяется само условие совпадения и разделения событий.

Если INSERT завершился ошибкой, report.accepted не появляется. Вместо него возникает безопасный request.failed, а HTTP получает технический отказ. Лог завершения при этом описывает статус ответа, но не содержит стека с секретами. Такая последовательность помогает отличить неудачную операцию от потерянной строки журнала. Однако отсутствие события всё ещё требует проверки самого пути stdout: сигнал мог не сохраниться.

Полезный вариант для самостоятельного разбора — два одновременно принятых запроса с разной длительностью SQL. Подумайте, как глобальная переменная перепутала бы их события и почему контекст через async storage сохраняет связь. Затем представьте отдельный worker: память процесса API там отсутствует. Этот пример естественно приводит к следующим двум главам, где локальная связь станет распределённой.

После этой главы журнал имеет устойчивую структуру и ограниченную область данных. Он помогает объяснить переходы, но ещё не измеряет интервалы и не объединяет процессы. Следующий урок добавит SERVER-span и SQL-span, а trace ID и span ID появятся в событиях из активного контекста. Так корреляция будет основана на общей модели OpenTelemetry, а не на случайном сходстве строк.

Предыдущий урок: Наблюдаемость сервиса заявок · Следующий урок: Spans запросов API и PostgreSQL

Оглавление серии · Исходники всех состояний.

Документация: Node.js: AsyncLocalStorage, OpenTelemetry: logs.