Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > comp.lang.python > #75063 > unrolled thread

My sys.excepthook dies painfully

Back to article view | Back to comp.lang.python

Contents

  My sys.excepthook dies painfully Steven D'Aprano <steve@pearwood.info> - 2014-07-23 07:14 +0000
    Re: My sys.excepthook dies painfully Chris Angelico <rosuav@gmail.com> - 2014-07-23 17:36 +1000
    Re: My sys.excepthook dies painfully Steven D'Aprano <steve@pearwood.info> - 2014-07-23 07:46 +0000
      Re: My sys.excepthook dies painfully Chris Angelico <rosuav@gmail.com> - 2014-07-23 18:02 +1000
      Re: My sys.excepthook dies painfully Jason Swails <jason.swails@gmail.com> - 2014-07-23 13:02 -0700
        Re: My sys.excepthook dies painfully Steven D'Aprano <steve+comp.lang.python@pearwood.info> - 2014-07-24 01:30 +0000
          Re: My sys.excepthook dies painfully Chris Angelico <rosuav@gmail.com> - 2014-07-24 11:50 +1000
            Re: My sys.excepthook dies painfully Steven D'Aprano <steve@pearwood.info> - 2014-07-24 10:12 +0000
              Re: My sys.excepthook dies painfully Chris Angelico <rosuav@gmail.com> - 2014-07-24 20:20 +1000
          Re: My sys.excepthook dies painfully Steven D'Aprano <steve@pearwood.info> - 2014-07-24 05:51 +0000
          Re: My sys.excepthook dies painfully Jason Swails <jason.swails@gmail.com> - 2014-07-23 23:46 -0700
    Re: My sys.excepthook dies painfully dieter <dieter@handshake.de> - 2014-07-24 07:36 +0200

#75063 — My sys.excepthook dies painfully

I have some code which sets up a logger instance, then installs it as 
sys.excepthook to capture any uncaught exceptions:



import logging
import logging.handlers
import sys

FACILITY = logging.handlers.SysLogHandler.LOG_LOCAL6
mylogger = logging.getLogger('spam')
handler = logging.handlers.SysLogHandler(
        address='/dev/log', facility=FACILITY)
formatter = logging.Formatter("%(levelname)s:%(message)s [%(module)s]")
handler.setFormatter(formatter)
mylogger.addHandler(handler)
mylogger.setLevel(logging.DEBUG)
mylogger.info('started logging')

def my_error_handler(type, value, tb):
    msg = "Uncaught %s: %s" % (type, value)
    mylogger.exception(msg)
    sys.__excepthook__(type, value, tb)  # print the traceback to stderr

# Install exception handler.
mylogger.info('installing error handler')
sys.excepthook = my_error_handler

foo  # Die with uncaught NameError.



If I run this code, the INFO logging messages are logged, but the 
exception is not. Instead it is printed to the console:


Error in sys.excepthook:
Traceback (most recent call last):
  File "/home/steve/mylogging.py", line 28, in my_error_handler
    mylogger.exception(msg)
AttributeError: 'NoneType' object has no attribute 'exception'

Original exception was:
Traceback (most recent call last):
  [...]
  File "/home/steve/mylogging.py", line 35, in <module>
    foo
NameError: name 'foo' is not defined



(I've trimmed out some of the traceback, because the details aren't 
relevant.)

Any ideas what I'm doing wrong? How does mylogger get set to None?



-- 
Steven

[toc] | [next] | [standalone]

#75066

On Wed, Jul 23, 2014 at 5:14 PM, Steven D'Aprano <steve@pearwood.info> wrote:
> Error in sys.excepthook:
> Traceback (most recent call last):
>   File "/home/steve/mylogging.py", line 28, in my_error_handler
>     mylogger.exception(msg)
> AttributeError: 'NoneType' object has no attribute 'exception'
>
> Original exception was:
> Traceback (most recent call last):
>   [...]
>   File "/home/steve/mylogging.py", line 35, in <module>
>     foo
> NameError: name 'foo' is not defined

I was not able to repro this with the 3.5-messy that I have on this
system, nor a clean 3.4.1 from Debian Jessie. It's slightly different:

rosuav@dewey:~$ python3 mylogging.py
Error in sys.excepthook:
Traceback (most recent call last):
  File "/usr/lib/python3.4/logging/__init__.py", line 846, in handle
    self.emit(record)
  File "/usr/lib/python3.4/logging/handlers.py", line 881, in emit
    msg = self.format(record)
  File "/usr/lib/python3.4/logging/__init__.py", line 821, in format
    return fmt.format(record)
  File "/usr/lib/python3.4/logging/__init__.py", line 566, in format
    record.exc_text = self.formatException(record.exc_info)
  File "/usr/lib/python3.4/logging/__init__.py", line 516, in formatException
    traceback.print_exception(ei[0], ei[1], tb, None, sio)
  File "/usr/lib/python3.4/traceback.py", line 169, in print_exception
    for line in _format_exception_iter(etype, value, tb, limit, chain):
  File "/usr/lib/python3.4/traceback.py", line 146, in _format_exception_iter
    for value, tb in values:
  File "/usr/lib/python3.4/traceback.py", line 125, in _iter_chain
    context = exc.__context__
AttributeError: 'NoneType' object has no attribute '__context__'

Original exception was:
Traceback (most recent call last):
  File "mylogging.py", line 24, in <module>
    foo  # Die with uncaught NameError.
NameError: name 'foo' is not defined

(Obviously that's the clean 3.4, but it's the same exception in 3.5.)

>From what I can see, the problem is that sys.exc_info() is returning
None, None, None at this point, and the Logger.exception() method
specifically looks for the currently-being-handled exception. You can
get equivalent functionality with this:

def my_error_handler(type, value, tb):
    msg = "Uncaught %s: %s" % (type, value)
    mylogger.error(msg, exc_info=(type, value, tb))
    sys.__excepthook__(type, value, tb)  # print the traceback to stderr

At least, I think that's correct. It does seem to dump a lot of stuff
into a single line in the log, though.

Can't repro your exact traceback, though, so I don't know what's going on there.

ChrisA

[toc] | [prev] | [next] | [standalone]

#75067

On Wed, 23 Jul 2014 07:14:27 +0000, Steven D'Aprano wrote:

> I have some code which sets up a logger instance, then installs it as
> sys.excepthook to capture any uncaught exceptions:

Oh! I should have said, I'm running Python 2.6.



-- 
Steven

[toc] | [prev] | [next] | [standalone]

#75069

On Wed, Jul 23, 2014 at 5:46 PM, Steven D'Aprano <steve@pearwood.info> wrote:
> On Wed, 23 Jul 2014 07:14:27 +0000, Steven D'Aprano wrote:
>
>> I have some code which sets up a logger instance, then installs it as
>> sys.excepthook to capture any uncaught exceptions:
>
> Oh! I should have said, I'm running Python 2.6.

Ah! I tried it in 2.7 and it seemed to work. One moment...

huix@huix:~$ python mylogging.py
Traceback (most recent call last):
  File "mylogging.py", line 24, in <module>
    foo  # Die with uncaught NameError.
NameError: name 'foo' is not defined
huix@huix:~$ python -V
Python 2.6.6
huix@huix:~$ tail /var/log/syslog
...
Jul 23 18:01:49 huix INFO: started logging [mylogging]
Jul 23 18:01:49 huix INFO: installing error handler [mylogging]
Jul 23 18:01:49 huix ERROR: Uncaught <type 'exceptions.NameError'>:
name 'foo' is not defined [mylogging]#012None

Still not sure what's going on. Odd.

ChrisA

[toc] | [prev] | [next] | [standalone]

#75096

On Jul 23, 2014, at 1:02 AM, Chris Angelico <rosuav@gmail.com> wrote:

> On Wed, Jul 23, 2014 at 5:46 PM, Steven D'Aprano <steve@pearwood.info> wrote:
>> On Wed, 23 Jul 2014 07:14:27 +0000, Steven D'Aprano wrote:
>> 
>>> I have some code which sets up a logger instance, then installs it as
>>> sys.excepthook to capture any uncaught exceptions:
>> 
>> Oh! I should have said, I'm running Python 2.6.
> 
> Ah! I tried it in 2.7 and it seemed to work. One moment...
> 
> huix@huix:~$ python mylogging.py
> Traceback (most recent call last):
>  File "mylogging.py", line 24, in <module>
>    foo  # Die with uncaught NameError.
> NameError: name 'foo' is not defined
> huix@huix:~$ python -V
> Python 2.6.6
> huix@huix:~$ tail /var/log/syslog
> ...
> Jul 23 18:01:49 huix INFO: started logging [mylogging]
> Jul 23 18:01:49 huix INFO: installing error handler [mylogging]
> Jul 23 18:01:49 huix ERROR: Uncaught <type 'exceptions.NameError'>:
> name 'foo' is not defined [mylogging]#012None
> 
> Still not sure what's going on. Odd.

Works for me, too:

swails@batman ~ $ python2.6 mylogging.py 
Traceback (most recent call last):
  File "mylogging.py", line 24, in <module>
    foo  # Die with uncaught NameError.
NameError: name 'foo' is not defined
swails@batman ~ $ sudo tail /var/log/messages 
...
Jul 23 16:02:30 batman INFO:started logging [mylogging]
Jul 23 16:02:30 batman INFO:installing error handler [mylogging]
Jul 23 16:02:30 batman ERROR:Uncaught <type 'exceptions.NameError'>: name 'foo' is not defined [mylogging]

I tried it with python2.2 through python2.7 (python 2.2 and earlier did not have the logging module).

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...

All the best,
Jason

[toc] | [prev] | [next] | [standalone]

#75111

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.

It's quite common for __del__ methods and daemon threads to be called 
during interpreter shutdown, but I've never come across an excepthook 
doing this.

I wonder whether I ought to use atexit to register the function, rather 
than mess with sys.excepthook directly?



-- 
Steven

[toc] | [prev] | [next] | [standalone]

#75112

On Thu, Jul 24, 2014 at 11:30 AM, Steven D'Aprano
<steve+comp.lang.python@pearwood.info> wrote:
> 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.

In other words, the problem changed when you added the NameError
trigger at the bottom of the script?

Would it be possible to snapshot all critical globals with a closure,
to force them to be held? Something like:

def handler_gen(mylogger, sys):
    def my_error_handler(type, value, tb):
        msg = "Uncaught %s: %s" % (type, value)
        mylogger.exception(msg)
        sys.__excepthook__(type, value, tb)  # print the traceback to stderr

# Install exception handler.
mylogger.info('installing error handler')
sys.excepthook = handler_gen(mylogger, sys)

It seems crazy, but it might work. It's a guaranteed one-way
connection, saying "this function NEEDS these objects".

ChrisA

[toc] | [prev] | [next] | [standalone]

#75137

On Thu, 24 Jul 2014 11:50:47 +1000, Chris Angelico wrote:

> On Thu, Jul 24, 2014 at 11:30 AM, Steven D'Aprano
> <steve+comp.lang.python@pearwood.info> wrote:
>> 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.
> 
> In other words, the problem changed when you added the NameError trigger
> at the bottom of the script?

Not quite. The problem changed when I reduced the code from the real code 
(about a dozen modules) down to the short sample I've given. Except 
that's not quite either -- even with the original code, I wasn't 
originally getting the double traceback either.

I've just stuck some print statements inside the exception handler, and 
just before the "foo":

print 'sys, mylogger', sys, mylogger
foo


They have their expected values just before "foo", but inside the 
excepthook function they are both None.


> Would it be possible to snapshot all critical globals with a closure, to
> force them to be held? Something like:

Probably. Or even as default argument parameters. But I'd like to know if 
that's actually fixing it or just perturbing the system enough that the 
bug won't show up until next time the moon is full.


-- 
Steven

[toc] | [prev] | [next] | [standalone]

#75138

On Thu, Jul 24, 2014 at 8:12 PM, Steven D'Aprano <steve@pearwood.info> wrote:
>> Would it be possible to snapshot all critical globals with a closure, to
>> force them to be held? Something like:
>
> Probably. Or even as default argument parameters. But I'd like to know if
> that's actually fixing it or just perturbing the system enough that the
> bug won't show up until next time the moon is full.

If the problem is that there's a circular reference (function to
module, module to function) and stuff's getting cleaned up in
arbitrary order, the snapshotting should cure it, as it's a one-way
reference. But since I can't recreate the exact symptoms you're
seeing, it's hard for me to be sure...

ChrisA

[toc] | [prev] | [next] | [standalone]

#75125

On Thu, 24 Jul 2014 01:30:41 +0000, Steven D'Aprano wrote:

> I wonder whether I ought to use atexit to register the function, rather
> than mess with sys.excepthook directly?

Ignore this. I was smoking crack. atexit has nothing to do with 
sys.excepthook and won't solve my problem.


-- 
Steven

[toc] | [prev] | [next] | [standalone]

#75127

[Multipart message — attachments visible in raw view] — view raw

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

[toc] | [prev] | [next] | [standalone]

#75124

Steven D'Aprano <steve@pearwood.info> writes:
> I have some code which sets up a logger instance, then installs it as 
> sys.excepthook to capture any uncaught exceptions:
>
>
>
> import logging
> import logging.handlers
> import sys
>
> FACILITY = logging.handlers.SysLogHandler.LOG_LOCAL6
> mylogger = logging.getLogger('spam')
> handler = logging.handlers.SysLogHandler(
>         address='/dev/log', facility=FACILITY)
> formatter = logging.Formatter("%(levelname)s:%(message)s [%(module)s]")
> handler.setFormatter(formatter)
> mylogger.addHandler(handler)
> mylogger.setLevel(logging.DEBUG)
> mylogger.info('started logging')
>
> def my_error_handler(type, value, tb):
>     msg = "Uncaught %s: %s" % (type, value)
>     mylogger.exception(msg)
>     sys.__excepthook__(type, value, tb)  # print the traceback to stderr
>
> # Install exception handler.
> mylogger.info('installing error handler')
> sys.excepthook = my_error_handler
>
> foo  # Die with uncaught NameError.
>
>
>
> If I run this code, the INFO logging messages are logged, but the 
> exception is not. Instead it is printed to the console:
>
>
> Error in sys.excepthook:
> Traceback (most recent call last):
>   File "/home/steve/mylogging.py", line 28, in my_error_handler
>     mylogger.exception(msg)
> AttributeError: 'NoneType' object has no attribute 'exception'

This tells you that "mylogger" is "None".

This can happen during finalization. When the interpreter is shut down,
it unbinds all variables in a complex process (somewhere, there
is a description how it proceeds). Unbinding a variable effectively
means bindiung it to "None".

This would suggest that the finalization starts before the "excepthook"
has been executed. I would consider this a bug.

[toc] | [prev] | [standalone]

Back to top | Article view | comp.lang.python

csiph-web