Python 2.7: log displayed twice when `logging` module is used in two python scripts
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: 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](http://docs.python.org/2/library/logging.html#logging.Logger.propagate)
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](http://docs.python.org/2/howto/), but in the actual module
docs, it's buried in the middle of a note about threading under
[`logging.log`](http://docs.python.org/2/library/logging.html#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!

