logging.config.dictConfig() with "disable_existing_loggers=False" closes existing handlers

[aparshin]

Bug report

Bug description:

Invoking logging.config.dictConfig() with "disable_existing_loggers": False breaks already added handlers, even if the config is empty. Specifically, it calls flush() and close() of all existing handlers.

Test script:

import logging
import logging.config

# test setup: add a FileHandler as the only handler of the root logger
fileHandler = logging.FileHandler("./debug_log.txt", mode="w")
fileHandler.setFormatter(logging.Formatter("%(message)s"))
root_logger = logging.getLogger()
root_logger.addHandler(fileHandler)

# this works fine - the message is added to the file
logging.warning("test message 1")

# set a trivial configuration: no formatters, handlers or loggers.
# "disable_existing_loggers" is set to False
logging.config.dictConfig({"version": 1, "disable_existing_loggers": False})

# the FileHandler doesn't work anymore - this message won't be added to the file
logging.warning("test message 2")

# the handler is in inconsistent state - it's still added to the logger,
# but it's already flush()'ed and close()'d
assert fileHandler in root_logger.handlers
assert fileHandler._closed == True

The content of the debug_log.txt after running this script is the following:

test message 1

But it supposed to be

test message 1
test message 2

Maybe issue #123239 is somehow related.

CPython versions tested on:

3.13

Operating systems tested on:

macOS

Linked PRs

• gh-127567: Avoid forceful shutting down of handlers during reconfiguration #127690

[ZeroIntensity]

@picnixz Have you confirmed this?

[picnixz]

Nope. I'm actually trusting users in general when they put the traceback and their expectation xD

[Agent-Hellboy]

Hi @ZeroIntensity and @picnixz
I looked into the commit that introduced this behavior. It seems the assumption was that both fileConfig and dictConfig are primarily used for reconfiguration, not for incremental patching of new configurations.

This is evident from the following commit(087570a) news entry:

Closed existing logging handlers before *reconfiguration* via fileConfig and dictConfig. Patch by Karthikeyan Singaravelan.

However, I agree that this approach is limiting for scenarios where users intend to preserve certain loggers while adding or modifying others.

A possible solution could be to add an option that allows users to specify which loggers to close, even when disable_existing_loggers=True. This would give users finer control over their logging configurations without introducing breaking changes.

I can share a WIP PR for you folks to check?

[ZeroIntensity]

I can share a WIP PR for you folks to check?

Go for it :)

[aparshin]

@Agent-Hellboy why can't we just close handlers that were removed from corresponding loggers during setting new configuration? Is it a problem with usage of the same handler in multiple loggers or with something else?

[Agent-Hellboy]

@Agent-Hellboy why can't we just close handlers that were removed from corresponding loggers during setting new configuration? Is it a problem with usage of the same handler in multiple loggers or with something else?

look at this comment #8008 (comment), it may cause issue if other logger is using it and you have also stated the same.

I have removed the automatic shutdown of handlers in-between reconfiguration as we do it at the end of the program , please review it

there is no fd leak as test_config15_ok is passing

[aparshin]

look at this comment #8008 (comment), it may cause issue if other logger is using it and you have also stated the same.

As I understand this comment, it demonstrates exactly the same problem as I described in this PR (but with SysLogHandler instead of FileHandler). In fact, this comment should become a new issue, not a comment to the PR...

So, the problem is not with handlers that should be replaced with handlers from new config, it's with handlers of loggers that are not supposed to be modified with the new config. For example, in the example of this issue, it's the root logger and its handler (FileHandler).

[Agent-Hellboy]

Hi @vsajip

In #8008, changes were made to ensure that handlers are closed before being removed to address file descriptor leaks. However, in the current scenario(my PR), I am not removing any handlers linked to an open file descriptor, yet I am encountering a file descriptor leak (the test added in #8008 is failng) after deleting something before it gets properly closed. Could you help identify which resource might be causing this issue?

Additionally, the current implementation assumes that if the incremental flag is not passed in the config, the user is reapplying the config, and as a result, all handlers should be cleared before reapplying. I have modified this behavior to close handlers only if disable_existing_loggers is not set to False. Furthermore, I introduced a new key, remove_handlers, to allow more flexibility in specifying which handlers to close.

I think I should have waited for your feedback before making these changes.

[aparshin]

@vsajip @Agent-Hellboy Here is my vision of the problem and possible solution.

First of all, we should decide what is the live circle of the logging handler. Particularly, critical question for this issue is the following: can we assume that for each added handler, the logging module is the only consumer of the handler?. If we can't assume that, we should never close() any handler (because, other possible consumers can continue to use handler after we remove it from all the loggers). Note, that this decision results in #78159 (fixed in #8008).

Is we can make that assumption (should we add it to documentation?), we should make sure that we call close() method for each handler, that is going to be removed from the loggers tree. We should be careful here and take into consideration several things:

1. The same handler can be used in multiple loggers (probably, we can use manager.loggerDict to detect that).
2. There are many ways to remove handlers: logger.removeHandler(), config.fileConfig(), config.dictConfig(), and, maybe, something else.

[daedric]

I just stumbled on this issue and I'm not sure what's the discussion about... When disable_existing_loggers is False, _clearExistingHandlers should not be called.
Thus a simple, expected fix could be:

                disable_existing = config.pop('disable_existing_loggers', True)
                if disable_existing: # the if is added.
                  _clearExistingHandlers()

That's it no?