[Twisted-Python] How to find out if exceptions are being raised in your errBack?
I've been hunting down a problem that I've finally found the cause of and I'd like to know what's the Twisted way to catch this "error within the code handling the error" type of error. Basically, in one branch of the errBack, there was a typo. A simple typo that caused an unhandled NameError exception, but only once in a few thousand runs. The exception got caught and "displayed" by Twisted, but it wasn't going anyplace anyone was looking (buried under zillions of lines of logging) and the app continues on as if nothing went wrong. I've put up a simple app that demonstrates the issue: http://pastebin.com/m59217f60 If you put in a 404 error URL, let it run through, you'll see the 404 error printed out, the exception will occur in the background, and the program just keeps on going. If you then hit Ctrl-C, you can see the traceback showing that Twisted caught the NameError . What is the best way to handle programming errors like this in deferreds so they don't slip by, unnoticed? Thanks, S (~/twisted_err)# ./errs_away.py URL: http://www.yahoo.com line = http://www.yahoo.com Got data, len == 9490 URL: http://thereisnodomainnamedthis.com line = http://thereisnodomainnamedthis.com Error: DNS lookup failed: address 'thereisnodomainnamedthis.com' not found: [Errno 8] nodename nor servname provided, or not known. URL: http://www.yahoo.com/non-existent-page line = http://www.yahoo.com/non-existent-page Error: 400 Bad Request <====== This triggers the code with the bad variable URL: ^C <============= manually stop the program ============= Then, you get to see the traceback ================== Unhandled error in Deferred: Traceback (most recent call last): File "/System/Library/Frameworks/Python.framework/Versions/2.6/ Extras/lib/python/twisted/web/client.py", line 143, in handleResponse self.status, self.message, response))) File "/System/Library/Frameworks/Python.framework/Versions/2.6/ Extras/lib/python/twisted/web/client.py", line 309, in noPage self.deferred.errback(reason) File "/System/Library/Frameworks/Python.framework/Versions/2.6/ Extras/lib/python/twisted/internet/defer.py", line 269, in errback self._startRunCallbacks(fail) File "/System/Library/Frameworks/Python.framework/Versions/2.6/ Extras/lib/python/twisted/internet/defer.py", line 312, in _startRunCallbacks self._runCallbacks() --- <exception caught here> --- File "/System/Library/Frameworks/Python.framework/Versions/2.6/ Extras/lib/python/twisted/internet/defer.py", line 328, in _runCallbacks self.result = callback(self.result, *args, **kw) File "./errs_away.py", line 15, in printError print oops # variable's not defined... exceptions.NameError: global name 'oops' is not defined Thanks, S
On Tue, Oct 13, 2009 at 8:02 PM, Steve Steiner (listsin) < listsin@integrateddevcorp.com> wrote:
I've been hunting down a problem that I've finally found the cause of and I'd like to know what's the Twisted way to catch this "error within the code handling the error" type of error.
The right way to catch this is to write tests for your code and run them before deploying it to production :). Trial will helpfully fail tests which cause exceptions to be logged, so you don't need to write any special extra test to make sure that nothing is blowing up; just test your error-handling case, and if it blows up you will see it.
Basically, in one branch of the errBack, there was a typo. A simple typo that caused an unhandled NameError exception, but only once in a few thousand runs.
If it's a NameError, you also could have used Pyflakes to catch it :).
The exception got caught and "displayed" by Twisted, but it wasn't going anyplace anyone was looking (buried under zillions of lines of logging) and the app continues on as if nothing went wrong.
The real lesson here is that you should be paying attention to logged tracebacks. There are many ways to do this. Many operations teams running Twisted servers will trawl the logs with regular expressions. Not my preferred way of doing it, but I'm not really an ops person :). If you want to handle logged exceptions specially, for example to put them in a separate file, or to e-mail them to somebody, consider writing a log observer that checks for the isError key and does something special there. You can find out more about writing log observers here: < http://twistedmatrix.com/projects/core/documentation/howto/logging.html>.
What is the best way to handle programming errors like this in deferreds so they don't slip by, unnoticed?
I'm answering a question you didn't ask, about logged errors, because I think it's the one you meant to ask. The answer to the question you are actually asking here, i.e. "how do I handle errors in an errback", is quite simple: add another errback. This is sort of like asking how to handle exceptions in an 'except:' block in Python. For example, if you want to catch errors from this code: try: foo() except: oops() you could modify it to look like this: try: foo() except: try: oops() except: handleOopsOops() which is what adding another errback is like. But, as I said: I don't think this is what you want, since it will only let you handle un-handled errors in Deferreds (not unhandled errors in, for example, protocols) and you will have to attach your error-handling callbacks everywhere (not to mention trying to guess a sane return value for the error-handler-error-handler.
Glyph Lefkowitz wrote: [...]
I'm answering a question you didn't ask, about logged errors, because I think it's the one you meant to ask. The answer to the question you are actually asking here, i.e. "how do I handle errors in an errback", is quite simple: add another errback. This is sort of like asking how to handle exceptions in an 'except:' block in Python. For example, if you [...]
To think about it another way, what happens when an unhandled exception occurs in a thread? The thread dies, and Python simply throws the traceback at stderr. There's not much else it can reasonably do. If you want to catch (or suppress) that error, you add (another) try/except at the outermost layer of the call stack. Possibly Twisted could provide some sort of last-ditch error reporting hook, like sys.excepthook in core Python, but I'm not sure it would offer much advantage over writing a log observer that looks for events where isError is set. -Andrew.
On Oct 14, 2009, at 3:22 AM, Andrew Bennetts wrote:
Glyph Lefkowitz wrote: [...]
I'm answering a question you didn't ask, about logged errors, because I think it's the one you meant to ask. The answer to the question you are actually asking here, i.e. "how do I handle errors in an errback", is quite simple: add another errback. This is sort of like asking how to handle exceptions in an 'except:' block in Python. For example, if you [...]
To think about it another way, what happens when an unhandled exception occurs in a thread? The thread dies, and Python simply throws the traceback at stderr. There's not much else it can reasonably do. If you want to catch (or suppress) that error, you add (another) try/except at the outermost layer of the call stack.
Yah, I started thinking about how far out I'd have to start the try/ except and started to get a headache when I thought about how much code it would have to encompass or, with an alternate approach, how many zillions of little extra blocks I'd have to insert everywhere.
Possibly Twisted could provide some sort of last-ditch error reporting hook, like sys.excepthook in core Python, but I'm not sure it would offer much advantage over writing a log observer that looks for events where isError is set.
I'm going to use the log observer option with tail -f in a separate console window on a linux console that's just sitting there doing nothing anyway. That way, if it shows up on that terminal, something bad is happening. Thanks! S
On Oct 14, 2009, at 2:07 AM, Glyph Lefkowitz wrote:
On Tue, Oct 13, 2009 at 8:02 PM, Steve Steiner (listsin) <listsin@integrateddevcorp.com
wrote: I've been hunting down a problem that I've finally found the cause of and I'd like to know what's the Twisted way to catch this "error within the code handling the error" type of error.
The right way to catch this is to write tests for your code and run them before deploying it to production :).
Yes, we're working on it but it's a large code base and we started with exactly zero tests. While that leaves infinite room for improvement, it's a little overwhelming. Oh well, at least we know where to concentrate first ;-0.
Trial will helpfully fail tests which cause exceptions to be logged, so you don't need to write any special extra test to make sure that nothing is blowing up; just test your error-handling case, and if it blows up you will see it.
We've just been using nose; is that something Trial handles specially for Twisted?
Basically, in one branch of the errBack, there was a typo. A simple typo that caused an unhandled NameError exception, but only once in a few thousand runs.
If it's a NameError, you also could have used Pyflakes to catch it :).
That's in our list of 'things to put in the commit pre-hook' as well. I'm not sure pyflakes would have caught this one, though because it's a legitimate instance variable, it's just not set to something usable before this particular error condition comes up.
The exception got caught and "displayed" by Twisted, but it wasn't going anyplace anyone was looking (buried under zillions of lines of logging) and the app continues on as if nothing went wrong.
The real lesson here is that you should be paying attention to logged tracebacks.
There are many ways to do this. Many operations teams running Twisted servers will trawl the logs with regular expressions. Not my preferred way of doing it, but I'm not really an ops person :).
I'm not much on the ops end either but I guess I'm learning...
If you want to handle logged exceptions specially, for example to put them in a separate file, or to e-mail them to somebody, consider writing a log observer that checks for the isError key and does something special there. You can find out more about writing log observers here: <http://twistedmatrix.com/projects/core/documentation/howto/logging.html
.
This is an area of Twisted I haven't explored at all since the code's all using the standard Python logging. That's the thing about Twisted; sometimes it's hard to know whether the stuff that has been built into standard Python since Twisted 'rolled their own' is a superset, a subset, or a completely different beast. Logging is a good case in point. Since we're using Python's logging everywhere, I wasn't even sure whether there would be an advantage to learning Twisted's similar system. Twisted's trial is another example; we've just been using nose. Seems like there's always some little extra that makes the Twisted stuff worth knowing.
What is the best way to handle programming errors like this in deferreds so they don't slip by, unnoticed?
I'm answering a question you didn't ask, about logged errors, because I think it's the one you meant to ask. The answer to the question you are actually asking here, i.e. "how do I handle errors in an errback", is quite simple: add another errback. This is sort of like asking how to handle exceptions in an 'except:' block in Python. For example, if you want to catch errors from this code:
try: foo() except: oops()
you could modify it to look like this:
try: foo() except: try: oops() except: handleOopsOops()
which is what adding another errback is like. But, as I said: I don't think this is what you want, since it will only let you handle un-handled errors in Deferreds (not unhandled errors in, for example, protocols) and you will have to attach your error-handling callbacks everywhere (not to mention trying to guess a sane return value for the error-handler-error-handler.
Right, I started thinking down that infinitely nested slippery slope and figured there must be a better way. I think the logging question you answered that I didn't ask was the one I meant ;-). Thanks again for another enlightening answer. S
On Wed, Oct 14, 2009 at 07:43:41AM -0400, Steve Steiner (listsin) wrote:
That's the thing about Twisted; sometimes it's hard to know whether the stuff that has been built into standard Python since Twisted 'rolled their own' is a superset, a subset, or a completely different beast. Logging is a good case in point. Since we're using Python's logging everywhere, I wasn't even sure whether there would be an advantage to learning Twisted's similar system. Twisted's trial is another example; we've just been using nose. Seems like there's always some little extra that makes the Twisted stuff worth knowing.
Most of the duplicate stuff in Twisted has the excuse of being written before any alternatives were available, and usually having one or two extra little integration features that current alternatives don't provide. A year or two ago I was planning a new project using Twisted, and (as a reaction to the masses of horrible, legacy code at my employer) had decreed that the project would use the Python stdlib wherever possible, including logging and testing, and well-integrated third-party tools where necessary. First on the chopping block was the use of standard Python unit-tests and nose. At the time, I don't believe it was possible to run TestCases inheriting from twisted.trial.unittest.TestCase in anything besides Trial - and you need to use trial's TestCase class if you want to do anything with Deferreds, so nose and the standard unittest.TestCase had to go. Once I was using Trial, which automatically sets up Twisted's logging system to log to a handy file for debugging purposes, I had to decide what to do about logging - try to reroute Twisted's logging into the Python logging system (which would mean doing something complicated for tests), or just give up and use Twisted's logging everywhere. I opted for the latter route as the path of least resistance (and because it would be easier to set up with twistd later). I believe nose does for Python logging what Trial does for Twisted logging these days, and if nose can run Trial's TestCase subclasses, you might just as well stick with what you're already using. There are integration advantages to using all the Twisted goodies together, but it's not nearly the same amazing quantum leap in understanding and capability that Twisted's core provides.
On Oct 14, 2009, at 8:26 AM, Tim Allen wrote:
On Wed, Oct 14, 2009 at 07:43:41AM -0400, Steve Steiner (listsin) wrote:
That's the thing about Twisted; sometimes it's hard to know whether the stuff that has been built into standard Python since Twisted 'rolled their own' is a superset, a subset, or a completely different beast. Logging is a good case in point. Since we're using Python's logging everywhere, I wasn't even sure whether there would be an advantage to learning Twisted's similar system. Twisted's trial is another example; we've just been using nose. Seems like there's always some little extra that makes the Twisted stuff worth knowing.
Most of the duplicate stuff in Twisted has the excuse of being written before any alternatives were available, and usually having one or two extra little integration features that current alternatives don't provide.
Yes, that extra little integration feature sometimes makes a huge difference. But, as you said, being as much of Twisted's stuff predates the 'equivalent' stdlib stuff, it's hard to know where the leverage is going to be. For example, Python's standard logging has the advantage of being able to generate many different types of logging outputs (e.g. logging.handlers.SMTPHandler) whereas Twisted's is better integrated with Twisted but is missing many of those types of things. Trial and deferreds vs. nose and its integration with e.g. coverage... It's hard to know when to use which and, as you said, we want to use standard library stuff wherever possible.
Once I was using Trial, which automatically sets up Twisted's logging system to log to a handy file for debugging purposes, I had to decide what to do about logging - try to reroute Twisted's logging into the Python logging system (which would mean doing something complicated for tests), or just give up and use Twisted's logging everywhere. I opted for the latter route as the path of least resistance (and because it would be easier to set up with twistd later).
I'm working out a blended method having a PythonLoggingObserver that relay's Twisted's log messages to Python standard logging, as per Glyph's suggestion. That way we don't have to mangle all of our working logging code, bug special notifications we can reroute to a special "Twisted Messages" file that we know to keep an eye on.
I believe nose does for Python logging what Trial does for Twisted logging these days, and if nose can run Trial's TestCase subclasses, you might just as well stick with what you're already using. There are integration advantages to using all the Twisted goodies together, but it's not nearly the same amazing quantum leap in understanding and capability that Twisted's core provides.
Again, we'll probably end up with a blended approach since we use nose for coverage and profiling integration as well. We are having fun now, right? S
On Wed, Oct 14, 2009 at 4:43 AM, Steve Steiner (listsin) < listsin@integrateddevcorp.com> wrote:
On Oct 14, 2009, at 2:07 AM, Glyph Lefkowitz wrote:
Yes, we're working on it but it's a large code base and we started with exactly zero tests. While that leaves infinite room for improvement, it's a little overwhelming. Oh well, at least we know where to concentrate first ;-0.
I realize it's a challenge, but, well, "Doctor, doctor, it hurts when I don't do this!". My immediate reaction is "go ahead and do it, then" :-).
Trial will helpfully fail tests which cause exceptions to be logged, so you don't need to write any special extra test to make sure that nothing is blowing up; just test your error-handling case, and if it blows up you will see it.
We've just been using nose; is that something Trial handles specially for Twisted?
Yes.
If you want to handle logged exceptions specially, for example to put them in a separate file, or to e-mail them to somebody, consider writing a log observer that checks for the isError key and does something special there. You can find out more about writing log observers here: < http://twistedmatrix.com/projects/core/documentation/howto/logging.html>.
This is an area of Twisted I haven't explored at all since the code's all using the standard Python logging. That's the thing about Twisted; sometimes it's hard to know whether the stuff that has been built into standard Python since Twisted 'rolled their own' is a superset, a subset, or a completely different beast. Logging is a good case in point. Since we're using Python's logging everywhere, I wasn't even sure whether there would be an advantage to learning Twisted's similar system. Twisted's trial is another example; we've just been using nose. Seems like there's always some little extra that makes the Twisted stuff worth knowing.
Another option here would be to set up a PythonLoggingObserver that relay's Twisted's log messages to Python standard logging, then setup a standard log handler (another poster suggests nose already does this) to fail the test when appropriate. I'm fairly sure that the information you need is being properly relayed to the relevant parties, but if I'm wrong, it's a bug and probably a pretty easy one to fix :).
participants (4)
-
Andrew Bennetts -
Glyph Lefkowitz -
Steve Steiner (listsin) -
Tim Allen