Python logging with multiple modules

Question

I have got various modules in which I use Python logging heavily. When I import them into the main module like in the Python documentation and try to run it, I don't get any output from the logging. Has anyone got any idea what is happening?

Logging is called in the module imported by the public module imported below (the piece of code is too large to be put up here). The piece of code below is where the whole program is run and the logging is initialized:

import logging
from bottle import run, debug
import public

logging.basicConfig(level=logging.DEBUG)

if __name__ == '__main__':
   logging.info('Started')
   debug(mode=True)
   run(host='localhost', port = 8080, reloader=True)
   logging.info('Finished')

Answer 1

Your problem is probably being caused by the import public statement making a call to logging.debug(...) or similar. What then happens is this:

1. You import public. As a side-effect, this calls e.g. logging.debug or similar, which automatically calls basicConfig, which adds a StreamHandler to the root logger, but doesn't change the level.
2. You then call basicConfig, but as the root logger already has a handler, it does nothing (as documented).
3. Since the default logging level is WARNING, your info and debug calls produce no output.

You really should avoid side-effects on import: for example, your call to basicConfig should be in the if __name__ == '__main__' clause. With this public.py:

import logging

def main():
    logging.debug('Hello from public')

and this main.py:

import logging
from bottle import run, debug
import public

def main():
    logging.basicConfig(level=logging.DEBUG)
    logging.info('Started')
    debug(mode=True)
    public.main()
    run(host='localhost', port = 8080, reloader=True)
    logging.info('Finished')

if __name__ == '__main__':
    main()

You get the following output:

$ python main.py
INFO:root:Started
DEBUG:root:Hello from public
INFO:root:Started
DEBUG:root:Hello from public
Bottle server starting up (using WSGIRefServer())...
Listening on http://localhost:8080/
Hit Ctrl-C to quit.

^CINFO:root:Finished
$ Shutdown...
INFO:root:Finished

You'll see from this that Bottle actually re-runs the script in a separate process, which accounts for the doubling up of messages. You can illustrate this by using a format string which shows the process ID: if you use

logging.basicConfig(level=logging.DEBUG,
                    format='%(process)s %(levelname)s %(message)s')

then you get output like

$ python main.py
13839 INFO Started
13839 DEBUG Hello from public
13840 INFO Started
13840 DEBUG Hello from public
Bottle server starting up (using WSGIRefServer())...
Listening on http://localhost:8080/
Hit Ctrl-C to quit.

^C13839 INFO Finished
$ Shutdown...
13840 INFO Finished

Note that if you add a side-effect producing statement to public.py like this:

logging.debug('Side-effect from public')

at the module level, then you get no logging output at all:

$ python main.py
Bottle server starting up (using WSGIRefServer())...
Listening on http://localhost:8080/
Hit Ctrl-C to quit.

^C$ Shutdown...

which appears to confirm the above analysis.

Answer 2

#!/usr/bin/env python
# -*- coding: utf-8 -*-

import logging
import logging.handlers
from logging.config import dictConfig

logger = logging.getLogger(__name__)

DEFAULT_LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
}
def configure_logging(logfile_path):
    """
    Initialize logging defaults for Project.

    :param logfile_path: logfile used to the logfile
    :type logfile_path: string

    This function does:

    - Assign INFO and DEBUG level to logger file handler and console handler

    """
    dictConfig(DEFAULT_LOGGING)

    default_formatter = logging.Formatter(
        "[%(asctime)s] [%(levelname)s] [%(name)s] [%(funcName)s():%(lineno)s] [PID:%(process)d TID:%(thread)d] %(message)s",
        "%d/%m/%Y %H:%M:%S")

    file_handler = logging.handlers.RotatingFileHandler(logfile_path, maxBytes=10485760,backupCount=300, encoding='utf-8')
    file_handler.setLevel(logging.INFO)

    console_handler = logging.StreamHandler()
    console_handler.setLevel(logging.DEBUG)

    file_handler.setFormatter(default_formatter)
    console_handler.setFormatter(default_formatter)

    logging.root.setLevel(logging.DEBUG)
    logging.root.addHandler(file_handler)
    logging.root.addHandler(console_handler)



[31/10/2015 22:00:33] [DEBUG] [yourmodulename] [yourfunction_name():9] [PID:61314 TID:140735248744448] this is logger infomation from hello module

I have try this code in my project. run configure_loggint(logpath) in the main.

and you can use

#!/usr/bin/env python
# -*- coding: utf-8 -*-

import logging

logger = logging.getLogger(__name__)

def hello():
    logger.debug("this is logger infomation from hello module")

Answer 3

EDIT 1:

The following was based on a misunderstanding of the OP's code (from the comment) and a false assumption on my part. As such, it's invalid.

There was at least one error with the code you provided. debug(mode=True) is wrong for two reasons:

1. it's being called by itself, as a method you defined, which you haven't
2. mode=True is an assignment, not a test for equality

The following, stripped of any ancillary modules and code, runs and logs for me:

import logging

mode = False

logging.basicConfig(level=logging.DEBUG)
logging.info('Started')
logging.debug(mode is True)
# ... other code ...
logging.info('Finished')

Run from the command line:

$ python my_logger.py
INFO:root:Started
DEBUG:root:False
INFO:root:Finished