How do you know it makes the lang=zh request first? In the log for #28714 I see:

• 02:34:26: karma task starts
• 02:35:13: Executed 0 of 1593
• 02:35:19: Requesting ...lang=fr...
• 02:35:22: proxying request ...lang=zh...
• 02:35:24: Test timed out
• 02:35:24: Language "zh" failed to load

This would be easier to debug if the apache access logs were in a less stupid format.

It's possible to get a rough idea of HTTP request execution time because the timestamp in the log line is the time at which the request started, but the log line is actually written when the request finishes.

For #28714, here is the lang=zh request:

localhost:80 127.0.0.1 - - [02/Feb/2016:02:35:22 +0000] "GET /jenkins-mediawiki-extensions-qunit-28714/load.php?skin=fallback&lang=zh&debug=false&modules=mediawiki.language.data%7Cmediawiki.language&only=scripts HTTP/1.1" 200 6137 "http://localhost:9876/context.html" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Ubuntu Chromium/48.0.2564.82 Chrome/48.0.2564.82 Safari/537.36"

You see that it starts at 02:35:22 as reported by the karma log. The end time was certainly before 02:35:28 because a static file was requested at that time, and we can assume that it was served pretty quickly. It was probably before 02:35:24 which is the adjacent log entry, for lang=nl.

But there are slow things here. See the full log for 02:34-02:35 at P2555. A whole lot of slow requests were queued up at 02:34:37, and the last of them finished some time between 02:34:57 and 02:35:08, i.e. 20 or 30 seconds later (you see why I hate this log format). The slowest was:

localhost:80 127.0.0.1 - - [02/Feb/2016:02:34:37 +0000] "GET /jenkins-mediawiki-extensions-qunit-28714/load.php?debug=false&lang=en&modules=dataTypes.DataType%2CDataTypeStore%2C__namespace%7CdataValues%7CdataValues.DataValue%2CTimeValue%2Cvalues%7Cext.cards.tests%7Cext.cite.style%7Cext.echo.dm%7Cext.echo.dm.tests%7Cext.eventLogging%2Cflow%7Cext.eventLogging.subscriber%2Ctests%7Cext.flow.components%2Cdm%2Ceditor%2Ctemplating%2Ctests%2Cui%7Cext.flow.dm.tests%7Cext.flow.jquery.conditionalScroll%2CfindWithParent%7Cext.flow.vendor.storer%7Cext.gather.api%2Cbuttonspinner%2Cicons%2Clogging%2Crelatedpages%2Cschema%7Cext.gather.api.tests%7Cext.gather.collection.base%2Cconfirm%2CcontentOverlay%2Cdelete%2Ceditor%7Cext.gather.collection.contentOverlay.tests%7Cext.gather.collection.editor.tests%7Cext.gather.page.search%7Cext.gather.page.search.tests%7Cext.gather.watchstar.icons%7Cext.guidedTour.lib%2Cstyles%7Cext.guidedTour.lib.internal%2Ctests%7Cext.thanks.mobilediff%7Cext.uls.i18n%2Cinit%2Clanguagenames%2Cmediawiki%2Cmessages%2Cpreferences%2Ctests%7Cext.visualEditor.base%2Ccore%2CdesktopArticleTarget%2Cexperimental%2Clanguage%2Cmediawiki%2Cmwalienextension%2Cmwcore%2Cmwformatting%2Cmwgallery%2Cmwimage%2Cmwlink%2Cmwmeta%2Cmwreference%2Cmwtransclusion%2Cstandalone%2Cswitching%2CtargetLoader%2Ctest%2Ctrack%2Cve%7Cext.visualEditor.core.desktop%7Cext.visualEditor.desktopArticleTarget.init%7Cext.visualEditor.mwimage.core%7Cext.visualEditor.mwreference.core%7Cext.visualEditor.mwtransclusion.core%7CglobeCoordinate.js%7Cjquery.AnimationEvent%2CPurposedCallbacks%2CanimateWithEvent%2CautoEllipsis%2Cautocompletestring%2CbyteLength%2CbyteLimit%2CcheckboxShiftClick%2Ccolor%2CcolorUtil%2Ccookie%2CfocusAt%2CgetAttrs%2Chidpi%2ChighlightText%2Ci18n%2Cinputautoexpand%2Clocalize%2CmakeCollapsible%2Cmw-jump%7Cjquery.AnimationEvent.tests%7Cjquery.PurposedCallbacks.tests%7Cjquery.animateWithEvent.tests%7Cjquery.autocompletestring.tests%7Cjquery.event.special.eachchange%7Cjquery.event.special.eachchange.tests%7Cjquery.focusAt.tests%7Cjquery.inputautoexpand.tests&skin=fallback&version=b317880d314b HTTP/1.1" 200 2653278 "http://localhost:9876/context.html" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Ubuntu Chromium/48.0.2564.82 Chrome/48.0.2564.82 Safari/537.36"

Where does the message "Language "zh" failed to load." come from?

In T125484#1988855, @tstarling wrote:

Where does the message "Language "zh" failed to load." come from?

ack 'Language .*? failed to load' --php --js
workdir/tests/qunit/suites/resources/mediawiki/mediawiki.jqueryMsg.test.js
380:                                            assert.ok( false, 'Language "' + test.lang + '" failed to load.' );
902:                                            assert.ok( false, 'Language "' + test.lang + '" failed to load' );

The QUnit test is randomly flapping on 1.27.0-wmf.12 (some finding at T125655).

Seems to me the language caching takes too long and the test suite AJAX query ends up with a timeout.

Maybe some languages cache should be populated before the run, or the timeout raised.

For wmf.12 we can bump:

$ grep testTimeout tests/qunit/data/testrunner.js 
	QUnit.config.testTimeout = 30 * 1000;

Change 268365 had a related patch set uploaded (by JanZerebecki):
increase maximum timeout for full qunit test run

https://gerrit.wikimedia.org/r/268365

Let's merge that ^ timeout increase and see if that helps, sooner than later :)

My patch is a hack that may lead to worse code. The correct thing to do would be to refactor the test "Match PHP parser" in tests/qunit/suites/resources/mediawiki/mediawiki.jqueryMsg.test.js so that it does call stop before every item of the test data instead of once for all of them together. I.e. refactor it to break up the test into smaller parts.

Change 268427 had a related patch set uploaded (by Thiemo Mättig (WMDE)):
Call QUnit.stop() before each asynchronous task

https://gerrit.wikimedia.org/r/268427

Change 268365 merged by jenkins-bot:
qunit: Increase individual test timeout to 60 seconds

https://gerrit.wikimedia.org/r/268365

Change 268427 merged by jenkins-bot:
mediawiki.jqueryMsg.test: Call async() before each async test step

https://gerrit.wikimedia.org/r/268427