classification
Title: sys.excepthook doesn't work in imported modules
Type: behavior Stage:
Components: Library (Lib) Versions: Python 2.7
process
Status: open Resolution:
Dependencies: Superseder:
Assigned To: Nosy List: Trundle, Valery.Lesin, amaury.forgeotdarc, benjamin.peterson, haypo, mikez302, pitrou
Priority: normal Keywords:

Created on 2011-03-28 22:29 by mikez302, last changed 2011-04-01 17:28 by haypo.

Files
File name Uploaded Description Edit
loggingTest.py mikez302, 2011-03-28 22:29 The file I used to demonstrate the problem.
Messages (7)
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) * (Python committer) 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)
-----------
History
Date User Action Args
2011-04-01 17:28:32hayposetmessages: + msg132762
2011-04-01 16:40:39eric.araujosetnosy: + amaury.forgeotdarc, pitrou, haypo, benjamin.peterson, Valery.Lesin
2011-03-29 03:02:11Trundlesetmessages: + msg132458
2011-03-29 02:42:27mikez302setmessages: + msg132457
2011-03-29 02:01:44Trundlesetmessages: + msg132456
2011-03-29 01:41:56mikez302setmessages: + msg132454
2011-03-28 23:44:56Trundlesetnosy: + Trundle
messages: + msg132445
2011-03-28 22:29:14mikez302create