sys.excepthook doesn't work in imported modules

[elias6]

BPO	11705
Nosy	@amauryfa, @pitrou, @vstinner, @benjaminp, @Trundle, @elias6
Files	loggingTest.py: The file I used to demonstrate the problem.

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = <Date 2015-03-08.08:06:02.509>
created_at = <Date 2011-03-28.22:29:14.128>
labels = ['invalid', 'type-bug', 'library']
title = "sys.excepthook doesn't work in imported modules"
updated_at = <Date 2015-03-08.08:06:02.508>
user = 'https://github.com/elias6'

bugs.python.org fields:

activity = <Date 2015-03-08.08:06:02.508>
actor = 'Claudiu.Popa'
assignee = 'none'
closed = True
closed_date = <Date 2015-03-08.08:06:02.509>
closer = 'Claudiu.Popa'
components = ['Library (Lib)']
creation = <Date 2011-03-28.22:29:14.128>
creator = 'elias'
dependencies = []
files = ['21446']
hgrepos = []
issue_num = 11705
keywords = []
message_count = 7.0
messages = ['132437', '132445', '132454', '132456', '132457', '132458', '132762']
nosy_count = 7.0
nosy_names = ['amaury.forgeotdarc', 'pitrou', 'vstinner', 'benjamin.peterson', 'Trundle', 'Valery.Lesin', 'elias']
pr_nums = []
priority = 'normal'
resolution = 'not a bug'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue11705'
versions = ['Python 2.7']

[elias6]

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.

[Trundle]

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):``).

[elias6]

Andreas, your explanation seems plausible. What has changed between 2.7 and 2.7.1 such that doing the same thing produces different results?

[Trundle]

The difference between 2.7 and 2.7.1 is issue bpo-10068 (e2aa3b1d08bc).

[elias6]

Is my issue a bug or is it expected behavior?

[Trundle]

In my opinion, it is expected behaviour (but then, I'm not a core developer).

[vstinner]

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)

---