How to get traceback of uncaught exceptions ? #34

Insoleet · 2015-06-30T06:26:23Z

Hi

I'd like to display tracebacks of uncaught exceptions.
At the moment I can't find a way to do it. Setting an exception_handler in the loop never calls it, enabling the debug by every possible way neither does.

Is there any limitations about this I dont know ?

harvimt · 2015-06-30T16:28:56Z

This may very well be a bug, exception_handler should be catching all
exceptions (this is pre 1.0 software), please provide a test case, so we
can repro.

On Mon, Jun 29, 2015 at 11:26 PM, Insoleet notifications@github.com wrote:

Hi

I'd like to display tracebacks of uncaught exceptions.
At the moment I can't find a way to do it. Setting an exception_handler in
the loop never calls it, enabling the debug by every possible way neither
does.

Is there any limitations about this I dont know ?

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

Insoleet · 2015-06-30T18:55:45Z

Here you go.

"""
Created on 1 févr. 2014

@author: inso
"""
import signal
import sys
import asyncio
import logging

from quamash import QEventLoop
from PyQt5.QtWidgets import QApplication, QWidget
from PyQt5.QtCore import QTimer, pyqtSlot

@asyncio.coroutine
def future_except():
    raise Exception("")

def exct_handler(loop, data):
    logging.debug("Handled exception {0}".format(data))

class testWidget(QWidget):
    def __init__(self):
        super().__init__()
        logging.debug("Timer except")
        QTimer.singleShot(1, self.test_except)
        logging.debug("Timer exit")
        QTimer.singleShot(1000, self.test_exit)

    @pyqtSlot()
    def test_except(self):
        logging.debug("Async except")
        asyncio.async(future_except())

    @pyqtSlot()
    def test_exit(self):
        logging.debug("Exit app")
        QApplication.exit(0)

if __name__ == '__main__':
    # activate ctrl-c interrupt
    signal.signal(signal.SIGINT, signal.SIG_DFL)

    logging.basicConfig(format='%(levelname)s:%(module)s:%(message)s',
        level=logging.DEBUG)
    app = QApplication(sys.argv)
    loop = QEventLoop(app)
    loop.set_debug(True)
    loop.set_exception_handler(exct_handler)
    asyncio.set_event_loop(loop)

    with loop:
        widget = testWidget()
        loop.run_forever()
    sys.exit()

Outputs :

/usr/bin/python3.4 /home/inso/code/ucoin/cutecoin/src/cutecoin/bug.py
DEBUG:selector_events:Using selector: _Selector
DEBUG:__init__:Adding reader callback for file descriptor 11
DEBUG:bug:Timer except
DEBUG:bug:Timer exit
DEBUG:__init__:Starting Qt event loop
DEBUG:bug:Async except
DEBUG:__init__:Registering callback <bound method Task._step of <Task pending coro=<coro() running at /usr/lib/python3.4/asyncio/coroutines.py:139> created at /usr/lib/python3.4/asyncio/base_events.py:212>> to be invoked with arguments () after 0 second(s)
DEBUG:__init__:Adding callback <Handle Task._step() created at /usr/lib/python3.4/site-packages/quamash/__init__.py:345> with delay 0
DEBUG:__init__:Callback timer fired, calling <Handle Task._step() created at /usr/lib/python3.4/site-packages/quamash/__init__.py:345>
DEBUG:bug:Exit app
DEBUG:__init__:Qt event loop ended with result 0
DEBUG:__init__:Already stopped
DEBUG:__init__:Closing event loop...
DEBUG:__init__:Removing reader callback for file descriptor 11
DEBUG:base_events:Close <QEventLoop running=False closed=False debug=True>
DEBUG:_unix:Closing

harvimt · 2015-06-30T20:26:08Z

I have created a branch for this issue: ~~https://github.com/harvimt/quamash/tree/gh37~~
and have confirmed that this is a bug (with a much simpler test case)

CI should come back with 1 test failed.

harvimt · 2015-06-30T20:33:06Z

this is #34 not "37" https://github.com/harvimt/quamash/tree/gh34

harvimt · 2015-06-30T22:03:18Z

for some reason the future isn't being deleted,
With a standard loop there are 2 references, one from the local frame and one from pdb.
But with quamash there is a third reference from asyncio.Task._step which is the same as fut._step

Insoleet · 2015-08-20T09:54:06Z

I'm trying to take a look into it because I really need this bug to be fixed...
Why do you have a third reference with quamash ?

Insoleet · 2015-08-20T12:57:58Z

So from my testings, there are exactly the same count of references using gc.get_referrers when running in debug mode (with pycharm debug mode).

With quamash enabled :

<cell at 0x7fef4c01e108: Task object at 0x7fef441140b8>
{'exc': None, '__class__': <class 'asyncio.tasks.Task'>, 'self': <Task finished coro=<coro() done, defined at /usr/lib/python3.4/asyncio/coroutines.py:139> exception=RuntimeError('Test error',) created at /home/inso/code/quamash/bug.py:41>, 'value': None}
<bound method Task._step of <Task finished coro=<coro() done, defined at /usr/lib/python3.4/asyncio/coroutines.py:139> exception=RuntimeError('Test error',) created at /home/inso/code/quamash/bug.py:41>>
{'i': 1, 'loop': <QEventLoop running=True closed=False debug=True>, 'task1': <Task finished coro=<coro() done, defined at /usr/lib/python3.4/asyncio/coroutines.py:139> exception=RuntimeError('Test error',) created at /home/inso/code/quamash/bug.py:41>, 'r': {...}, 'refs': [<cell at 0x7fef4c01e108: Task object at 0x7fef441140b8>, {'exc': None, '__class__': <class 'asyncio.tasks.Task'>, 'self': <Task finished coro=<coro() done, defined at /usr/lib/python3.4/asyncio/coroutines.py:139> exception=RuntimeError('Test error',) created at /home/inso/code/quamash/bug.py:41>, 'value': None}, <bound method Task._step of <Task finished coro=<coro() done, defined at /usr/lib/python3.4/asyncio/coroutines.py:139> exception=RuntimeError('Test error',) created at /home/inso/code/quamash/bug.py:41>>, {...}]}

With asyncio standard loop :

<cell at 0x7f6f7a6c5108: Task object at 0x7f6f7cadc198>
{'self': <Task finished coro=<coro() done, defined at /usr/lib/python3.4/asyncio/coroutines.py:139> exception=RuntimeError('Test error',) created at /home/inso/code/quamash/bug.py:41>, 'exc': None, 'value': None, '__class__': <class 'asyncio.tasks.Task'>}
{'r': {...}, 'task1': <Task finished coro=<coro() done, defined at /usr/lib/python3.4/asyncio/coroutines.py:139> exception=RuntimeError('Test error',) created at /home/inso/code/quamash/bug.py:41>, 'i': 1, 'loop': <_UnixSelectorEventLoop running=True closed=False debug=True>, 'refs': [<cell at 0x7f6f7a6c5108: Task object at 0x7f6f7cadc198>, {'self': <Task finished coro=<coro() done, defined at /usr/lib/python3.4/asyncio/coroutines.py:139> exception=RuntimeError('Test error',) created at /home/inso/code/quamash/bug.py:41>, 'exc': None, 'value': None, '__class__': <class 'asyncio.tasks.Task'>}, {...}, <bound method Task._step of <Task finished coro=<coro() done, defined at /usr/lib/python3.4/asyncio/coroutines.py:139> exception=RuntimeError('Test error',) created at /home/inso/code/quamash/bug.py:41>>]}
<bound method Task._step of <Task finished coro=<coro() done, defined at /usr/lib/python3.4/asyncio/coroutines.py:139> exception=RuntimeError('Test error',) created at /home/inso/code/quamash/bug.py:41>>

Without debug mode, here is what I get :

With quamash enabled, two referers :

<bound method Task._step of <Task finished coro=<coro() done, defined at /usr/lib/python3.4/asyncio/coroutines.py:139> exception=RuntimeError('Test error',) created at /home/inso/code/quamash/bug.py:42>>
<cell at 0x7f3b538463a8: Task object at 0x7f3b49044320>

With standard asyncio loop, only one referer :

<cell at 0x7fc2cd70f3a8: Task object at 0x7fc2cd470b70>

I'm using the following code to analyse the problem (your test method with pauses and logs to analyse what is happening) :

import asyncio
import sys
import gc
import quamash

def task_test():
    task1 = None
    @asyncio.coroutine
    def future_except():
        print("coro run")
        raise RuntimeError("Test error")

    @asyncio.coroutine
    def sleep_exit():
        nonlocal task1
        print("Start sleep")
        for i in range(0, 2):
            refs = gc.get_referrers(task1)
            print("Referers : {0}".format(len(refs)))
            for r in refs:
                print(r)
            yield from asyncio.sleep(1)
        print("Removing ref")
        task1 = None
        for i in range(0, 4):
            yield from asyncio.sleep(1)
        print("End sleep")
        loop.stop()

    def exct_handler(loop, data):
        print("except handler")
        print(data["message"])
        print(data["exception"])

    #loop = asyncio.new_event_loop()
    loop = quamash.QEventLoop(quamash.QApplication(sys.argv))
    asyncio.set_event_loop(loop)

    loop.set_debug(True)

    loop.set_exception_handler(exct_handler)
    task1 = asyncio.async(future_except())
    asyncio.async(sleep_exit())
    loop.run_forever()

task_test()

Insoleet · 2015-08-20T14:13:49Z

Using https://pypi.python.org/pypi/objgraph I was able to get this graph (with a max_depth of 6) :

My guess, seeing this graph, is that we can see on the right a QTimer object. As it is not deleted, it prevents the reference on Task._step to be deleted. Thus, the reference on the Task is never deleted.

I removed the self._app reference from the QTimer instanciation, and by going deeper I was able to discover a cyclic reference with the task and the QTimer, because of the exception :

Fix issue #34

harvimt · 2015-08-20T22:13:14Z

I'll have to remember this tool (obigraph) If I need to debug gc issues in the future.

Insoleet · 2015-08-24T15:37:30Z

Do you plan releasing a new quamash version soon ? :)

harvimt · 2015-08-24T16:08:40Z

yeah. I've had relatives in town and have been doing stuff.

On Mon, Aug 24, 2015 at 8:37 AM, Insoleet notifications@github.com wrote:

Do you plan releasing a new quamash version soon ? :)

—
Reply to this email directly or view it on GitHub
#34 (comment).

harvimt · 2015-08-24T16:14:55Z

Release pushed.

On Mon, Aug 24, 2015 at 9:08 AM, Mark Harviston infinull@gmail.com wrote:

yeah. I've had relatives in town and have been doing stuff.

On Mon, Aug 24, 2015 at 8:37 AM, Insoleet notifications@github.com
wrote:

Do you plan releasing a new quamash version soon ? :)

—
Reply to this email directly or view it on GitHub
#34 (comment).

Insoleet · 2015-08-27T07:53:02Z

Thanks !

Insoleet · 2015-09-14T20:13:30Z

Just wondering, why don't you merge gh34 with branch master ?

harvimt · 2015-09-14T20:24:53Z

I did... I just forgot to git push

On Mon, Sep 14, 2015 at 1:13 PM, Insoleet notifications@github.com wrote:

Just wondering, why don't you merge gh34 with branch master ?

—
Reply to this email directly or view it on GitHub
#34 (comment).

Insoleet · 2015-09-14T20:49:29Z

Ahah :D

harvimt self-assigned this Jun 30, 2015

harvimt added the bug label Jun 30, 2015

harvimt pushed a commit that referenced this issue Jun 30, 2015

mention #34 so it gets linked

02a96e3

harvimt pushed a commit that referenced this issue Jun 30, 2015

test for #34 reproduced

72c9b7f

harvimt mentioned this issue Jul 23, 2015

Windows Errors #38

Open

harvimt pushed a commit that referenced this issue Jul 23, 2015

test for #34 reproduced

dbb189d

Insoleet mentioned this issue Jul 24, 2015

Exception when leaving the app in debug mode #37

Closed

harvimt added a commit that referenced this issue Aug 20, 2015

Merge pull request #40 from Insoleet/gh34

ff9c371

Fix issue #34

harvimt closed this as completed Aug 29, 2015

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

How to get traceback of uncaught exceptions ? #34

How to get traceback of uncaught exceptions ? #34

Insoleet commented Jun 30, 2015

harvimt commented Jun 30, 2015

Insoleet commented Jun 30, 2015

harvimt commented Jun 30, 2015

harvimt commented Jun 30, 2015

harvimt commented Jun 30, 2015

Insoleet commented Aug 20, 2015

Insoleet commented Aug 20, 2015

Insoleet commented Aug 20, 2015

harvimt commented Aug 20, 2015

Insoleet commented Aug 24, 2015

harvimt commented Aug 24, 2015

harvimt commented Aug 24, 2015

Insoleet commented Aug 27, 2015

Insoleet commented Sep 14, 2015

harvimt commented Sep 14, 2015

Insoleet commented Sep 14, 2015

How to get traceback of uncaught exceptions ? #34

How to get traceback of uncaught exceptions ? #34

Comments

Insoleet commented Jun 30, 2015

harvimt commented Jun 30, 2015

Insoleet commented Jun 30, 2015

harvimt commented Jun 30, 2015

harvimt commented Jun 30, 2015

harvimt commented Jun 30, 2015

Insoleet commented Aug 20, 2015

Insoleet commented Aug 20, 2015

Insoleet commented Aug 20, 2015

harvimt commented Aug 20, 2015

Insoleet commented Aug 24, 2015

harvimt commented Aug 24, 2015

harvimt commented Aug 24, 2015

Insoleet commented Aug 27, 2015

Insoleet commented Sep 14, 2015

harvimt commented Sep 14, 2015

Insoleet commented Sep 14, 2015