Created on 2011-03-28 22:29 by mikez302, last changed 2011-04-01 17:28 by haypo.
|loggingTest.py||mikez302, 2011-03-28 22:29||The file I used to demonstrate the problem.|
|msg132437 - (view)||Author: Elias Zamaria (mikez302) *||Date: 2011-03-28 22:29|
I am trying to design a Python program that logs all uncaught exceptions using the logging module. I am doing this by using the sys.excepthook function to override the default exception handling. I noticed that if I run the program directly from the command line, it works fine, but if I try to import the file, it doesn't work. It seems like the sys.excepthook function is unaware of the logging module. Here is an example: #! /usr/bin/env python2.7 import logging, sys logger = logging.getLogger() logger.setLevel(logging.DEBUG) logger.addHandler(logging.FileHandler("test.log")) print "outside of exception handler: logger = %s" % logger def handleException(excType, excValue, traceback): #global logger # this function doesn't work whether or not I include this line print "inside exception handler: logger = %s" % logger logger.error("Uncaught exception", exc_info=(excType, excValue, traceback)) sys.excepthook = handleException logger.debug("starting") asdf # create an exception If I run this from the command line (`./loggingTest.py`), it works fine. The exception gets logged, and I see this output: outside of exception handler: logger = <logging.RootLogger object at 0x7f2022eab950> inside exception handler: logger = <logging.RootLogger object at 0x7f2022eab950> However, if I run the Python interpreter and try to import the file (`import loggingTest`), it acts strangely. The exception doesn't get logged and I see this: outside of exception handler: logger = <logging.RootLogger object at 0x7f8ab04f3ad0> inside exception handler: logger = None Error in sys.excepthook: Traceback (most recent call last): File "loggingTest.py", line 13, in handleException logger.error("Uncaught exception", exc_info=(excType, excValue, traceback)) AttributeError: 'NoneType' object has no attribute 'error' Original exception was: Traceback (most recent call last): File "<stdin>", line 1, in <module> File "loggingTest.py", line 18, in <module> asdf # create an exception NameError: name 'asdf' is not defined I can maybe work around this problem by importing the logging module again within sys.excepthook, but I am still curious: why is this happening? The above text was copied from my question on Stack Overflow (http://stackoverflow.com/questions/5451746/sys-excepthook-doesnt-work-in-imported-modules). Someone on there (Jochen Ritzel) has mentioned that he noticed this bug in Python 2.7.1 but not 2.7. To me, it seems like the sys.excepthook function is unaware of any imported modules, unless those modules are imported from inside the function.
|msg132445 - (view)||Author: Andreas Stührk (Trundle)||Date: 2011-03-28 23:44|
I really doubt that this issue has anything to do with `sys.excepthook` at all. It's rather that module members are set to `None` during module cleanup. Because the module raises an exception when one tries to import it, it will be cleaned up immediately (see `PyImport_ExecCodeModuleEx`: it calls `remove_module` which will call at some point `_PyModule_Clear`). At the time when `sys.excepthook` is called, all module members are already set to `None`. One can easily demonstrate that this is really the problem by removing the exception raise in your example code: If one then imports "loggingTest" in an interactive session and raises an exception, the expected behaviour can be observed. Another workaround is to bind `logger` as a default argument (i.e. ``def handleException(excType, excValue, traceback, logger=logger):``).
|msg132454 - (view)||Author: Elias Zamaria (mikez302) *||Date: 2011-03-29 01:41|
Andreas, your explanation seems plausible. What has changed between 2.7 and 2.7.1 such that doing the same thing produces different results?
|msg132456 - (view)||Author: Andreas Stührk (Trundle)||Date: 2011-03-29 02:01|
The difference between 2.7 and 2.7.1 is issue #10068 (e2aa3b1d08bc).
|msg132457 - (view)||Author: Elias Zamaria (mikez302) *||Date: 2011-03-29 02:42|
Is my issue a bug or is it expected behavior?
|msg132458 - (view)||Author: Andreas Stührk (Trundle)||Date: 2011-03-29 03:02|
In my opinion, it is expected behaviour (but then, I'm not a core developer).
|msg132762 - (view)||Author: STINNER Victor (haypo) *||Date: 2011-04-01 17:28|
python -c "import loggingTest" calls PyRun_SimpleStringFlags(). python import_loggingTest.py (import_loggingTest.py just contains "import loggingTest") calls PyRun_SimpleFileExFlags(). Both functions calls PyErr_Print() on error. An error occurs ("raise Exception" in loggingTest.py) while importing the module, in PyImport_ExecCodeModuleEx(). The real problem is that the module is cleared because it raised an error. Extract of PyImport_ExecCodeModuleEx: v = PyEval_EvalCode((PyCodeObject *)co, d, d); if (v == NULL) goto error; ... error: remove_module(name); (remove_module() does something like del sys.modules['loggingTest']: because there is only once reference, the destructor of the module is called) -- You can workaround this corner case by keeping a reference to all used objects using a closure: ----------- def create_closure(logger, print_exception): def handleException(excType, excValue, traceback): print_exception(excType, excValue, traceback) print "inside exception handler: logger = %s" % logger logger.error("Uncaught exception", exc_info=(excType, excValue, traceback)) return handleException sys.excepthook = create_closure(logger, tb.print_exception) -----------
|2011-04-01 17:28:32||haypo||set||messages: + msg132762|
+ amaury.forgeotdarc, pitrou, haypo, benjamin.peterson, Valery.Lesin|
|2011-03-29 03:02:11||Trundle||set||messages: + msg132458|
|2011-03-29 02:42:27||mikez302||set||messages: + msg132457|
|2011-03-29 02:01:44||Trundle||set||messages: + msg132456|
|2011-03-29 01:41:56||mikez302||set||messages: + msg132454|
messages: + msg132445