Filed by: philringnalda [at] gmail.com https://treeherder.mozilla.org/logviewer.html#?job_id=4020085&repo=autoland https://queue.taskcluster.net/v1/task/ak1teQVQTBCKihnmbW9h9g/runs/0/artifacts/public%2Flogs%2Flive_backing.log

This timeout happens almost exclusively on Android Debug, but there are also some Linux failures. Logs consistently show the timeout following "window.location http-to-https strict-origin-when-cross-origin". [task 2016-11-21T01:10:15.057327Z] 01:10:15 INFO - 295 INFO TEST-PASS | dom/base/test/test_bug704320.html | window.location http-to-https same-origin [task 2016-11-21T01:10:15.057808Z] 01:10:15 INFO - 296 INFO TEST-PASS | dom/base/test/test_bug704320.html | window.location http-to-https strict-origin [task 2016-11-21T01:10:15.058298Z] 01:10:15 INFO - 297 INFO TEST-PASS | dom/base/test/test_bug704320.html | window.location http-to-https strict-origin-when-cross-origin [task 2016-11-21T01:10:15.058728Z] 01:10:15 INFO - Buffered messages finished [task 2016-11-21T01:10:15.070451Z] 01:10:15 INFO - 298 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug704320.html | Test timed out. [task 2016-11-21T01:10:15.070885Z] 01:10:15 INFO - reportError@SimpleTest/TestRunner.js:114:7 [task 2016-11-21T01:10:15.071365Z] 01:10:15 INFO - TestRunner._checkForHangs@SimpleTest/TestRunner.js:135:7 [task 2016-11-21T01:10:15.071578Z] 01:10:15 INFO - 299 INFO TEST-OK | dom/base/test/test_bug704320.html | took 1238917ms [task 2016-11-21T01:10:15.072136Z] 01:10:15 INFO - 300 ERROR [SimpleTest.finish()] this test already called finish! [task 2016-11-21T01:10:15.072292Z] 01:10:15 INFO - 301 INFO TEST-UNEXPECTED-ERROR | dom/base/test/test_bug704320.html | called finish() multiple times Failures started shortly after bug 1276836 updated the test.

Android logcats show the timing best. https://public-artifacts.taskcluster.net/TsKsQYTNTLiPt75CdBGcjg/0/public/test_info//logcat-emulator-5554.log 11-20 17:09:41.513 765 784 I GeckoDump: ⰲ겿{"action":"test_status","time":1479690581516,"thread":null,"pid":null,"source":"mochitest","test":"/tests/dom/base/test/test_bug704320.html","subtest":"window.location http-to-https same-origin","status":"PASS","js_source":"TestRunner.js"}ⰲ겿 11-20 17:09:41.523 765 784 I GeckoDump: ⰲ겿{"action":"test_status","time":1479690581523,"thread":null,"pid":null,"source":"mochitest","test":"/tests/dom/base/test/test_bug704320.html","subtest":"window.location http-to-https strict-origin","status":"PASS","js_source":"TestRunner.js"}ⰲ겿 11-20 17:09:41.523 765 784 I GeckoDump: ⰲ겿{"action":"test_status","time":1479690581530,"thread":null,"pid":null,"source":"mochitest","test":"/tests/dom/base/test/test_bug704320.html","subtest":"window.location http-to-https strict-origin-when-cross-origin","status":"PASS","js_source":"TestRunner.js"}ⰲ겿 11-20 17:09:41.673 765 784 I GeckoDump: MEMORY STAT | vsize 536MB | residentFast 159MB | heapAllocated 64MB 11-20 17:09:47.402 278 281 D dalvikvm: GC_CONCURRENT freed 704K, 35% free 5563K/8548K, paused 6ms+44ms, total 255ms 11-20 17:09:52.483 765 784 I Gecko : --DOCSHELL 0x55338400 == 11 [pid = 765] [id = {dd084995-ac90-4a6c-944b-9730fff4951c}] 11-20 17:09:52.483 765 784 I Gecko : --DOCSHELL 0x599e3c00 == 10 [pid = 765] [id = {35b02a3d-20b7-4f85-be35-a99f28a29fa1}] 11-20 17:09:52.493 765 784 I Gecko : --DOCSHELL 0x55337400 == 9 [pid = 765] [id = {1f810d86-b023-46a7-9558-33ef6860b39a}] 11-20 17:10:02.082 765 784 I Gecko : --DOCSHELL 0x599e3400 == 8 [pid = 765] [id = {9b6ce320-8275-4018-ae76-97a6915cd08b}] 11-20 17:10:02.553 765 784 I Gecko : --DOMWINDOW == 46 (0x599eb000) [pid = 765] [serial = 782] [outer = 0x0] [url = about:blank] 11-20 17:10:02.553 765 784 I Gecko : --DOMWINDOW == 45 (0x552f9400) [pid = 765] [serial = 780] [outer = 0x0] [url = about:blank] 11-20 17:10:02.563 765 784 I Gecko : --DOMWINDOW == 44 (0x5a00f400) [pid = 765] [serial = 769] [outer = 0x0] [url = https://example.com/tests/dom/base/test/bug704320.sjs?action=create-1st-level-iframe&scheme-from=https&scheme-to=http&policy=unsafe-url] 11-20 17:10:02.563 765 784 I Gecko : --DOMWINDOW == 43 (0x5538c400) [pid = 765] [serial = 775] [outer = 0x0] [url = about:blank] 11-20 17:10:02.563 765 784 I Gecko : --DOMWINDOW == 42 (0x59c64400) [pid = 765] [serial = 773] [outer = 0x0] [url = about:blank] 11-20 17:10:02.563 765 784 I Gecko : --DOMWINDOW == 41 (0x59895c00) [pid = 765] [serial = 776] [outer = 0x0] [url = https://example.com/tests/dom/base/test/bug704320.sjs?action=create-1st-level-iframe&scheme-from=https&scheme-to=http&policy=origin] 11-20 17:10:02.593 765 784 I Gecko : --DOMWINDOW == 40 (0x5a7f3400) [pid = 765] [serial = 774] [outer = 0x0] [url = about:blank] 11-20 17:10:02.593 765 784 I Gecko : --DOMWINDOW == 39 (0x59925c00) [pid = 765] [serial = 781] [outer = 0x0] [url = about:blank] 11-20 17:10:02.733 765 784 I GeckoDump: ⰲ겿{"action":"test_status","time":1479690602732,"thread":null,"pid":null,"source":"mochitest","test":"/tests/dom/base/test/test_bug704320.html","subtest":"Test timed out.","status":"FAIL","expected":"PASS","stack":" reportError@SimpleTest/TestRunner.js:114:7\n TestRunner._checkForHangs@SimpleTest/TestRunner.js:135:7\n","js_source":"TestRunner.js"}ⰲ겿

Thanks for reporting and looking at this, not sure why it blocks strict-origin-when-cross-origin, I will take a closer look at this bug.

I looked into the only linux failure https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=38466077#L8366 and it does not seems to be related, even the test test_bug704320 was not run. Narrow down to platform android-4-3-armv7-api15. FWIW, bug 1284763, there're some intermittents in platform android-4-3-armv7-api15 also

I see there're many warnings related to mixed content. Trying to disable hsts + mixed content, and running 20 times on try. Let's see. https://treeherder.mozilla.org/#/jobs?repo=try&revision=2df95c7ffa49c444d8f54efc09465bfc426882d7

MozReview-Commit-ID: FkJZ4TLJVlE

20 tests on Android android-4-3-armv7-api15 look good. Hi Franziskus, could you please review this so that I could land the intermittent fix? This is testonly fix and turning off mixed_content, hsts should not have effect to the purpose and result of the test. Thanks

Thanks ：）

Pushed by cbook@mozilla.com: https://hg.mozilla.org/integration/mozilla-inbound/rev/c4ae65fa000a turn off hsts, mixed_content block to suspress intermittent on try. r=franziskus

I had to back this out in https://hg.mozilla.org/mozilla-central/rev/f179934df0c1bab590c558485d419c7910e41325 because it apparently made android debug m(3) nearly permafail: https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&fromchange=126cbbb0afcd6123fa538cad01ba4eec9660e455&bugfiler&group_state=expanded&noautoclassify&filter-searchStr=android%20debug%20m(3)&selectedJob=40913233 (No results for several of the pushes right where this landed because a different patch broke the builds.)

Likely I was wrong to check the root cause of intermittent, thanks for backing out this.

Recent spike here: https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&filter-searchStr=android%20mochitest-3%20debug&tochange=9fcb7e13923d49421a951e60b30576e3838c9738&fromchange=6351f15cf90b4f2a5d340deca535442e880f3004

:gbrown, I added some comments in bug 1284763 after doing some investigation, please add more there so we can figure this out as both that bug and this are perma failing.

Re-triggers shown in comment 30 indicate that this Android Debug near-perma-fail started with bug 1335751. We noted a general slow-down of Android Debug mochitests with bug 1335751 and addressed that with more test chunks in bug 1345350. As in https://bugzilla.mozilla.org/show_bug.cgi?id=1284763#c9, it is possible that the extra checks in bug 1335751 have pushed this test over the test timeout. It was already a long-running test on Android: Test durations for dom/base/test/test_bug704320.html on mozilla-central,mozilla-inbound,autoland between 2017-02-28 and 2017-03-06 android-4-3-armv7-api15/debug-chunked: 990.76 s (849.75 s - 1171.80 s over 401 runs) android-4-3-armv7-api15/opt-chunked: 389.89 s (314.63 s - 507.72 s over 133 runs) The test already calls SimpleTest.requestLongerTimeout(4), for a timeout of about 1200 seconds on Android. I'll look into requestLongerTimeout(5).

In https://treeherder.mozilla.org/#/jobs?repo=try&revision=8c4bf65e59d0f6b48fe608b6327a04fb19b81c1c, the test passes with requestLongerTimeout(5), typically in about 1200 seconds - so that's an option here.

I would like to assert this is fixed, going to mark as resolved/fixed- if there is a desire to keep this open please feel free to reopen.