[Twisted-Python] Weird PyPY twisted.internet.defer.TimeoutError ERROR*12 during full test run

[Daniel Sutcliffe]

Many thanks Tristan for sharing your experiences here, I'm sure
they'll get me a little closer to finding the root cause of these test
result peculiarities.

On Sat, 5 Aug 2017 at 00:44 Daniel Sutcliffe <dansut at gmail.com> wrote:
>> For the buildbot:
>>   https://buildbot.twistedmatrix.com/builders/ubuntu16.04-pypy5/
>> they seem to pretty much consistently happen during:
>>   twisted.protocols.test.test_tls.TLSMemoryBIOTests.test_hugeWrite_TLSv1_1
>> but running in my own environment(s) I also always see the 12
>> TimoutError but they can occur in a variety of different tests, I've
>> seen them in these as well as the above:
>>   twisted.news.test.test_news.NewsTests.testArticleRequest
>>   twisted.names.test.test_server.DNSServerFactoryTests.test_verboseDefault
>>   twisted.positioning.test.test_nmea.BrokenSentenceCallbackTests.test_dontSwallowCallbackException
>> and a bunch of others.

On Fri, Aug 4, 2017 at 11:22 PM, Tristan Seligmann
<mithrandi at mithrandi.net> wrote:
> This kind of timeout usually means that the test is waiting for some event,
> and due to an event ordering that wasn't expected, the event never happens;
> for example, it might have already happened before you start waiting for it,
> or it might not happen at all due to an error.
>
> Sometimes this means that the test is really stuck, but often it means that
> an error has occurred but was not handled by the test, so you get an error
> (maybe logged, maybe not) but also the test never ends.

Having now looked deeper into the other tests I have had the ERROR
occur in I can confidently say there seems to little in common with
the tests I have seen get stuck in the TimeoutError. The last two in
list specifically seem like very unlikely culprits...

>From this my gut is that this is nothing to do with the tests
themselves and more to do with something in the long running trial
that is having issues when run under PyPy

>> Always exactly 12 and always during same test for a single test run.
>> I've not been able to reproduce running anything but the full
>> testsuite - but they have always occurred for me during full run.
>>
>> Just wondered if anybody with more experience had a clue/idea as to
>> why this could happen (why 12), and how I could go about tracking down
>> the root cause.
>
> Look for missing error handling in the test to see if an error is occurring
> that the test does not notice; if you're lucky, these errors may have been
> logged (check test.log). If not, you may need to improve the error handling
> and / or play around in a debugger.

Nothing in test.log when this happens, and I've yet to work out a way
of getting a debugger to cooperate by dropping me out of execution
when these TimeoutError occur so I can get an idea of what is being
waited for, where.

> If the test really is stuck, a common cause of PyPy vs CPython issues is
> garbage collection or weakref callbacks happening in an unpredictable
> ordering of events. I haven't looked at the tests in question but I would
> check for things like __del__ methods (eg. files not being closed
> explicitly) or weakref use in the vicinity.

I've certainly noticed differences with weakref and GC under PyPy, I think:
  twisted.test.test_threadpool.ThreadPoolTests.test_threadCreationArgumentsCallInThreadWithCallback
specifically shows as a FAIL under PyPy because the test relies on a
weakref being collected, when this can't be relied on under PyPy.

Cheers
/dan
-- 
Daniel Sutcliffe <dansut at gmail.com>