Twisted Postponed Do Not Display Unhandled Exception Without Errors

Question

I Read McKellar and Fettig Fundamentals of Network Virtualization, 2nd ed.

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

There is an example Unhandled Error in Deferred section that should raise Unhandled Error in Deferred - but I only get 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)

The minimum example from the actual text of the book

The actual example from the book is as follows:

 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 result is indicated in the book as:

callback3 throws an Exception , and since there is no errback registered to handle the Exception , the program terminates and reports the user Unhandled Error user. Result:

 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 got an error to display correctly on my machine.

To enable error logging without having an errback handler in the Deferred object, I need to add the following to my fragment:

 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 check that Twisted really causes an error, because it is designed - I just did not want to tell me for some reason. If anyone can clarify why this would be the default case for handling an exception without a specific errback, I would like to know.

I changed the name to reflect my new question.

Answer 1

I found this question after I came across a very similar question, having worked my way through Dave Perticola, an excellent Twisted Introduction specifically in Part 9: The second interlude, postponed , it has an example similar to the one you wrote:

 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" 

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 suspected a problem with version Twisted 16 from PyPy 5.0.1 on EL6 for me, but research has brought me here; and then when you turned on registration, as suggested in another answer, it did not affect what I consider the actual answer.

The key to my answer was in the textbook I worked with, with the statement:

the reason that “Finished” in the first place is because the message “Unhandled” was not printed until the garbage collected was set aside.

For some reason, for you and for me, by the time the garbage collector turns around, it no longer has the ability to output. If you want this to be 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 maybe this bit of information will let you get some sleep, even if we don’t know why this works for some, we know leading to the disappearance of expected error messages.

Answer 2

I think there is nothing wrong with our code.

I tried here:

 $ python deferred.py 

And the result was:

 Unhandled error in Deferred: Traceback (most recent call last): File "deferred.py", line 8, in <module> d.callback("oh no") File "/home/vagrant/.virtualenvs/asyncproxy/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 393, in callback self._startRunCallbacks(result) File "/home/vagrant/.virtualenvs/asyncproxy/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 501, in _startRunCallbacks self._runCallbacks() --- <exception caught here> --- File "/home/vagrant/.virtualenvs/asyncproxy/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 588, in _runCallbacks current.result = callback(current.result, *args, **kw) File "deferred.py", line 4, in raiseErr raise Exception(err) exceptions.Exception: oh no 

I am using Twisted 15.5.0 and Python 2.7.6.

PS: No need to initialize the log. He worked without him.

Answer 3

This code gives the same result on all of my Windows machines that I tested on and not on any of the Linux machines. I will conclude that this is a problem with something related to Windows, twisted or pywin32.