logging.shutdown should cope with IO errors from handler.release methods

[ncoghlan]

BPO	15960
Nosy	@vsajip, @ncoghlan

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = 'https://github.com/vsajip'
closed_at = <Date 2012-09-20.14:35:32.923>
created_at = <Date 2012-09-18.07:40:20.258>
labels = ['type-bug']
title = 'logging.shutdown should cope with IO errors from handler.release methods'
updated_at = <Date 2012-09-20.14:35:32.922>
user = 'https://github.com/ncoghlan'

bugs.python.org fields:

activity = <Date 2012-09-20.14:35:32.922>
actor = 'vinay.sajip'
assignee = 'vinay.sajip'
closed = True
closed_date = <Date 2012-09-20.14:35:32.923>
closer = 'vinay.sajip'
components = []
creation = <Date 2012-09-18.07:40:20.258>
creator = 'ncoghlan'
dependencies = []
files = []
hgrepos = []
issue_num = 15960
keywords = []
message_count = 4.0
messages = ['170635', '170647', '170698', '170807']
nosy_count = 2.0
nosy_names = ['vinay.sajip', 'ncoghlan']
pr_nums = []
priority = 'normal'
resolution = 'wont fix'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue15960'
versions = ['Python 2.7', 'Python 3.2', 'Python 3.3']

[ncoghlan]

logging.shutdown includes a try/except block to avoid emitting spurious IO errors while the interpreter is shutting down. This fails if a registered handler tries to do IO (such as calling flush()) in its release method.

It would be better if the flush-and-close block was written as:

try:
hr.acquire()
try:
hr.flush()
hr.close()
finally:
hr.release()
except (IOError, ValueError):
# Tolerate handlers that try to do IO in release()

[vsajip]

I'm not against making this change, but I'm curious - why would a handler do clean-up I/O in its release() method (which is just for releasing the I/O lock) where it could just as easily override the close() method to do the same thing? It seems like programmer error to be doing any I/O in a handler after close() is called on it.

[ncoghlan]

The particular app that is getting affected is clearing out and rebuilding the logging configuration without restarting in response to a notification that the application config has changed. This was working OK on 2.6, but started misbehaving when ported to 2.7.

It's http://pypi.python.org/pypi/ConcurrentLogHandler that's calling self.stream.flush() inside release(), and I suspect that *is* a bug on that side as well.

It's also possible that we should just be skipping the use of ConcurrentLogHandler entirely on 2.7, but I haven't looked into the feasibility of that as yet.

This specific bug report is just because I noticed that the stdlib is *trying* to be tolerant of handler misbehaviour, but not quite succeeding in this particular case. Perhaps we should be writing something out to stderr when ignoring one of these errors?

[ncoghlan]

Dan and Amit worked out a patch for ConcurrentLogHandler (https://bugzilla.redhat.com/show_bug.cgi?id=858912) so I'm OK with rejecting this one.