My sys.excepthook dies painfully

[Steven D'Aprano]

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

[Chris Angelico]

On Wed, Jul 23, 2014 at 5:14 PM, Steven D'Aprano <st...@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

[Steven D'Aprano]

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

[Chris Angelico]

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

[Jason Swails]

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

> On Wed, Jul 23, 2014 at 5:46 PM, Steven D'Aprano <st...@pearwood.info> wrote:

> 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

[Steven D'Aprano]

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

[Chris Angelico]

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

[dieter]

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.

[Steven D'Aprano]

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

[Jason Swails]

On Wed, Jul 23, 2014 at 6:30 PM, Steven D'Aprano <steve+comp....@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

[Steven D'Aprano]

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

[Chris Angelico]

On Thu, Jul 24, 2014 at 8:12 PM, Steven D'Aprano <st...@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