1458558 - Intermittent testing/mochitest/tests/browser/browser_BrowserTestUtils.js | Test timed out -

Status: RESOLVED INCOMPLETE

(Testing :: Mochitest, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: nbeleuzu [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=176565290&repo=autoland

https://queue.taskcluster.net/v1/task/KwUADw-rRQ2jygLW2dHlgw/runs/0/artifacts/public/logs/live_backing.log

Comment 1

[Intermittent Failures Robot]

37 failures in 110 pushes (0.336 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* mozilla-inbound: 15
* autoland: 12
* mozilla-central: 10

Platform breakdown:
* linux64: 12
* windows10-64: 10
* windows7-32: 9
* osx-10-10: 6

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1458558&startday=2018-05-02&endday=2018-05-02&tree=trunk

Comment 2

[Tiberius Oros[:tiberius_oros]]

There have been 47 failures in the last day.
This was filed 13 hours ago.

Failures per platform:
- Linux x64: 12
- OS X 10.10: 6
- Windows 7: 9
- windows10-64: 20
 

Failures per build type: 
- asan: 3
- debug: 13
- opt: 12
- pgo: 9

Here is a recent relevant log and a snippet with the failure:
https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=176572520&lineNumber=14346 
15:18:01     INFO -  18 INFO TEST-PASS | testing/mochitest/tests/browser/browser_BrowserTestUtils.js | synthesizeMouseAtCenter mouseup with complex selector cancelled -
15:18:01     INFO -  19 INFO Leaving test bound
15:18:01     INFO -  20 INFO Entering test bound
15:18:01     INFO -  Buffered messages finished
15:18:01    ERROR -  21 INFO TEST-UNEXPECTED-FAIL | testing/mochitest/tests/browser/browser_BrowserTestUtils.js | Test timed out -
15:18:01     INFO -  22 INFO TEST-PASS | testing/mochitest/tests/browser/browser_BrowserTestUtils.js | I'm a cleanup function in head file -
15:18:01     INFO -  23 INFO TEST-PASS | testing/mochitest/tests/browser/browser_BrowserTestUtils.js | Head cleanup function scope is correct -
15:18:01     INFO -  GECKO(5984) | MEMORY STAT | vsize 2098974MB | vsizeMaxContiguous 129942008MB | residentFast 284MB | heapAllocated 97MB
15:18:01     INFO -  24 INFO TEST-OK | testing/mochitest/tests/browser/browser_BrowserTestUtils.js | took 90072ms
15:18:01     INFO -  Not taking screenshot here: see the one that was previously logged
15:18:01    ERROR -  25 INFO TEST-UNEXPECTED-FAIL | testing/mochitest/tests/browser/browser_BrowserTestUtils.js | Found a tab after previous test timed out: about:blank -
15:18:01     INFO -  GECKO(5984) | ++DOCSHELL 0000020315742000 == 1 [pid = 3192] [id = {a7673208-a308-4860-88af-b9e55e71a58c}]
15:18:01     INFO -  GECKO(5984) | ++DOMWINDOW == 1 (000002031ADBEC00) [pid = 3192] [serial = 7] [outer = 0000000000000000]
15:18:01     INFO -  26 INFO checking window state

:jmaher, is this something to worry about considering it's a test-verify?

Comment 3

[Joel Maher ( :jmaher ) (UTC -8)]

we should ignore this- I believe the failure is gone now...but I want to see if I can fix this failure :)

Comment 4

[Joel Maher ( :jmaher ) (UTC -8)]

well some simple hacking didn't allow me to fix this bug- it appears that we register an about: handler, then unregistering it doesn't seem to work well- at least in a loop; we unregister but cannot register it again.

Comment 5

[Intermittent Failures Robot]

41 failures in 551 pushes (0.074 failures/push) were associated with this bug in the last 7 days. 

This is the #35 most frequent failure this week.  

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **  

Repository breakdown:
* mozilla-inbound: 19
* autoland: 12
* mozilla-central: 10

Platform breakdown:
* windows7-32: 12
* linux64: 12
* windows10-64: 11
* osx-10-10: 6

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1458558&startday=2018-04-30&endday=2018-05-06&tree=trunk

Comment 6

[Emma Humphries ☕️🎸🧞‍♀️✨ (she/they) [:emceeaich] (Pacific Time) use needinfo]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Comment 7

[Cristina Coroiu [:ccoroiu]]

Recent failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=190466228&repo=autoland&lineNumber=4127

[task 2018-07-27T08:11:50.197Z] 08:11:50     INFO - TEST-PASS | testing/mochitest/tests/browser/browser_BrowserTestUtils.js | I'm a test in head file - 
[task 2018-07-27T08:11:50.198Z] 08:11:50     INFO - Entering test bound 
[task 2018-07-27T08:11:50.199Z] 08:11:50     INFO - Buffered messages logged at 08:10:21
[task 2018-07-27T08:11:50.199Z] 08:11:50     INFO - Console message: [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "resource://gre/modules/FileUtils.jsm" line: 170}]
[task 2018-07-27T08:11:50.200Z] 08:11:50     INFO - Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "data:text/html,<body onclick='document.getElementById("out").textContent = event.target.localName + "," + event.clientX + "," + event.clientY;' style='margin: 0'><button id='one' style='margin: 0; margin-left: 16px; margin-top: 14px; width: 30px; height: 40px;'>Test</button><div onmousedown='event.preventDefault()' style='margin: 0; width: 80px; height: 60px;'>Other</div><span id='out'></span></body>" line: 0}]
[task 2018-07-27T08:11:50.201Z] 08:11:50     INFO - Buffered messages finished
[task 2018-07-27T08:11:50.203Z] 08:11:50     INFO - TEST-UNEXPECTED-FAIL | testing/mochitest/tests/browser/browser_BrowserTestUtils.js | Test timed out - 
[task 2018-07-27T08:11:50.205Z] 08:11:50     INFO - TEST-PASS | testing/mochitest/tests/browser/browser_BrowserTestUtils.js | I'm a cleanup function in head file - 
[task 2018-07-27T08:11:50.207Z] 08:11:50     INFO - TEST-PASS | testing/mochitest/tests/browser/browser_BrowserTestUtils.js | Head cleanup function scope is correct - 
[task 2018-07-27T08:11:50.210Z] 08:11:50     INFO - GECKO(4634) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
[task 2018-07-27T08:11:50.211Z] 08:11:50     INFO - GECKO(4634) | MEMORY STAT heapAllocated not supported in this build configuration.
[task 2018-07-27T08:11:50.212Z] 08:11:50     INFO - GECKO(4634) | MEMORY STAT | vsize 20973873MB | residentFast 964MB
[task 2018-07-27T08:11:50.213Z] 08:11:50     INFO - TEST-OK | testing/mochitest/tests/browser/browser_BrowserTestUtils.js | took 90500ms
[task 2018-07-27T08:11:50.215Z] 08:11:50     INFO - Not taking screenshot here: see the one that was previously logged
[task 2018-07-27T08:11:50.216Z] 08:11:50     INFO - TEST-UNEXPECTED-FAIL | testing/mochitest/tests/browser/browser_BrowserTestUtils.js | Found a tab after previous test timed out: data:text/html,<body onclick='document.getElementById("out").textContent = event.target.localName + "," + event.clientX + "," + event.clientY;' style='margin: 0'><button id='one' style='margin: 0; margin-left: 16px; margin-top: 14px; width: 30px; height: 40px;'>Test</button><div onmousedown='event.preventDefault()' style='margin: 0; width: 80px; height: 60px;'>Other</div><span id='out'></span></body> - 
[task 2018-07-27T08:11:50.218Z] 08:11:50     INFO - checking window state
[task 2018-07-27T08:11:50.219Z] 08:11:50     INFO - TEST-START | testing/mochitest/tests/browser/browser_add_task.js
[task 2018-07-27T08:11:50.228Z] 08:11:50     INFO - GECKO(4634) | MEMORY STAT | vsize 20973866MB | residentFast 956MB
[task 2018-07-27T08:11:50.229Z] 08:11:50     INFO - TEST-OK | testing/mochitest/tests/browser/browser_add_task.js | took 149ms
[task 2018-07-27T08:11:50.407Z] 08:11:50     INFO - checking window state
[task 2018-07-27T08:11:50.490Z] 08:11:50     INFO - TEST-START | testing/mochitest/tests/browser/browser_async.js
[task 2018-07-27T08:11:50.555Z] 08:11:50     INFO - Not taking screenshot here: see the one that was previously logged
[task 2018-07-27T08:11:50.556Z] 08:11:50     INFO - Buffered messages logged at 08:11:50
[task 2018-07-27T08:11:50.557Z] 08:11:50     INFO - TEST-PASS | testing/mochitest/tests/browser/browser_async.js | I'm a test in head file - 
[task 2018-07-27T08:11:50.557Z] 08:11:50     INFO - Buffered messages finished
[task 2018-07-27T08:11:50.558Z] 08:11:50     INFO - TEST-UNEXPECTED-FAIL | testing/mochitest/tests/browser/browser_BrowserTestUtils.js | Uncaught exception received from previously timed out test - at chrome://mochitests/content/browser/testing/mochitest/tests/browser/browser_BrowserTestUtils.js:16 - TypeError: BrowserTestUtils is null
[task 2018-07-27T08:11:50.558Z] 08:11:50     INFO - Stack trace:
[task 2018-07-27T08:11:50.559Z] 08:11:50     INFO - @chrome://mochitests/content/browser/testing/mochitest/tests/browser/browser_BrowserTestUtils.js:16:3
[task 2018-07-27T08:11:50.560Z] 08:11:50     INFO - Async*Tester_execTest/<@chrome://mochikit/content/browser-test.js:1103:34
[task 2018-07-27T08:11:50.560Z] 08:11:50     INFO - async*Tester_execTest@chrome://mochikit/content/browser-test.js:1094:16
[task 2018-07-27T08:11:50.561Z] 08:11:50     INFO - nextTest/<@chrome://mochikit/content/browser-test.js:996:9
[task 2018-07-27T08:11:50.561Z] 08:11:50     INFO - SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:795:59
[task 2018-07-27T08:11:51.002Z] 08:11:51     INFO - TEST-PASS | testing/mochitest/tests/browser/browser_async.js | timeout ran - 
[task 2018-07-27T08:11:51.002Z] 08:11:51     INFO - TEST-PASS | testing/mochitest/tests/browser/browser_async.js | I'm a cleanup function in head file - 
[task 2018-07-27T08:11:51.003Z] 08:11:51     INFO - TEST-PASS | testing/mochitest/tests/browser/browser_async.js | Head cleanup function scope is correct - 
[task 2018-07-27T08:11:51.020Z] 08:11:51     INFO - GECKO(4634) | MEMORY STAT | vsize 20973872MB | residentFast 964MB

Comment 8

[Intermittent Failures Robot]

1 failures in 760 pushes (0.001 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 1

Platform breakdown:
* linux64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1458558&startday=2018-07-23&endday=2018-07-29&tree=trunk

Comment 9

[Firefox Bug Husbandry Bot]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup