logging в Python: уровни, настройка и повторные сообщения

logging записывает события работы Python-программы с уровнем важности и именем источника. Если сообщение INFO не появляется, сначала проверь порог: по умолчанию у корневого логгера он равен WARNING. Если одна строка выводится дважды, проверь обработчики и передачу записи родительскому логгеру через propagate.

Разберём оба случая на импорте трёх строк: две содержат числа, одна — слово «два». Настроим вывод, добавим сведения об ошибке и проследим, откуда берутся дубли. logging входит в стандартную библиотеку, устанавливать пакет не нужно.

Все полные примеры сохраняй в import_orders.py и запускай командой python3 import_orders.py. Каждый запуск создаёт новый процесс; не склеивай примеры в одну сессию консоли. Ниже есть и короткие замены отдельных строк — для них указан исходный пример. Файл не называй logging.py, чтобы он не перекрыл библиотечный модуль.

Почему logging.info ничего не выводит

Воспроизведём симптом двумя вызовами:

import logging

logging.info("Начинаем импорт")
logging.warning("Строка 2 пропущена")

В терминале появится только:

WARNING:root:Строка 2 пропущена

Первый вызов работает, но событие не проходит порог. Функции logging.info() и logging.warning() обращаются к корневому логгеру, который в выводе назван root. Если у него ещё нет обработчиков, эти функции сами вызывают базовую настройку. В новом процессе порог остаётся WARNING, поэтому INFO отбрасывается. Это поведение разобрано в руководстве Python по logging.

print() удобен для результата, который программа отдаёт пользователю. Логи помогают понять ход работы: какая строка не разобралась, сколько записей принято, на каком шаге произошёл сбой. В примерах ниже логирование пишет в stderr, стандартный поток диагностических сообщений. Это нормальное назначение потока; само попадание туда не означает аварийное завершение программы.

Выбрать уровень: от DEBUG до CRITICAL

Уровень описывает событие. Порог настройки определяет, какие события будут видны.

При пороге INFO видны события INFO и выше; DEBUG скрыт. Выбор ERROR вместо WARNING сам по себе не останавливает скрипт. Решение о продолжении принимает код.

Настроить basicConfig и запустить импорт

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

Замени файл целиком:

import logging

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

accepted = 0
logger.info("Начинаем импорт")
for row, raw in enumerate(["3", "два", "5"], start=1):
    try:
        quantity = int(raw)
    except ValueError:
        logger.warning("Строка %s пропущена: количество не число", row)
        continue
    logger.debug("Строка %s: количество %s", row, quantity)
    accepted += 1
logger.info("Принято строк: %s", accepted)

Вывод:

INFO | importer | Начинаем импорт
WARNING | importer | Строка 2 пропущена: количество не число
INFO | importer | Принято строк: 2

Для этого учебного импорта неверную строку пропускаем, остальные читаем дальше. Два вызова logger.debug() при пороге INFO не видны. Если заменить настройку на level=logging.DEBUG, появятся ещё две строки: количество 3 для первой записи и 5 для третьей.

В формате сообщения три поля: levelname задаёт уровень, name — имя логгера, а message — текст события. Вызов logger.info("Принято строк: %s", accepted) передаёт шаблон и значение отдельно: logging подставит значение при форматировании записи.

Имя importer выбрано явно для примера. В модулях проекта часто используют logging.getLogger(__name__): тогда имя отражает модуль, из которого пришло событие. Общую настройку оставляют в точке запуска приложения.

Python / 01koddo

Порог INFO пропускает события с уровнем 20 и выше

Добавить traceback через logger.exception

Предупреждение сообщает, какую строку пропустили, но не показывает место сбоя. Для разбора исключения замени вызов logger.warning(...) внутри except ValueError на:

        logger.exception("Строка %s пропущена", row)

Остальной код импорта оставь прежним. logger.exception() пишет событие уровня ERROR и добавляет трассировку текущего исключения. Сокращённый фрагмент вывода — строки с путём файла и указателем на код опущены:

ERROR | importer | Строка 2 пропущена
Traceback (most recent call last):
…
ValueError: invalid literal for int() with base 10: 'два'

Используй logger.exception() внутри обработчика except, где есть активное исключение. Обычный logger.error() без exc_info=True записывает сообщение без этой трассировки. Поведение описано в справочнике Logger.exception.

После сообщения импорт всё равно примет третью строку и напишет Принято строк: 2: за это отвечает наш continue, а не logging. Если по условию задачи ошибка должна остановить импорт, её передают выше через raise. Разница между записью сообщения и обработкой сбоя разобрана в статье про try/except.

Почему второй basicConfig не меняет настройку

basicConfig() по умолчанию ничего не делает, если у root уже есть обработчик. Это легко увидеть в отдельном скрипте:

import logging

logging.basicConfig(level=logging.WARNING, format="%(levelname)s | %(message)s")
logging.basicConfig(level=logging.INFO)
logging.info("Начинаем импорт")
logging.warning("Строка 2 пропущена")

Вывод остаётся таким:

WARNING | Строка 2 пропущена

Поэтому добавление basicConfig(level=logging.INFO) ниже первого logging.info() из самого начала статьи не поможет: тот вызов уже создал обработчик. В обычном скрипте перенеси настройку перед первым сообщением и запусти файл заново.

Когда намеренно перенастраиваешь собственный процесс, доступен force=True. Он удаляет и закрывает прежние обработчики корневого логгера, затем применяет новую настройку. Это не переключатель уровня отдельного модуля; настройки фреймворка так можно стереть. Точные правила приведены в описании basicConfig.

Откуда берутся одинаковые сообщения

Обработчик, или handler, отправляет запись в консоль, файл или другое место. Одну запись могут получить несколько обработчиков. Поэтому две строки в терминале ещё не доказывают, что функция импорта сработала дважды.

В этом отдельном примере сообщение проходит по двум путям:

import logging

logging.basicConfig(level=logging.INFO, format="root: %(message)s")
logger = logging.getLogger("importer")
handler = logging.StreamHandler()
handler.setFormatter(logging.Formatter("local: %(message)s"))
logger.addHandler(handler)

logger.info("Принято строк: 2")

Вывод:

local: Принято строк: 2
root: Принято строк: 2

Сначала запись выводит собственный обработчик importer. Затем она доходит до обработчика root: у логгера по умолчанию propagate=True. Разные префиксы добавлены специально, чтобы увидеть оба пути.

Python / 02koddo

Один вызов, два обработчика, две строки

Выбери, какой путь нужен:

Для нашего импорта достаточно первого варианта: настройка через basicConfig, без собственного обработчика у importer. Не отключай propagate без причины у логгера, который полагается на обработчик root: сообщение INFO потеряет путь к нему.

Есть второй источник дублей: повторная настройка добавляет новые экземпляры StreamHandler тому же логгеру. getLogger("importer") каждый раз возвращает один и тот же объект. Создавай обработчики при настройке приложения, а не при обработке каждой строки или вызове рабочей функции.

У логгера и обработчика есть отдельные пороги. В наших примерах именованный логгер наследует уровень root, а обработчики не вводят дополнительного ограничения. При propagate запись идёт прямо обработчикам предков: уровень самого родительского логгера повторно не проверяется. Эта деталь важна при раздельной настройке; она зафиксирована в описании Logger.propagate.

Записать тот же журнал в файл

Вернись к полному примеру импорта с logger.warning и замени только вызов basicConfig:

logging.basicConfig(
    filename="import.log",
    encoding="utf-8",
    level=logging.INFO,
    format="%(levelname)s | %(name)s | %(message)s",
)

После запуска те же три сообщения окажутся в import.log в текущей рабочей папке. В терминале их не будет: эта настройка создаёт файловый обработчик вместо консольного. По умолчанию новые записи дописываются в конец; повторный запуск добавит ещё три строки. Как устроены режимы открытия и пути, разобрано в статье о файлах в Python.

Проверь настройку на своих данных

Возьми полный пример импорта и изменяй по одному условию:

1. Установи DEBUG. Ожидай пять строк: начало, две подробности, предупреждение и итог. Подробности должны стоять у строк 1 и 3.
2. Замени вход на ["3", "4", "5"] и верни порог INFO. Ожидай две строки без предупреждения, итоговое количество — 3.
3. Снова добавь неверное значение. Реши, достаточно ли номера строки и предупреждения или для разбора нужен traceback. Замени вызов внутри except, сохранив понятный итог импорта.

Лог помогает восстановить ход выполнения, а тест с pytest проверяет ожидаемый результат автоматически. Для практики возьми задачу из курса Python для продолжающих: сначала проверь ответ функции, затем добавь в локальный скрипт сообщения, по которым можно объяснить ошибку. Когда данных достаточно для такого объяснения, наращивать число логов незачем.