0052. Структурированные журналы, корреляция запросов и метрики процесса

Статус: accepted. Дата: 2026-10-01.

Контекст

После ADR 0048 у API и worker был единственный DiagnosticLogger, но аудит эксплуатации показал:

• уровни только info|warning|error, без настройки; компоненты api|storage|worker; строки длиннее 2048 символов молча исчезали, счётчик потерь был зашит в код (diagnostics.dropped.N, всегда storage);
• строки не содержали службу, версию, PID и хост — по одной строке нельзя было понять, какой процесс её написал;
• запуск API, миграции, GC и scrub печатали произвольный текст (stderr/stdout вперемешку, JSON без времени и уровня); потеря владения, drain и его тайм-аут не журналировались; не было обработчиков unhandledRejection/uncaughtException;
• worker писал только итог задачи без durationMs, attempts, uploadId, generation; исчерпание попыток и отказ продления lease проходили без строки; фоновые задачи писали cleanup.unavailable без причины;
• входящий X-Request-Id игнорировался, traceparent не читался; requestId был в ответе об ошибке, но не попадал в задачи и аудит, хотя API_EVOLUTION обещает request ID в аудите;
• метрик не было вовсе, хотя PROJECT_PLAN требует p95/p99, ошибки и повторы;
• вывод планировщика обновлений Windows терялся, а deploy CLI печатал текст без времени и скрывал только URL PostgreSQL.

Решение

1. Журнал. DiagnosticLogger остаётся собственным и без зависимостей (pino и подобные не нужны для JSON-строк и усложнили бы контроль backpressure). Уровни debug|info|warning|error, минимальный уровень ARKVORY_LOG_LEVEL (по умолчанию info) проверяется при загрузке конфигурации: неизвестное значение — ошибка запуска. Фильтр применяется до сериализации. Компоненты — закрытое объединение api|http|storage|worker|maintenance|migrate|process|diagnostics. Каждая строка начинается с timestamp, level, service (api|worker|migrate|gc|scrub), version (из releases/<version>/release.json, иначе dev), pid, hostname (ограниченный набор символов, ≤ 64), затем component, code. Набор полей закрыт интерфейсом DiagnosticFields; свободный текст — только reason, уже прошедший редактор.
2. Backpressure и размер. Логгер не буферизует сверх high-water mark потока: пока write() вернул false или поток в ошибке, записи считаются и отбрасываются; на drain пишется одна запись diagnostics.dropped с числовым полем dropped. Строковые поля обрезаются (256 символов, reason — 240) с полем truncated; если строка всё равно длиннее 4096 символов (экранирование), она заменяется ограниченной записью diagnostics.oversized с recordCode и requestId. Учётные записи diagnostics.* не фильтруются уровнем. Счётчики written/dropped/truncated/oversized доступны в метриках.
3. Корреляция. X-Request-Id принимается, только если непосредственный peer входит в ARKVORY_TRUSTED_PROXIES и значение — одно, 8–128 символов [A-Za-z0-9._:-], начинается с буквы или цифры; иначе генерируется UUID. Значение по-прежнему возвращается в X-Request-Id. W3C traceparent проверяется строго (нижний регистр hex, версия ≠ ff, ненулевые trace/parent id, для версии 00 без хвоста) и даёт поле traceId в access log и HTTP-диагностике; заголовок не возвращается и никогда не используется для прав. traceparent принимается от любого peer: это контекст для поиска, а не идентификатор сервера, поэтому подделка влияет только на поиск по trace ID, но не на requestId, ответы, задачи и аудит.
4. Передача requestId (миграция 24). Expand-only: nullable request_id varchar(128) в arkvory_jobs, arkvory_security_audit, arkvory_audit; SCHEMA_VERSION = 24. Значение передаётся явно, без глобального состояния и AsyncLocalStorage: RequestContext.authenticate сохраняет копию Principal с необязательным полем requestId, и оно проходит через уже существующие параметры сценариев (Principal → MutationAccess → порт хранилища). Политики авторизации поле не читают. Анонимные login/register получают его отдельным параметром, SecurityActor — необязательным requestId. Повторная постановка задачи заменяет request_id на запрос, который её поставил. Worker продолжает выполнение с requestId задачи. Публичные списки аудита и ответ задачи не меняются: поле не добавлено в wire-контракт, чтобы не менять SDK; корреляция выполняется по журналу или SQL.
5. Worker. completion.started (debug), итог completion.completed|failed|lease_lost с jobId, uploadId, repository, generation, attempts, requestId, durationMs, errorCode и идентификаторами причины. Исчерпание попыток вынесено в JobStore.exhaust() (UPDATE … RETURNING): каждая такая задача даёт ровно одну строку completion.attempts_exhausted (error) у того worker, чей UPDATE её завершил; take() больше не делает это неявно. Отказ продления lease — completion.heartbeat_failed (warning) через наблюдатель PostgresJobLease. Фоновые задачи API пишут errorName/errno/sqlstate через failureCause. GC и scrub пишут gc.*/scrub.* записи (scrub.verification_failed с artifactId), короткая подсказка остаётся в stderr.
6. Жизненный цикл. api.listening (адрес и порт), api.ownership_lost, drain.started (окно, активные запросы, сигнал), drain.settled/drain.timeout и api.stopped с durationMs, drain.expedited для второго сигнала, api.stop_timeout/api.stop_failed. migrate.started/completed/failed с fromSchema/toSchema. Ошибка запуска — startup.failed (API) и worker.unavailable (worker) в stdout плюс короткая подсказка в stderr. API, worker, GC и scrub ставят обработчики unhandledRejection/uncaughtException: одна запись process.unhandled (origin, редактированный reason, errorName/errno/sqlstate), ожидание сброса журнала до 1 с, выход с кодом 1 (crash-only; перезапускает супервизор). Логгер точек входа не закрывается до выхода, чтобы поздний сбой тоже был записан.
7. Метрики. GET /health/metrics (getMetrics, аддитивная операция): Prometheus text 0.0.4, авторизация как у /health/ready — любой действующий credential (401 без него), вне бюджета ARKVORY_MAX_REQUESTS, доступен во время drain. Реестр без зависимостей; метки ограничены шаблоном маршрута (или unmatched), нормализованным методом, классом статуса, направлением передачи; у каждой метрики не более 2048 серий, лишние сворачиваются в серию other и считаются в arkvory_metrics_series_overflow_total. Состав: счётчик ответов и гистограмма длительности (фиксированные границы 5 мс–30 мин), байты запросов/ответов (дельты сокета), активные передачи, глубина очереди и отказы допуска, запросы в работе, записи журнала, версия, время старта, RSS; из БД — число queued/running completion jobs и время ожидания самой давней готовой к выполнению queued-задачи без учёта backoff (кеш 5 с, single-flight, ошибка — счётчик и пропуск значения). Значения процессные и сбрасываются при перезапуске. У worker нет HTTP-слушателя: счётчики исходов задач не публикуются, их дают строки completion.*.
8. Deploy. Одна функция redactSecrets для всех строк deploy CLI (URL PostgreSQL целиком, учётные данные в URL, заголовки Authorization, Bearer, токены GitHub и Arkvory, key=value-секреты, длинные непрозрачные строки), формат <ISO-8601> <LEVEL> <текст>. Планировщик обновлений Windows без консоли перезапускает updates-poll с выводом в logs/updater.log (дескриптор файла передаётся дочернему процессу напрямую, без pipe), ротация по размеру 20 MiB × 5 файлов как у WinSW. Аргументы задачи не меняются, поэтому откат на старый релиз не ломает регистрацию.

Альтернативы

• pino/OpenTelemetry SDK: зрелые форматы и экспорт, но новые зависимости, собственная буферизация и сложнее доказать «не блокирует передачу». Формат JSON-строк совместим со сборщиками (Vector, Fluent Bit, Loki), OTLP можно добавить отдельным ADR.
• AsyncLocalStorage для requestId: меньше правок сигнатур, но скрытый контекст (service locator) теряется на границах очередей и таймеров и не виден в портах. Поле Principal уже передаётся явно в каждый сценарий.
• Отдельный параметр requestId во всех сценариях: явнее, но меняет десятки сигнатур и тестов без выигрыша в безопасности.
• Публичный /metrics: стандартно для Prometheus, но раскрывает маршруты, нагрузку и очереди; оставлено под тем же правилом, что подробная готовность.
• Метрики worker через таблицу БД: потребовали бы новой записи на каждый исход и отдельного ADR о росте таблицы.

Последствия

• Новый код требует миграцию 24 (порядок прежний: migrate, затем запуск). Она только добавляет nullable столбцы без перезаписи таблиц и долгих блокировок; contract-шаг не нужен. Строки, записанные до миграции или процессом без запроса, хранят NULL.
• ARKVORY_LOG_LEVEL=warning|error скрывает и http.access (info). Код записей diagnostics.dropped.N и diagnostics.queue_dropped.N заменён на diagnostics.dropped/diagnostics.queue_dropped с полем dropped; компоненты access log и HTTP-ошибок — http, жизненного цикла — process; запись startup.failed теперь в stdout.
• Вывод GC/scrub — JSON-строки; скрипты, читавшие единственную JSON-строку scrub, должны искать запись scrub.completed.
• Без ARKVORY_TRUSTED_PROXIES входящий X-Request-Id всегда заменяется; балансировщик должен брать ID из ответа. Доверенный proxy обязан перезаписывать X-Request-Id (nginx: proxy_set_header X-Request-Id $request_id), иначе через него пройдёт значение клиента; пример обновлён.
• 403 для /health/metrics не возникает: достаточно любого действующего credential, как для /health/ready. Отдельное право system.observe остаётся проектным (API_MAP).
• Счётчики метрик принадлежат процессу: при нескольких API их суммирует Prometheus; после рестарта используется arkvory_process_start_time_seconds.

Проверка

• tests/observability.test.mjs: фильтр уровней до сериализации, поля процесса и их ограничения, версия из манифеста, обрезка и diagnostics.oversized, учёт потерь, правила X-Request-Id (доверенный/недоверенный peer, CIDR, IPv4-mapped, формат), traceparent, наблюдатель heartbeat, журнал drain.
• tests/metrics.test.mjs: формат text 0.0.4, экранирование, кумулятивные гистограммы, сворачивание серий, метки маршрутов без сырых URL, gauges допуска.
• tests/startup-diagnostics.test.mjs: дочерние API и worker пишут process.unhandled без секретов и выходят с кодом 1.
• tests/deploy-output.test.mjs: формат строк, редактирование, ротация, захват вывода.
• tests/integration/observability.test.mjs: request_id в задаче, строках worker (включая attempts_exhausted), каталожном и security-аудите; недоверенный peer; неизменность списков аудита; traceId в access log; 401 и содержимое /health/metrics.
• tests/integration/migration-upgrade.test.mjs, review-regressions.test.mjs: схема 24 одинакова для новой и обновлённой БД, readiness согласована с SCHEMA_VERSION.