При изменении кода в существующем проекте я обнаружил, что отладочные сообщения выводятся в stderr, даже если уровень обработчика для этих журналов установлен на уровне INFO, поэтому я не ожидаю никаких сообщений отладки. Причиной такого поведения, по-видимому, является то, что при импорте используется logging.debug(), где после этого вызова он изменил способ вывода сообщений на консоль.
Я сократил проблему до приведенного ниже примера кода, чтобы получить справку при понимании того, почему эти сообщения уровня отладки регистрируются:
import logging
import sys
# get root logger singleton
root_logger = logging.getLogger()
# create my own logger object
test_logger = logging.getLogger("test_logger")
test_logger.setLevel(logging.DEBUG)
# add handler to my logger
sh = logging.StreamHandler(sys.stdout)
sh.setLevel(logging.INFO)
test_logger.addHandler(sh)
test_logger.info("Info message from test_logger")
test_logger.debug("Debug message before logging.debug")
print("test_logger handlers before: " + str(test_logger.handlers))
print("test_logger level before: " + str(test_logger.getEffectiveLevel()))
print("Root before: " + str(root_logger.handlers) + " level: "+ str(root_logger.getEffectiveLevel()))
# This call causes the debug messages after it to go to stderr
# Also, it results in the root logger object having a handler added to it
logging.debug("Debug message from logging")
# This debug message is unexpectedly logged to stderr
test_logger.debug("Debug message after logging.debug")
print("test_logger handlers after: " + str(test_logger.handlers))
print("test_logger logging level after: " + str(test_logger.getEffectiveLevel()))
print("Root after: " + str(root_logger.handlers) + " level: " + str(root_logger.getEffectiveLevel()))
Приведенный выше код имеет следующий вывод, где по какой-то причине выводится только одно из сообщений отладки и он собирается в stderr:
DEBUG:test_logger:Debug message after logging.debug
Info message from test_logger
test_logger handlers before: [<StreamHandler <stdout> (INFO)>]
test_logger level before: 10
Root before: [] level: 30
test_logger handlers after: [<StreamHandler <stdout> (INFO)>]
test_logger logging level after: 10
Root after: [<StreamHandler <stderr> (NOTSET)>] level: 30
Для меня имеет смысл, почему StreamHandler добавляется в root logger, поскольку вызывается logging.debug () и без обработчика в root он добавит его. Диаграмма в https://docs.python.org/3.5/howto/logging.html#logging -flow также представляется уместной в том смысле, что она показывает, что сообщения от регистраторов с родителем go для родителя и root регистратора должны быть родительскими для test_logger.
Добавление следующей строки кода предотвратит создание отладочного сообщения в stderr, поэтому, похоже, проблема связана с распространением сообщения его предкам. Однако я не уверен, что это подходящее решение или просто обходной путь.
test_logger.propagate = False
В документах по этому адресу https://docs.python.org/3/library/logging.html#logging .Logger.propagate объясняется, что:
Сообщения передаются непосредственно обработчикам регистраторов предков - ни уровень, ни фильтры рассматриваемых регистраторов предков не рассматриваются.
Для меня это означает, что регистратор root должен получить это сообщение, но печатное сообщение отладки показывает регистратор как test_logger DEBUG:test_logger:Debug message after logging.debug, поэтому он, похоже, не поступает из регистратора root. У логгера root также есть уровень логирования по умолчанию. WARN (30), и, насколько я понимаю, если обработчик логгера обрабатывает сообщение отладки, он печатается только в том случае, если уровень лога на логгере равен или ниже уровень сообщения?
Кто-нибудь может объяснить, что здесь происходит, и, возможно, я пропускаю какой-то обязательный шаг? Например, в этом коде я должен инициализировать регистратор root, чтобы избежать добавления обработчиков по умолчанию, даже если я создаю именованный регистратор и планирую его использовать?
ОБНОВЛЕНИЕ: Как указал @blues, это работает, как ожидалось, и я не правильно читал документацию. Сообщения передаются непосредственно в родительский регистратор обработчики , а не в реальные регистраторы.
Я прошел через библиотеку журналирования Python (v3.7.3), чтобы продемонстрировать это поведение в коде, так как сначала мне показалось странным.
Метод callHandlers () этого фрагмента трассировки стека показывает, как это происходит.
callHandlers, init .py: 1585
дескриптор, init .py: 1529
_log, init .py: 1519
отладка, init .py: 1371