How to get traceback of uncaught exceptions ?

Question

How to get traceback of uncaught exceptions ?

Insoleet opened this issue 9 years ago · 16 comments

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 ?

Insoleet commented 9 years ago

Thanks !

Insoleet commented 9 years ago

Ahah :D

Answer 1 · 2015-06-30T16:28:56.000Z

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.

Answer 2 · 2015-06-30T18:55:45.000Z

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

Answer 3 · 2015-06-30T20:26:08.000Z

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.

Answer 4 · 2015-06-30T20:33:06.000Z

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

Answer 5 · 2015-06-30T22:03:18.000Z

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

Answer 6 · 2015-08-20T09:54:06.000Z

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 ?

Answer 7 · 2015-08-20T12:57:58.000Z

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()

Answer 8 · 2015-08-20T14:13:49.000Z

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 :

Answer 9 · 2015-08-20T22:13:14.000Z

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

Answer 10 · 2015-08-24T15:37:30.000Z

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

Answer 11 · 2015-08-24T16:08:40.000Z

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

Answer 12 · 2015-08-24T16:14:55.000Z

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

Answer 13 · 2015-09-14T20:13:30.000Z

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

Answer 14 · 2015-09-14T20:24:53.000Z

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