Non-working error handler when creating a task with assigning a variable

[rshakh]

BPO	39839
Nosy	@asvetlov, @cjrh, @cjerdonek, @1st1

^{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 = None
created_at = <Date 2020-03-03.18:24:30.080>
labels = ['3.7', 'expert-asyncio']
title = 'Non-working error handler when creating a task with assigning a variable'
updated_at = <Date 2020-05-19.00:58:36.307>
user = 'https://bugs.python.org/rshakh'

bugs.python.org fields:

activity = <Date 2020-05-19.00:58:36.307>
actor = 'chris.jerdonek'
assignee = 'none'
closed = False
closed_date = None
closer = None
components = ['asyncio']
creation = <Date 2020-03-03.18:24:30.080>
creator = 'rshakh'
dependencies = []
files = []
hgrepos = []
issue_num = 39839
keywords = []
message_count = 4.0
messages = ['363287', '363290', '364274', '369311']
nosy_count = 5.0
nosy_names = ['asvetlov', 'cjrh', 'chris.jerdonek', 'yselivanov', 'rshakh']
pr_nums = []
priority = 'normal'
resolution = None
stage = None
status = 'open'
superseder = None
type = None
url = 'https://bugs.python.org/issue39839'
versions = ['Python 3.7']

[rshakh]

#This example does not work due to assigning the task to a variable

import asyncio
import logging


def handle_exception(loop, context):
    msg = context.get("exception", context["message"])
    logging.error("Caught exception: %s", msg)

async def test():
    await asyncio.sleep(1)
    raise Exception("Crash.")

def main():
    loop = asyncio.get_event_loop()
    loop.set_exception_handler(handle_exception)
    # if removed "task = " - exception handler will work.
    task = loop.create_task(test())
    try:
        loop.run_forever()
    finally:
        loop.close()


if __name__ == "__main__":
    main()

[rshakh]

# This line doesn`t work
task = loop.create_task(test())
    
# This line works
loop.create_task(test())

[cjrh]

Can reproduce also on 3.8. Another version that "works" (raises the exception) is

    task = loop.create_task(test())
    del task

Suggests there's something going on with reference counting or garbage collection. In the version that "doesn't work", the task exception only appears in the custom exception handler when the loop is stopped, not before. I've added a log message to show each second that passes, and the loop is stopped after 5 seconds:

    import asyncio
    import logging


    def handle_exception(loop, context):
        msg = context.get("exception", context["message"])
        logging.error("Caught exception: %s", msg)


    async def test():
        await asyncio.sleep(1)
        raise Exception("Crash.")


    def second_logger(loop, count) -> int:
        logging.warning(count)
        loop.call_later(1, lambda count=count: second_logger(loop, count + 1))


    def main():
        loop = asyncio.get_event_loop()
        loop.call_later(1, lambda: second_logger(loop, 0))
        loop.call_later(5, loop.stop)
        loop.set_exception_handler(handle_exception)
        task = loop.create_task(test())
        try:
            loop.run_forever()
        finally:
            loop.close()


    if __name__ == "__main__":
        main()

OUTPUT:

    $ py -3.8 -u bpo-issue39839.py
    WARNING:root:0
    WARNING:root:1
    WARNING:root:2
    WARNING:root:3
    WARNING:root:4
    ERROR:root:Caught exception: Crash.

[cjerdonek]

I took a look at this.

Basically, the reason the exception handler isn't firing when the task is still in scope is that the exception handler is only a handler of "last resort." You can see that the exception handler is called inside Task.__del__ here:

cpython/Lib/asyncio/tasks.py

Lines 167 to 176 in 3764069

	def __del__(self):
	if self._state == futures._PENDING and self._log_destroy_pending:
	context = {
	'task': self,
	'message': 'Task was destroyed but it is pending!',
	}
	if self._source_traceback:
	context['source_traceback'] = self._source_traceback
	self._loop.call_exception_handler(context)
	super().__del__()

The reason to do it this way is that if the Task is still in scope, there's still a chance that the caller might want to handle the exception themselves, e.g. by awaiting on the Task themselves. It's only when all references to the task go away that you know that the Task's exceptions can no longer be handled manually.

Maybe this would be worth clarifying somewhere in the Error Handling API docs:
https://docs.python.org/3/library/asyncio-eventloop.html#error-handling-api
If you agree, we can change this issue to a documentation issue.

[kumaraditya303]

The exception handler is only called if the task was garbage collected and is pending. This usually happens when a task was created but there is no reference to it. It is documented at https://docs.python.org/3/library/asyncio-task.html#asyncio.create_task

[gvanrossum]

Ironically this "bug" reported in this issue is actually (although the OP never quite comes out and says it) that the task raises an exception but that exception is never reported. Following the advice that we recently added to the docs (basically "hold on to the task") causes the "bug". If you disregard the advice, not assigning the task to a variable, the exception handler is called (unless the task gets GC'ed before it is scheduled to run, which is rare but possible since you didn't hang on to it :-).

Maybe we need to add another piece of advice: await the task in order to get an exception reported. However, the best advice is to use TaskGroup, which propagates exceptions from all tasks (since it awaits all of them). Also use asyncio.run(), which reports exceptions propagated to the main() coroutine.