[Twisted-Python] intermittent test failures: fixed
![](https://secure.gravatar.com/avatar/0f15c04b6acde258bd27586371ae94b1.jpg?s=120&d=mm&r=g)
Hi all.. I spent some time yesterday looking into the intermittent test failures in test_tcp and test_threadpool. These failures only occurred when the full test suite was run (./admin/runtests -v -t), not when test_tcp was run by itself (./admin/runtests -v -t twisted.test.test_tcp). I finally figured out what was happening and wanted to share my findings to help others track down future problems. Early in the test sequence, test_woven did some kind of session/login thing. One particular test case was verifying an Unauthorized response, which involved creating a Deferred that was then .errback()'ed. However, there was no errback handler added to the Deferred. Inside that test, web.guard started a 60 second session timeout, with a callLater() function that referenced that Deferred (or an object holding it). test_woven finishes. The timer is still running. The Deferred (with pending error) is still alive, since the callLater timer prevents it from being garbage-collected. Other test cases run. [60 seconds pass] Some other innocent test case is running, depending upon the speed of the machine. On my CPU, it was usually test_tcp. During some call to reactor.iterate, the web.guard session timer expires, the callback does whatever callbacky things it likes, and an object gets freed. That leads to the Deferred being freed. The Deferred has a pending error but no .errback handler. Deferred.__del__ does log.msg() with the "Unhandled error in Deferred" message, and log.err() with the "Unauthorized" Failure object that wanted an .errback but had none. log.err() puts the message in the error queue. log.msg() goes into the test.log file, but not into the error queue. test_tcp finishes without problem, but unittest.py looks in the error queue and sees the Failure. It adds the traceback of the Failure (which is the call trace leading up to the creation of the Unauthorized exception, which is in web.guard, and doesn't mention test_woven at all) to the error results of the test. test_tcp is flunked, and as explanation unittest.py emits the error results (the Unauthorized exception and the web.guard stack trace) The basic issue is timers that "leak" over from one unit test to another. Unit tests are supposed to be isolated from each other, but if one test changes the state of the reactor (by adding timers or establishing listenTCP ports) without cleaning it up when it finishes, that state can affect other tests. This is not always obvious, as several modules create timers internally. This is very convenient, and works fine in normal applications. It is only in the unit tests where it causes a problem. I've added IReactorTime.getDelayedCalls() as a reactor-portable way to retrieve the list of pending callLater() timers, and changed unittest.py to cancel all pending timers between test cases. This succeeded in moving the failure back to the test that caused it. I've also added a warning message (which goes into test.log) that indicates when a test leaves timers running after it completes. There are a handful that do; most are benign but should probably be cleaned up. This warning message may turn into a test failure someday. Some tools I used to track this down, in case they prove useful to others: added code to Deferred and DelayedCall to record the stack track when they are created, then print them in __repr__ or added to the "unhandled error in deferred" Failure. The traceback of creation is often more useful than the traceback of .callback, .errback, or timer execution. added .extra attribute to Failures, insert its contents in the traceback. I used this to display the Deferred-creation traceback. There are still a few issues: I need to implement getDelayedCalls for the cReactor, and my unit test for getDelayedCalls is stymied by a recurring timer created when the 'popsicle' module is imported, but in general it seems to make the unit test suite behave sensibly (no more intermittent failures). cheers, -Brian
participants (1)
-
Brian Warner