Duplicate log output, but no duplicate handlers

Question

I am getting duplicate log output from a logger that only has 1 handler attached.

How can I debug this?

Code (should be copy-and-paste-able):

import io
import logging
import os
import sys
from typing import Optional


DEFAULT_LOG_LEVEL = logging.INFO


def get_sub_loggers():
    return [
        logging.getLogger('a'),
        logging.getLogger('b'),
        logging.getLogger('c')
    ]


def safe_add_handler(logger: logging.Logger, h: logging.Handler) -> None:
    if h not in logger.handlers:
        logger.addHandler(h)


def safe_add_filter(logger: logging.Logger, f: logging.Filter) -> None:
    if f not in logger.filters:
        logger.addFilter(f)


def configure_logging(main_logger: logging.Logger,
                      log_level = DEFAULT_LOG_LEVEL,
                      log_file = None,
                      fmt: Optional[str] = None,
                      force_add_handler: bool = False) -> None:
    main_logger.setLevel(log_level)
    logging.captureWarnings(True)  # send all warnings to be logged

    if force_add_handler or not main_logger.hasHandlers():
        if log_file is None or log_file == '-':
            log_file = sys.stderr

        if isinstance(log_file, (str, os.PathLike)):
            handler = logging.FileHandler(log_file)
        else:
            handler = logging.StreamHandler(log_file)

        handler.setFormatter(logging.Formatter(fmt if fmt is not None else logging.BASIC_FORMAT))

        main_logger.addHandler(handler)
        log_output_location = handler.stream.name if isinstance(handler, logging.StreamHandler) else handler.baseFilename
        main_logger.info('Writing logs to {}'.format(log_output_location))
    else:
        main_logger.info('Using existing log handlers')

    main_logger.info('Using log level {}'.format(log_level))

    for logger in get_sub_loggers():
        logger.setLevel(log_level)
        for h in main_logger.handlers:
            safe_add_handler(logger, h)
        for f in main_logger.filters:
            safe_add_filter(logger, f)
        main_logger.debug('Configured logger {}'.format(logger.name))

    main_logger.info('Configured submodule loggers.')


configure_logging(logging.getLogger())

a_logger = logging.getLogger('a')
assert len(a_logger.handlers) == 1

# Should only output "hi" once, but it does it twice
a_logger.info('hi')

Why are you adding the same handler to four loggers? – user2357112 Jan 30 '19 at 18:20 — user2357112, Jan 30 '19 at 18:20

user2357112 · Accepted Answer · 2019-01-30T18:24:52.923

1

Loggers propagate log events to their ancestors' handlers by default. a_logger may only have one handler, but its parent, the root logger, also has a handler (actually the same handler). a_logger.info('hi') is handled by both handlers (actually the same handler twice).

You don't need to attach the same handler to every logger. Attaching it to the root logger is enough.

edited Jan 30 '19 at 18:24

answered Jan 30 '19 at 18:22

user2357112

260,549
28
431
505

I see, so I need to check to see if any of the sub-loggers' parents have handlers, in addition to checking the loggers themselves? – shadowtalker Jan 30 '19 at 18:24
@shadowtalker: You don't need to attach your handler to every logger manually. You attached it to the root logger. That's enough. – user2357112 Jan 30 '19 at 18:25
This code will be used on loggers other than the root logger (which might not be a parent of any of the sub-loggers). – shadowtalker Jan 30 '19 at 18:26
@shadowtalker: Are you saying the root logger might not be a parent of any of the sub-loggers? The root logger is an ancestor of every other logger. If you're saying the root logger might not be one of the loggers you add the handler to, you're going to have problems with things like what happens when you add a handler to a logger *after* adding that handler to a descendant of that logger. – user2357112 Jan 30 '19 at 18:30
The latter. I don't think I will have that issue in my use case. – shadowtalker Jan 30 '19 at 18:33
Adding the same handler to multiple loggers is rarely a good idea. Even if you don't want to add it to the root logger, adding it to *your package's* "root" logger is usually enough. Log event propagation will handle submodule logging. – user2357112 Jan 30 '19 at 18:34
That's a good compromise, I'll do that. Will filters propagate as well? Or do I still need to add those individually. – shadowtalker Jan 30 '19 at 18:38
@shadowtalker: Filters aren't propagated. A filter on an ancestor logger isn't considered, but filters on the *handlers* are considered. (The log event is passed directly to ancestor logger handlers, bypassing the loggers' filters, but not the handlers' filters.) It's confusing. – user2357112 Jan 30 '19 at 18:42
Do you recommend adding the filter to each logger, or adding the filter to the handler? – shadowtalker Jan 30 '19 at 18:44
1

@shadowtalker: I don't know. Either way has problems. (I really dislike the `logging` module design in general.) – user2357112 Jan 30 '19 at 18:46

Duplicate log output, but no duplicate handlers

1 Answers1