Как сделать журнал ошибок Python полезным для разбора сбоя

Полезный журнал ошибок отвечает не на вопрос «была ли ошибка», а на три более практичных вопроса: где именно упало, над какой записью и что можно показать коллегам без раскрытия лишних данных. Для учебного разбора возьмём маленький скрипт на Python 3.12 со стандартной библиотекой logging: он обрабатывает три записи, у одной поле score содержит строку 'oops' и вызывает исключение.

Ниже цель узкая: сделать такой журнал, в котором видны уровень события, идентификатор записи и traceback, но нет email, токенов и полного исходного payload. При этом логирование не должно подменять обработку ошибки: после сбоя код всё ещё обязан принять решение, что делать дальше с пакетом данных.

Что понадобится для разбора сбоя

Минимальный набор состоит из трёх частей. Первая — именованный логгер, а не случайные вызовы в корневой логгер. Тогда по имени источника видно, какой участок приложения пишет сообщение. В документации Python именно такой способ и показан как рабочая практика для модулей: логгер создают через logging.getLogger(__name__) или через другое осмысленное имя пространства, например edu.batch_import.

Вторая часть — контекст операции. Если в журнале есть только текст ValueError, вы знаете тип проблемы, но не знаете, какую запись он сломал. Поэтому в каждое сообщение стоит передавать хотя бы стабильный идентификатор записи и название шага обработки. Для нашей задачи достаточно пары полей: record_id и op.

Третья часть — отдельная обработка ошибки. Лог нужен для разбора, но он сам ничего не исправляет. После записи исключения нужно либо продолжить пакетную обработку, либо вернуть статус выше по стеку, либо аккуратно завершить задачу. Если ограничиться одним logger.exception(...), сбой будет красиво описан, но бизнес-результат останется неуправляемым.

Настройка именованного логгера

У стандартного логирования есть уровни DEBUG, INFO, WARNING, ERROR и CRITICAL. По умолчанию корневой логгер работает с порогом WARNING, поэтому без явной настройки вы не увидите обычные рабочие сообщения уровня INFO. Для учебного пакетного обработчика это неудобно: нам как раз полезно видеть начало обработки записи, успешное завершение и место ошибки.

В маленьком скрипте можно начать с basicConfig(), но как только нужен свой формат и отдельный файл, проще настроить обработчик явно. Ещё один практический момент: конфигурацию стоит делать до первых вызовов логгера, иначе часть событий уйдёт не в том формате или не туда, куда вы рассчитывали.

import logging
from pathlib import Path

LOG_PATH = Path('batch.log')


def build_logger() -> logging.Logger:
    logger = logging.getLogger('edu.batch_import')
    logger.setLevel(logging.INFO)
    logger.propagate = False

    if not logger.handlers:
        handler = logging.FileHandler(LOG_PATH, encoding='utf-8', mode='w')
        formatter = logging.Formatter(
            '%(asctime)s %(levelname)s %(name)s '
            'record_id=%(record_id)s op=%(op)s %(message)s'
        )
        handler.setFormatter(formatter)
        logger.addHandler(handler)

    return logger

Здесь важны два решения. Во-первых, имя edu.batch_import сразу показывает источник сообщений. Во-вторых, формат вынесен в явные поля: уровень, имя логгера, идентификатор записи и шаг операции. Такой журнал потом проще фильтровать глазами и искать по нему строкой record_id=.... Поля record_id и op будут передаваться через extra, поэтому их нужно добавлять в каждую запись, где они используются в формате.

Запись исключения с контекстом операции

УЧЕБНЫЙ ПРИМЕР. Ниже скрипт обрабатывает три учебные записи. В лог попадают только идентификатор записи и название шага, а email и токен остаются в исходных данных и не записываются. Одна запись падает на преобразовании int('oops'), после чего журнал получает traceback, а функция продолжает обработку остальных элементов и возвращает сводку.

def normalize_score(raw_value: str) -> int:
    score = int(raw_value)
    if not 0 <= score <= 100:
        raise ValueError(f'score out of range: {score}')
    return score


def safe_context(record: dict, op: str) -> dict:
    return {
        'record_id': record.get('id', 'unknown'),
        'op': op,
    }


def process_records(records: list[dict]) -> tuple[list[dict], dict]:
    logger = build_logger()
    processed = []
    failed_ids = []

    for record in records:
        ctx = safe_context(record, 'normalize_score')
        logger.info('start record', extra=ctx)
        try:
            score = normalize_score(record['score'])
            processed.append({'id': record['id'], 'score': score})
            logger.info('record processed', extra=ctx)
        except Exception:
            failed_ids.append(record.get('id', 'unknown'))
            logger.exception('record failed', extra=ctx)
            continue

    summary = {
        'processed': len(processed),
        'failed': len(failed_ids),
        'failed_ids': failed_ids,
    }
    logger.info(
        'batch finished: processed=%s failed=%s',
        summary['processed'],
        summary['failed'],
        extra={'record_id': '-', 'op': 'summary'},
    )
    return processed, summary


records = [
    {'id': 'R-1001', 'email': 'anna@example.test', 'api_token': 'tok_live_111', 'score': '91'},
    {'id': 'R-1002', 'email': 'boris@example.test', 'api_token': 'tok_live_222', 'score': 'oops'},
    {'id': 'R-1003', 'email': 'clara@example.test', 'api_token': 'tok_live_333', 'score': '76'},
]

processed, summary = process_records(records)
print(processed)
print(summary)

Почему здесь выбран именно logger.exception()? В документации Python этот метод описан как вариант, который пишет сообщение уровня ошибки вместе со stack trace и должен вызываться внутри обработчика исключения. Для разбора сбоя это точнее обычного logger.error('failed'), потому что без traceback вы увидите факт ошибки, но не путь до конкретной строки.

Проверяемый результат у примера такой: успешно обработаны записи R-1001 и R-1003, а R-1002 попадает в список ошибок. Значит, итоговые значения согласованы арифметически: processed = 2, failed = 1, failed_ids = ['R-1002']. Это и есть важный момент про «не подменять обработку ошибки логированием»: журнал зафиксировал падение, а функция всё равно вернула управляемый итог.

Ожидаемый фрагмент журнала: строка уровня INFO со стартом обработки R-1002, затем строка уровня ERROR с тем же record_id и блок Traceback. При этом в файле не должно быть email вроде boris@example.test и токена tok_live_222.

Как проверить полезность и приватность журнала

После первой настройки полезно проверить журнал по двум спискам. Первый список — что обязательно должно быть для разбора. Второй — что точно не должно утекать. В учебном скрипте можно ориентироваться на такую таблицу.

Проверку можно сделать прямо кодом. Она особенно полезна в учебных и тестовых сценариях, потому что превращает абстрактное «лог вроде нормальный» в набор конкретных условий. Ниже пример аудита того же файла batch.log.

def audit_log() -> dict:
    text = LOG_PATH.read_text(encoding='utf-8')
    return {
        'has_failed_id': 'record_id=R-1002' in text,
        'has_traceback': 'Traceback' in text,
        'has_email_leak': 'boris@example.test' in text,
        'has_token_leak': 'tok_live_222' in text,
    }

print(audit_log())
# Ожидаемо:
# {
#   'has_failed_id': True,
#   'has_traceback': True,
#   'has_email_leak': False,
#   'has_token_leak': False,
# }

Если журнал не проходит такую проверку, исправление обычно лежит в одном из трёх мест. Либо в лог пишется весь входной объект целиком, либо сообщение об ошибке собирается из лишних полей, либо форматтер требует контекстные поля, но часть вызовов идёт без них. Удобное рабочее правило такое: логируйте идентификатор и шаг, а не весь объект; исключение пишите через logger.exception() внутри except; после записи ошибки принимайте отдельное решение о дальнейшем ходе обработки.

Если хотите потренировать этот подход в веб-проекте, во внутренней карточке каталога курса FastAPI сохранена программа с темами про обработку исключений, конфигурацию приложения и отдельным модулем по логированию: уровни, формат, basicConfig, extra и логирование ошибок.