Почему ERROR попадают в INFO‑лог в Python и как это исправить

Почему в Python logging ошибки попадают в app_info.log: роль propagate и как задать propagate=false в dictConfig, чтобы разделить INFO и ERROR без дублей.

Разделять логи уровней INFO и ERROR по разным файлам кажется простой задачей, но из‑за одного тонкого нюанса конфигурации logging в Python записи ERROR могут оказываться и в INFO‑файле. Если вы видите дубли на консоли и сообщения об ошибках пишутся одновременно в app_error.log и app_info.log, причина почти наверняка одна: распространение записей на самом деле не отключено.

Постановка задачи

Рассмотрим конфигурацию, в которой INFO должны уходить в app_info.log, а ERROR — в app_error.log. Намерение видно из настроек ниже, но результат всё равно такой: ERROR попадают в оба файла.

{
  "version": 1,
  "disable_existing_loggers": false,
  "formatters": {
    "fmt_line": {
      "format": "%(asctime)s - %(name)s -  %(levelname)s - %(message)s"
    }
  },
  "handlers": {
    "InfoSink": {
      "class": "logging.handlers.RotatingFileHandler",
      "filename": "app_info.log",
      "level": "INFO",
      "formatter": "fmt_line",
      "maxBytes": 10485760,
      "backupCount": 5,
      "encoding": "utf-8"
    },
    "ErrorSink": {
      "class": "logging.handlers.RotatingFileHandler",
      "filename": "app_error.log",
      "level": "ERROR",
      "formatter": "fmt_line",
      "maxBytes": 10485760,
      "backupCount": 5,
      "encoding": "utf-8"
    },
    "ConsoleSink": {
      "class": "logging.StreamHandler",
      "level": "INFO",
      "formatter": "fmt_line",
      "stream": "ext://sys.stdout"
    }
  },
  "loggers": {
    "svc_ERR": {
      "handlers": ["ConsoleSink", "ErrorSink"],
      "level": "ERROR",
      "propagate": "no"
    },
    "svc_INFO": {
      "handlers": ["ConsoleSink", "InfoSink"],
      "level": "INFO",
      "propagate": "no"
    }
  },
  "root": {
    "level": "DEBUG",
    "handlers": ["ConsoleSink", "InfoSink"]
  }
}

Минимальный загрузчик этой конфигурации может выглядеть так:

import logging
import logging.config
import json

CFG_PATH = "log_config.json"

active_log = None

def start_logger(alias):
    global active_log
    with open(CFG_PATH, "r") as fh:
        cfg_obj = json.load(fh)
    if cfg_obj is None:
        raise ValueError("initialize log json file is not set")
    logging.config.dictConfig(cfg_obj)
    active_log = logging.getLogger(alias)
    return active_log

И пример использования:

>>> import logger_bootstrap  # your module containing start_logger
>>> lg = logger_bootstrap.start_logger("svc_ERR")
>>> lg.error("this is test2")

Несмотря на то что мы задействуем логгер ошибок, сообщение записывается и в app_error.log, и в app_info.log. К тому же появляются дублирующиеся строки на консоли, когда и именованный логгер, и корневой логгер пишут в stdout.

Почему так происходит

Работают два механизма. Во‑первых, обработчик с уровнем INFO принимает записи уровня INFO и выше, то есть и ERROR. Во‑вторых, будет ли запись подниматься к родительским логгерам, определяется атрибутом propagate. Важно понять, как именно этот атрибут интерпретируется.

Если это свойство оценивается как true, события, записанные этим логгером, будут переданы обработчикам логгеров более высокого уровня (родительских), помимо обработчиков, привязанных к этому логгеру.

В конфигурации выше propagate задан непустой строкой, например "no". Любая непустая строка оценивается как True. Значит, распространение не отключено, и записи из svc_ERR поднимаются к корневому логгеру, к которому привязан InfoSink. Поскольку INFO означает «INFO и выше», корень тоже записывает ERROR в app_info.log.

Замена строки на другую непустую, например "false", ничего не меняет: она всё равно трактуется как True. Чтобы действительно отключить распространение, атрибут должен быть булевым false, числом 0 или пустой строкой.

Решение

Используйте для propagate настоящий булев тип. Вот исправленная конфигурация; больше ничего менять не требуется.

{
  "version": 1,
  "disable_existing_loggers": false,
  "formatters": {
    "fmt_line": {
      "format": "%(asctime)s - %(name)s -  %(levelname)s - %(message)s"
    }
  },
  "handlers": {
    "InfoSink": {
      "class": "logging.handlers.RotatingFileHandler",
      "filename": "app_info.log",
      "level": "INFO",
      "formatter": "fmt_line",
      "maxBytes": 10485760,
      "backupCount": 5,
      "encoding": "utf-8"
    },
    "ErrorSink": {
      "class": "logging.handlers.RotatingFileHandler",
      "filename": "app_error.log",
      "level": "ERROR",
      "formatter": "fmt_line",
      "maxBytes": 10485760,
      "backupCount": 5,
      "encoding": "utf-8"
    },
    "ConsoleSink": {
      "class": "logging.StreamHandler",
      "level": "INFO",
      "formatter": "fmt_line",
      "stream": "ext://sys.stdout"
    }
  },
  "loggers": {
    "svc_ERR": {
      "handlers": ["ConsoleSink", "ErrorSink"],
      "level": "ERROR",
      "propagate": false
    },
    "svc_INFO": {
      "handlers": ["ConsoleSink", "InfoSink"],
      "level": "INFO",
      "propagate": false
    }
  },
  "root": {
    "level": "DEBUG",
    "handlers": ["ConsoleSink", "InfoSink"]
  }
}

Когда распространение отключено истинным булевым значением, записи, обработанные svc_ERR, не поднимаются к корневому логгеру и перестают попадать в app_info.log. Аналогично исчезают дубли на консоли, потому что корень больше не получает и не переиздаёт ту же запись.

Почему это важно

Непреднамеренное распространение нарушает чистое разделение между файлами INFO и ERROR. Это сводит на нет идею отдельных целей для логирования и порождает дубли, когда одно событие обрабатывается несколькими обработчиками. Гарантируйте, что propagate действительно отключён, — и вы получите точную маршрутизацию вместо шумных и вводящих в заблуждение потоков.

Итоги

Задавайте propagate как булев false, а не строку. Помните, пороги уровней — включающие: обработчик на INFO принимает и ERROR. Если вы полагаетесь на корневой логгер, учитывайте, что события будут подниматься вверх, пока распространение явно и корректно не отключено. Соблюдая эти нюансы, вы получите предсказуемые, раздельные INFO‑ и ERROR‑логи без дублей.