https://bugzilla.wikimedia.org/show_bug.cgi?id=71971
Bug ID: 71971 Summary: site_tests.testImageusage timeout error after maximum retries Product: Pywikibot Version: core (2.0) Hardware: All OS: All Status: NEW Severity: normal Priority: Unprioritized Component: tests Assignee: Pywikipedia-bugs@lists.wikimedia.org Reporter: jayvdb@gmail.com Web browser: --- Mobile Platform: ---
The recent travis builds are regularly failing on site_tests.testImageusage with a timeout error only when run against en.wp. Travis runs this test for each checking against 2.6, 2.7.8 and 3.3.5 at the moment. It doesnt happen every time, and it hasnt happend on 2.6 yet for some reason.
Note this bug is _not_ bug 60214, which is about content & caching assumptions in the test case, which very affect mostly re-runs of the test suite on a warm cache, and only very rarely occur on a cold cache.
Python 2.7.8 log (https://travis-ci.org/wikimedia/pywikibot-core/jobs/37633107)
ERROR: testImageusage (tests.site_tests.TestSiteObject) Test the site.imageusage() method ---------------------------------------------------------------------- Traceback (most recent call last): File "/home/travis/build/wikimedia/pywikibot-core/tests/site_tests.py", line 616, in testImageusage for using in mysite.imageusage(imagepage, filterredir=True, total=5): File "/home/travis/build/wikimedia/pywikibot-core/pywikibot/data/api.py", line 971, in __iter__ self.data = self.request.submit() File "/home/travis/build/wikimedia/pywikibot-core/pywikibot/data/api.py", line 764, in submit self._data = super(CachedRequest, self).submit() File "/home/travis/build/wikimedia/pywikibot-core/pywikibot/data/api.py", line 535, in submit self.wait() File "/home/travis/build/wikimedia/pywikibot-core/pywikibot/data/api.py", line 648, in wait raise TimeoutError("Maximum retries attempted without success.") TimeoutError: Maximum retries attempted without success.
----
Python 3.3.5 has a two part log (https://travis-ci.org/wikimedia/pywikibot-core/jobs/37633111)
Traceback (most recent call last): File "/home/travis/build/wikimedia/pywikibot-core/pywikibot/data/api.py", line 517, in submit headers=headers, body=body) File "/home/travis/build/wikimedia/pywikibot-core/pywikibot/tools.py", line 367, in wrapper return method(*__args, **__kw) File "/home/travis/build/wikimedia/pywikibot-core/pywikibot/comms/http.py", line 258, in request raise request.data File "/home/travis/build/wikimedia/pywikibot-core/pywikibot/comms/threadedhttp.py", line 219, in request max_redirects, connection_type File "/home/travis/virtualenv/python3.3.5/lib/python3.3/site-packages/httplib2-0.9_pywikibot1-py3.3.egg/httplib2/__init__.py", line 1292, in request (response, content) = self._request(conn, authority, uri, request_uri, method, body, headers, redirections, cachekey) File "/home/travis/virtualenv/python3.3.5/lib/python3.3/site-packages/httplib2-0.9_pywikibot1-py3.3.egg/httplib2/__init__.py", line 1042, in _request (response, content) = self._conn_request(conn, request_uri, method, body, headers) File "/home/travis/virtualenv/python3.3.5/lib/python3.3/site-packages/httplib2-0.9_pywikibot1-py3.3.egg/httplib2/__init__.py", line 995, in _conn_request response = conn.getresponse() File "/opt/python/3.3.5/lib/python3.3/http/client.py", line 1147, in getresponse response.begin() File "/opt/python/3.3.5/lib/python3.3/http/client.py", line 358, in begin version, status, reason = self._read_status() File "/opt/python/3.3.5/lib/python3.3/http/client.py", line 320, in _read_status line = str(self.fp.readline(_MAXLINE + 1), "iso-8859-1") File "/opt/python/3.3.5/lib/python3.3/socket.py", line 297, in readinto return self._sock.recv_into(b) File "/opt/python/3.3.5/lib/python3.3/ssl.py", line 493, in recv_into return self.read(nbytes, buffer) File "/opt/python/3.3.5/lib/python3.3/ssl.py", line 367, in read v = self._sslobj.read(len, buffer) socket.timeout: The read operation timed out During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/home/travis/build/wikimedia/pywikibot-core/tests/site_tests.py", line 616, in testImageusage for using in mysite.imageusage(imagepage, filterredir=True, total=5): File "/home/travis/build/wikimedia/pywikibot-core/pywikibot/data/api.py", line 971, in __iter__ self.data = self.request.submit() File "/home/travis/build/wikimedia/pywikibot-core/pywikibot/data/api.py", line 764, in submit self._data = super(CachedRequest, self).submit() File "/home/travis/build/wikimedia/pywikibot-core/pywikibot/data/api.py", line 535, in submit self.wait() File "/home/travis/build/wikimedia/pywikibot-core/pywikibot/data/api.py", line 648, in wait raise TimeoutError("Maximum retries attempted without success.") pywikibot.data.api.TimeoutError: Maximum retries attempted without success.
The lowest travis job number i've found with this problem is https://travis-ci.org/wikimedia/pywikibot-core/jobs/37481646
https://bugzilla.wikimedia.org/show_bug.cgi?id=71971
John Mark Vandenberg jayvdb@gmail.com changed:
What |Removed |Added ---------------------------------------------------------------------------- Priority|Unprioritized |High
https://bugzilla.wikimedia.org/show_bug.cgi?id=71971
John Mark Vandenberg jayvdb@gmail.com changed:
What |Removed |Added ---------------------------------------------------------------------------- CC| |CommodoreFabianus@gmx.de
--- Comment #1 from John Mark Vandenberg jayvdb@gmail.com --- This may have been caused by changing the travis retry number to 2 : https://gerrit.wikimedia.org/r/#/c/160000/ , which was merged on 13 Sept 3:30 AM
We could try increasing max_retries to 5 to see if that fixes the problem.
Another solution is to disable this test ;-) Pending patch: https://gerrit.wikimedia.org/r/160192 from bug 68671
But it is likely this test is doing something odd/extreme and the solution needs to be found.
Another possible cause is the logic to select a page for this test was changed 11 Sept. https://gerrit.wikimedia.org/r/#/c/159633/
Now that 13 Sept looks like the date this problem stated occurring _regularly_, I've found an earlier instance of the problem: 18 Sept 18 2014 https://gerrit.wikimedia.org/r/#/c/161201/ https://travis-ci.org/wikimedia/pywikibot-core/jobs/35616554
Next one I can find is 25 Sept https://gerrit.wikimedia.org/r/#/c/162863/ https://travis-ci.org/wikimedia/pywikibot-core/jobs/36296502
https://travis-ci.org/wikimedia/pywikibot-core/jobs/36903977 https://travis-ci.org/wikimedia/pywikibot-core/jobs/37111303 https://travis-ci.org/wikimedia/pywikibot-core/jobs/37270052
I was able to reproduce this timeout once on my workstation by running the test several times with en.wp set as my default site on a cold cache, sometimes it only times out once, but occasionally it times out three times.
rm -rf tests/apicache/; python -m unittest tests.site_tests.TestSiteObject.testImageusage
I can find pre-13 Sept instances of the same error in this test, but as the retry limit was very high the API code keeps trying to bypass the problem
https://travis-ci.org/wikimedia/pywikibot-core/jobs/35049020#L375
----
testImageusage on a cold cache runs 12 queries; on a warm cache it only makes one live request, caching the other 11.
(In the process I found a regression https://gerrit.wikimedia.org/r/#/c/166367/)
When run against en.wp as default site, site_tests.testImageusage uses [[en:File:Wiktionary-logo-en.svg]] which is used on [[en:!!]]
The query which takes the longest is:
https://en.wikipedia.org/w/api.php?inprop=protection&giulimit=5&maxl...
Running wget on that URL, repeatedly, doesnt reproduce the problem.
https://bugzilla.wikimedia.org/show_bug.cgi?id=71971
--- Comment #2 from John Mark Vandenberg jayvdb@gmail.com --- Note that the slow query is finding images on redirects only, which sounds like it should be a slow query. e.g.
https://en.wikipedia.org/w/index.php?title=Ambulance%20chaser&redirect=n...
https://bugzilla.wikimedia.org/show_bug.cgi?id=71971
--- Comment #3 from Gerrit Notification Bot gerritadmin@wikimedia.org --- Change 166375 had a related patch set uploaded by John Vandenberg: Split testImageusage into four tests
https://gerrit.wikimedia.org/r/166375
https://bugzilla.wikimedia.org/show_bug.cgi?id=71971
Gerrit Notification Bot gerritadmin@wikimedia.org changed:
What |Removed |Added ---------------------------------------------------------------------------- Status|NEW |PATCH_TO_REVIEW
https://bugzilla.wikimedia.org/show_bug.cgi?id=71971
John Mark Vandenberg jayvdb@gmail.com changed:
What |Removed |Added ---------------------------------------------------------------------------- CC| |legoktm.wikipedia@gmail.com | |, valhallasw@arctus.nl
--- Comment #4 from John Mark Vandenberg jayvdb@gmail.com --- testImageusage
https://travis-ci.org/wikimedia/pywikibot-core/jobs/37837770 https://travis-ci.org/wikimedia/pywikibot-core/jobs/37871882
Here is it failing _once_ only in py2.6
https://travis-ci.org/wikimedia/pywikibot-core/jobs/37876770
now also seeing the same problem with testUsercontribs
https://travis-ci.org/wikimedia/pywikibot-core/jobs/37871878 https://travis-ci.org/wikimedia/pywikibot-core/jobs/37871882
And possible unrelated testUsers has a new assert
FAIL: testUsers (tests.site_tests.SiteUserTestCase) Test the site.users() method ---------------------------------------------------------------------- Traceback (most recent call last): File "/home/travis/build/wikimedia/pywikibot-core/tests/site_tests.py", line 1017, in testUsers us = list(mysite.users(mysite.user())) File "/home/travis/build/wikimedia/pywikibot-core/pywikibot/site.py", line 3588, in users usprop="blockinfo|groups|editcount|registration|emailable" File "/home/travis/build/wikimedia/pywikibot-core/pywikibot/data/api.py", line 1199, in __init__ QueryGenerator.__init__(self, list=listaction, **kwargs) File "/home/travis/build/wikimedia/pywikibot-core/pywikibot/data/api.py", line 819, in __init__ self.update_limit() # sets self.prefix File "/home/travis/build/wikimedia/pywikibot-core/pywikibot/data/api.py", line 914, in update_limit for param in self._modules[mod].get("parameters", []): File "/home/travis/build/wikimedia/pywikibot-core/pywikibot/data/api.py", line 866, in _modules assert "paraminfo" in data AssertionError
https://travis-ci.org/wikimedia/pywikibot-core/jobs/37871882
Please review r/166375 so that subsequent travis builds help narrow down the exact problem.
Could it be HHVM related?
https://bugzilla.wikimedia.org/show_bug.cgi?id=71971
--- Comment #5 from Gerrit Notification Bot gerritadmin@wikimedia.org --- Change 166375 merged by jenkins-bot: Split testImageusage into four tests
https://gerrit.wikimedia.org/r/166375
https://bugzilla.wikimedia.org/show_bug.cgi?id=71971
John Mark Vandenberg jayvdb@gmail.com changed:
What |Removed |Added ---------------------------------------------------------------------------- Status|PATCH_TO_REVIEW |NEW
--- Comment #6 from John Mark Vandenberg jayvdb@gmail.com --- As expected it is test_image_usage_in_redirects which is causing the problem
https://travis-ci.org/wikimedia/pywikibot-core/jobs/37887126 https://travis-ci.org/wikimedia/pywikibot-core/jobs/37887726
I think the next step is:
set max-retries to 0 or 1 for all test runs, except keep travis at 2 to avoid red builds
create TestCase.expectedFailureIf , and add @expectedFailureIf(<travis>) to test_image_usage_in_redirect.
This will mean that developer testing will fail if it occurs on their workstation, but it wont cause red builds on Travis since we already know about this problem and are tracking it down.
https://bugzilla.wikimedia.org/show_bug.cgi?id=71971
John Mark Vandenberg jayvdb@gmail.com changed:
What |Removed |Added ---------------------------------------------------------------------------- Summary|site_tests.testImageusage |site_tests |timeout error after maximum |test_image_usage_in_redirec |retries |t timeout error after | |maximum retries
https://bugzilla.wikimedia.org/show_bug.cgi?id=71971
--- Comment #7 from Gerrit Notification Bot gerritadmin@wikimedia.org --- Change 166532 had a related patch set uploaded by John Vandenberg: @expectedFailureIf(TRAVIS=true) on imageusage test
https://gerrit.wikimedia.org/r/166532
https://bugzilla.wikimedia.org/show_bug.cgi?id=71971
Gerrit Notification Bot gerritadmin@wikimedia.org changed:
What |Removed |Added ---------------------------------------------------------------------------- Status|NEW |PATCH_TO_REVIEW
https://bugzilla.wikimedia.org/show_bug.cgi?id=71971
--- Comment #8 from John Mark Vandenberg jayvdb@gmail.com --- This one is very strange. First is the error in test_image_usage_in_redirects , then one of the results in test_image_usage_no_redirect_filter is wrong!
https://travis-ci.org/wikimedia/pywikibot-core/jobs/37948029
https://bugzilla.wikimedia.org/show_bug.cgi?id=71971
--- Comment #9 from Gerrit Notification Bot gerritadmin@wikimedia.org --- Change 166532 merged by XZise: @expectedFailureIf(TRAVIS=true) on imageusage test
https://gerrit.wikimedia.org/r/166532
https://bugzilla.wikimedia.org/show_bug.cgi?id=71971
Mpaa mpaa.wiki@gmail.com changed:
What |Removed |Added ---------------------------------------------------------------------------- CC| |mpaa.wiki@gmail.com
--- Comment #10 from Mpaa mpaa.wiki@gmail.com --- I got this locally if it can help, on wikipedia:
rm -rf tests/apicache/; python -m unittest tests.site_tests.TestImageUsage.test_image_usage_in_redirects
site_tests.TestImageUsage found [[en:File:Wiktionary-logo-en.svg]] on [[en:!!]] ERROR: Traceback (most recent call last): File "pywikibot/data/api.py", line 567, in submit headers=headers, body=body) File "pywikibot/tools.py", line 529, in wrapper return obj(*__args, **__kw) File "pywikibot/comms/http.py", line 258, in request raise request.data SSLError: The read operation timed out
WARNING: Waiting 5 seconds before retrying.
...
https://bugzilla.wikimedia.org/show_bug.cgi?id=71971
--- Comment #11 from Mpaa mpaa.wiki@gmail.com --- Next run was OK:
site_tests.TestImageUsage found [[en:File:Wiktionary-logo-en.svg]] on [[en:!!]] [[en:Cock sucker]] [[en:Ambulance chaser]] [[en:Cyberpet]] [[en:Colorfast]] 35.620s . ---------------------------------------------------------------------- Ran 1 test in 35.621s
OK
https://bugzilla.wikimedia.org/show_bug.cgi?id=71971
--- Comment #12 from Mpaa mpaa.wiki@gmail.com --- I think that the fastest way to solve this is to request 500 elements instead of 5 in this test. The generator image usage will go much faster. Speed is related to iulimit parameter, but I think this is out of our control if we want to keep the same implementation for all the possible queries.
Compare speed of:
https://en.wikipedia.org/w/api.php?inprop=protection&giulimit=500&ma...
with:
https://en.wikipedia.org/w/api.php?inprop=protection&giulimit=5&maxl...
https://bugzilla.wikimedia.org/show_bug.cgi?id=71971
John Mark Vandenberg jayvdb@gmail.com changed:
What |Removed |Added ---------------------------------------------------------------------------- Status|PATCH_TO_REVIEW |NEW
--- Comment #13 from John Mark Vandenberg jayvdb@gmail.com --- Changes to the tests have been merged. Underlying problem hasnt been fixed.
https://bugzilla.wikimedia.org/show_bug.cgi?id=71971
--- Comment #14 from John Mark Vandenberg jayvdb@gmail.com --- (In reply to John Mark Vandenberg from comment #8)
This one is very strange. First is the error in test_image_usage_in_redirects , then one of the results in test_image_usage_no_redirect_filter is wrong!
https://travis-ci.org/wikimedia/pywikibot-core/jobs/37948029
Another error in test_image_usage_no_redirect_filter
https://travis-ci.org/wikimedia/pywikibot-core/jobs/38570786
(It is probably not the same bug as the test_image_usage_in_redirect bug, and a new bug should be created once we have more information about the cause.)
https://bugzilla.wikimedia.org/show_bug.cgi?id=71971
--- Comment #15 from Mpaa mpaa.wiki@gmail.com --- (In reply to John Mark Vandenberg from comment #13)
Changes to the tests have been merged. Underlying problem hasnt been fixed.
I do not think there is an underlying problem in test_image_usage_in_redirects. The API is already slow by itself when called with those parameters.
One solution would be to change the logic that we currently use for setting the query limits.
I think this can be avoided just raising the number of retrieved tems from 5 to 500 instead of @expectedFailureIf(TRAVIS=true) on imageusage test.
https://bugzilla.wikimedia.org/show_bug.cgi?id=71971
--- Comment #16 from John Mark Vandenberg jayvdb@gmail.com --- I've forked the test_image_usage_no_redirect_filter problem to bug 73120.
pywikipedia-bugs@lists.wikimedia.org