Logging is sometimes duplicated without color

[thomasaarholt]

Asking here primarily to see if you know an obvious reason why this is happening:

I'm sometimes getting a double logging output in my log:

1-19 14:26:36 DEBUG    First dates from partial predictions: {'transfer_rates': datetime.date(2020, 10, 5), 'orders_day': datetime.date(2020, 10, 5), 'units_order': datetime.date(2020, 10, 5)}
11-19 14:26:36 DEBUG    First date of joint prediction: 2020-10-05
11-19 14:26:36 DEBUG    Days predicted in partial predictions fron joint first date: {'transfer_rates': 42, 'orders_day': 42, 'units_order': 42}
11-19 14:26:36 DEBUG    Last date of joint prediction: 2020-11-15
11-19 14:26:38 DEBUG    Using expected new [[ 850. 1200. 1200. 1200. 3000. 3000. 3000.]]
11-19 14:26:38 DEBUG    Using expected winback [[2400. 2600. 2600. 2500. 3000. 3000. 3200.]]
11-19 14:26:38 DEBUG    Added noise to expected new and winback
11-19 14:26:38 DEBUG    Normalize ranges and draws on prediction for transfer_rates
DEBUG:main:Normalize ranges and draws on prediction for transfer_rates
11-19 14:26:38 DEBUG    Normalize ranges and draws on prediction for orders_day
DEBUG:main:Normalize ranges and draws on prediction for orders_day
11-19 14:26:38 DEBUG    Normalize ranges and draws on prediction for units_order
DEBUG:main:Normalize ranges and draws on prediction for units_order
11-19 14:26:38 INFO     Add adjustments
INFO:main:Add adjustments

The white lines containing :main: are the lines I do not expect. Once these lines start appearing, the double logs appear with every single logging statement.

We import a logger in our scripts that is defined as:

def make_logger(console=True):
    logger = logging.getLogger(name)
    logger.setLevel(level)

    if console:
        color_fmt = "%(log_color)s" if use_color and console else ""
        # some additional unrelated code here, removed for clarity
   
        # set logger stream variable so color only in interactive
        # terminals AND notebooks, preventing ANSI escape signatures
        # in grayscale log files
        stream = None if is_in_ipython_session() else sys.stderr

        formatter = colorlog.ColoredFormatter(
            fmt=color_fmt + log_format_for_console,
            datefmt=time_format_for_console,
            log_colors={
                "DEBUG": "blue",
                "INFO": "green",
                "WARNING": "yellow",
                "ERROR": "red",
                "CRITICAL": "bold_red,bg_white",
            },
            stream=stream,
        )
        if log_in_gmt:
            formatter.converter = time.gmtime

        handler = colorlog.StreamHandler()
        handler.setFormatter(formatter)

        logger.addHandler(handler)

I've use this as logger = make_logger(), and then e.g. logger.debug(...). I've noticed that I can trigger the double line behaviour if I accidentally call logging.debug instead of logger.debug, but that is not the case in the above.

Do you have any idea what's going on?

[borntyping]

It's extremly likely that somewhere in the code another handler is being created. Maybe make_logger is being called twice?

[thomasaarholt]

You might be right, although I'm struggling to figure out where. I'll try to raise an error if a handler already exists, and see what the traceback says!

[thomasaarholt]

This might be related. I notice that if I erroneously call logging.debug instead of logger.debug, all future logger.debug calls are printed twice, second time without color.

import colorlog
import logging

handler = colorlog.StreamHandler()
handler.setFormatter(colorlog.ColoredFormatter(
	'%(log_color)s%(levelname)s:%(name)s:%(message)s'))

logger = colorlog.getLogger('example')
logger.addHandler(handler)

logger.warning('Normal logging')
logging.warning("Logging using root") # using logging instead of logger
logger.warning('This message is printed twice') # logger now outputs message twice

This also applies to the normal logger:

import logging

handler = logging.StreamHandler()
handler.setFormatter(logging.Formatter(
	'%(levelname)s:%(name)s:%(message)s'))

logger = logging.getLogger('example')
logger.addHandler(handler)

logger.warning('Normal logging')
# WARNING:example:Normal logging

logging.warning("Logging using root") # using logging instead of logger
# WARNING:root:Logging using root

logger.warning('This message is printed twice') # logger now outputs message twice
# WARNING:example:This message is printed twice
# WARNING:example:This message is printed twice

Now, I don't call logging.debug by accident (I mean, I did and that is how I discovered this, but that is no longer the case), but the above does look identical to my behaviour, except that in my case there is never output a root logging message.

[thomasaarholt]

After calling the above, there is still only one handler in logger.handlers :/

[borntyping]

logging.debug sets up a handler if there are no existing handler on the root logger (i.e. top level logger returned by logging.getLogger() with no arguments). Colorlog implements something very similar in it's own colorlog.debug type functions.

https://github.com/python/cpython/blob/3.10/Lib/logging/__init__.py#L2137-L2139

In your example you'll probably find that logging.getLogger().handlers != logging.getLogger('example').handlers.