logging.shutdown() should clear logging._handlerList if that's what it's called with

[cjw296]

Bug report

Bug description:

In the wild, I've encountered situations where logging.shutdown gets called more than once in a process.

The current implementation is called with logging._handlerList by default, meaning that handlers can have their flush() and close() methods called more than once, which can cause bad things to happen if those handlers are not amenable to being closed more than once.

If logging.shutdown() is processing logging._handlerList, it should clear that list once it finished to prevent handlers having their flush() and close() methods called more than once.

CPython versions tested on:

3.12, CPython main branch

Operating systems tested on:

Linux, macOS

Linked PRs

• gh-129268: Don't attempt to cleanup handlers again if logging.shutdown is called multiple times #129681

[ZeroIntensity]

Would you like to submit a PR?

[cjw296]

Would be good to get a second opinion as to why this is the way it is. @vsajip - you around on here?

[vsajip]

Well, the API documentation for logging.shutdown says:

This should be called at application exit and no further use of the logging system should be made after this call.

When the logging module is imported, it registers this function as an exit handler (see atexit), so normally there’s no need to do that manually.

So, calling shutdown() in user code is mildly questionable practice (as not needed, due to the atexit handler), and calling it more than once perhaps more strongly so (given the "no further use should be made ...").

logging.shutdown also catches and ignores OSError and ValueError exceptions raised when flushing/closing, so perhaps those bad things happening are due to handlers being badly written.

The logging.shutdown API is used internally in logging.config and in the logging test suite, so changing it could have ramifications there, too.

Since the case you mention involves calling shutdown more than once and perhaps involves handlers that don't just throw exceptions if called inappropriately, surely any changes to the stdlib in this area would be more of a band-aid, rather than addressing the root cause of the problems? I appreciate you may not have direct control of the code calling shutdown or of the handlers.

If the handlers throw some other stdlib exception than OSError and ValueError, I can look at broadening that catch clause.

[cjw296]

@vsajip - what reason could there be to not logging._handlerList.clear() once the processing is done during shutdown?

[picnixz]

Similar but not a duplicate: #129143

[vsajip]

what reason could there be to not

Don't know yet if there is one, but I'm generally not keen on making changes to cover for what might be bad practice in user code. I gave some specific reasons why I thought there might be bad practice, but those haven't been addressed.

As for #129143 - it just looks like a documentation inaccuracy, as the docstring matches the behaviour of the code.

[cjw296]

Okay, so I put up the PR, I guess where I'm at:

• I can see no downsides of this change.
• If .shutdown() is intended to only ever be called once, then it should not be part of the public API, but I think that ship has sailed.

So, hopefully a quick approval on the PR and we can all move on 😅

[vsajip]

• I'm not especially keen on making changes just because there're no immediately apparent downsides. If some emerge, I will have to deal with any fallout.
• Any function that is part of the API comes with conditions as to when to call it, how to call it etc. If those conditions aren't followed, that isn't the fault of the API.
• You still haven't addressed the points I made in my first response. As you can probably tell, I'm not especially keen on making this change, small though it is, as I consider you haven't given enough justification for it other than having to work around some code "out there" calling shutdown() more than once in a process, contravening the contract of the API as documented.

[cjw296]

I'm not especially keen on making changes just because there're no immediately apparent downsides. If some emerge, I will have to deal with any fallout.

Well, one of us core developers will have to deal with any fallout, and I'm quite happy to commit to doing so for any impact of this change...

The logging.shutdown API is used internally in logging.config and in the logging test suite, so changing it could have ramifications there, too.

Ramifications in the test suite would, I hope, be covered by the runs carried out on the pull request?
Do you consider the logging test suite to be insufficient to highlight any ramifications in logging.config? What testing could I add that would give you confidence?

Since the case you mention involves calling shutdown more than once and perhaps involves handlers that don't just throw exceptions if called inappropriately, surely any changes to the stdlib in this area would be more of a band-aid, rather than addressing the root cause of the problems? I appreciate you may not have direct control of the code calling shutdown or of the handlers.

The concrete case I encountered was running code that called logging.basicConfig being run under a set of integration tests. It was a surprise to see an accumulation of state inside the logging package, in spite of carefully adding and removing and configured log handlers either side of the tests. So, digging into that felt like the root cause of the problem was the unconstrained accumulation of state inside _handlerList, which appears to keep a list of references to stale resources even after it has freed them, which doesn't seem like the right thing to do.

If the handlers throw some other stdlib exception than OSError and ValueError, I can look at broadening that catch clause.

What are your concrete concerns around emptying a list of resources that have just been freed, versus letting that list grow in an unbound way? I appreciate that in non-test code, this is unlikely to be a practical problem, but still feels like something that's worth fixing, given the small nature of the fix.

[vsajip]

running code that called logging.basicConfig

basicConfig() shouldn't create any handlers if the root logger has any handlers, so calling it multiple times will at most create one handler and add it to the root logger (under normal circumstances).

the unconstrained accumulation of state inside _handlerList, which appears to keep a list of references to stale resources even after it has freed them

I was curious about this, so I wrote a short script to see what might be happening:

import logging
import tempfile
import unittest

logger = logging.getLogger(__name__)

class TestCase(unittest.TestCase):
    def test_handler_leaks(self):
        print(f'Initial: {len(logging._handlerList)}: {logging._handlerList}')
        for i in range(1000):
            stream = tempfile.NamedTemporaryFile(mode='w', prefix=f'test-leak-{i + 1}-', suffix='.log')
            h = logging.StreamHandler(stream)
            logger.addHandler(h)
            logger.error('Disaster!')
            logger.removeHandler(h)
            h.close()
            stream.close()  # StreamHandler doesn't close its streams
            # print(f'{i + 1}: {len(logging._handlerList)}')
        print(f'Final  : {len(logging._handlerList)}: {logging._handlerList}')
        print(f'Last handler was at: 0x{id(h):x} (for {stream.name})')

if __name__ == '__main__':
    unittest.main()

This loops 1000 times creating, adding, outputting to, removing and closing handlers. Example output:

Initial: 1: [<weakref at 0x7f094c9d00e0; to 'logging._StderrHandler' at 0x7f094c96da90>]
Final  : 2: [<weakref at 0x7f094c9d00e0; to 'logging._StderrHandler' at 0x7f094c96da90>, <weakref at 0x7f094b3192b0; to 'logging.StreamHandler' at 0x7f094b2f7ad0>]
Last handler was at: 0x7f094b2f7ad0 (for /tmp/test-leak-1000-k3sfej6z.log)
.
----------------------------------------------------------------------
Ran 1 test in 0.183s

OK

So, logging._handlerList contains only two references at the end, despite 1000 handlers having been created/added/removed/closed in the test. Perhaps I've missed something obvious, or perhaps the test is too simple to show up the problem - please point out any mistake I've made. Changing the loop counter to 10000 and 100000 made no difference to the final size of _handlerList - the test just took longer.

[cjw296]

Okay, I'm unclear what to do with this bug or the associated PR; it looks like we don't agree but this isn't a big enough thing to do anything more on it. My suggestion would be to close the PR but leave this issue open in case others want to chime in later.
How does that sound?

[vsajip]

I'm still curious as to how/why you're experiencing a potentially unbounded growth in _handlerList, whereas I'm not seeing it in the simple test script above. Also you haven't mentioned multiple calls to shutdown() recently, and as far as I'm concerned, we shouldn't make changes just to support multiple calls to shutdown() - which is the only time we pass _handlerList as a default. Other than that, of course I'd be interested in preventing unbounded increases in the size of _handlerList, but if you don't have time to look at reproducing it in e.g. an adaptation of my simple test script right now, fair enough - you can do as you suggest in your last comment.

[cjw296]

Well, the API documentation for logging.shutdown says:

This should be called at application exit and no further use of the logging system should be made after this call.

When the logging module is imported, it registers this function as an exit handler (see atexit), so normally there’s no need to do that manually.

So, calling shutdown() in user code is mildly questionable practice (as not needed, due to the atexit handler), and calling it more than once perhaps more strongly so (given the "no further use should be made ...").

It's pretty challenging that the logging framework does this "mildly questionable practice" itself; see this example where ipdb is configuring logging during set_trace, itself a somewhat interesting choice, but which resultings in logging.shutdown being called in a situation where logging is definitely not being shutdown.

[vsajip]

I'm not talking about this specific example, but in general, code internal to an API is not subject to the same constraints as the public API. For example, internal code can take advantage of implementation details, but the users of the public API shouldn't (or else risk breakage if the internals change).