Stopping Twisted from swallowing exceptions

Question

Is there a way to stop Twisted reactor from automatically swallowing exceptions (eg. NameError)? I just want it to stop execution, and give me a stack trace in console?

There's even a FAQ question about it, but to say the least, it's not very helpful.

Currently, in every errback I do this:

def errback(value):
    import traceback
    trace = traceback.format_exc()
    # rest of the errback...

but that feels clunky, and there has to be a better way?

Update

In response to Jean-Paul's answer, I've tried running the following code (with Twisted 11.1 and 12.0):

from twisted.internet.endpoints import TCP4ClientEndpoint
from twisted.internet import protocol, reactor

class Broken(protocol.Protocol):
    def connectionMade(self):
        buggy_user_code()

e = TCP4ClientEndpoint(reactor, "127.0.0.1", 22) 
f = protocol.Factory()
f.protocol = Broken
e.connect(f)
reactor.run()

After running it, it just hangs there, so I have to Ctrl-C it:

> python2.7 tx-example.py
^CUnhandled error in Deferred:
Unhandled Error
Traceback (most recent call last):
Failure: twisted.internet.error.ConnectionRefusedError: Connection was refused by other side: 111: Connection refused.

Answer 1

What you could do as a workaround is register a log listener and stop the reactor whenever you see a critical error! This is a twisted(verb) approach but luckily all "Unhandled errors" are raised with LogLevel.critical.

from twisted.logger._levels import LogLevel

def analyze(event):
    if event.get("log_level") == LogLevel.critical:
        print "Stopping for: ", event
        reactor.stop()

globalLogPublisher.addObserver(analyze)

Answer 2

Let's explore "swallow" a little bit. What does it mean to "swallow" an exception?

Here's the most direct and, I think, faithful interpretation:

try:
    user_code()
except:
    pass

Here any exceptions from the call to user code are caught and then discarded with no action taken. If you look through Twisted, I don't think you'll find this pattern anywhere. If you do, it's a terrible mistake and a bug, and you would be helping out the project by filing a bug pointing it out.

What else might lead to "swallowing exceptions"? One possibility is that the exception is coming from application code that isn't supposed to be raising exceptions at all. This is typically dealt with in Twisted by logging the exception and then moving on, perhaps after disconnecting the application code from whatever event source it was connected to. Consider this buggy application:

from twisted.internet.endpoints import TCP4ClientEndpoint
from twisted.internet import protocol, reactor

class Broken(protocol.Protocol):
    def connectionMade(self):
        buggy_user_code()


e = TCP4ClientEndpoint(reactor, "127.0.0.1", 22)
f = protocol.Factory()
f.protocol = Broken
e.connect(f)
reactor.run()

When run (if you have a server running on localhost:22, so the connection succeeds and connectionMade actually gets called), the output produced is:

Unhandled Error
Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/twisted/python/log.py", line 84, in callWithLogger
    return callWithContext({"system": lp}, func, *args, **kw)
  File "/usr/lib/python2.7/dist-packages/twisted/python/log.py", line 69, in callWithContext
    return context.call({ILogContext: newCtx}, func, *args, **kw)
  File "/usr/lib/python2.7/dist-packages/twisted/python/context.py", line 118, in callWithContext
    return self.currentContext().callWithContext(ctx, func, *args, **kw)
  File "/usr/lib/python2.7/dist-packages/twisted/python/context.py", line 81, in callWithContext
    return func(*args,**kw)
--- <exception caught here> ---
  File "/usr/lib/python2.7/dist-packages/twisted/internet/selectreactor.py", line 146, in _doReadOrWrite
    why = getattr(selectable, method)()
  File "/usr/lib/python2.7/dist-packages/twisted/internet/tcp.py", line 674, in doConnect
    self._connectDone()
  File "/usr/lib/python2.7/dist-packages/twisted/internet/tcp.py", line 681, in _connectDone
    self.protocol.makeConnection(self)
  File "/usr/lib/python2.7/dist-packages/twisted/internet/protocol.py", line 461, in makeConnection
    self.connectionMade()
  File "/usr/lib/python2.7/dist-packages/twisted/internet/endpoints.py", line 64, in connectionMade
    self._wrappedProtocol.makeConnection(self.transport)
  File "/usr/lib/python2.7/dist-packages/twisted/internet/protocol.py", line 461, in makeConnection
    self.connectionMade()
  File "proderr.py", line 6, in connectionMade
    buggy_user_code()
exceptions.NameError: global name 'buggy_user_code' is not defined

This error clearly isn't swallowed. Even though the logging system hasn't been initialized in any particular way by this application, the logged error still shows up. If the logging system had been initialized in a way that caused errors to go elsewhere - say some log file, or /dev/null - then the error might not be as apparent. You would have to go out of your way to cause this to happen though, and presumably if you direct your logging system at /dev/null then you won't be surprised if you don't see any errors logged.

In general there is no way to change this behavior in Twisted. Each exception handler is implemented separately, at the call site where application code is invoked, and each one is implemented separately to do the same thing - log the error.

One more case worth inspecting is how exceptions interact with the Deferred class. Since you mentioned errbacks I'm guessing this is the case that's biting you.

A Deferred can have a success result or a failure result. When it has any result at all and more callbacks or errbacks, it will try to pass the result to either the next callback or errback. The result of the Deferred then becomes the result of the call to one of those functions. As soon as the Deferred has gone though all of its callbacks and errbacks, it holds on to its result in case more callbacks or errbacks are added to it.

If the Deferred ends up with a failure result and no more errbacks, then it just sits on that failure. If it gets garbage collected before an errback which handles that failure is added to it, then it will log the exception. This is why you should always have errbacks on your Deferreds, at least so that you can log unexpected exceptions in a timely manner (rather than being subject to the whims of the garbage collector).

If we revisit the previous example and consider the behavior when there is no server listening on localhost:22 (or change the example to connect to a different address, where no server is listening), then what we get is exactly a Deferred with a failure result and no errback to handle it.

e.connect(f)

This call returns a Deferred, but the calling code just discards it. Hence, it has no callbacks or errbacks. When it gets its failure result, there's no code to handle it. The error is only logged when the Deferred is garbage collected, which happens at an unpredictable time. Often, particularly for very simple examples, the garbage collection won't happen until you try to shut down the program (eg via Control-C). The result is something like this:

$ python someprog.py
... wait ...
... wait ...
... wait ...
<Control C>
Unhandled error in Deferred:
Unhandled Error
Traceback (most recent call last):
Failure: twisted.internet.error.ConnectionRefusedError: Connection was refused by other side: 111: Connection refused.

If you've accidentally written a large program and fallen into this trap somewhere, but you're not exactly sure where, then twisted.internet.defer.setDebugging might be helpful. If the example is changed to use it to enable Deferred debugging:

from twisted.internet.defer import setDebugging
setDebugging(True)

Then the output is somewhat more informative:

exarkun@top:/tmp$ python proderr.py
... wait ...
... wait ...
... wait ...
<Control C>
Unhandled error in Deferred:
(debug:  C: Deferred was created:
 C:  File "proderr.py", line 15, in <module>
 C:    e.connect(f)
 C:  File "/usr/lib/python2.7/dist-packages/twisted/internet/endpoints.py", line 240, in connect
 C:    wf = _WrappingFactory(protocolFactory, _canceller)
 C:  File "/usr/lib/python2.7/dist-packages/twisted/internet/endpoints.py", line 121, in __init__
 C:    self._onConnection = defer.Deferred(canceller=canceller)
 I: First Invoker was:
 I:  File "proderr.py", line 16, in <module>
 I:    reactor.run()
 I:  File "/usr/lib/python2.7/dist-packages/twisted/internet/base.py", line 1162, in run
 I:    self.mainLoop()
 I:  File "/usr/lib/python2.7/dist-packages/twisted/internet/base.py", line 1174, in mainLoop
 I:    self.doIteration(t)
 I:  File "/usr/lib/python2.7/dist-packages/twisted/internet/selectreactor.py", line 140, in doSelect
 I:    _logrun(selectable, _drdw, selectable, method, dict)
 I:  File "/usr/lib/python2.7/dist-packages/twisted/python/log.py", line 84, in callWithLogger
 I:    return callWithContext({"system": lp}, func, *args, **kw)
 I:  File "/usr/lib/python2.7/dist-packages/twisted/python/log.py", line 69, in callWithContext
 I:    return context.call({ILogContext: newCtx}, func, *args, **kw)
 I:  File "/usr/lib/python2.7/dist-packages/twisted/python/context.py", line 118, in callWithContext
 I:    return self.currentContext().callWithContext(ctx, func, *args, **kw)
 I:  File "/usr/lib/python2.7/dist-packages/twisted/python/context.py", line 81, in callWithContext
 I:    return func(*args,**kw)
 I:  File "/usr/lib/python2.7/dist-packages/twisted/internet/selectreactor.py", line 146, in _doReadOrWrite
 I:    why = getattr(selectable, method)()
 I:  File "/usr/lib/python2.7/dist-packages/twisted/internet/tcp.py", line 638, in doConnect
 I:    self.failIfNotConnected(error.getConnectError((err, strerror(err))))
 I:  File "/usr/lib/python2.7/dist-packages/twisted/internet/tcp.py", line 592, in failIfNotConnected
 I:    self.connector.connectionFailed(failure.Failure(err))
 I:  File "/usr/lib/python2.7/dist-packages/twisted/internet/base.py", line 1048, in connectionFailed
 I:    self.factory.clientConnectionFailed(self, reason)
 I:  File "/usr/lib/python2.7/dist-packages/twisted/internet/endpoints.py", line 144, in clientConnectionFailed
 I:    self._onConnection.errback(reason)
)
Unhandled Error
Traceback (most recent call last):
Failure: twisted.internet.error.ConnectionRefusedError: Connection was refused by other side: 111: Connection refused.

Notice near the top, where the e.connect(f) line is given as the origin of this Deferred - telling you a likely place where you should be adding an errback.

However, the code should have been written to add an errback to this Deferred in the first place, at least to log the error.

There are shorter (and more correct) ways to display exceptions than the one you've given, though. For example, consider:

d = e.connect(f)
def errback(reason):
    reason.printTraceback()
d.addErrback(errback)

Or, even more succinctly:

from twisted.python.log import err
d = e.connect(f)
d.addErrback(err, "Problem fetching the foo from the bar")

This error handling behavior is somewhat fundamental to the idea of Deferred and so also isn't very likely to change.

If you have a Deferred, errors from which really are fatal and must stop your application, then you can define a suitable errback and attach it to that Deferred:

d = e.connect(f)
def fatalError(reason):
    err(reason, "Absolutely needed the foo, could not get it")
    reactor.stop()

d.addErrback(fatalError)