I am writing a simple server program. They will be inevitable typos and other errors in fresh code, and usually the python interpreter will print a ValueError/AttributeError traceback and exit. The traceback can point to the exact position of the error. However under the twisted framework, these errors are not printed. Like in the following example:
from twisted.internet import reactor, protocol, task
#from twisted.internet.defer import setDebugging
#setDebugging(True)
class MyProtocol(protocol.Protocol):
def dataReceived(self, data):
try:
set_position(int(data))
except ValueError:
pass
def connectionMade(self):
self.factory.clientConnectionMade(self)
def connectionLost(self, reason):
self.factory.clientConnectionLost(self)
class MyFactory(protocol.Factory):
protocol = MyProtocol
def __init__(self):
self.clients = []
self.lc = task.LoopingCall(self.announce)
self.lc.start(1)
def announce(self):
pos = A_GREAT_TYPO_HERE()
for client in self.clients:
client.transport.write("Posiiton is {0}\n".format(pos).encode('utf-8'))
def clientConnectionMade(self, client):
self.clients.append(client)
def clientConnectionLost(self, client):
self.clients.remove(client)
def get_position():
return position[0]
def set_position(pos):
position[0] = pos
def main():
global position
position = [0]
myfactory = MyFactory()
reactor.listenTCP(5362, myfactory)
reactor.run()
if __name__ == "__main__":
main()
A_GREAT_TYPO_HERE() in MyFactory.announce is meant to be get_position(). But it is a typo.
And when the server is run, the terminal only outputs
Unhandled error in Deferred:
and nothing else. Even if I enable Defer debugging (uncomment the 2nd and 3rd line), the terminal outputs:
Unhandled error in Deferred:
(debug: C: Deferred was created:
C: File "nodes/test.py", line 48, in <module>
C: main()
C: File "nodes/test.py", line 43, in main
C: myfactory = MyFactory()
C: File "nodes/test.py", line 21, in __init__
C: self.lc.start(1)
C: File "/home/sgsdxzy/anaconda3/lib/python3.6/site-packages/twisted/internet/task.py", line 189, in start
C: deferred = self._deferred = defer.Deferred()
I: First Invoker was:
I: File "nodes/test.py", line 48, in <module>
I: main()
I: File "nodes/test.py", line 43, in main
I: myfactory = MyFactory()
I: File "nodes/test.py", line 21, in __init__
I: self.lc.start(1)
I: File "/home/sgsdxzy/anaconda3/lib/python3.6/site-packages/twisted/internet/task.py", line 194, in start
I: self()
I: File "/home/sgsdxzy/anaconda3/lib/python3.6/site-packages/twisted/internet/task.py", line 241, in __call__
I: d.addErrback(eb)
I: File "/home/sgsdxzy/anaconda3/lib/python3.6/site-packages/twisted/internet/defer.py", line 332, in addErrback
I: errbackKeywords=kw)
I: File "/home/sgsdxzy/anaconda3/lib/python3.6/site-packages/twisted/internet/defer.py", line 310, in addCallbacks
I: self._runCallbacks()
I: File "/home/sgsdxzy/anaconda3/lib/python3.6/site-packages/twisted/internet/defer.py", line 653, in _runCallbacks
I: current.result = callback(current.result, *args, **kw)
I: File "/home/sgsdxzy/anaconda3/lib/python3.6/site-packages/twisted/internet/task.py", line 236, in eb
I: d.errback(failure)
)
It points the error as close as to self.lc.start(1), but not A_GREAT_TYPO_HERE(). How can I debug my program so tracebacks can point to actual errors?
The "C" and "I" lines you're seeing are due to the fact that you've enabled Deferred debugging. The "C" lines give you the stack where the Deferred was created. The "I" lines give you the stack where the Deferred was "invoked" (its callback or errback method was called).
Neither of those is what you're looking for, it seems. If you want to see the stack associated with the Failure the Deferred has been fired with, the most straightforward solution is to make sure the Failure gets logged (and that you have a log observer so that you can actually see that log event).
You should add this to your main:
from sys import stdout
from twisted.logger import globalLogBeginner, textFileLogObserver
globalLogBeginner.beginLoggingTo([textFileLogObserver(stdout)])
This directs the log stream to stdout as text. It is most likely sufficient to get you the information you want. However, to be really safe, you also want to explicitly log failures instead of relying on the garbage collector to do it for you. So you also want to change:
self.lc.start(1)
To:
# Module scope
from twisted.logger import Logger
logger = Logger()
...
# in __init__
d = self.lc.start(1)
d.addErrback(lambda f: logger.failure("Loop thing problem", f))
(Also you may want to consider taking this code out of __init__ and putting it in startFactory instead; also consider not using a global reactor but instead pass it around as a parameter.)
This will give you output like:
2017-04-25T06:53:14-0400 [__main__.MyFactory#critical] Foo
Traceback (most recent call last):
File "debugging2.py", line 52, in main
myfactory = MyFactory()
File "debugging2.py", line 28, in __init__
d = self.lc.start(1)
File "/tmp/debugging/local/lib/python2.7/site-packages/twisted/internet/task.py", line 194, in start
self()
File "/tmp/debugging/local/lib/python2.7/site-packages/twisted/internet/task.py", line 239, in __call__
d = defer.maybeDeferred(self.f, *self.a, **self.kw)
--- <exception caught here> ---
File "/tmp/debugging/local/lib/python2.7/site-packages/twisted/internet/defer.py", line 150, in maybeDeferred
result = f(*args, **kw)
File "debugging2.py", line 32, in announce
pos = A_GREAT_TYPO_HERE()
exceptions.NameError: global name 'A_GREAT_TYPO_HERE' is not defined