Twisted Deferred not displaying unhandled Exception without errback

Question

I'm reading through McKellar and Fettig's Twisted Network Programming Essentials, 2nd Ed.

I am running Twisted 15.5.0 on Python 2.7.10 on Windows 7.

In the section about Deferred there's an example that is supposed to raise an Unhandled Error in Deferred - but I am only getting complete silence from the console when I run the minimal example below:

Minimal example

from twisted.internet.defer import Deferred

def raiseErr(err):
    raise Exception(err)

d = Deferred()
d.addCallback(raiseErr)
d.callback("oh no")

$ python test.py (no output)

Minimal example from actual book text

The actual example from the book is along these lines:

from twisted.internet.defer import Deferred

def callback1(result):
    print "Callback 1 said:", result
    return result

def callback2(result):
    print "Callback 2 said:", result

def callback3(result):
    raise Exception("Callback 3")

def errback1(failure):
    print "Errback 1 had an an error on", failure
    return failure

d = Deferred()
d.addCallback(callback1)
d.addCallback(callback2)
d.addCallback(callback3)
d.callback("Test")

And the expected output is listed in the book as:

callback3 raises an Exception, and because there is no registered errback to handle the Exception, the program terminates and reports an Unhandled Error to the user. The result is:

Callback 1 said: Test
Callback 2 said: Test
Unhandled error in Deferred:
Unhandled Error
Traceback (most recent call last):
File "/tmp/test.py", line 33, in <module>
d.callback("Test")
<...>
File "/tmp/test.py", line 11, in callback3
raise Exception("Callback 3")
exceptions.Exception: Callback 3

Am I doing something wrong?

EDIT:

I have gotten the error to display correctly on my machine.

To enable the error to get logged without having an errback handler on the Deferred object, I needed to add the following to my snippet:

import sys
from twisted.python import log

log.startLogging(sys.stdout)

# rest of the code goes here

Now, when I run my minimal example from the first code snippet in my question, I get the following output:

2016-02-05 09:45:43-0600 [-] Log opened.
2016-02-05 09:45:43-0600 [-] Invalid format string or unformattable object in log message: '%(log_legacy)s', {'format': '%(log_legacy)s', 'log_legacy': <twisted.logger._stdlib.StringifiableFromEvent object at 0x038913F0>, 'time': 1454687143.778, 'message': (), 'log_time': 1454687143.778, 'log_namespace': 'twisted.internet.defer', 'log_level': <LogLevel=critical>, 'log_source': None, 'system': '-', 'isError': True, 'log_logger': <Logger 'twisted.internet.defer'>, 'log_format': 'Unhandled error in Deferred:'}
2016-02-05 09:45:43-0600 [-] Unhandled Error
        Traceback (most recent call last):
          File "testd.py", line 13, in <module>
            d.callback("oh no")
          File "C:\Swat\.virtualenvs\twisted\lib\site-packages\twisted\internet\defer.py", line 393, in callback
            self._startRunCallbacks(result)
          File "C:\Swat\.virtualenvs\twisted\lib\site-packages\twisted\internet\defer.py", line 501, in _startRunCallbacks
            self._runCallbacks()
        --- <exception caught here> ---
          File "C:\Swat\.virtualenvs\twisted\lib\site-packages\twisted\internet\defer.py", line 588, in _runCallbacks
            current.result = callback(current.result, *args, **kw)
          File "testd.py", line 9, in raiseErr
            raise Exception(err)
        exceptions.Exception: oh no

So, now I can verify that Twisted does indeed raise an error as it is meant to - it just didn't feel like telling me for some reason. If anyone can elaborate as to why that would be the default case for handling an exception without an errback defined, I'd love to know.

I've changed the title to reflect my new question.

Answer 1

I found this question after hitting a very similar issue whilst working my way through Dave Perticola's excellent Twisted Introduction specifically in Part 9: A Second Interlude, Deferred he has an example similar to the one you have posted:

from twisted.internet.defer import Deferred
def callback(res):
    raise Exception('oops')
d = Deferred()
d.addCallback(callback)
d.callback('Here is your result.')
print "Finished"

Just like you I did not get the output that was suggested:

Finished
Unhandled error in Deferred:
Traceback (most recent call last):
 ...
--- <exception caught here> ---
 ...
exceptions.Exception: oops

I initially assumed a versioning issue, Twisted 16 with PyPy 5.0.1 on EL6 for me, but research led me to here; and then when turning on logging, as suggested in another answer, had no effect on to what I think is the actual answer.

The clue to my answer was in the tutorial I was working from with a statement of:

the reason that “Finished” comes first is because the “Unhandled” message isn’t actually printed until the deferred is garbage collected.

For some reason, for you and I, by the time the garbage collector gets around to doing its thing it no longer has anywhere to output to. If you want to see this is true, here is my modified code:

import gc
from twisted.internet.defer import Deferred
def callback(res):
    raise Exception('oops call')
d = Deferred()
d.addCallback(callback)
d.callback('Here is your result.')
d = None
gc.collect()
print "Finished"

I guess the real answer is to deal with your Exceptions before the garbage collector gets to them, but perhaps this bit of info will let you sleep a bit easier even if we don't know why it works for some, we know what is causing our expected error messages to disappear.