Перейти к основному содержимому

ADR 0035 — Trace без коллектора и путь между слоями в логе

Контекст​

ADR 0026 спроектировал сквозную корреляцию: сессия — корневой trace, traceparent проходит через три точки внедрения, а три сервиса логируют JSON с одним и тем же trace_id. Ничего из этого не было неверным. Проблема в том, что в разработке ничего из этого не существовало — а разработка — это место, где логи читают глазами.

Решение 9 того ADR поставило инструментирование в зависимость от OTEL_EXPORTER_OTLP_ENDPOINT, с обоснованием, что экспортёр, отправляющий в никуда, заполняет лог сбоями соединения. Обоснование верное. Реализация смешала две разные вещи: создание телеметрии и доставку телеметрии.

В api без переменной NodeSDK не создавался. Без start() нет ни зарегистрированного context manager, ни пропагатора, поэтому:

  • currentTraceId() возвращал undefined, а mixin pino не ставил trace_id ни в одну строку;
  • traceparent, который web отправляет в каждом запросе, молча отбрасывался;
  • injectTraceHeaders ничего не внедрял в вызовы к engine.

В engine gate был ещё хуже: инвертирован. Конфигурации :opentelemetry в проекте нет (и не было), поэтому SDK поднимался со значением по умолчанию otel_configuration, то есть {opentelemetry_exporter, %{}}, указывающим на localhost:4318. Engine платил за обречённый batch в разработке и в mix test — ровно ту стоимость, которой gate якобы избегал. А то, что gate выключал, — это OpentelemetryBandit.setup(), то есть извлечение входящего traceparent: единственная деталь, делающая span engine потомком span api. Moduledoc Engine.Telemetry.Span утверждал, что без коллектора всё становится no-op; это было ложью, и тест рядом теперь доказывает обратное.

При расследовании обнаружились три дыры корреляции, все молчаливые:

  1. Engine.Outbox.Event не объявлял колонку metadata. У struct не было ключа, первое условие Drain.traceparent/1 было недостижимым, и каждый job Oban рождался с traceparent: nil. Api записывала колонку правильно с Фазы 5. Ни один worker не читал аргумент, поэтому исправление только схемы оставило бы данные инертными.
  2. traceparent engine→api внедрялся внутри post_returning/3, воронки только POST. Шесть Req.get и llm_turn_stream шли без trace — вся читающая половина разговора между сервисами выглядела как осиротевший trace.
  3. chat-stream.ts обходит api-client.ts и не отправлял traceparent. Это был единственный путь web без trace, причём худший из возможных: ход LLM.

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

Решение​

1. Инструментировать и экспортировать — отдельные решения. SDK поднимается всегда, в обоих сервисах. OTEL_EXPORTER_OTLP_ENDPOINT начинает управлять только местом назначения:

с endpointбез endpoint
apitraceExporter OTLPspanProcessors: [NoopSpanProcessor]
engineзначение по умолчанию opentelemetry_exportertraces_exporter: :none
контекст и распространениезарегистрированызарегистрированы

Явный spanProcessors в api — не украшение: без него SDK падает в getSpanProcessorsFromEnv(), который при пустом OTEL_TRACES_EXPORTER собирает экспортёр на localhost:4318 — тот же дефект, которого пытался избежать gate. А список должен иметь хотя бы один элемент, потому что sdk.start() регистрирует глобальный tracer provider только когда spanProcessors.length > 0; без provider span рождается невалидным, и пропагатор ничего не внедряет.

Оба выбора безопасны для памяти, и по построению: NoopSpanProcessor ничего не удерживает в onEnd, а otel_batch_processor Erlang вызывает disable/1, когда экспортёр none, и начинает возвращать dropped, не трогая ETS. Альтернативы такими не были бы — BatchSpanProcessor с мёртвым экспортёром удерживает 2048 spans и продолжает повторять попытки, а InMemorySpanExporter растёт без предела.

2. tracing.ts экспортирует функцию, а побочный эффект живёт в tracing-boot.ts. startTracing() в виде функции позволяет spec импортировать модуль, не регистрируя глобальное состояние, — что сломало бы trace-context.spec.ts, который намеренно утверждает обратное. Но вызов не может находиться в теле main.ts: TypeScript и SWC поднимают все require наверх, поэтому строка между imports выполнилась бы после загрузки pg и express, а monkey-patch не применяется к уже загруженному модулю. Отдельный модуль решает это, потому что require синхронен.

3. Путь между слоями берётся из AsyncLocalStorage, а не из span. Декоратор @Traced('<camada>') на границах регистрирует класс, метод, слой и длительность в контексте на запрос; глобальный interceptor выдаёт одну строку в конце. Span тоже открывается, но путь от него не зависит — именно это заставляет функцию работать без коллектора.

Шаблон тот же, что у drizzle-context.ts, который уже переносил активную транзакцию по стеку вызовов. У контекста потолок в 64 шага: без него use case, вызывающий репозиторий в цикле, наращивал бы массив на протяжении жизни запроса и затем сериализовал бы всё в одну строку лога.

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

4. @Traced запрещён под apps/api/src/interfaces/http/**. Жёсткое правило, и причина — безопасность. Декораторы Nest (SetMetadata и производные) записывают metadata на объект функции метода; legacy-декораторы применяются снизу вверх, поэтому замена descriptor.value отбрасывает metadata, записанную ниже. В контроллере это @RequireRole, который исчезает, — компилируется, проходит набор тестов и является дырой авторизации.

Декорировать контроллер нечего выигрывать: interceptor покрывает HTTP-границу бесплатно, читая ExecutionContext.getClass() и getHandler(). Вариант без diff в 30 файлах — к тому же безопасный. (Декоратор всё равно копирует metadata дальше, как ремень и подтяжки.)

Два исключения по той же технической причине: ничего, что возвращает Observable или является генератором. Эвристика «это thenable?» классифицировала бы оба как синхронные и закрыла бы span до того, как поток что-то произведёт. traced-llm-provider.chat — асинхронный генератор и остался вне; обработчик @Sse остаётся на interceptor, который использует finalize.

5. ownSpan: true для тех, кто уже управляет собственным span. CreateSessionUseCase.execute открывает session.create, который ADR 0026 назначает корнем trace сессии и который docs/reference/events.md документирует как корень. Обернуть его значило бы сделать span декоратора корнем: trace_id остался бы верным, а документация стала бы ложной, ничего не сломав. С ownSpan шаг пути регистрируется, и новый span не открывается.

6. Pretty в разработке, одна строка JSON в production. В production transport отсутствует, и pino пишет один JSON.stringify на событие — это требование, а не эстетика: Alloy читает stdout pod построчно.

В разработке pino-pretty работает внутри процесса, как поток, а не через transport. Причина конкретна: transport выполняется в worker thread, и опции проходят через structured clone, поэтому messageFormat и customPrettifiers в виде функции передать нельзя — а именно они рисуют дерево слоёв. require защищён try/catch, потому что pino-pretty — devDependency и отсутствует в production-образе; запасной вариант — JSON, а это правильный режим отказа для логгера.

В engine Engine.Telemetry.LogFields стал единым источником полей, JsonLogFormatter только сериализует, а новый PrettyLogFormatter покрывает dev — где dev.exs выбрасывал метку времени и всю metadata, оставляя trace_id, session_id и mfa невидимыми.

7. trace_id остаётся контрактом, и в нём ничего не изменилось. Новые поля (path, duration_ms, layer_count, layer, class, fn) входят как плоские соседи. stage.json Alloy выбирает по выражению, а не перечисляет, поэтому новый соседний ключ игнорируется, а derivedFields Loki продолжает работать. Массив layers остаётся вне production: как строка path это ~150 байт, как массив — в 5-10×, а Loki берёт плату за байт.

8. Три дыры, закрытые вместе. field :metadata в схеме outbox плюс Span.with_session(args["traceparent"], …) и Logger.metadata(session_id:) в двух workers — Logger.metadata/1 не вызывался нигде в engine, и поэтому поле session_id форматтера всегда отсутствовало. Воронка headers/0 в EngineApiClient, покрывающая 8 мест вызова. И traceparent в chat-stream.ts.

Последствия​

  • С нулём коллекторов pnpm dev производит три потока логов с одним и тем же trace_id, сгенерированным в браузере. Это разница между тем, можно или нельзя проследить действие пользователя, пересекающее процессы.
  • Одна строка на запрос показывает путь между слоями с длительностью каждого шага. В dev — как дерево с отступами; в production — как поле path.
  • Асинхронная работа агентов стала реально коррелируемой: job Psicólogo, запущенный закрытием сессии, несёт trace_id породившей его сессии. Раньше — traceparent: nil в каждом job.
  • Читающая половина разговора engine→api вышла из сиротства, включая llm_turn_stream.
  • Engine перестал тратить обречённый batch экспорта в dev и в наборе тестов.
  • Лог api получил тест формы, которого не было: одна строка в production, trace_id наверху и список redact как контракт. Список вырос за счёт служебного токена api↔engine, который не скрывался.
  • allowedHeaders CORS стал явным. Раньше вся корреляция зависела от значения по умолчанию пакета cors, который отражает запрошенный в preflight заголовок, — неявное поведение библиотеки без покрывающего теста.
  • Engine получил журнал доступа (его не было вовсе), а отказ служебного токена перестал быть молчаливым.
  • WEB_LOG_LEVEL подключён в k8s: logger.debug был мёртвым кодом в каждом опубликованном окружении.
  • Два текста, утверждавшие противоположное поведению, исправлены: moduledoc Engine.Telemetry.Span и причина 1 из «когда нет trace» в runbook — последняя была ложной для engine ещё до этого изменения.

Известные ограничения​

  1. Guard выполняется до interceptor. JwtAuthGuard, RateLimitGuard и RolesGuard остаются вне пути (~1-3 мс, уже видимые как spans pg в Tempo). Путь улучшения аддитивен: перенести только runWithRequestContext в middleware и оставить interceptor засевающим и выдающим.
  2. depth при конкурентности приблизителен. Promise.all декорированных вызовов перемешивает глубины, и дерево кривится. Критические пути последовательны.
  3. Строка SSE приходит при закрытии потока, через finalize — возможно, через минуты после начала запроса. Это согласуется со строкой res pino-http, которая тоже ждёт завершения ответа.
  4. genReqId не трогали. Это был бы второй ключ корреляции, который ничто не потребляет, рядом с полем, которое ADR 0026 называет контрактом. Корреляция идёт по trace_id.
  5. Лог web не доходит до Loki. Alloy читает только stdout pod. trace_id браузера служит человеку, чтобы сопоставить строку консоли со span сервера, — остаётся в силе то, что зафиксировал ADR 0026.
  6. @Traced применён только на критических путях (сессии, действия, аутентификация и мост api↔engine). Остальные репозитории остаются вне, по выбору объёма, а не из-за препятствия.
  7. Ни одной RN не создано. Бизнес-правила живут в apps/api/src/domain/, который чист; наблюдаемость — не бизнес-правило. Зафиксировано здесь, чтобы не выглядело забывчивостью.
  8. Web не получил error boundary, и ~20 немых catch {} остаются немыми вне путей аутентификации и чата. Boundary — решение UI, а преобразование остальных механическое — оба заслуживают собственного изменения.