Closed Bug 1305622 Opened 8 years ago Closed 7 years ago

Intermittent dom/base/test/test_bug704320.html | Test timed out.

Categories

(Core :: DOM: Core & HTML, defect, P5)

Product:
Core
Component:
DOM: Core & HTML
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Tracking Flags:
Tracking Status
firefox53 --- affected

People

(Reporter: intermittent-bug-filer, Assigned: tnguyen)

References

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell fixed:other])

Attachments

(1 file)

turn off hsts, mixed_content block to suspress intermittent on try
1.39 KB, patch
franziskus
: review+
Details | Diff | Splinter Review 
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.
Blocks: 1276836
Flags: needinfo?(tnguyen)
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.
Flags: needinfo?(tnguyen)
Assignee: nobody → tnguyen
Priority: -- → P3
See Also: → 1284763
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
Attachment #8820605 - Flags: review?(franziskuskiefer)
Attachment #8820605 - Flags: review?(franziskuskiefer) → review+
Thanks ：）
Keywords: checkin-needed
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
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/c4ae65fa000a
Status: NEW → RESOLVED
Closed: 7 years ago
status-firefox53: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla53
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.)
Status: RESOLVED → REOPENED
status-firefox53: fixed → affected
Resolution: FIXED → ---
Target Milestone: mozilla53 → ---
Likely I was wrong to check the root cause of intermittent, thanks for backing out this.
Flags: needinfo?(tnguyen)
Assignee: tnguyen → nobody
Whiteboard: [stockwell needswork]
: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).
Blocks: 1335751
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.
Flags: needinfo?(gbrown)
Depends on: 1346874
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.
Status: REOPENED → RESOLVED
Closed: 7 years ago → 7 years ago
Resolution: --- → FIXED
Whiteboard: [stockwell needswork] → [stockwell fixed]
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Priority: P3 → P5
Status: REOPENED → RESOLVED
Closed: 7 years ago → 7 years ago
Resolution: --- → FIXED
Whiteboard: [stockwell fixed] → [stockwell fixed:other]
Assignee: nobody → tnguyen
Component: DOM → DOM: Core & HTML
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: