Пара 22: Структурированные логи и расследование запроса

90 минут · 3 курс, ML.

Содержание и результат

Найти событие по request_id и составить временную линию без утечки входных данных.

План занятия

0–10: контекст и исходная задача. 10–40: устройство и механизмы. 40–55: демонстрация команд. 55–80: лабораторная работа. 80–90: разбор результата и фиксация исправлений.

Практика выполняется в своей учебной папке и на localhost. Подготовка окружения описана в lab/README.md.

Структура события

Время, уровень, событие, версия и идентификатор запроса.

JSON-строки удобны для машинного фильтра. Наш журнал содержит timestamp, event, request_id, route, status, duration_ms и model_version. Тело входа не пишется. INFO означает обычное событие, WARNING — ожидаемую проблему запроса, ERROR — внутреннюю ошибку или отказ сохранения. Уровни — соглашение команды; важно определить, что действительно требует действия. В stdout идут operational logs, а в /data/events.jsonl сохраняется учебный результат; это разные роли хранения. Журнал может ротироваться или исчезнуть, поэтому доказательства важного инцидента сохраняем отдельно с минимальными данными.

Аналогия: квитанция позволяет найти заказ без фотографии всех документов клиента.

Корреляция вместо угадывания

По одному идентификатору сопоставляем ответ и запись.

Сервис выдаёт собственный случайный X-Request-ID, не доверяя произвольному пользовательскому заголовку как безопасной метке. Клиент сохраняет заголовок, оператор ищет соответствующую строку. Для нескольких сервисов единый trace context обычно переносится стандартизированным способом; на курсе показываем идею, не пишем собственную tracing-платформу. Время фиксируется в UTC, чтобы не путать ноутбуки и серверы; при отображении учитываем локальную зону. Расхождение часов может нарушить порядок событий между узлами. По одной строке нельзя придумывать незафиксированные действия.

Аналогия: номер обращения связывает разговоры разных смен поддержки.

Конфиденциальность и сроки хранения

Больше логов не всегда означает лучшую диагностику.

Пароли, токены, персональные входы и большие payload не сохраняем по умолчанию. Логи могут содержать URL с параметрами, поэтому маршрут нормализуем, query не пишем. Даже ID может быть чувствительным в контексте другой системы. Ограничение объёма и сроки хранения предотвращают заполнение диска. Docker logging driver с max-size/max-file ограничивает локальные operational logs. В нашем учебном data-файле нет персональных данных, но для настоящего проекта нужен отдельный retention. Изоляция в контейнере не скрывает логи от оператора, имеющего Docker-доступ.

Аналогия: журнал проходной должен помогать расследованию, а не копировать содержимое всех сумок.

Команды и наблюдения

Окружение: Ubuntu / Bash, lab.

curl -sS -D /tmp/studypulse-headers.txt -H "Content-Type: application/json" -d '{"hours":4}' http://127.0.0.1:8000/predict
cat /tmp/studypulse-headers.txt
docker compose logs --no-log-prefix --tail 100 app > /tmp/studypulse-logs.jsonl
python3 scripts/read_logs.py /tmp/studypulse-logs.jsonl

read_logs.py понимает только чистые JSON-строки и сообщает, если строка не подходит. Случайные секреты в вывод не копируем.

Ожидаемый результат: В заголовках виден X-Request-ID, в JSON-журнале — соответствующее событие, сырое hours не записано.

Вариант для macOS

JSON-парсер и фильтрация request_id переносимы. Не смешивайте Docker-логи приложения с macOS unified logging, это разные источники.

docker compose logs --no-log-prefix --tail 100 app > /tmp/studypulse-logs.jsonl
python3 scripts/read_logs.py /tmp/studypulse-logs.jsonl

Практика: История одного запроса

1. Сделайте успешный и неправильный predict, сохраните два request_id.
2. Найдите каждую запись через read_logs.py --request-id.
3. Заполните таблицу время / версия / статус / длительность.
4. Проверьте, не содержат ли записи тело запроса, query и лишние идентификаторы.

Результат: Две минимальные временные линии без пользовательских payload.

Проверка: События сопоставлены по фактам; поля и privacy проверены.

Неисправность для разбора: Текстовый grep по JSON используется как доказательство точного совпадения поля.

Решение и диагностика

Возьмите ID из X-Request-ID, затем python3 scripts/read_logs.py /tmp/studypulse-logs.jsonl --request-id ID. Скрипт фильтрует parsed JSON по точному значению поля. Для неверного hours ожидается status=400 и warning; для нормального — 200 и info. Не добавлять request_id в Prometheus labels для удобства поиска.

Основные выводы

• Лог, потому что ID имеет высокую кардинальность.
• Нет; для инфраструктурной диагностики обычно достаточно минимального контекста.

Самостоятельная работа

Добавить к runbook перечень допустимых полей лога и правило безопасного обмена доказательствами.

Источники

• Документация
• Документация