Unhandled Exceptions

[meejah]

I ran across the following problem: if you have an unhandled exception somewhere in your Twisted stuff (e.g. a missing errback handler), pytest-twisted "hangs" and needs a ctrl-c to stop the test -- at which point you get a traceback into pytest-twisted internals.

Obviously, having a Deferred without an errback is a problem, but if pytest-twisted can do something nicer here, that'd be amazing. (FWIW, _result ends up being None in this case). I don't know enough about greenlets nor pytest to suggest something.

I do have a SSCCE that I detailed in this blog post: https://meejah.ca/pytest-twisted-blockon (and I hereby declare that's Unlicensed if you want any of it).

[schmir]

Thanks for your bug report. I don't use python anymore and therefore won't take care of the issue.

Maybe I can move the project to the new pytest organization.

[etataurov]

In your case deferred won't be called, and I there is needed some kind of timeout, like in https://github.com/eugeniy/pytest-tornado
So it's more like a error in the test, but which should be catched by testing tool.

Unhandled errors should be reported too, I think.
I don't know if it is possible, but maybe we need to look into twisted.trial internals

[meejah]

Its possibly enough just for pytest-twisted to add an errback handler to every deferred it sees...but I didnt try that yet.

[etataurov]

but this won't help with deferreds that haven't been called.
and callLater doesn't return deferred.

I am not sure if I'm getting it right, but in your case the best solution will be deferLater

from twisted.internet import reactor, task
import pytest
@pytest.fixture
def foo():
    def blammo():
        raise RuntimeError('foo')
    d = task.deferLater(reactor, 0.1, blammo)
    return pytest.blockon(d)
def test_meaning(foo):
    assert foo == 42

and for the pytest-twisted the best solution to have a timeout for deferreds (like trial and pytest-tornado do)

[meejah]

Well, my example test was meant to illustrate the problem I really encountered which is/was that an unhandled exception wasn't getting logged or printed anywhere.

Definitely that's a code problem (i.e. something missing an errback handler) but I filed a ticket in case there's something smart pytest-twisted could do for these cases.

So, yes, your fix above is correct -- but in a complex code-base there can easily be hard-to-find Deferreds that are missing appropriate handling (e.g. someone calls a Deferred-returning method as if it was synchronous).

[etataurov]

Yeah, I understand problem now.
The tricky part is to find unhandled exceptions,
and as far as I understood, the only thing you can get about unhandled errors is that they are logged

So there is a possible solution which adds log handler

diff --git a/pytest_twisted/plugin.py b/pytest_twisted/plugin.py
index c3f4c73..954ff6b 100644
--- a/pytest_twisted/plugin.py
+++ b/pytest_twisted/plugin.py
@@ -16,6 +16,16 @@ def blockon(d):
         if greenlet.getcurrent() is not current:
             current.switch(result)

+    def error_observer(eventDict):
+        if eventDict['isError'] and 'failure' in eventDict:
+            if not eventDict.get('why'):
+                failure = eventDict['failure']
+                if greenlet.getcurrent() is not current:
+                    current.throw(failure.type, failure.value, failure.tb)
+
+    from twisted.python import log
+    log.addObserver(error_observer)
+
     d.addCallbacks(cb, cb)
     if not result:
         _result = gr_twisted.switch()

I'm not really familiar with greenlet, so there might be some edge cases

[meejah]

Yeah, that looks plausible. I will try against my test-case.
I also am unfamiliar with greenlet, so...

[altendky]

In case someone wants a copy/paste fixture that asserts on any (noticed) unhandled deferred error, here's what I pieced together from reading here and chatting in #twisted. Noticed as in it banks on gc.collect() __del__'ing the problem deferred and probably various other caveats.

https://gist.github.com/altendky/b4929da7f414d8173a4d87fa7d2cd29b

import gc
import twisted.logger


class Observer:
    def __init__(self):
        self.failures = []

    def __call__(self, event_dict):
        is_error = event_dict.get('isError')
        s = 'Unhandled error in Deferred'.casefold()
        is_unhandled = s in event_dict.get('log_format', '').casefold()

        if is_error and is_unhandled:
            self.failures.append(event_dict)

    def assert_empty(self):
        assert [] == self.failures


@pytest.fixture
def assert_no_unhandled_errbacks():
    observer = Observer()
    twisted.logger.globalLogPublisher.addObserver(observer)

    yield

    gc.collect()
    twisted.logger.globalLogPublisher.removeObserver(observer)

    observer.assert_empty()

[altendky]

@vtitor, would the above thing be considered useful in a PR with test(s)?

@meejah, any chance you've been using it? I just noticed it in my code again and thought 'hey, I should share this...'. I can't say I've been exercising it much though so I was curious if you had any feedback about it 'working' or not in real use.

[altendky]

Given that it yields nothing, should assert_no_unhandled_errbacks() be a wrapping decorator instead of a fixture?

(entirely untested)

def assert_no_unhandled_errbacks(f):
    @functools.wraps(f)
    def wrapped(*args, **kwargs):
        observer = Observer()
        twisted.logger.globalLogPublisher.addObserver(observer)

        result = f(*args, **kwargs)

        gc.collect()
        twisted.logger.globalLogPublisher.removeObserver(observer)

        observer.assert_empty()

        return result

    return wrapped

[altendky]

Hmm, I guess a fixture let's you auto-use... not sure if that's a good approach or not.

[rschwiebert]

Hi: @altendky
Using that proposed fixture with the test involves nothing more than including it in the test_ function call as a fixture, correct?

The reason is that I tried to use it when I encountered the same problem (#61 ); however, it did not seem to change the problem. Thanks for your input.

[altendky]

@rschwiebert, that looks to be what I did with it once upon a time.

https://github.com/altendky/stlib/blob/b34796cbba959d9cb2cb843f3cc5fc815c7cb6c6/epyqlib/tests/utils/test_twisted.py#L97

def test_sequence_normal(action_logger, assert_no_unhandled_errbacks):

But, it's definitely a 'best effort' sort of situation, not a guaranteed catch. I'll look at #61 now.

[dc740]

Thanks for the fixture workaround. Using a decorator does not seem to work, but the fixture did. This bug is actually very problematic while developing the test cases, and it requires some serious debugging until you find this ticket and realize where the error is.