classification
Title: logging depends on multiprocessing
Type: crash Stage:
Components: Library (Lib) Versions: Python 2.6
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: vinay.sajip Nosy List: amaury.forgeotdarc, barry, benjamin.peterson, gvanrossum, jnoller, pitrou, pjenvey, r.david.murray, vinay.sajip
Priority: normal Keywords:

Created on 2009-10-14 01:04 by gvanrossum, last changed 2009-10-16 14:08 by vinay.sajip. This issue is now closed.

Files
File name Uploaded Description Edit
traceback.txt gvanrossum, 2009-10-14 01:04
Messages (20)
msg93952 - (view) Author: Guido van Rossum (gvanrossum) * (Python committer) Date: 2009-10-14 01:04
Following my own (Twitter) advice I downloaded the 2.6.4rc1 release 
candidate and installed it on my x86 iMac running OS X 10.5.8, and tried 
to run a Google App Engine app with it.  Google App Engine prefers Python 
2.5, but so far it has always worked with 2.6 as well, modulo 1-2 
warnings.  But not 2.6.4rc1!  Even on a trivial app I get "RuntimeError: 
maximum recursion depth exceeded".  I'm attaching a file with the 
traceback (repetitive stuff elided).

I'd be happy to provide more details if they are needed to reproduce.  I'm 
using the Google App Engine SDK 1.2.6.
msg93954 - (view) Author: Guido van Rossum (gvanrossum) * (Python committer) Date: 2009-10-14 01:08
FWIW, I've ruled out App Engine SDK 1.2.6 as the source of the regression; 
on a MacBook Pro with the same OS 10.5.8 I get a similar traceback with 
SDK 1.2.6.
msg93955 - (view) Author: Benjamin Peterson (benjamin.peterson) * (Python committer) Date: 2009-10-14 01:27
How many lines are there in the traceback? Are there repetitions?
msg93956 - (view) Author: Guido van Rossum (gvanrossum) * (Python committer) Date: 2009-10-14 01:36
The full traceback had probably 1000 lines (or whatever the limit is); the 
piece between two calls to logging.warn() is repeated over and over.
msg93958 - (view) Author: Philip Jenvey (pjenvey) * (Python committer) Date: 2009-10-14 01:47
App engine shows up after every import statement, so it must have some 
kind of import hook -- which can do evil things
msg93959 - (view) Author: Guido van Rossum (gvanrossum) * (Python committer) Date: 2009-10-14 01:52
Yes, App Engine uses a PEP 302 style import hook to implement the sandbox.  
Could it be that there's a new module dependency introduced by 2.6.3-4?
msg93960 - (view) Author: Benjamin Peterson (benjamin.peterson) * (Python committer) Date: 2009-10-14 01:58
While I am not able to reproduce this by running 1.2.6 on Gentoo Linux
with Rietveld, I will make an educated guess that it is the "from
multiprocessing import current_process" line in r75130. I doubt this
module is available on app engine, so it tries to use logging.warn,
which tries to import multiprocessing...
msg93963 - (view) Author: Guido van Rossum (gvanrossum) * (Python committer) Date: 2009-10-14 02:49
The dependency of logging on multiprocessing feels backwards.  But it's 
not actually a new regression, it seems that was there in 2.6.2.
msg93964 - (view) Author: Guido van Rossum (gvanrossum) * (Python committer) Date: 2009-10-14 03:37
The addition of multiprocessing support to logging seems to have happened 
in 2.6.2; bad timing for a feature. :-(
msg93967 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2009-10-14 05:55
I propose to fix it by just setting logRecord.processName to None for
now, which is what should happen if multiprocessing isn't available.

In environments where multiprocessing is not available,
logging.logMultiprocessing should be False, but that fix needs to go
into GAE, I guess?

Benjamin, I believe you added this change (in r70348), are you
comfortable with what I'm proposing? Anyone else have any objections?
msg93968 - (view) Author: Amaury Forgeot d'Arc (amaury.forgeotdarc) * (Python committer) Date: 2009-10-14 08:38
Whatever the value of logMultiprocessing is, I suggest to not import the
multiprocessing module if the application did not import it before:
something like:

    if "multiprocessing" in sys.modules:
        from multiprocessing import current_process
        self.processName = current_process().name
    else:
        # current_process().name returns this the first time
        self.processName = 'MainProcess'
msg93972 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2009-10-14 10:00
> Whatever the value of logMultiprocessing is, I suggest to not import the

> multiprocessing module if the application did not import it before:
> something like:
> 
>     if "multiprocessing" in sys.modules:
>         from multiprocessing import current_process
>         self.processName = current_process().name
>     else:
>         # current_process().name returns this the first time
>         self.processName = 'MainProcess'
> 

I suggested "None" because that was the value used in r70348 when logMultipocessing is False. I presume you're only talking about when it's True? I'm confused by your "Whatever the value of logMultiprocessing is, ...".

Should the system behaviour really change depending on whether multiprocessing was already imported? I can see why you're suggesting it but it makes me a little uneasy :-S
msg93976 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2009-10-14 12:00
`self.processName` could be a lazily computed property, since it doesn't
seem to be used anywhere by default. Something like:

    _processName = None

    @property
    def processName(self):
        n = self._processName
        if n is not None:
            return n
        if 'multiprocessing' not in sys.modules:
            n = 'mainProcess'
        else:
            n = sys.modules['multiprocessing'].current_process().name
        self._processName = n
        return n


If you don't like the overhead of a property, you could do the caching
dance in a __getattr__ method instead.

NB : if 'multiprocessing' isn't in sys.modules, it means that you can
only be in the main process, as far as I understand. Processes launched
by multiprocessing itself *will* have 'multiprocessing' in sys.modules,
unless it is doing really weird stuff.
msg94021 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2009-10-14 19:54
Fix checked into release26-maint (r75425). Please verify in GAE
environment, will make same fix in trunk and py3k once verified.

Fixed based on Antoine's message, though not identical to his posted code.
msg94031 - (view) Author: Guido van Rossum (gvanrossum) * (Python committer) Date: 2009-10-14 21:07
Confirmed, the stack limit error is gone now. Thanks!!

(There's another error, the import of _scproxy from urllib, but that's 
easily added to the App Engine SDK's whitelist. I am still concerned 
about the amount of change in the 2.6 branch, but the cat is out of the 
bag.)
msg94032 - (view) Author: Guido van Rossum (gvanrossum) * (Python committer) Date: 2009-10-14 21:15
(I don't know why the tracker reopened the issue when I added a comment. 
Anyway, is the fix going into 2.6.4 or will it have to wait for 2.6.5?)
msg94035 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2009-10-14 21:46
> Guido van Rossum  added the comment:

> 
> (I don't know why the tracker reopened the issue when I added a comment. 
> Anyway, is the fix going into 2.6.4 or will it have to wait for 2.6.5?)

That's OK, I'll close it once I've made the same changes in trunk and py3k.

In terms of when the fix goes in, I guess it's Barry's call.
msg94042 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2009-10-14 22:32
On Wed, 14 Oct 2009 at 21:46, Vinay Sajip wrote:
> Vinay Sajip <vinay_sajip@yahoo.co.uk> added the comment:
>> Guido van Rossum  added the comment:
>>
>> (I don't know why the tracker reopened the issue when I added a comment.
>> Anyway, is the fix going into 2.6.4 or will it have to wait for 2.6.5?)

If a ticket is set to pending, any comment addition changes it back
to open.  The idea is that you set a ticket to 'pending feedback',
and if there is no feedback for time X, the ticket gets closed.
(An auto-close-pending feature has been proposed, but I don't think it
has been implemented yet.)

> In terms of when the fix goes in, I guess it's Barry's call.

Well, your commit to the 2.6 branch puts it into the next RC unless
someone (eg Barry) reverts it.
msg94054 - (view) Author: Jesse Noller (jnoller) * (Python committer) Date: 2009-10-14 23:44
>The addition of multiprocessing support to logging seems to have 
happened 
> in 2.6.2; bad timing for a feature. :-(

Just in minor self-defense, this wasn't a feature, it was a bug fix. The 
original multiprocessing code base relied on some unfortunate monkey-
patching of the logging module to insert itself into the logging module. 
That code was broken in the merge into 2.6, and I didn't catch it. So, I 
felt this was a bug fix, and not a feature-add.

I apologize for this.
msg94139 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2009-10-16 14:08
Fix checked into trunk and py3k (r75445).
History
Date User Action Args
2009-10-16 14:08:59vinay.sajipsetstatus: pending -> closed

messages: + msg94139
2009-10-15 04:26:02vinay.sajipsetstatus: open -> pending
nosy: + barry
2009-10-14 23:44:25jnollersetnosy: + jnoller
messages: + msg94054
2009-10-14 22:32:53r.david.murraysetnosy: + r.david.murray
messages: + msg94042
2009-10-14 21:46:19vinay.sajipsetmessages: + msg94035
2009-10-14 21:15:11gvanrossumsetmessages: + msg94032
2009-10-14 21:07:29gvanrossumsetstatus: pending -> open

messages: + msg94031
2009-10-14 19:54:02vinay.sajipsetstatus: open -> pending
resolution: fixed
messages: + msg94021
2009-10-14 12:00:47pitrousetnosy: + pitrou
messages: + msg93976
2009-10-14 10:00:38vinay.sajipsetmessages: + msg93972
2009-10-14 08:38:25amaury.forgeotdarcsetnosy: + amaury.forgeotdarc
messages: + msg93968
2009-10-14 05:55:31vinay.sajipsetmessages: + msg93967
2009-10-14 03:37:14gvanrossumsetmessages: + msg93964
title: 2.6.4rc1 regression -> logging depends on multiprocessing
2009-10-14 02:49:19gvanrossumsetmessages: + msg93963
2009-10-14 01:58:56benjamin.petersonsetassignee: vinay.sajip
messages: + msg93960
2009-10-14 01:52:33gvanrossumsetmessages: + msg93959
2009-10-14 01:48:19pjenveysetnosy: + vinay.sajip
2009-10-14 01:47:36pjenveysetnosy: + pjenvey
messages: + msg93958
2009-10-14 01:36:48gvanrossumsetmessages: + msg93956
2009-10-14 01:27:49benjamin.petersonsetnosy: + benjamin.peterson
messages: + msg93955
2009-10-14 01:08:22gvanrossumsetmessages: + msg93954
2009-10-14 01:04:05gvanrossumcreate