classification
Title: logging module errors out if log called when multiprocessing module not finished loading
Type: crash Stage: resolved
Components: Library (Lib) Versions: Python 2.6
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: vinay.sajip Nosy List: chris.jerdonek, flox, vinay.sajip
Priority: normal Keywords:

Created on 2010-03-22 09:29 by chris.jerdonek, last changed 2010-03-22 23:00 by chris.jerdonek. This issue is now closed.

Messages (8)
msg101489 - (view) Author: Chris Jerdonek (chris.jerdonek) * (Python committer) Date: 2010-03-22 09:29
The logging module errors out if the multiprocessing module is not finished loading when logging.log() is called.

This can happen, for example, if a custom import hook is defined that causes third-party code to execute when the multiprocessing module gets to an import statement.  (autoinstall is an example of a package that defines such an import hook: http://pypi.python.org/pypi/autoinstall/0.1a2 )

Here is a stack trace of the issue in action:

  File "/Users/chris_g4/dev/apple/WebKit-git/WebKitTools/Scripts/webkitpy/executive.py", line 118, in cpu_count
    import multiprocessing
  File "/opt/local/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/multiprocessing/__init__.py", line 60, in <module>
    import os
  File "/Users/chris_g4/dev/apple/WebKit-git/WebKitTools/Scripts/webkitpy/thirdparty/autoinstall.py", line 279, in find_module
    _logger.debug("find_module(%s, path=%s)" % (fullname, path))
  File "/opt/local/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/logging/__init__.py", line 1036, in debug
    self._log(DEBUG, msg, args, **kwargs)
  File "/opt/local/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/logging/__init__.py", line 1164, in _log
    record = self.makeRecord(self.name, level, fn, lno, msg, args, exc_info, func, extra)
  File "/opt/local/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/logging/__init__.py", line 1139, in makeRecord
    rv = LogRecord(name, level, fn, lno, msg, args, exc_info, func)
  File "/opt/local/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/logging/__init__.py", line 279, in __init__
    self.processName = sys.modules['multiprocessing'].current_process().name
AttributeError: 'module' object has no attribute 'current_process'


Here is a possible fix (in logging/__init__.py):

         if not logMultiprocessing:
             self.processName = None
         # "current_process" might not be defined if multiprocessing is
         # not finished loading yet.  This can happen, for example, if
         # a custom import hook is defined that causes third-party code
         # to execute when the multiprocessing module calls import.
-        elif 'multiprocessing' not in sys.modules:
+        elif 'multiprocessing' not in sys.modules or \
+             'current_process' not in dir(sys.modules['multiprocessing']):
             self.processName = 'MainProcess'
         else:
             self.processName = sys.modules['multiprocessing'].current_process().name
         if logProcesses and hasattr(os, 'getpid'):
             self.process = os.getpid()
msg101499 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2010-03-22 12:34
A slightly more generic fix checked into trunk (r79279), please verify in your environment.
msg101500 - (view) Author: Florent Xicluna (flox) * (Python committer) Date: 2010-03-22 12:42
I would suggest something like:

if logMultiprocessing:
    try:
        self.processName = sys.modules['multiprocessing'] .current_process().name
    except StandardError:
        self.processName = 'MainProcess'
else:
    self.processName = None
msg101516 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2010-03-22 15:39
It's structured the way it is for two reasons:
 1. IMO It's better (more readable) to have the simpler case in the "then" clause and the more complicated case in the "else" clause.
 2. If multiprocessing is not used, the process name needs to be set anyway to "MainProcess". So, I've structured it so the assignment is in just one place.
msg101523 - (view) Author: Chris Jerdonek (chris.jerdonek) * (Python committer) Date: 2010-03-22 18:19
Reversing the if-else in Florent's suggestion seems to address points (1) and (2).  Is there a reason to set and check an mp variable rather than simply having the try-except block?

if not logMultiprocessing:
    self.processName = None
else:
    # Errors may occur if multiprocessing has not finished loading
    # yet - e.g. if a custom import hook causes third-party code
    # to run when multiprocessing calls import. See issue 8200
    # for an example
    try:
        self.processName = sys.modules['multiprocessing'].current_process().name
    except StandardError:
        self.processName = 'MainProcess'

Thanks for the quick action!  I'll try in my dev environment when this is settled.
msg101526 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2010-03-22 18:45
----- Original Message ----

Reversing the if-else in Florent's suggestion seems to 
> address points (1) and (2).  Is there a reason to set and check an mp 
> variable rather than simply having the try-except block?

Just that it went over the 80-column limit :-)

Also, I know about asking forgiveness rather than permission, but Florent's change doesn't make clear the intent to call current_process only if multiprocessing has already been imported (i.e. is in sys.modules). In other words, he would catch both the KeyError and any error due to an incomplete import of multiprocessing. While either version will work, the way I have it preserves the original intent and only traps errors due to multiprocessing being incompletely imported.
msg101527 - (view) Author: Chris Jerdonek (chris.jerdonek) * (Python committer) Date: 2010-03-22 19:04
I agree.  Thanks!
msg101549 - (view) Author: Chris Jerdonek (chris.jerdonek) * (Python committer) Date: 2010-03-22 23:00
FYI, I verified the fix in my local environment.  Thanks again.
History
Date User Action Args
2010-03-22 23:00:43chris.jerdoneksetmessages: + msg101549
2010-03-22 19:04:35chris.jerdoneksetmessages: + msg101527
2010-03-22 18:45:43vinay.sajipsetmessages: + msg101526
2010-03-22 18:19:34chris.jerdoneksetmessages: + msg101523
2010-03-22 15:39:55vinay.sajipsetmessages: + msg101516
2010-03-22 12:42:06floxsetpriority: normal

nosy: + flox
messages: + msg101500

stage: resolved
2010-03-22 12:34:39vinay.sajipsetstatus: open -> closed
assignee: vinay.sajip
resolution: fixed
messages: + msg101499
2010-03-22 09:46:01chris.jerdoneksetnosy: + vinay.sajip
2010-03-22 09:29:25chris.jerdonekcreate