classification
Title: Logging shutdown regressions with weakrefs
Type: behavior Stage:
Components: Library (Lib) Versions: Python 3.2, Python 3.3, Python 2.7
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: vinay.sajip Nosy List: flox, gz, python-dev, vinay.sajip, xdegaye
Priority: normal Keywords: patch

Created on 2010-08-03 22:39 by gz, last changed 2013-01-16 12:02 by xdegaye. This issue is now closed.

Files
File name Uploaded Description Edit
loggingcleanup.py gz, 2010-08-03 22:44 Script demonstrating first case
loggingclose.py gz, 2010-08-03 22:46 Script demonstrating second case
teardown_module.py xdegaye, 2013-01-15 16:24
teardown_module.diff xdegaye, 2013-01-15 16:24 review
Messages (10)
msg112713 - (view) Author: Martin (gz) * Date: 2010-08-03 22:39
With the logging change to using weakrefs for handler cleanup done by the follow-on patch in issue 6615 exceptions may now be thrown during module teardown.

There are two distinct problem cases:
1) The new `_removeHandlerRef` function may run during teardown (when module globals are being set to None) but uses the module globals `_acquireLock`, `_releaseLock`, and `_handlerList`.
2) The `Handler.close` method no longer removes the instance from the module global list, this means if the caller then closes the underlying file but keeps a reference to the handler, the `shutdown` function will attempt to flush the already-closed file.

It may be that this new way of doing things is preferred and the response to closing underlying files or holding on to handler references is Don't Do That Then, but this seems like an accidental regression.
msg112716 - (view) Author: Martin (gz) * Date: 2010-08-03 22:44
This could be fixed in a similar way to was done for the shutdown function in r51206 (which incidentally seems both unnecessary and incomplete - the function runs atexit which precedes module teardown, but also uses the raiseExceptions module global which is not rebound locally).
msg112717 - (view) Author: Martin (gz) * Date: 2010-08-03 22:46
For the second case, just reverting the change to Handler.close may be best, I don't see why the module should be keeping responsibility for flushing and closing handlers it no longer has a strong reference to.
msg114739 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2010-08-23 21:37
Fix checked into py3k and release27-maint (r84282).
msg180033 - (view) Author: Xavier de Gaye (xdegaye) * (Python triager) Date: 2013-01-15 16:24
Still randomly getting ignored exceptions on 3.3 and the default
branch, got for example:
Exception TypeError: TypeError("argument of type 'NoneType' is not
iterable",) in <function _removeHandlerRef at 0x7fcbe6014200> ignored

This happens in a threaded application. The root cause is explained in
http://bugs.python.org/issue1722344#msg62078
Instead of building a test case to reproduce the problem, the attached
teardown_module.py script is a contrived example that shows the issue
9501 is not fully fixed. Ignored exceptions appear randomly, so
teardown_module.py must be run in a loop, for example:

    $ while [ 1 ]; do python teardown_module.py; sleep .1; done

The attached patch fix the issue by testing all the globals used in
_removeHandlerRef and teardown_module.py runs fine with this patch
applied.
msg180039 - (view) Author: Roundup Robot (python-dev) (Python triager) Date: 2013-01-15 17:57
New changeset 966887830011 by Vinay Sajip in branch '2.7':
Issue #9501: Improved shutdown handling to deal with module attributes correctly.
http://hg.python.org/cpython/rev/966887830011

New changeset 8eac88f49cc0 by Vinay Sajip in branch '3.2':
Issue #9501: Improved shutdown handling to deal with module attributes correctly.
http://hg.python.org/cpython/rev/8eac88f49cc0

New changeset 3161a94ff73c by Vinay Sajip in branch '3.3':
Issue #9501: Merged fix from 3.2.
http://hg.python.org/cpython/rev/3161a94ff73c

New changeset 4fd8c35a05b2 by Vinay Sajip in branch 'default':
Issue #9501: Merged fix from 3.3.
http://hg.python.org/cpython/rev/4fd8c35a05b2
msg180064 - (view) Author: Xavier de Gaye (xdegaye) * (Python triager) Date: 2013-01-15 23:08
The reason why this happens in python 3.3.0 and not in 3.2:

1) lastResort holds a reference to an instance of _StderrHandler at
   module tear down, thus potentially triggering a TypeError in
   _removeHandlerRef.

2) The logging code has the following two lines that are meant to
   avoid the occurence of this problem:

    _defaultLastResort = _StderrHandler(WARNING)
    lastResort = _defaultLastResort

Issue 12637 describes another unrelated problem with lastResort in
python 3.2. As a workaround to this issue 12637, my application sets
lastResort to None and this works fine in 3.2 (the logging howto
states 'To obtain the pre-3.2 behaviour, logging.lastResort can be set
to None').  With python 3.3 it is this setting of lastResort to None
that causes these spurious 'exception ignored' messages, after
removing this setting no messages are printed anymore.
msg180065 - (view) Author: Xavier de Gaye (xdegaye) * (Python triager) Date: 2013-01-15 23:18
The initial teardown_module.py can be simply replaced with
(not a contrived example anymore) the following statements
to print the spurious ignored Exceptions:

# Run the script in a loop:
# while [ 1 ]; do python3 teardown_module.py; sleep .1; done
import logging
logging.lastResort = None
print('Fin')
msg180079 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2013-01-16 11:30
Thanks for hunting these down. With the latest version, neither variant of the teardown script produces any error message on my system, either with 3.3 or 3.4 (default).
msg180081 - (view) Author: Xavier de Gaye (xdegaye) * (Python triager) Date: 2013-01-16 12:02
Yes, my last two messages refer to python 3.3.0 only.
The changes logged in http://bugs.python.org/issue9501#msg180039
do fix the behavior of both versions of teardown_module.py.
History
Date User Action Args
2013-01-16 12:02:40xdegayesetmessages: + msg180081
2013-01-16 11:30:16vinay.sajipsetmessages: + msg180079
2013-01-15 23:18:39xdegayesetmessages: + msg180065
2013-01-15 23:08:30xdegayesetmessages: + msg180064
2013-01-15 17:57:34python-devsetnosy: + python-dev
messages: + msg180039
2013-01-15 16:24:46xdegayesetfiles: + teardown_module.diff
keywords: + patch
2013-01-15 16:24:20xdegayesetfiles: + teardown_module.py
nosy: + xdegaye
messages: + msg180033

2010-08-23 21:37:22vinay.sajipsetstatus: open -> closed
resolution: fixed
messages: + msg114739
2010-08-22 18:53:06vinay.sajipsetassignee: vinay.sajip
2010-08-03 22:46:57gzsetfiles: + loggingclose.py

messages: + msg112717
2010-08-03 22:44:19gzsetfiles: + loggingcleanup.py

messages: + msg112716
2010-08-03 22:39:40gzcreate