classification
Title: Multiprocessing, logging and atexit play not well together
Type: behavior Stage: test needed
Components: Library (Lib) Versions: Python 3.2, Python 2.7
process
Status: closed Resolution: out of date
Dependencies: Superseder:
Assigned To: georg.brandl Nosy List: aronacher, georg.brandl, loewis
Priority: high Keywords: patch

Created on 2010-09-04 15:32 by aronacher, last changed 2010-12-18 08:52 by georg.brandl. This issue is now closed.

Files
File name Uploaded Description Edit
9775-fix.patch aronacher, 2010-09-04 15:32 review
t.py loewis, 2010-09-04 19:07
Messages (8)
msg115578 - (view) Author: Armin Ronacher (aronacher) * (Python committer) Date: 2010-09-04 15:32
It's hard to say what exactly is to blame here, but I will try to outline the problem as good as I can and try to track it down:

A library of mine is using a Thread that is getting entries from a multiprocessing.Queue periodically.  What I find when the python interpreter is shutting down is this on stderr:

Error in sys.exitfunc:
Traceback (most recent call last):
  File "python2.6/atexit.py", line 24, in _run_exitfuncs
    func(*targs, **kargs)
  File "python2.6/multiprocessing/util.py", line 270, in _exit_function
    info('process shutting down')
TypeError: 'NoneType' object is not callable

Tracking down the issue shows that something has a __del__ [i have not found the object, i was under the impression the ProcessAwareLogger monkeypatch was, but apprently it's not the culprit] and clears out the module.  When the exit handler is running info is already set to None.  It can be easily checked if that is the issue when a weird monkepatch is added:

def fix_logging_in_multiprocesing():
    from multiprocessing import util, process
    import logging
    util._check_logger_class()
    old_class = logging.getLoggerClass()
    def __del__(self):
        util.info = util.debug = lambda *a, **kw: None
        process._cleanup = lambda *a, **kw: None
    old_class.__del__ = __del__
  
I originally thought that the destructor of the ProcessAwareLogger class was the issue, but apparently not so because it does not have one.

Interestingly if one looks into the util.py module the following comment can be found:

def _check_logger_class():
    '''
    Make sure process name is recorded when loggers are used
    '''
    # XXX This function is unnecessary once logging is patched
    import logging
    if hasattr(logging, 'multiprocessing'):
        return
    ...

This is interesting because the logging monkeypatch is unused if logging is multiprocessing aware (which it should be in 2.6 at least).  However apparently at one point the toplevel multiprocessing import was removed which makes this test fall all the time.  Looking at the current 26 branch it appears that the monkeypatch was removed by jesse noller in [68737] over a year ago.

With the current development version (and I suppose a later release than 2.6.1 which I am currently testing) the error disappears as well.

However the core issue would come back as soon as the atexit call moves past a destructor again I suppose.  Because of that I would recommend aliasing info to _info and debug to _debug and then calling the underscored methods in the atexit handler.

Any reasons for not doing that?  Otherwise I would like to propose committing that patch.
msg115585 - (view) Author: Martin v. Löwis (loewis) * (Python committer) Date: 2010-09-04 16:15
IIUC, you are proposing to fix Python 2.6 only. Please understand that this branch is closed for bug fixes (unless they are security issues, which this issue is not).

As for 2.7: please try explaining again what specific issue the patch is meant to resolve? What monkey-patching are you referring to? What destructor? Why is aliasing these functions going to solve a problem?

As for "a reason not to do the change": lacking a clear problem definition, the aliasing seems pointless.
msg115587 - (view) Author: Armin Ronacher (aronacher) * (Python committer) Date: 2010-09-04 16:39
This also affects 2.7, I just worked on 2.6 because this is where I encountered the issue.

> As for 2.7: please try explaining again what specific issue the patch
> is meant to resolve? What monkey-patching are you referring to? What 
> destructor? Why is aliasing these functions going to solve a problem?

As mentioned above I cannot provide more information because I am unable to find the root of the issue.  All I know is that if the atexit handler is executed after the module globals were set to None it fails to shutdown properly.

The old monkey patch can be found here: http://svn.python.org/view/python/tags/r261/Lib/multiprocessing/util.py?revision=71601&view=markup

I am pretty sure that this is one way to trigger the issue but by itself not the root of the problem.
msg115590 - (view) Author: Martin v. Löwis (loewis) * (Python committer) Date: 2010-09-04 17:29
> As mentioned above I cannot provide more information because I am
> unable to find the root of the issue.  All I know is that if the
> atexit handler is executed after the module globals were set to None
> it fails to shutdown properly.

Ok - but this is not supposed to happen. The exitfuncs are called
*before* any other interpreter shutdown happens.

> 
> The old monkey patch can be found here:
> http://svn.python.org/view/python/tags/r261/Lib/multiprocessing/util.py?revision=71601&view=markup
>
>  I am pretty sure that this is one way to trigger the issue but by
> itself not the root of the problem.

Indeed, this is not part of Python anymore, so we should remove it from
the discussion.

In any case, unless you can come up with a reproducible test case,
I'm closing this as "works for me".
msg115597 - (view) Author: Armin Ronacher (aronacher) * (Python committer) Date: 2010-09-04 18:31
Put the stuff from an older version back in with a monkeypatch and you will see the issue again.  There are certainly many more ways to trigger that issue, that was just the easiest.  I will try to create a simpler test case.
msg115608 - (view) Author: Martin v. Löwis (loewis) * (Python committer) Date: 2010-09-04 19:07
I don't see the issue at all; the attached script runs just fine.
msg115628 - (view) Author: Georg Brandl (georg.brandl) * (Python committer) Date: 2010-09-05 07:08
I'll sort this out with Armin.
msg124277 - (view) Author: Georg Brandl (georg.brandl) * (Python committer) Date: 2010-12-18 08:52
Not reproducable anymore.
History
Date User Action Args
2010-12-18 08:52:49georg.brandlsetstatus: open -> closed

messages: + msg124277
resolution: out of date
2010-12-14 01:54:03r.david.murraysettype: behavior
stage: test needed
2010-09-05 07:12:14georg.brandlsetpriority: normal -> high
assignee: georg.brandl
versions: + Python 3.2, - Python 2.6
2010-09-05 07:08:54georg.brandlsetnosy: + georg.brandl
messages: + msg115628
2010-09-04 19:07:13loewissetfiles: + t.py

messages: + msg115608
2010-09-04 18:31:09aronachersetstatus: closed -> open
resolution: works for me -> (no value)
messages: + msg115597
2010-09-04 17:31:31loewissetstatus: open -> closed
resolution: works for me
2010-09-04 17:29:41loewissetmessages: + msg115590
2010-09-04 16:39:08aronachersetmessages: + msg115587
2010-09-04 16:35:11aronachersetversions: + Python 2.7
2010-09-04 16:15:34loewissetnosy: + loewis
messages: + msg115585
2010-09-04 15:32:29aronachersetfiles: + 9775-fix.patch
keywords: + patch
2010-09-04 15:32:08aronachercreate