classification
Title: asyncio: KeyboardInterrupt inside a coroutine causes AttributeError
Type: behavior Stage:
Components: asyncio Versions: Python 3.4
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: gvanrossum, oconnor663, vstinner, yselivanov
Priority: normal Keywords:

Created on 2014-09-17 07:36 by oconnor663, last changed 2015-01-06 00:36 by vstinner. This issue is now closed.

Messages (6)
msg226985 - (view) Author: Jack O'Connor (oconnor663) * Date: 2014-09-17 07:36
The following test script prints a KeyboardInterrupt traceback (expected), but also an AttributeError traceback (unexpected):


import asyncio
@asyncio.coroutine
def main():
    raise KeyboardInterrupt
asyncio.get_event_loop().run_until_complete(main())


Traceback (most recent call last):
  File "test.py", line 9, in <module>
    asyncio.get_event_loop().run_until_complete(main())
  File "/usr/lib/python3.4/asyncio/base_events.py", line 203, in run_until_complete
    self.run_forever()
  File "/usr/lib/python3.4/asyncio/base_events.py", line 184, in run_forever
    self._run_once()
  File "/usr/lib/python3.4/asyncio/base_events.py", line 817, in _run_once
    handle._run()
  File "/usr/lib/python3.4/asyncio/events.py", line 39, in _run
    self._callback(*self._args)
  File "/usr/lib/python3.4/asyncio/tasks.py", line 321, in _step
    result = next(coro)
  File "/usr/lib/python3.4/asyncio/tasks.py", line 103, in coro
    res = func(*args, **kw)
  File "test.py", line 6, in main
    raise KeyboardInterrupt
KeyboardInterrupt
--- Logging error ---
Traceback (most recent call last):
--- Logging error ---
Traceback (most recent call last):
Exception ignored in: <bound method Task.__del__ of Task(<coro>)<exception=KeyboardInterrupt()>>
Traceback (most recent call last):
  File "/usr/lib/python3.4/asyncio/futures.py", line 184, in __del__
  File "/usr/lib/python3.4/asyncio/base_events.py", line 725, in call_exception_handler
  File "/usr/lib/python3.4/logging/__init__.py", line 1296, in error
  File "/usr/lib/python3.4/logging/__init__.py", line 1402, in _log
  File "/usr/lib/python3.4/logging/__init__.py", line 1412, in handle
  File "/usr/lib/python3.4/logging/__init__.py", line 1482, in callHandlers
  File "/usr/lib/python3.4/logging/__init__.py", line 846, in handle
  File "/usr/lib/python3.4/logging/__init__.py", line 977, in emit
  File "/usr/lib/python3.4/logging/__init__.py", line 899, in handleError
  File "/usr/lib/python3.4/traceback.py", line 169, in print_exception
  File "/usr/lib/python3.4/traceback.py", line 153, in _format_exception_iter
  File "/usr/lib/python3.4/traceback.py", line 18, in _format_list_iter
  File "/usr/lib/python3.4/traceback.py", line 65, in _extract_tb_or_stack_iter
  File "/usr/lib/python3.4/linecache.py", line 15, in getline
  File "/usr/lib/python3.4/linecache.py", line 41, in getlines
  File "/usr/lib/python3.4/linecache.py", line 126, in updatecache
  File "/usr/lib/python3.4/tokenize.py", line 437, in open
AttributeError: 'module' object has no attribute 'open'


The issue is that Task._step() calls self.set_exception() for both Exceptions and BaseExceptions, but it reraises BaseExceptions. That means that the BaseEventLoop never gets to call future.result() to clear the exception when it's a BaseException. Future.__del__ eventually tries to log this uncleared exception, but something about the circumstances of program exit (caused by the same exception) has already cleaned up the builtins needed for logging.

Is that __del__ violating some best practices for finalizers by calling such a complicated function? Either way, I'm not sure this case should be considered an "unretrieved exception" at all. It's propagating outside the event loop after all. Should Task._step() be setting it in the first place, if it's going to reraise it? Should it be set without _log_traceback=True somehow?
msg226995 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2014-09-17 11:59
I see different issues in your example:


* If the coroutine raises an exception which doesn't inherit from Exception (but inherits from BaseException), run_until_complete() doesn't consume the exception from the temporary task object

=> run_until_complete(coroutine) sets the _log_destroy_pending attribute of the temporary Task to False, but this attribute controls the "Task was destroyed but it is pending!" warning. The "%s exception was never retrieved" warning is controlled by the Future._log_traceback attribute (in Python 3.4+). This attribute is set to True in Future.set_exception().*


* If a Task is deleted late during Python shutdown, the logging module fails to log the traceback because the builtin function has been deleted.

=> IMO it's an issue in the traceback module. It may catch the AttributeError on the call to linecache.getline(). It's not convinient to get a new exception (traceback) when trying to display a traceback... Maybe the traceback can check if Python is exiting before calling the linecache module?


* If you call again loop.run_forever(): it exits immediatly because a call to loop.stop() was scheduled by future.set_exception()

=> I created the issue #22429


I don't think that it's a bug that Task._step() calls set_exception() for BaseException. Otherwise, how do you know that a task failed?
msg227458 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2014-09-24 14:47
The issue #22480 has been marked as a duplicate of this issue.
msg228989 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2014-10-10 11:37
> => IMO it's an issue in the traceback module. It may catch the AttributeError on the call to linecache.getline().

I created the issue #22599 for this bug.
msg228995 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2014-10-10 12:23
> If the coroutine raises an exception which doesn't inherit from Exception (but inherits from BaseException), run_until_complete() doesn't consume the exception from the temporary task object

I created the issue #22601 for this bug.
msg233495 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2015-01-06 00:36
A lot of fixes has been commited to fix this general issue with asyncio at exit.

run_until_complete() doesn't log an error anymore when a BaseException (like KeyboardInterrupted) is raised. The caller is able to decide how to handle it.

The traceback module has been enhanced to try to fix the "AttributeError: 'module' object has no attribute 'open'" error (or at least reduce the risk of such error). A better solution is being developed.

The initial issue was fixed, I close the issue. Thanks for the report Jack. Sorry, I forgot to update this issue since it was splitted in many smaller and more specific issues.
History
Date User Action Args
2015-01-06 00:36:24vstinnersetstatus: open -> closed
resolution: fixed
messages: + msg233495
2014-10-10 12:23:50vstinnersetmessages: + msg228995
2014-10-10 11:37:33vstinnersetmessages: + msg228989
2014-09-24 14:47:39vstinnersetmessages: + msg227458
2014-09-24 14:47:24vstinnerlinkissue22480 superseder
2014-09-17 11:59:25vstinnersetmessages: + msg226995
2014-09-17 10:21:50vstinnersettitle: KeyboardInterrupt inside a coroutine causes AttributeError -> asyncio: KeyboardInterrupt inside a coroutine causes AttributeError
2014-09-17 07:36:10oconnor663create