Path: csiph.com!v102.xanadu-bbs.net!xanadu-bbs.net!feeder.erje.net!eu.feeder.erje.net!ecngs!feeder2.ecngs.de!novso.com!newsfeed.xs4all.nl!newsfeed2a.news.xs4all.nl!xs4all!newsgate.cistron.nl!newsgate.news.xs4all.nl!post.news.xs4all.nl!not-for-mail Return-Path: X-Original-To: python-list@python.org Delivered-To: python-list@mail.python.org X-Spam-Status: OK 0.007 X-Spam-Evidence: '*H*': 0.99; '*S*': 0.00; 'interpreter': 0.05; 'subject:skip:s 10': 0.07; 'variables': 0.07; 'arrays': 0.09; 'cc:addr:python-list': 0.11; 'python': 0.11; 'bug': 0.12; '23,': 0.16; '6:30': 0.16; 'called.': 0.16; 'cc:name:python list': 0.16; 'none.': 0.16; 'overwriting': 0.16; 'quits': 0.16; 'reproduce': 0.16; 'throw': 0.16; 'to:addr:pearwood.info': 0.16; 'to:addr:steve+comp.lang.python': 0.16; "to:name:steven d'aprano": 0.16; 'wrote:': 0.18; 'variable': 0.18; 'wed,': 0.18; 'appears': 0.22; 'code,': 0.22; 'cc:addr:python.org': 0.22; 'fairly': 0.24; 'cc:2**0': 0.24; "i've": 0.25; 'source': 0.25; '>': 0.26; 'handling': 0.26; 'logging': 0.26; 'order.': 0.26; 'possibly': 0.26; 'header:In-Reply-To:1': 0.27; 'idea': 0.28; 'function': 0.29; 'fixed': 0.29; 'sets': 0.30; 'message-id:@mail.gmail.com': 0.30; "i'm": 0.30; 'work.': 0.31; 'getting': 0.31; 'too.': 0.31; 'url:wiki': 0.31; '(although': 0.31; '-0700,': 0.31; "d'aprano": 0.31; 'steven': 0.31; 'used,': 0.33; "can't": 0.35; 'but': 0.35; 'received:google.com': 0.35; 'possible': 0.36; 'jason': 0.38; 'pm,': 0.38; 'rather': 0.38; 'skip:& 20': 0.39; 'sure': 0.39; 'enough': 0.39; 'called': 0.40; 'how': 0.40; 'skip:u 10': 0.60; 'most': 0.60; 'tell': 0.60; 'gone': 0.61; 'course': 0.61; "you've": 0.63; 'kind': 0.63; 'happen': 0.63; 'more': 0.64; 'frequently': 0.68; 'caused': 0.69; 'jul': 0.74; 'obvious': 0.74; 'glance': 0.84; 'shutdown': 0.84; 'race': 0.95 DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20120113; h=mime-version:in-reply-to:references:date:message-id:subject:from:to :cc:content-type; bh=RpdUNEyrtQcpQnGA8LQWwYtzL+A7Znh6fKkfQDamQsQ=; b=p8joYkPHUwcnZJKRMQF5+mNpenW6MXvreHGQYoJAhZBoZPaOHH30pV3HnV3TbRp/ib bsJQ8XLEawYmgx2d2bTAw8CQhnVs7d/1bLN7U+c7xKNH664OS2If6zOoDzDiVbL17jtW UwOsrASii+WJL1w1zYhecb5iJRrgZfxrgVwHgbq5FeNY1vl7InL07Y4da3DDBoMqdg9U aFsY4Dhkgg4vSgTsIQrXZ8pJWFqmOSBXNF6kmEQZaAfJf6f/2HAG7bTPbe323gVwDjW9 13ZWL8ZNPn/ku46BbZkFNh5t8dAG55U1GXQ5nX62wB4QpHTWnfcmf/dZve+8vrvc3URk 8TdQ== MIME-Version: 1.0 X-Received: by 10.236.1.36 with SMTP id 24mr9827052yhc.45.1406184416905; Wed, 23 Jul 2014 23:46:56 -0700 (PDT) In-Reply-To: <53d061c1$0$29966$c3e8da3$5496439d@news.astraweb.com> References: <53cf60d3$0$29897$c3e8da3$5496439d@news.astraweb.com> <53cf6867$0$29897$c3e8da3$5496439d@news.astraweb.com> <53d061c1$0$29966$c3e8da3$5496439d@news.astraweb.com> Date: Wed, 23 Jul 2014 23:46:56 -0700 Subject: Re: My sys.excepthook dies painfully From: Jason Swails To: "Steven D'Aprano" Content-Type: multipart/alternative; boundary=001a1133db94a8921f04feead22c Cc: python list X-BeenThere: python-list@python.org X-Mailman-Version: 2.1.15 Precedence: list List-Id: General discussion list for the Python programming language List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Newsgroups: comp.lang.python Message-ID: Lines: 112 NNTP-Posting-Host: 2001:888:2000:d::a6 X-Trace: 1406184425 news.xs4all.nl 2918 [2001:888:2000:d::a6]:56175 X-Complaints-To: abuse@xs4all.nl Xref: csiph.com comp.lang.python:75127 --001a1133db94a8921f04feead22c Content-Type: text/plain; charset=UTF-8 On Wed, Jul 23, 2014 at 6:30 PM, Steven D'Aprano < steve+comp.lang.python@pearwood.info> wrote: > On Wed, 23 Jul 2014 13:02:51 -0700, Jason Swails wrote: > > > I'm not sure how the "mylogger" variable is getting set to None in your > > my_error_handler callback, but I don't see how that can possibly be > > happening with the provided code... > > Dammit, it's a Heisenbug... now it's gone away for me too. > > http://c2.com/cgi/wiki?HeisenBug > > > However, I think I have a glimmer of an idea for how the global variable > might be set to None. When the Python interpreter shuts down, it sets > global variables to None in some arbitrary order. If the excepthook > function isn't called until after the shutdown process begins, then > depending on the phase of the moon, it's possible that ``mylogger`` may > have been set to None by the time it is called. > Looking at your code, it would seem like the shutdown process would happen when you call the original excepthook function (although Python quits whether or not that excepthook is called). How frequently do you observe this Heisenbug? The ones I've encountered were fairly reproducible, although those were more often caused by uninitialized variables or overwriting arrays -- not race conditions like this would seem to be (although unless it's threaded, how do we get a race condition?). Looking at the logging source code, threading is used, although it appears at a cursory glance to be more of a case of handling threaded applications rather than actually using threads to do any kind of work. A possible idea is to throw in a time.sleep(1) call after the call to mylogger.exception to see if that delays interpreter shutdown long enough for mylogger.exception to resolve. Of course if you can't reproduce the bug often enough, it'll be hard to tell if you've fixed it. The most unreliable Heisenbug I've ever fixed still happened ~1/3 of the time, so it was pretty obvious when I fixed it... All the best, Jason --001a1133db94a8921f04feead22c Content-Type: text/html; charset=UTF-8 Content-Transfer-Encoding: quoted-printable

<= /div>


On Wed, = Jul 23, 2014 at 6:30 PM, Steven D'Aprano <steve+co= mp.lang.python@pearwood.info> wrote:
On Wed, 23 Jul 2014 13:02:51= -0700, Jason Swails wrote:

> I'm not sure how the "mylogger" variable is getting set = to None in your
> my_error_handler callback, but I don't see how that can possibly b= e
> happening with the provided code...

Dammit, it's a Heisenbug... now it's gone away for me too.
http://c2.co= m/cgi/wiki?HeisenBug


However, I think I have a glimmer of an idea for how the global variable might be set to None. When the Python interpreter shuts down, it sets
global variables to None in some arbitrary order. If the excepthook
function isn't called until after the shutdown process begins, then
depending on the phase of the moon, it's possible that ``mylogger`` may=
have been set to None by the time it is called.

Looking at your= code, it would seem like the shutdown process would happen when you call t= he original excepthook function (although Python quits whether or not that = excepthook is called).

How frequently do you observ= e this Heisenbug? =C2=A0The ones I've encountered were fairly reproduci= ble, although those were more often caused by uninitialized variables or ov= erwriting arrays -- not race conditions like this would seem to be (althoug= h unless it's threaded, how do we get a race condition?).

Looking at the logging sourc= e code, threading is used, although it appears at a cursory glance to be mo= re of a case of handling threaded applications rather than actually using t= hreads to do any kind of work.

A possible idea is to throw = in a time.sleep(1) call after the call to mylogger.exception to see if that= delays interpreter shutdown long enough for mylogger.exception to resolve.= =C2=A0Of course if you can't reproduce the bug often enough, it'll= be hard to tell if you've fixed it. =C2=A0The most unreliable Heisenbu= g I've ever fixed still happened ~1/3 of the time, so it was pretty obv= ious when I fixed it...

All the best,
Jason
--001a1133db94a8921f04feead22c--