Bug report

Bug description:

I found an issue when the root logger is configured after some loggers were initialized (not necessarily configured).

Experiment

I wrote a small reproducer of the issue. There are 4 functions in the file. All of them initialize some loggers, configure some other loggers and finally log some messages. What it is different from each other is:

• The order in which loggers are initialized and configured.
• Which is the logger being configured.

The reproducer:

import sys
import logging
from logging.config import dictConfig


LOGCFG = {
    'version': 1,
    'formatters': {
        'std': {
            'format': '[%(levelname)s  - %(asctime)s - %(name)s::] %(message)s'
        },
    },
    'handlers': {
        'console': {
            'level': 'DEBUG',
            'formatter': 'std',
            'class': 'logging.StreamHandler',
            'stream': 'ext://sys.stdout'
        },
    },
    'root': {
        'level':'DEBUG',
        'handlers': ['console'],
    },
}


def cfg_logger(logger):
    return {
        'version': 1,
        'formatters': {
            'std': {
                'format': f"{logger.upper()}[%(levelname)s  - %(asctime)s - %(name)s::] %(message)s"
            },
        },
        'handlers': {
            'console': {
                'level': 'DEBUG',
                'formatter': 'std',
                'class': 'logging.StreamHandler',
                'stream': 'ext://sys.stdout'
            },
        },
        'loggers': {
            logger: {
                'level':'DEBUG',
                'handlers': ['console'],
            },
        },
    }


def configure_root_then_init_loggers():
    dictConfig(LOGCFG)
    foo = logging.getLogger('foo')
    foobar = logging.getLogger('foo.bar')
    foo.error('whot')
    foobar.error('foobar')

def configure_foo_then_init_loggers():
    dictConfig(cfg_logger('foo'))
    foo = logging.getLogger('foo')
    foobar = logging.getLogger('foo.bar')
    foo.error('whot')
    foobar.error('foobar')

def init_loggers_then_config_foo():
    foo = logging.getLogger('foo')
    foobar = logging.getLogger('foo.bar')
    dictConfig(cfg_logger('foo'))
    foo.error('whot')
    foobar.error('foobar')

def init_loggers_then_config_root():
    foo = logging.getLogger('foo')
    foobar = logging.getLogger('foo.bar')
    dictConfig(LOGCFG)
    foo.error('whot')
    foobar.error('foobar')

def init_loggers_then_config_foobar_then_foo():
    foo = logging.getLogger('foo')
    foobar = logging.getLogger('foo.bar')
    dictConfig(cfg_logger('foo.bar'))
    foo.error('whot')
    foobar.error('foobar')
    dictConfig(cfg_logger('foo'))
    foo.error('whot')
    foobar.error('foobar')


def main():
    funcs = [
        configure_foo_then_init_loggers,
        configure_root_then_init_loggers,
        init_loggers_then_config_foo,
        init_loggers_then_config_root,
        init_loggers_then_config_foobar_then_foo,
    ]
    func = funcs[int(sys.argv[1])]
    print(f"Running: {func.__name__}\n{'.'*60}")
    func()
    print(f"\n\n{'_'*60}")


if __name__ == "__main__":
    main()

Results

And the results for each of the analysed cases:

$ python3.12 reproducer.py 0
Running: configure_foo_then_init_loggers
............................................................
FOO[ERROR  - 2024-06-19 18:39:48,426 - foo::] whot
FOO[ERROR  - 2024-06-19 18:39:48,426 - foo.bar::] foobar


____________________________________________________________
$ python3.12 reproducer.py 1
Running: configure_root_then_init_loggers
............................................................
[ERROR  - 2024-06-19 18:39:49,757 - foo::] whot
[ERROR  - 2024-06-19 18:39:49,758 - foo.bar::] foobar


____________________________________________________________
$ python3.12 reproducer.py 2
Running: init_loggers_then_config_foo
............................................................
FOO[ERROR  - 2024-06-19 18:39:52,000 - foo::] whot
FOO[ERROR  - 2024-06-19 18:39:52,000 - foo.bar::] foobar


____________________________________________________________
$ python3.12 reproducer.py 3
Running: init_loggers_then_config_root
............................................................


____________________________________________________________
$ python3.12 reproducer.py 4
Running: init_loggers_then_config_foobar_then_foo
............................................................
FOO.BAR[ERROR  - 2024-06-20 08:29:57,727 - foo.bar::] foobar
FOO[ERROR  - 2024-06-20 08:29:57,728 - foo::] whot
FOO[ERROR  - 2024-06-20 08:29:57,728 - foo.bar::] foobar


____________________________________________________________

Case 0 configure_foo_then_init_loggers

First the foo logger is configured using logging.config.dictConfig. Then, instances for foo and its child logger foo.bar are created via getLogger.

In simple terms, as foo was configured, IIUC, foo.bar inherits its parent configuration. Then, both logs are put into the stdout.

Case 1 configure_root_then_init_loggers

First the root logger is configured using logging.config.dictConfig. Then, instances for foo and its child logger foo.bar are created via getLogger.

In simple terms, as the root logger was configured, both foo and foo.bar inherit the configuration from its parent configuration, which this time is root.

Case 2 init_loggers_then_config_foo

Now, the logger instances are first initialized for both foo and foo.bar. Then, only the parent foo logger is configured by using logging.config.dictConfig.

During foo's configuration its already existing children (foo.bar) will be also treated. IIUC, that will happen approximately in https://github.com/python/cpython/blob/v3.12.3/Lib/logging/config.py#L653-L654, as foo.bar is in the existing loggers list as well as in the child_loggers list.

The output (written into the stdout), will be the same as case 0.

Case 3 init_loggers_then_config_root

In this case, foo and foo.bar loggers are initialized first, but not configured, as in case 2. Then, the root logger is configured by means of logging.config.dictConfig.

In this specific case, the already existing loggers (foo and foo.bar) won't be processed in _handle_existing_loggers, as they exist but are not in the child_loggers list.

There won't be any log written to the stdout.

Case 4 init_loggers_then_config_foobar_then_foo

Last case: foo and foo.bar are initialized. Then, foo.bar is configured. It's also checked that it works as expected. Right after that, foo is configured, which also affects its already existing and configured child foo.bar.

After that, logs from foo.bar will follow the configuration of foo.

Note about python3.9 and case 4

Case 4 doesn't report the same result for python3.9. From python3.10 on, the result is the same as the one reported above. For python3.9, though, will be the following:

$ python3.9 report.py 4
Running: init_loggers_then_config_foobar_then_foo
............................................................
FOO.BAR[ERROR  - 2024-06-20 10:28:19,770 - foo.bar::] foobar
FOO[ERROR  - 2024-06-20 10:28:19,770 - foo.bar::] foobar


____________________________________________________________

But that's another topic.

Expected results

All the cases seem to follow the same behavior except for case 3. When a logger is configured, all of its children will follow the last applied configuration.

However, configuring the root logger by dictConfig won't apply that configuration over the rest of loggers. This is IMHO, a behavior conflict, compared to the expected one from configuring any other logger. Isn't root the parent of all the rest of loggers after all?

CPython versions tested on:

3.9, 3.10, 3.11, 3.12

Operating systems tested on:

Linux