Python 2.7: log displayed twice when `logging` mod

Question

Context:

Python 2.7.

Two files in the same folder:

• First: main script.
• Second: custom module.

Goal:

Possibility to use the logging module without any clash (see output below).

Files:

a.py:

import logging
from b import test_b

def test_a(logger):
    logger.debug("debug")
    logger.info("info")
    logger.warning("warning")
    logger.error("error")

if __name__ == "__main__":
    # Custom logger.
    logger = logging.getLogger("test")

    formatter = logging.Formatter('[%(levelname)s] %(message)s')
    handler = logging.StreamHandler()
    handler.setFormatter(formatter)

    logger.setLevel(logging.DEBUG)
    logger.addHandler(handler)

    # Test A and B.
    print "B"
    test_b()
    print "A"
    test_a(logger)

b.py:

import logging

def test_b():
    logging.debug("debug")
    logging.info("info")
    logging.warning("warning")
    logging.error("error")

Output:

As one could see below, the log is displayed twice.

python a.py
B
WARNING:root:warning
ERROR:root:error
A
[DEBUG] debug
DEBUG:test:debug
[INFO] info
INFO:test:info
[WARNING] warning
WARNING:test:warning
[ERROR] error
ERROR:test:error

Would anyone have a solution to this?

EDIT: not running test_b() will cause no log duplication and correct log formatting (expected).

Answer 1

I'm not sure I understand your case, because the description doesn't match the output… but I think I know what your problem is.

As the docs explain:

Note: If you attach a handler to a logger and one or more of its ancestors, it may emit the same record multiple times. In general, you should not need to attach a handler to more than one logger - if you just attach it to the appropriate logger which is highest in the logger hierarchy, then it will see all events logged by all descendant loggers, provided that their propagate setting is left set to True. A common scenario is to attach handlers only to the root logger, and to let propagation take care of the rest.

And that "common scenario" usually works great, but I assume you need to attach a custom handler to "test", without affecting the root logger.

So, if you want a custom handler on "test", and you don't want its messages also going to the root handler, the answer is simple: turn off its propagate flag:

logger.propagate = False

---

The reason this only happens if you call test_b is that otherwise, the root logger never gets initialized. The first time you log to any logger that hasn't been configured, it effectively does a basicConfig() on that logger. So, calling logging.getLogger().info(msg) or logging.info(msg) will configure the root logger. But propagating from a child logger will not.

I believe this is explained somewhere in the logging HOWTO or cookbook, both under HOWTOs, but in the actual module docs, it's buried in the middle of a note about threading under logging.log:

Note: The above module-level functions which delegate to the root logger should not be used in threads, in versions of Python earlier than 2.7.1 and 3.2, unless at least one handler has been added to the root logger before the threads are started. These convenience functions call basicConfig() to ensure that at least one handler is available; ; in earlier versions of Python, this can (under rare circumstances) lead to handlers being added multiple times to the root logger, which can in turn lead to multiple messages for the same event.

It's pretty easy to see how you could have missed that!