Re: My sys.excepthook dies painfully
On Wed, Jul 23, 2014 at 6:30 PM, Steven D'Aprano steve+comp.lang.pyt...@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 -- https://mail.python.org/mailman/listinfo/python-list
Re: My sys.excepthook dies painfully
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.pyt...@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 -- https://mail.python.org/mailman/listinfo/python-list
Re: My sys.excepthook dies painfully
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 -- https://mail.python.org/mailman/listinfo/python-list
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
--
https://mail.python.org/mailman/listinfo/python-list
Re: My sys.excepthook dies painfully
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 -- https://mail.python.org/mailman/listinfo/python-list
Re: My sys.excepthook dies painfully
On Wed, 23 Jul 2014 07:14:27 +, 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 -- https://mail.python.org/mailman/listinfo/python-list
Re: My sys.excepthook dies painfully
On Wed, Jul 23, 2014 at 5:46 PM, Steven D'Aprano st...@pearwood.info wrote: On Wed, 23 Jul 2014 07:14:27 +, 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 -- https://mail.python.org/mailman/listinfo/python-list
Re: My sys.excepthook dies painfully
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: On Wed, 23 Jul 2014 07:14:27 +, 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 -- https://mail.python.org/mailman/listinfo/python-list
Re: My sys.excepthook dies painfully
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 -- https://mail.python.org/mailman/listinfo/python-list
Re: My sys.excepthook dies painfully
On Thu, Jul 24, 2014 at 11:30 AM, Steven D'Aprano
steve+comp.lang.pyt...@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
--
https://mail.python.org/mailman/listinfo/python-list
Re: My sys.excepthook dies painfully
Steven D'Aprano st...@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.
--
https://mail.python.org/mailman/listinfo/python-list
Re: My sys.excepthook dies painfully
On Thu, 24 Jul 2014 01:30:41 +, 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 -- https://mail.python.org/mailman/listinfo/python-list
