How logging is happening in this python code sample

Question

I am trying to understand python logging by fiddling with this basic example. I add some lines in that code and reproduced below. Find #added by me comment to find which line I added:

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"')

Console output

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()

Doubts

1. Why I get following lines in console?:

   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. Why those last five lines in console do not follow format of others?

3. Why there is no

   DEBUG:root:-->testing logger debug
   

4. Why these lines not in file:

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

5. Basically how child module logging behave when I call logging.xyz() instead of logging.getLogger('abc').xyz() inside child module (here auxiliary_module)?

Answer 1

1, 2, 3, 4. The nature of your problem is that you use two loggers. The first one you have created with the code logger = logging.getLogger('spam_application'). The second one is root logger. You started it with the code logging.debug("-->testing logger debug"). Usually you need multiple loggers to distinguish between sources of logging messages. Keep track of your loggers and do not mix them.

To take an easy start with logging in python you may use only root logger. You can configure it with logging.basicConfig(...) and create log messages with, for example, logging.info(...).

5. It behaves just fine. You do not need any extra actions to make logging work correctly. Although you may experience difficulties with logging across multiple threads and processes.