Логи: запись о событии и её контекст

§1Лог: запись о событии

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

Лог (журнал событий) — последовательность записей о событиях, произошедших в программе. Каждая запись фиксирует, когда что-то произошло, где и с каким результатом.

Событие — это завершение HTTP-запроса, вход пользователя, неудачная попытка подключения к базе, запуск фоновой задачи. Какие события записывать, решает разработчик, и от этого решения зависит, что удастся выяснить при расследовании.

Ниже две записи об одном и том же запросе.

Request processed

2026-09-22T13:23:26.548Z ERROR products-api
request_completed route=/products
status=500 duration_ms=76.503
request_id=1cf09e6f…

Вторая запись полезна благодаря полям. Следующий раздел разбирает каждое поле.

§2Какие поля нужны записи

Состав полей определяют вопросы, на которые должна отвечать запись. Для веб-сервиса набор почти всегда один и тот же. Ниже запись сервиса о запросе, завершившемся ошибкой. Выберите поле, чтобы прочитать, что оно даёт.

{"timestamp": "2026-09-22T13:23:26.548004+00:00", "level": "ERROR",
 "service": "products-api", "event": "request_completed", "status": 500,
 "request_id": "1cf09e6f86f04fa7b6b4941d75d388e9", "duration_ms": 76.503}

Про единицы. Поле duration со значением 72 можно понять как секунды, миллисекунды или микросекунды. Если единица записана в имени поля, как в duration_ms, ошибиться нельзя. Время события записывается в UTC с явным смещением +00:00, чтобы записи с разных серверов сравнивались без пересчёта.

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

Одно из полей, level, определяет, попадёт ли запись в журнал вообще.

§3Уровни важности

У каждой записи есть уровень важности. По нему поток фильтруют: в обычной работе смотрят только предупреждения и ошибки, а при отладке включают подробные сообщения. В модуле logging пять стандартных уровней, у каждого есть числовое значение.

Логгер пропускает записи, уровень которых не ниже заданного. При уровне INFO записи DEBUG отбрасываются, а INFO, WARNING, ERROR и CRITICAL проходят. Сравнение идёт по числу: порог INFO равен 20, уровень DEBUG равен 10 и порог не проходит.

Поля и уровни разобраны. Следующий раздел показывает, как записи создаются в коде.

§4Модуль logging в Python

Для записи логов в Python есть стандартный модуль logging. Им пользуются и сервис стенда, и Uvicorn. Минимальная настройка показана на отдельном примере.

import logging

logging.basicConfig(
    level=logging.INFO,
    format="%(asctime)s %(levelname)s %(name)s %(message)s",
)
logger = logging.getLogger("telemetry_lab")

logger.debug("подробности для отладки")
logger.info("request_completed status=%s duration_ms=%s", 200, 82.627)
logger.warning("slow_request duration_ms=%s", 3022.741)

2026-09-15 16:17:58,865 INFO telemetry_lab request_completed status=200 duration_ms=82.627
2026-09-15 16:17:58,865 WARNING telemetry_lab slow_request duration_ms=3022.741

logger.debug(f"данные: {big_object}")

logger.debug("данные: %s", big_object)

Время в выводе записано по местному времени машины и без часового пояса: 2026-09-15 16:17:58,865. Для одного компьютера этого достаточно, для нескольких серверов нет. Поэтому сервис стенда формирует время события через datetime.now(timezone.utc).

Первоисточник: Python · logging ↗

Пример выводит записи строкой текста. Чтобы по записям можно было искать, их формат делают строже.

§5Структурированные записи в JSON

Строку status=200 duration_ms=82.627 человек прочитает, а программе её придётся разбирать. Если в тексте сообщения встретится пробел или знак равенства, разбор сломается. Поэтому в рабочих сервисах записи часто пишут в JSON: каждое поле становится ключом объекта.

import json
import logging

logging.basicConfig(level=logging.INFO, format="%(message)s")
logger = logging.getLogger("telemetry_lab")

event = {
    "event": "request_completed",
    "route": "/products",
    "status": 200,
    "duration_ms": 82.627,
    "request_id": "e14dff1e8db440709a2640f599322917",
}
logger.info(json.dumps(event, ensure_ascii=False))

{"event": "request_completed", "route": "/products", "status": 200, "duration_ms": 82.627, "request_id": "e14dff1e8db440709a2640f599322917"}

Запись собрана в словарь, а json.dumps превращает его в строку JSON. Параметр ensure_ascii=False оставляет русские буквы как есть, без замены на коды вида \u0442. В формате логгера оставлено только %(message)s, чтобы каждая строка вывода была корректным JSON.

Польза видна при поиске. Системы хранения логов разбирают JSON на поля, и запрос «все записи, где status равен 500 и route равен /products» выполняется точно. С текстовыми строками пришлось бы писать регулярное выражение и надеяться, что формат сообщения нигде не отличается.

В контейнерах логи пишут в стандартный вывод процесса. Docker и Kubernetes собирают вывод каждого контейнера, а отдельный агент пересылает записи в хранилище. Приложению не нужно самому управлять файлами логов и их ротацией.

Формат записи готов. Осталось разобрать записи, которые при расследовании читают чаще других: записи об ошибках.

§6Исключение и traceback

При расследовании чаще других нужны записи об ошибках. Для них у логгера есть метод logger.exception: он добавляет к сообщению полный traceback текущего исключения.

Traceback — отчёт Python о цепочке вызовов, которая привела к исключению. Он показывает, в каком файле, строке и функции возникла ошибка и через какие вызовы выполнение туда пришло.

import logging

logging.basicConfig(format="%(levelname)s %(message)s")
logger = logging.getLogger("telemetry_lab")


def load_products():
    raise TimeoutError("dependency timeout")


try:
    load_products()
except TimeoutError:
    logger.exception("dependency_timeout request_id=%s", "1cf09e6f86f04fa7b6b4941d75d388e9")

ERROR dependency_timeout request_id=1cf09e6f86f04fa7b6b4941d75d388e9
Traceback (most recent call last):
  File ".../log_exception.py", line 12, in <module>
    load_products()
  File ".../log_exception.py", line 8, in load_products
    raise TimeoutError("dependency timeout")
TimeoutError: dependency timeout

Traceback читают снизу вверх.

1. Последняя строка — что случилось

   Тип исключения и сообщение: TimeoutError: dependency timeout.

2. Над ней — где случилось

   Файл, строка 8, функция load_products и сам код строки.

3. Ещё выше — откуда пришли

   Строка 12, код верхнего уровня <module>. Так восстанавливается путь выполнения до ошибки.

Первая строка вывода — сообщение, переданное в logger.exception. Метод всегда пишет запись уровня ERROR. Вызывают его только внутри блока except: вне обработки исключения traceback взять неоткуда.

В Python 3.12 traceback содержит абсолютный путь к файлу, например /home/deploy/app/log_exception.py, и в журнал попадает устройство файловой системы сервера. Сервис стенда перед сохранением убирает путь к папке проекта и оставляет только имя файла.

Traceback разобран на отдельном примере. Следующий раздел находит его в записи сервиса стенда.

§7Ошибка 500 на стенде

Теперь ошибка на стенде: на странице стенда запущен сценарий error. Обработчик ждёт зависимость, поднимает TimeoutError, перехватывает его, записывает событие и возвращает клиенту ответ 500.

12345

Строка итога: HTTP 500 · клиент: 78.4 ms · обработчик: 76.5 ms. Ошибка вернулась быстрее успешного быстрого ответа, потому что этап serialize не выполнялся.

Блок HTTP — то, что получил клиент: объект detail с кратким описанием simulated dependency timeout и request_id. Traceback клиенту не отправляется: пользователю внутреннее устройство сервиса не нужно, а злоумышленнику сведения о коде могут пригодиться.

Блок LOG содержит полную запись: уровень ERROR, код 500 и сценарий error. В поле exception — traceback, записанный в одну строку JSON. Снизу вверх: TimeoutError: Simulated dependency timeout; no database is connected возникла в файле app.py, строка 55, функция products.

Блок TRACE показывает только два этапа: validate — 11,1 мс и dependency.wait (simulated) — 61,1 мс. Третьего этапа нет: исключение прервало выполнение до него.

Ответ пользователю и запись в логе связывает request_id. Клиент получает идентификатор 1cf09e6f… в теле ответа и в заголовке X-Request-ID. Пользователь пересылает его в поддержку. Разработчик ищет по нему запись в хранилище логов и находит полный traceback, которого у пользователя нет.

try:
    await stage("dependency.wait (simulated)", 3.0 if scenario == "slow" else 0.06)
    if scenario == "error":
        raise TimeoutError("Simulated dependency timeout; no database is connected")
    await stage("serialize", 0.01)
except TimeoutError:
    status = 500
    exception_text = traceback.format_exc().replace(str(Path(__file__).parent) + os.sep, "")
    logger.exception("dependency_timeout request_id=%s", request_id)

traceback.format_exc() возвращает текст traceback текущего исключения строкой. Метод replace убирает из него путь к папке проекта. Строка попадает в поле exception записи, а logger.exception дополнительно выводит сообщение с traceback в терминал Uvicorn.

Первоисточник: Python · traceback ↗

В логах есть запись о каждом запросе. Следующий раздел проверяет, можно ли по ним считать то же, что считают метрики.

§8Можно ли считать метрики по логам

Раз в логах есть запись о каждом запросе, из них можно получить и количества. В файле events.json записанного прогона есть записи обо всех двадцати запросах, и расчёт сделан по нему.

import json

with open("results/events.json") as file:
    events = json.load(file)

errors = sum(1 for event in events if event["status"] >= 500)
print("событий:", len(events))
print("ошибок:", errors)
print(f"доля: {errors / len(events):.1%}")

событий: 20
ошибок: 1
доля: 5.0%

Результат совпал с расчётом по CSV из главы 1.4, потому что выполнены два условия: каждый запрос записан ровно один раз, и в записи есть нужное поле. На стенде событие request_completed создаётся один раз в конце обработчика.

Даже с правильными событиями расчёт метрик по логам требует много места. Сервис с 1000 запросов в секунду и записью по 500 байт создаёт около 43 ГБ логов в сутки, а метрика с тем же смыслом занимает несколько рядов. Поэтому доли и длительности обычно считают метриками, а логи держат для подробностей.

Логи хранят подробности, и из-за этого у них есть ограничение, которого нет у метрик.

§9Чего не должно быть в логах

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

Это решают при проектировании записи, до первой утечки. Надёжнее перечислить поля, которые писать можно, чем запрещать отдельные: тогда новое поле запроса не попадёт в лог случайно.

§10Частые ошибки

§11Проверьте себя

§12Шпаргалка