Logging in python with JSON configuration - things get logged more than once?

Short answer

This is because of a special property called propagate. It is a flag that determines whether a logger should pass a log record to its parent logger (propagate=True) or not (propagate=False). You need either to remove the common configuration from the intermediate loggers, leaving only the unique stuff, or pass "propagate": false to all the loggers.

Long answer

loggers hierarchy and log record propagation

All loggers in Python are organized in a hierarchy: there is always a root logger, returned when you call getLogger without a name:

root_logger = logging.getLogger()

All the loggers you create with a name are children of the root logger, so

my_logger = logging.getLogger('my-special-logger')

has root_logger as parent. Now, when you call my_logger.info('Hello world'), the following happens: my_logger will

• handle the record itself
• check whether it has propagate set to True, if yes, then it will pass the record to its parent logger (the root logger in this case), which will also handle the record.

This is also visualized in the logging flow diagram, you can check it out if you want.

Now, you can probably already guess what happens if I configure both loggers like this:

"loggers": {
    "my-special-logger": {
        "handlers": ["debug_file_handler"]
    },
},

"root": {
    "handlers": ["debug_file_handler"]
}

On each incoming log record, the my-special-logger writes the record to debug.log, then passes the record further up to root, which also writes the record to debug.log. So the record will appear twice in the end.

module namespace hierarchy

However, the question is: why there are three copies of some records in the debug log? The answer is found in Advanced Logging Tutorial:

Each [logger] instance has a name, and they are conceptually arranged in a namespace hierarchy using dots (periods) as separators. For example, a logger named scan is the parent of loggers scan.text, scan.html and scan.pdf.

So now you can evaluate the logger hierarchy in your code:

root                                                -> writes to debug.log
└── spam_application
     └── spam_application.auxiliary                -> writes to debug.log
          └── spam_application.auxiliary.Auxiliary -> writes to debug.log

solution

The propagation of records in the logging hierharchy has the advantage that you don't need to repeat the configuration for each logger. So, when your application should log to debug.log, add the debug_file_handler to root logger once and it will already serve all the other loggers, no matter whether you add them to config or not.

This way, your initial config can be reduced to:

{
    "version": 1,
    "disable_existing_loggers": false,
    "formatters": { ... },

    "handlers": {
        "debug_file_handler": { ... }
    },

    "root": {
        "level": "DEBUG",
        "handlers": ["debug_file_handler"]
    }
}

The alternative to that would be passing "propagate": false to each explicitly configured logger so the messages won't be handled multiple times by the debug_file_handler:

{
    "version": 1,

    ...

    "loggers": {
        "spam_application.auxiliary.Auxiliary": {
            "level": "DEBUG",
            "handlers": ["debug_file_handler"],
            "propagate": false
        },
        "spam_application.auxiliary": {
            "level": "DEBUG",
            "handlers": ["debug_file_handler"],
            "propagate": false
        }
    },

    ...