Weird behaviour with exceptions

Question

Weird behaviour with exceptions

Closed this issue 9 years ago · 4 comments

Consider the following code :

import asyncio
from PyQt5.QtCore import QTimer
import logging
import quamash
from quamash import QApplication


class Bug():
    def __init__(self):
        pass

    @asyncio.coroutine
    def errorlvl3(self):
        raise TypeError()

    @asyncio.coroutine
    def errorlvl2(self):
        yield from self.errorlvl3()

    @asyncio.coroutine
    def errorlvl1(self):
        yield from self.errorlvl2()

    def go(self):
        asyncio.async(self.wait_and_close())
        asyncio.async(self.errorlvl1())

    @asyncio.coroutine
    def wait_and_close(self):
        for i in range(0, 3):
            yield from asyncio.sleep(1)
        self.lp.stop()

    def test_bug(self):
        self.qapplication = QApplication([])
        self.lp = quamash.QEventLoop(self.qapplication)
        self.lp.set_debug(True)
        asyncio.set_event_loop(self.lp)

        with self.lp:
            QTimer.singleShot(0, self.go)
            self.lp.run_forever()
        asyncio.set_event_loop(None)


if __name__ == '__main__':
    logging.basicConfig(format='%(levelname)s:%(module)s:%(funcName)s:%(message)s',
        level=logging.DEBUG)
    Bug().test_bug()

When I run this, I get the following output :

/home/inso/.pyenv/versions/cutecoin/bin/python3 /home/inso/code/quamash/bug.py -d
DEBUG:selector_events:__init__:Using selector: _Selector
DEBUG:__init__:add_reader:Adding reader callback for file descriptor 10
DEBUG:__init__:run_forever:Starting Qt event loop
DEBUG:__init__:call_later:Registering callback <bound method Task._step of <Task pending coro=<wait_and_close() running at /home/inso/code/quamash/bug.py:30> created at /home/inso/.pyenv/versions/3.4.3/lib/python3.4/asyncio/base_events.py:212>> to be invoked with arguments () after 0 second(s)
DEBUG:__init__:_add_callback:Adding callback <Handle Task._step() created at /home/inso/code/quamash/quamash/__init__.py:346> with delay 0
DEBUG:__init__:call_later:Registering callback <bound method Task._step of <Task pending coro=<errorlvl1() running at /home/inso/code/quamash/bug.py:22> created at /home/inso/.pyenv/versions/3.4.3/lib/python3.4/asyncio/base_events.py:212>> to be invoked with arguments () after 0 second(s)
DEBUG:__init__:_add_callback:Adding callback <Handle Task._step() created at /home/inso/code/quamash/quamash/__init__.py:346> with delay 0
DEBUG:__init__:upon_timeout:Callback timer fired, calling <Handle Task._step() created at /home/inso/code/quamash/quamash/__init__.py:346>
DEBUG:__init__:call_later:Registering callback <bound method Future._set_result_unless_cancelled of <Future pending created at /home/inso/.pyenv/versions/3.4.3/lib/python3.4/asyncio/tasks.py:490>> to be invoked with arguments (None,) after 1 second(s)
DEBUG:__init__:_add_callback:Adding callback <Handle Future._set_result_unless_cancelled(None) created at /home/inso/code/quamash/quamash/__init__.py:346> with delay 1
DEBUG:__init__:upon_timeout:Callback timer fired, calling <Handle Task._step() created at /home/inso/code/quamash/quamash/__init__.py:346>
DEBUG:__init__:upon_timeout:Callback timer fired, calling <Handle Future._set_result_unless_cancelled(None) created at /home/inso/code/quamash/quamash/__init__.py:346>
DEBUG:__init__:call_later:Registering callback <bound method Task._wakeup of <Task pending coro=<wait_and_close() running at /home/inso/code/quamash/bug.py:33> wait_for=<Future finished result=None created at /home/inso/.pyenv/versions/3.4.3/lib/python3.4/asyncio/tasks.py:490> created at /home/inso/code/quamash/bug.py:27>> to be invoked with arguments (<Future finished result=None created at /home/inso/.pyenv/versions/3.4.3/lib/python3.4/asyncio/tasks.py:490>,) after 0 second(s)
DEBUG:__init__:_add_callback:Adding callback <Handle Task._wakeup(<Future finis.../tasks.py:490>) created at /home/inso/code/quamash/quamash/__init__.py:346> with delay 0
DEBUG:__init__:upon_timeout:Callback timer fired, calling <Handle Task._wakeup(<Future finis.../tasks.py:490>) created at /home/inso/code/quamash/quamash/__init__.py:346>
DEBUG:__init__:call_later:Registering callback <bound method Future._set_result_unless_cancelled of <Future pending created at /home/inso/.pyenv/versions/3.4.3/lib/python3.4/asyncio/tasks.py:490>> to be invoked with arguments (None,) after 1 second(s)
DEBUG:__init__:_add_callback:Adding callback <Handle Future._set_result_unless_cancelled(None) created at /home/inso/code/quamash/quamash/__init__.py:346> with delay 1
DEBUG:__init__:upon_timeout:Callback timer fired, calling <Handle Future._set_result_unless_cancelled(None) created at /home/inso/code/quamash/quamash/__init__.py:346>
DEBUG:__init__:call_later:Registering callback <bound method Task._wakeup of <Task pending coro=<wait_and_close() running at /home/inso/code/quamash/bug.py:33> wait_for=<Future finished result=None created at /home/inso/.pyenv/versions/3.4.3/lib/python3.4/asyncio/tasks.py:490> created at /home/inso/code/quamash/bug.py:27>> to be invoked with arguments (<Future finished result=None created at /home/inso/.pyenv/versions/3.4.3/lib/python3.4/asyncio/tasks.py:490>,) after 0 second(s)
DEBUG:__init__:_add_callback:Adding callback <Handle Task._wakeup(<Future finis.../tasks.py:490>) created at /home/inso/code/quamash/quamash/__init__.py:346> with delay 0
DEBUG:__init__:upon_timeout:Callback timer fired, calling <Handle Task._wakeup(<Future finis.../tasks.py:490>) created at /home/inso/code/quamash/quamash/__init__.py:346>
DEBUG:__init__:call_later:Registering callback <bound method Future._set_result_unless_cancelled of <Future pending created at /home/inso/.pyenv/versions/3.4.3/lib/python3.4/asyncio/tasks.py:490>> to be invoked with arguments (None,) after 1 second(s)
DEBUG:__init__:_add_callback:Adding callback <Handle Future._set_result_unless_cancelled(None) created at /home/inso/code/quamash/quamash/__init__.py:346> with delay 1
DEBUG:__init__:upon_timeout:Callback timer fired, calling <Handle Future._set_result_unless_cancelled(None) created at /home/inso/code/quamash/quamash/__init__.py:346>
DEBUG:__init__:call_later:Registering callback <bound method Task._wakeup of <Task pending coro=<wait_and_close() running at /home/inso/code/quamash/bug.py:33> wait_for=<Future finished result=None created at /home/inso/.pyenv/versions/3.4.3/lib/python3.4/asyncio/tasks.py:490> created at /home/inso/code/quamash/bug.py:27>> to be invoked with arguments (<Future finished result=None created at /home/inso/.pyenv/versions/3.4.3/lib/python3.4/asyncio/tasks.py:490>,) after 0 second(s)
DEBUG:__init__:_add_callback:Adding callback <Handle Task._wakeup(<Future finis.../tasks.py:490>) created at /home/inso/code/quamash/quamash/__init__.py:346> with delay 0
DEBUG:__init__:upon_timeout:Callback timer fired, calling <Handle Task._wakeup(<Future finis.../tasks.py:490>) created at /home/inso/code/quamash/quamash/__init__.py:346>
DEBUG:__init__:stop:Stopping event loop...
DEBUG:__init__:stop:Stopped event loop
DEBUG:__init__:run_forever:Qt event loop ended with result 0
DEBUG:__init__:stop:Already stopped
DEBUG:__init__:close:Closing event loop...
DEBUG:__init__:remove_reader:Removing reader callback for file descriptor 10
DEBUG:base_events:close:Close <QEventLoop running=False closed=False debug=True>
DEBUG:_unix:close:Closing
DEBUG:__init__:default_exception_handler:Default exception handler executing
ERROR:__init__:__log_error:Task exception was never retrieved
future: <Task finished coro=<errorlvl1() done, defined at /home/inso/code/quamash/bug.py:22> exception=TypeError() created at /home/inso/code/quamash/bug.py:28>
source_traceback: [('/home/inso/code/quamash/bug.py', 51, '<module>', 'Bug().test_bug()'), ('/home/inso/code/quamash/bug.py', 44, 'test_bug', 'self.lp.run_forever()'), ('/home/inso/code/quamash/quamash/__init__.py', 271, 'run_forever', 'rslt = self.__app.exec_()'), ('/home/inso/code/quamash/bug.py', 28, 'go', 'asyncio.async(self.errorlvl1())')]
Traceback (most recent call last):
  File "/home/inso/.pyenv/versions/3.4.3/lib/python3.4/asyncio/tasks.py", line 238, in _step
    result = next(coro)
  File "/home/inso/code/quamash/bug.py", line 24, in errorlvl1
    yield from self.errorlvl2()
  File "/home/inso/code/quamash/bug.py", line 20, in errorlvl2
    yield from self.errorlvl3()
  File "/home/inso/.pyenv/versions/3.4.3/lib/python3.4/asyncio/coroutines.py", line 141, in coro
    res = func(*args, **kw)
  File "/home/inso/code/quamash/bug.py", line 16, in errorlvl3
    raise TypeError()
TypeError

Process finished with exit code 0

What we can see here, is that the exception is only displayed when the loop closes. Shouldn't the exception be displayed during the "wait_and_close" method ?

Answer 1 · 2015-11-05T21:42:15.000Z

probably. Have you tried with a standard event loop?

also, loop.call_soon(self.go) should do what you want w/o getting a qtimer
involved (it will use a qtimer under the covers of course).

On Thu, Nov 5, 2015 at 1:17 PM, Insoleet notifications@github.com wrote:

Consider the following code :

import asynciofrom PyQt5.QtCore import QTimerimport loggingimport quamashfrom quamash import QApplication

class Bug():
def init(self):
pass
@asyncio.coroutine
def errorlvl3(self):
    raise TypeError()

@asyncio.coroutine
def errorlvl2(self):
    yield from self.errorlvl3()

@asyncio.coroutine
def errorlvl1(self):
    yield from self.errorlvl2()

def go(self):
    asyncio.async(self.wait_and_close())
    asyncio.async(self.errorlvl1())

@asyncio.coroutine
def wait_and_close(self):
    for i in range(0, 3):
        yield from asyncio.sleep(1)
    self.lp.stop()

def test_bug(self):
    self.qapplication = QApplication([])
    self.lp = quamash.QEventLoop(self.qapplication)
    self.lp.set_debug(True)
    asyncio.set_event_loop(self.lp)

    with self.lp:
        QTimer.singleShot(0, self.go)
        self.lp.run_forever()
    asyncio.set_event_loop(None)
if name == 'main':
logging.basicConfig(format='%(levelname)s:%(module)s:%(funcName)s:%(message)s',
level=logging.DEBUG)
Bug().test_bug()

When I run this, I get the following output :

/home/inso/.pyenv/versions/cutecoin/bin/python3 /home/inso/code/quamash/bug.py -d
DEBUG:selector_events:init:Using selector: _Selector
DEBUG:init:add_reader:Adding reader callback for file descriptor 10
DEBUG:init:run_forever:Starting Qt event loop
DEBUG:init:call_later:Registering callback <bound method Task._step of <Task pending coro=<wait_and_close() running at /home/inso/code/quamash/bug.py:30> created at /home/inso/.pyenv/versions/3.4.3/lib/python3.4/asyncio/base_events.py:212>> to be invoked with arguments () after 0 second(s)
DEBUG:init:_add_callback:Adding callback <Handle Task._step() created at /home/inso/code/quamash/quamash/init.py:346> with delay 0
DEBUG:init:call_later:Registering callback <bound method Task._step of <Task pending coro=<errorlvl1() running at /home/inso/code/quamash/bug.py:22> created at /home/inso/.pyenv/versions/3.4.3/lib/python3.4/asyncio/base_events.py:212>> to be invoked with arguments () after 0 second(s)
DEBUG:init:_add_callback:Adding callback <Handle Task._step() created at /home/inso/code/quamash/quamash/init.py:346> with delay 0
DEBUG:init:upon_timeout:Callback timer fired, calling <Handle Task._step() created at /home/inso/code/quamash/quamash/init.py:346>
DEBUG:init:call_later:Registering callback <bound method Future._set_result_unless_cancelled of <Future pending created at /home/inso/.pyenv/versions/3.4.3/lib/python3.4/asyncio/tasks.py:490>> to be invoked with arguments (None,) after 1 second(s)
DEBUG:init:_add_callback:Adding callback <Handle Future._set_result_unless_cancelled(None) created at /home/inso/code/quamash/quamash/init.py:346> with delay 1
DEBUG:init:upon_timeout:Callback timer fired, calling <Handle Task._step() created at /home/inso/code/quamash/quamash/init.py:346>
DEBUG:init:upon_timeout:Callback timer fired, calling <Handle Future._set_result_unless_cancelled(None) created at /home/inso/code/quamash/quamash/init.py:346>
DEBUG:init:call_later:Registering callback <bound method Task._wakeup of <Task pending coro=<wait_and_close() running at /home/inso/code/quamash/bug.py:33> wait_for=<Future finished result=None created at /home/inso/.pyenv/versions/3.4.3/lib/python3.4/asyncio/tasks.py:490> created at /home/inso/code/quamash/bug.py:27>> to be invoked with arguments (<Future finished result=None created at /home/inso/.pyenv/versions/3.4.3/lib/python3.4/asyncio/tasks.py:490>,) after 0 second(s)
DEBUG:init:_add_callback:Adding callback <Handle Task._wakeup(<Future finis.../tasks.py:490>) created at /home/inso/code/quamash/quamash/init.py:346> with delay 0
DEBUG:init:upon_timeout:Callback timer fired, calling <Handle Task._wakeup(<Future finis.../tasks.py:490>) created at /home/inso/code/quamash/quamash/init.py:346>
DEBUG:init:call_later:Registering callback <bound method Future._set_result_unless_cancelled of <Future pending created at /home/inso/.pyenv/versions/3.4.3/lib/python3.4/asyncio/tasks.py:490>> to be invoked with arguments (None,) after 1 second(s)
DEBUG:init:_add_callback:Adding callback <Handle Future._set_result_unless_cancelled(None) created at /home/inso/code/quamash/quamash/init.py:346> with delay 1
DEBUG:init:upon_timeout:Callback timer fired, calling <Handle Future._set_result_unless_cancelled(None) created at /home/inso/code/quamash/quamash/init.py:346>
DEBUG:init:call_later:Registering callback <bound method Task._wakeup of <Task pending coro=<wait_and_close() running at /home/inso/code/quamash/bug.py:33> wait_for=<Future finished result=None created at /home/inso/.pyenv/versions/3.4.3/lib/python3.4/asyncio/tasks.py:490> created at /home/inso/code/quamash/bug.py:27>> to be invoked with arguments (<Future finished result=None created at /home/inso/.pyenv/versions/3.4.3/lib/python3.4/asyncio/tasks.py:490>,) after 0 second(s)
DEBUG:init:_add_callback:Adding callback <Handle Task._wakeup(<Future finis.../tasks.py:490>) created at /home/inso/code/quamash/quamash/init.py:346> with delay 0
DEBUG:init:upon_timeout:Callback timer fired, calling <Handle Task._wakeup(<Future finis.../tasks.py:490>) created at /home/inso/code/quamash/quamash/init.py:346>
DEBUG:init:call_later:Registering callback <bound method Future._set_result_unless_cancelled of <Future pending created at /home/inso/.pyenv/versions/3.4.3/lib/python3.4/asyncio/tasks.py:490>> to be invoked with arguments (None,) after 1 second(s)
DEBUG:init:_add_callback:Adding callback <Handle Future._set_result_unless_cancelled(None) created at /home/inso/code/quamash/quamash/init.py:346> with delay 1
DEBUG:init:upon_timeout:Callback timer fired, calling <Handle Future._set_result_unless_cancelled(None) created at /home/inso/code/quamash/quamash/init.py:346>
DEBUG:init:call_later:Registering callback <bound method Task._wakeup of <Task pending coro=<wait_and_close() running at /home/inso/code/quamash/bug.py:33> wait_for=<Future finished result=None created at /home/inso/.pyenv/versions/3.4.3/lib/python3.4/asyncio/tasks.py:490> created at /home/inso/code/quamash/bug.py:27>> to be invoked with arguments (<Future finished result=None created at /home/inso/.pyenv/versions/3.4.3/lib/python3.4/asyncio/tasks.py:490>,) after 0 second(s)
DEBUG:init:_add_callback:Adding callback <Handle Task._wakeup(<Future finis.../tasks.py:490>) created at /home/inso/code/quamash/quamash/init.py:346> with delay 0
DEBUG:init:upon_timeout:Callback timer fired, calling <Handle Task._wakeup(<Future finis.../tasks.py:490>) created at /home/inso/code/quamash/quamash/init.py:346>
DEBUG:init:stop:Stopping event loop...
DEBUG:init:stop:Stopped event loop
DEBUG:init:run_forever:Qt event loop ended with result 0
DEBUG:init:stop:Already stopped
DEBUG:init:close:Closing event loop...
DEBUG:init:remove_reader:Removing reader callback for file descriptor 10
DEBUG:base_events:close:Close
DEBUG:_unix:close:Closing
DEBUG:init:default_exception_handler:Default exception handler executing
ERROR:init:log_error:Task exception was never retrieved
future: <Task finished coro=<errorlvl1() done, defined at /home/inso/code/quamash/bug.py:22> exception=TypeError() created at /home/inso/code/quamash/bug.py:28>
source_traceback: [('/home/inso/code/quamash/bug.py', 51, '', 'Bug().test_bug()'), ('/home/inso/code/quamash/bug.py', 44, 'test_bug', 'self.lp.run_forever()'), ('/home/inso/code/quamash/quamash/__init.py', 271, 'run_forever', 'rslt = self._app.exec()'), ('/home/inso/code/quamash/bug.py', 28, 'go', 'asyncio.async(self.errorlvl1())')]
Traceback (most recent call last):
File "/home/inso/.pyenv/versions/3.4.3/lib/python3.4/asyncio/tasks.py", line 238, in _step
result = next(coro)
File "/home/inso/code/quamash/bug.py", line 24, in errorlvl1
yield from self.errorlvl2()
File "/home/inso/code/quamash/bug.py", line 20, in errorlvl2
yield from self.errorlvl3()
File "/home/inso/.pyenv/versions/3.4.3/lib/python3.4/asyncio/coroutines.py", line 141, in coro
res = func(_args, *_kw)
File "/home/inso/code/quamash/bug.py", line 16, in errorlvl3
raise TypeError()
TypeError

Process finished with exit code 0

What we can see here, is that the exception is only displayed when the
loop closes. Shouldn't the exception be displayed during the
"wait_and_close" method ?

—
Reply to this email directly or view it on GitHub
#52.

Answer 2 · 2015-11-05T23:06:39.000Z

Yes with standard loop the behaviour is correct :

import asyncio
from PyQt5.QtCore import QTimer
import logging
import quamash
from quamash import QApplication


class Bug():
    def __init__(self):
        pass

    @asyncio.coroutine
    def errorlvl3(self):
        raise TypeError()

    @asyncio.coroutine
    def errorlvl2(self):
        yield from self.errorlvl3()

    @asyncio.coroutine
    def errorlvl1(self):
        yield from self.errorlvl2()

    def go(self):
        asyncio.async(self.wait_and_close())
        asyncio.async(self.errorlvl1())

    @asyncio.coroutine
    def wait_and_close(self):
        for i in range(0, 3):
            yield from asyncio.sleep(1)
        self.lp.stop()

    def test_bug(self):
        #self.qapplication = QApplication([])
        self.lp = asyncio.get_event_loop()#quamash.QEventLoop(self.qapplication)
        self.lp.set_debug(True)
        asyncio.set_event_loop(self.lp)

        #with self.lp:
        self.lp.call_soon(self.go)
        self.lp.run_forever()
        asyncio.set_event_loop(None)


if __name__ == '__main__':
    logging.basicConfig(format='%(levelname)s:%(module)s:%(funcName)s:%(message)s',
        level=logging.DEBUG)
    Bug().test_bug()

/home/inso/.pyenv/versions/cutecoin/bin/python3 /home/inso/code/quamash/bug.py -d
DEBUG:selector_events:__init__:Using selector: EpollSelector
ERROR:base_events:default_exception_handler:Task exception was never retrieved
future: <Task finished coro=<errorlvl1() done, defined at /home/inso/code/quamash/bug.py:20> exception=TypeError() created at /home/inso/code/quamash/bug.py:26>
source_traceback: Object created at (most recent call last):
  File "/home/inso/code/quamash/bug.py", line 49, in <module>
    Bug().test_bug()
  File "/home/inso/code/quamash/bug.py", line 42, in test_bug
    self.lp.run_forever()
  File "/home/inso/.pyenv/versions/3.4.3/lib/python3.4/asyncio/base_events.py", line 276, in run_forever
    self._run_once()
  File "/home/inso/.pyenv/versions/3.4.3/lib/python3.4/asyncio/base_events.py", line 1164, in _run_once
    handle._run()
  File "/home/inso/.pyenv/versions/3.4.3/lib/python3.4/asyncio/events.py", line 120, in _run
    self._callback(*self._args)
  File "/home/inso/code/quamash/bug.py", line 26, in go
    asyncio.async(self.errorlvl1())
Traceback (most recent call last):
  File "/home/inso/.pyenv/versions/3.4.3/lib/python3.4/asyncio/tasks.py", line 238, in _step
    result = next(coro)
  File "/home/inso/code/quamash/bug.py", line 22, in errorlvl1
    yield from self.errorlvl2()
  File "/home/inso/code/quamash/bug.py", line 18, in errorlvl2
    yield from self.errorlvl3()
  File "/home/inso/.pyenv/versions/3.4.3/lib/python3.4/asyncio/coroutines.py", line 141, in coro
    res = func(*args, **kw)
  File "/home/inso/code/quamash/bug.py", line 14, in errorlvl3
    raise TypeError()
TypeError
INFO:base_events:_run_once:poll 999.396 ms took 1001.060 ms: timeout
INFO:base_events:_run_once:poll 999.761 ms took 1001.074 ms: timeout
INFO:base_events:_run_once:poll 999.799 ms took 1001.069 ms: timeout
DEBUG:base_events:close:Close <_UnixSelectorEventLoop running=False closed=False debug=True>

Process finished with exit code 0

Answer 3 · 2015-11-08T11:10:43.000Z

Here is a unit test :

import asyncio
from PyQt5.QtCore import QTimer
import logging
import quamash
import unittest
from quamash import QApplication


class Bug(unittest.TestCase):
    def setUp(self):
        self.excepted = False

    def except_hook(self, lp, ctx):
        self.excepted = True
        lp.default_exception_handler(ctx)

    @asyncio.coroutine
    def errorlvl3(self):
        raise TypeError()

    @asyncio.coroutine
    def errorlvl2(self):
        yield from self.errorlvl3()

    @asyncio.coroutine
    def errorlvl1(self):
        yield from self.errorlvl2()

    def go(self):
        asyncio.async(self.wait_and_close())
        asyncio.async(self.errorlvl1())

    @asyncio.coroutine
    def wait_and_close(self):
        for i in range(0, 3):
            yield from asyncio.sleep(1)
        self.lp.stop()

    def test_bug(self):
        self.qapplication = QApplication([])
        #self.lp = asyncio.get_event_loop()
        self.lp = quamash.QEventLoop(self.qapplication)
        self.lp.set_exception_handler(self.except_hook)
        self.lp.set_debug(True)
        asyncio.set_event_loop(self.lp)

        with self.lp:
            self.lp.call_soon(self.go)
            self.lp.run_forever()
        asyncio.set_event_loop(None)
        self.assertTrue(self.excepted)


if __name__ == '__main__':
    logging.basicConfig(format='%(levelname)s:%(module)s:%(funcName)s:%(message)s',
        level=logging.DEBUG)
    unittest.main()

It fails with quamash event loop but success with standard asyncio event loop.

Answer 4 · 2015-11-08T16:32:57.000Z

Sorry, false positive. Didn't have the good commits on my fork, this bug was fixed a long time ago. You can close it.