Как происходит регистрация в этом примере кода Python

Question

Я пытаюсь понять регистрацию в Python, играя с этим базовым примером . Я добавил несколько строк в этот код и воспроизвел их ниже. Найдите #added by me комментарий, чтобы найти, какую строку я добавил:

spam_application.py

import logging
import auxiliary_module

# create logger with 'spam_application'
logger = logging.getLogger('spam_application')
logger.setLevel(logging.DEBUG)
# create file handler which logs even debug messages
fh = logging.FileHandler('spam.log')
fh.setLevel(logging.DEBUG)
# create console handler with a higher log level
ch = logging.StreamHandler()
ch.setLevel(logging.ERROR)
# create formatter and add it to the handlers
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
fh.setFormatter(formatter)
ch.setFormatter(formatter)
# add the handlers to the logger
logger.addHandler(fh)
logger.addHandler(ch)

logger.error("Testing logger err")   #added by me
logger.debug("desting logger debug") #added by me

logger.info('creating an instance of auxiliary_module.Auxiliary')
a = auxiliary_module.Auxiliary()
logger.info('created an instance of auxiliary_module.Auxiliary')
logger.info('calling auxiliary_module.Auxiliary.do_something')
a.do_something()
logger.info('finished auxiliary_module.Auxiliary.do_something')
logger.info('calling auxiliary_module.some_function()')
auxiliary_module.some_function()
logger.info('done with auxiliary_module.some_function()')

auxiliary_module.py

import logging

# create logger
module_logger = logging.getLogger('spam_application.auxiliary')

class Auxiliary:
    def __init__(self):
        self.logger = logging.getLogger('spam_application.auxiliary.Auxiliary')
        self.logger.info('creating an instance of Auxiliary')

    def do_something(self):
        self.logger.info('doing something')
        a = 1 + 1
        self.logger.debug("a =%s", a)   #added by me
        self.logger.info('done doing something')
        self.logger.error("Testing logger err")     #added by me
        self.logger.debug("testing logger debug")   #added by me
        logging.debug("-->testing logger debug")    #added by me
        logging.error("-->testing logger err")      #added by me

def some_function():
    module_logger.info('received a call to "some_function"')

Консольный вывод

2018-09-07 18:43:57,041 - spam_application - ERROR - Testing logger err
2018-09-07 18:43:57,041 - spam_application.auxiliary.Auxiliary - ERROR - Testing logger err
ERROR:root:-->testing logger err
INFO:spam_application:finished auxiliary_module.Auxiliary.do_something
INFO:spam_application:calling auxiliary_module.some_function()
INFO:spam_application.auxiliary:received a call to "some_function"
INFO:spam_application:done with auxiliary_module.some_function()

spam.log

2018-09-07 18:43:57,041 - spam_application - ERROR - Testing logger err
2018-09-07 18:43:57,041 - spam_application - DEBUG - desting logger debug
2018-09-07 18:43:57,041 - spam_application - INFO - creating an instance of auxiliary_module.Auxiliary
2018-09-07 18:43:57,041 - spam_application.auxiliary.Auxiliary - INFO - creating an instance of Auxiliary
2018-09-07 18:43:57,041 - spam_application - INFO - created an instance of auxiliary_module.Auxiliary
2018-09-07 18:43:57,041 - spam_application - INFO - calling auxiliary_module.Auxiliary.do_something
2018-09-07 18:43:57,041 - spam_application.auxiliary.Auxiliary - INFO - doing something
2018-09-07 18:43:57,041 - spam_application.auxiliary.Auxiliary - DEBUG - a =2
2018-09-07 18:43:57,041 - spam_application.auxiliary.Auxiliary - INFO - done doing something
2018-09-07 18:43:57,041 - spam_application.auxiliary.Auxiliary - ERROR - Testing logger err
2018-09-07 18:43:57,041 - spam_application.auxiliary.Auxiliary - DEBUG - testing logger debug
2018-09-07 18:43:57,042 - spam_application - INFO - finished auxiliary_module.Auxiliary.do_something
2018-09-07 18:43:57,042 - spam_application - INFO - calling auxiliary_module.some_function()
2018-09-07 18:43:57,042 - spam_application.auxiliary - INFO - received a call to "some_function"
2018-09-07 18:43:57,042 - spam_application - INFO - done with auxiliary_module.some_function()

Сомнения

1. Почему я получаю следующие строки в консоли?:

   INFO:spam_application:finished auxiliary_module.Auxiliary.do_something
   INFO:spam_application:calling auxiliary_module.some_function()
   INFO:spam_application.auxiliary:received a call to "some_function"
   INFO:spam_application:done with auxiliary_module.some_function()
   

2. Почему эти последние пять строк в консоли не соответствуют формату других?

3. Почему нет

   DEBUG:root:-->testing logger debug
   

4. Почему эти строки отсутствуют в файле:

   DEBUG:root:-->testing logger debug
   ERROR:root:-->testing logger err
   

5. В основном, как ведется ведение журнала дочернего модуля, когда я вызываю logging.xyz() вместо logging.getLogger('abc').xyz() внутри дочернего модуля (здесь auxiliary_module)?

Answer 1

1, 2, 3, 4. Суть вашей проблемы в том, что вы используете два регистратора. Первый, который вы создали с кодом logger = logging.getLogger('spam_application'). Второй - root logger. Вы начали это с кодом logging.debug("-->testing logger debug"). Обычно вам нужно несколько регистраторов, чтобы различать источники сообщений. Следите за своими регистраторами и не смешивайте их.

Чтобы начать работу с Python, вы можете использовать только root logger. Вы можете настроить его с помощью logging.basicConfig(...) и создавать сообщения журнала, например, logging.info(...).

5. Он ведет себя просто отлично. Вам не нужно никаких дополнительных действий, чтобы логирование работало корректно. Хотя вы можете испытывать трудности при ведении журнала между несколькими потоками и процессами.