[Twisted-Python] Weird PyPY twisted.internet.defer.TimeoutError ERROR*12 during full test run
During the PyPy2.7 5.8.0 testsuite run (actually happens under PyPy3.5 5.8.0 too) there always seems to be a group of 12 ERROR due to: twisted.internet.defer.TimeoutError 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. 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 occured 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. Getting close to having PyPy be able to run twisted tests with no FAILs but I have no idea what might be causing this. Cheers /dan -- Daniel Sutcliffe <dansut@gmail.com>
On Sat, 5 Aug 2017 at 00:44 Daniel Sutcliffe <dansut@gmail.com> 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. Always exactly 12 and always during same test for a single test run.
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. 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.
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@gmail.com> wrote:
On Fri, Aug 4, 2017 at 11:22 PM, Tristan Seligmann <mithrandi@mithrandi.net> wrote:
From this my gut is that this is nothing to do with the tests
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... themselves and more to do with something in the long running trial that is having issues when run under PyPy
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.
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@gmail.com>
On Sat, 5 Aug 2017 at 00:44 Daniel Sutcliffe <dansut@gmail.com> 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. Always exactly 12 and always during same test for a single test run.
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. 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.
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@gmail.com> wrote:
On Fri, Aug 4, 2017 at 11:22 PM, Tristan Seligmann <mithrandi@mithrandi.net> wrote:
From this my gut is that this is nothing to do with the tests
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... themselves and more to do with something in the long running trial that is having issues when run under PyPy
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.
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@gmail.com>
participants (2)
-
Daniel Sutcliffe -
Tristan Seligmann