Logging module sample code repeats messages n-time

Question

I'm surprised by the output from Python's logging module. I wrote up the Python.org's How-To for Logging. When I run the sample code, there is a lot of (confusing) duplication.

The StreamHandler duplicates the log messages, one for each time I reload the file in iPython with the magic %run

In [4]: %run main.py
2018-05-11 2127:33 - WARNING - 3. This is a warning, yous!
2018-05-11 2127:33 - ERROR - 4. Here is an error
2018-05-11 2127:33 - CRITICAL - 5. This is f-ing critical!
[...]
In [7]: %run main.py
2018-05-11 2127:38 - WARNING - 3. This is a warning, yous!
2018-05-11 2127:38 - WARNING - 3. This is a warning, yous!
2018-05-11 2127:38 - WARNING - 3. This is a warning, yous!
2018-05-11 2127:38 - ERROR - 4. Here is an error
2018-05-11 2127:38 - ERROR - 4. Here is an error
2018-05-11 2127:38 - ERROR - 4. Here is an error
2018-05-11 2127:38 - CRITICAL - 5. This is f-ing critical!
2018-05-11 2127:38 - CRITICAL - 5. This is f-ing critical!
2018-05-11 2127:38 - CRITICAL - 5. This is f-ing critical!

I added a FileHandler:

fh = logging.FileHandler("app.log")
fh.setLevel(logging.DEBUG)
fh.setFormatter(formatter)
logger.addHandler(fh)

This also duplicates:

xtian@spaceghost> cat app.log
2018-05-11 2159:24 - WARNING - 3. This is a warning!
2018-05-11 2159:24 - ERROR - 4. This is an error
2018-05-11 2159:24 - CRITICAL - 5. This is fucking critical!
[...]
2018-05-11 2201:00 - WARNING - 3. This is a warning, yous!
2018-05-11 2201:00 - WARNING - 3. This is a warning, yous!
2018-05-11 2201:00 - WARNING - 3. This is a warning, yous!
2018-05-11 2201:00 - ERROR - 4. Here is an error.
2018-05-11 2201:00 - ERROR - 4. Here is an error.
2018-05-11 2201:00 - ERROR - 4. Here is an error.
2018-05-11 2201:00 - CRITICAL - 5. This is f-ing critical!
2018-05-11 2201:00 - CRITICAL - 5. This is f-ing critical!
2018-05-11 2201:00 - CRITICAL - 5. This is f-ing critical!

I also followed the suggestions from other posts, and added these lines just before the message calls:

# propagation fix
logger.propagate = False

The results are the same.

---

Setting up to post, I see a similar question:

What could cause the logging module to log a record multiple times?

But all this debugging is for the OP's original custom code. My issue is with the sample code, which I expect should warn or explain better what's happening.

The docs say,

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.

You can see the full test file main.py here to see if I have 'more than one logger'.

import logging

# Root Logger
logger = logging.getLogger(__name__)

# Console handler
ch = logging.StreamHandler()
ch.setLevel(logging.WARNING)

# Formatter
formatter = logging.Formatter(fmt='%(asctime)s - %(levelname)s - %(message)s' , datefmt='%Y-%m-%d %H%M:%S', style='%')

# Add formatter to Console handler ch
ch.setFormatter(formatter)

# Add ch to logger
logger.addHandler(ch)

# Text File handler
fh = logging.FileHandler("app.log")
fh.setLevel(logging.DEBUG)
fh.setFormatter(formatter)
logger.addHandler(fh)

# propagation fix
logger.propagate = False

# Example Application code
logger.debug("1. This is a debug message.")
logger.info("2. This is an info message.")
logger.warning('3. This is a warning!')
logger.error('4. This is an error')
logger.critical("5. This is fucking critical!")

Answer 1

The logger returned by logging.getLogger(__name__) is the same logger each time %run main.py is executed. But

ch = logging.StreamHandler()

instantiates a new StreamHandler each time, which is then added to the logger:

logger.addHandler(ch)

Thus, on subsequent runs of %run main.py, the logger has multiple handlers attached to it and a record gets emitted by each handler.

---

In [5]: %run main.py
2018-05-11 2251:17 - WARNING - 3. This is a warning!
2018-05-11 2251:17 - ERROR - 4. This is an error
2018-05-11 2251:17 - CRITICAL - 5. This is fucking critical!

In [6]: logger
Out[6]: <logging.Logger at 0x7f5d0152fe10>

The first time %run main.py is run, two handlers are attached to logger:

In [7]: logger.handlers
Out[12]: 
[<logging.StreamHandler at 0x7f5d0152fdd8>,
 <logging.FileHandler at 0x7f5d014c40f0>]

In [13]: %run main.py
2018-05-11 2251:44 - WARNING - 3. This is a warning!
2018-05-11 2251:44 - WARNING - 3. This is a warning!
2018-05-11 2251:44 - ERROR - 4. This is an error
2018-05-11 2251:44 - ERROR - 4. This is an error
2018-05-11 2251:44 - CRITICAL - 5. This is fucking critical!
2018-05-11 2251:44 - CRITICAL - 5. This is fucking critical!

The second time, there are now four handlers:

In [14]: logger.handlers
Out[14]: 
[<logging.StreamHandler at 0x7f5d0152fdd8>,
 <logging.FileHandler at 0x7f5d014c40f0>,
 <logging.StreamHandler at 0x7f5d014c4668>,
 <logging.FileHandler at 0x7f5d014c4550>]

In [15]: logger
Out[15]: <logging.Logger at 0x7f5d0152fe10> 

To prevent duplication, you could call logger.removeHandler between %run calls:

In [29]: for handler in logger.handlers: logger.removeHandler(handler)

In [30]: %run main.py
2018-05-11 2257:30 - WARNING - 3. This is a warning!
2018-05-11 2257:30 - ERROR - 4. This is an error
2018-05-11 2257:30 - CRITICAL - 5. This is fucking critical!

or, modify main.py so that new handlers are not attached each time %run is called. For example, you could setup logger using logging.config.dictConfig:

import logging
import logging.config

# Modified using https://stackoverflow.com/a/7507842/190597 as a template
logging_config = { 
    'version': 1,
    'formatters': { 
        'standard': { 
            'format': '%(asctime)s - %(levelname)s - %(message)s'
        },
    },
    'handlers': { 
        'stream': { 
            'level': 'INFO',
            'formatter': 'standard',
            'class': 'logging.StreamHandler',
        },
        'file': { 
            'level': 'DEBUG',
            'formatter': 'standard',
            'class': 'logging.FileHandler',
            'filename': 'app.log'
        },
    },
    'loggers': { 
        __name__: { 
            'handlers': ['stream', 'file'],
            'level': 'WARN',
            'propagate': False
        },
    } 
}
logging.config.dictConfig(logging_config)
logger = logging.getLogger(__name__)

# Example Application code
logger.debug("1. This is a debug message.")
logger.info("2. This is an info message.")
logger.warning('3. This is a warning!')
logger.error('4. This is an error')
logger.critical("5. This is fucking critical!")

Using this code, %run main.py emits the same output each time.