1345722 - Intermittent browser/components/extensions/test/browser/test-oop-extensions/browser_ext_webNavigation_onCreatedNavigationTarget.js | This test exceeded the timeout threshold. It should be rewritten or split up.

Status: RESOLVED FIXED

(WebExtensions :: Request Handling, defect)

Description

[Treeherder Bug Filer]

Filed by: philringnalda [at] gmail.com

https://treeherder.mozilla.org/logviewer.html#?job_id=82621054&repo=mozilla-inbound

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

Comment 2

[Intermittent Failures Robot]

5 failures in 790 pushes (0.006 failures/push) were associated with this bug in the last 7 days.   

Repository breakdown:
* mozilla-inbound: 2
* mozilla-central: 1
* mozilla-aurora: 1
* graphics: 1

Platform breakdown:
* linux32: 5

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1345722&startday=2017-03-06&endday=2017-03-12&tree=all

Comment 3

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

:rpl, this has been picking up in frequency this week:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1345722&startday=2017-03-10&endday=2017-03-17&tree=all

primarily on linux32 debug, but a bit on linux64 debug as well. all on e10s only.

I see this is a fairly new test (so I have confidence you are the right person to work on this!)

here is a linux32 debug failure:
https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=84542228&lineNumber=25467

which has a corresponding screenshot (not that useful imo):
https://public-artifacts.taskcluster.net/CaL5qCYMRjS49vmevopSXA/0/public/test_info//mozilla-test-fail-screenshot_zTIbjR.png

and data from the failing log:
[task 2017-03-17T06:37:46.211055Z] 06:37:46     INFO - Buffered messages logged at 06:37:28
[task 2017-03-17T06:37:46.213054Z] 06:37:46     INFO - Extension loaded
[task 2017-03-17T06:37:46.215559Z] 06:37:46     INFO - Console message: Warning: attempting to write 15441 bytes to preference extensions.webextensions.uuids. This is bad for general performance and memory usage. Such an amount of data should rather be written to an external file. This preference will not be sent to any content processes.
[task 2017-03-17T06:37:46.217786Z] 06:37:46     INFO - Buffered messages logged at 06:37:31
[task 2017-03-17T06:37:46.219867Z] 06:37:46     INFO - Open a subframe link in a new tab from the context menu
[task 2017-03-17T06:37:46.222194Z] 06:37:46     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_webNavigation_onCreatedNavigationTarget.js | found contextMenu item for "Open Link in New Tab" - 
[task 2017-03-17T06:37:46.225714Z] 06:37:46     INFO - Buffered messages logged at 06:37:35
[task 2017-03-17T06:37:46.227916Z] 06:37:46     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_webNavigation_onCreatedNavigationTarget.js | Got the expected tabId property - 
[task 2017-03-17T06:37:46.231132Z] 06:37:46     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_webNavigation_onCreatedNavigationTarget.js | Got the expected sourceTabId property - 
[task 2017-03-17T06:37:46.233393Z] 06:37:46     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_webNavigation_onCreatedNavigationTarget.js | Got the expected sourceFrameId property - 
[task 2017-03-17T06:37:46.236960Z] 06:37:46     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_webNavigation_onCreatedNavigationTarget.js | Got the expected url property - 
[task 2017-03-17T06:37:46.239443Z] 06:37:46     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_webNavigation_onCreatedNavigationTarget.js | Got the expected webNavigation.onCompleted tabId property - 
[task 2017-03-17T06:37:46.241797Z] 06:37:46     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_webNavigation_onCreatedNavigationTarget.js | Got the expected webNavigation.onCompleted url property - 
[task 2017-03-17T06:37:46.245110Z] 06:37:46     INFO - Open a subframe link in a new window from the context menu
[task 2017-03-17T06:37:46.247514Z] 06:37:46     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_webNavigation_onCreatedNavigationTarget.js | found contextMenu item for "Open Link in New Window" - 
[task 2017-03-17T06:37:46.249583Z] 06:37:46     INFO - Buffered messages logged at 06:37:41
[task 2017-03-17T06:37:46.253874Z] 06:37:46     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_webNavigation_onCreatedNavigationTarget.js | Got the expected tabId property - 
[task 2017-03-17T06:37:46.256398Z] 06:37:46     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_webNavigation_onCreatedNavigationTarget.js | Got the expected sourceTabId property - 
[task 2017-03-17T06:37:46.258795Z] 06:37:46     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_webNavigation_onCreatedNavigationTarget.js | Got the expected sourceFrameId property - 
[task 2017-03-17T06:37:46.266979Z] 06:37:46     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_webNavigation_onCreatedNavigationTarget.js | Got the expected url property - 
[task 2017-03-17T06:37:46.269631Z] 06:37:46     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_webNavigation_onCreatedNavigationTarget.js | Got the expected webNavigation.onCompleted tabId property - 
[task 2017-03-17T06:37:46.274262Z] 06:37:46     INFO - TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_webNavigation_onCreatedNavigationTarget.js | Got the expected webNavigation.onCompleted url property - 
[task 2017-03-17T06:37:46.277127Z] 06:37:46     INFO - Buffered messages logged at 06:37:42
[task 2017-03-17T06:37:46.280408Z] 06:37:46     INFO - Leaving test bound test_on_created_navigation_target_from_context_menu_subframe
[task 2017-03-17T06:37:46.282419Z] 06:37:46     INFO - Buffered messages finished
[task 2017-03-17T06:37:46.285163Z] 06:37:46     INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_webNavigation_onCreatedNavigationTarget.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. - 
[task 2017-03-17T06:37:46.291989Z] 06:37:46     INFO - GECKO(1278) | MEMORY STAT | vsize 1075MB | residentFast 313MB | heapAllocated 126MB
[task 2017-03-17T06:37:46.294244Z] 06:37:46     INFO - TEST-OK | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_webNavigation_onCreatedNavigationTarget.js | took 94154ms


I see this takes 70+ seconds to run normally (on linux32 debug- avg is 82 seconds) and similar for linux64 debug.  Windows debug is so much faster.

Given the already long runs, I would be fine with a requestLongerTimeout unless we can see an easy way to split the test up :)  My concern is we find the one case that is causing this to timeout and then something happens 3 months later and we end up splitting the test or requesting a longer timeout.

Comment 4

[Luca Greco [:rpl] [:luca] [:lgreco]]

Hi :jmaher,
thanks for all the additional details you collected on this intermittent, I noticed that this was starting to fail intermittently during this week and I was planning to taking a look at it asap.

I'm going to opt for splitting this test into two or three test files (and move the shared helpers into a test asset file).

Some notes on this test and the possible timeout reasons: 
this test file opens and closes a number of tabs and windows to test the webNavigation.onCreatedNavigationTarget event, which is probably what introduces the latency time into this tests that make it to fail for timeout (in fact, none of the test case seems to actually fail, the test file goes in timeout while is exiting), and it also waits for the opened tab/window has been loaded before exiting the test (because the WebNavigationContent.js framescript runs in the child process and the test extension does not wait it to be unloaded/disabled when the extension is unloaded and so the framescript will be wrongly detected as a leak if we exit the test too soon), which probably makes this test to take even more time to exit completely.

Comment 5

[Intermittent Failures Robot]

90 failures in 777 pushes (0.116 failures/push) were associated with this bug in the last 7 days. 

This is the #15 most frequent failure this week. 

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

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

Repository breakdown:
* autoland: 48
* mozilla-inbound: 19
* mozilla-central: 14
* try: 5
* graphics: 3
* oak: 1

Platform breakdown:
* linux32: 65
* linux64: 25

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1345722&startday=2017-03-13&endday=2017-03-19&tree=all

Comment 6

[Luca Greco [:rpl] [:luca] [:lgreco]]

Attachment: Bug 1345722 - Split webNavigation onCreatedNavigationTarget tests to prevent them to fail intermittently.

Review commit: https://reviewboard.mozilla.org/r/122040/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/122040/

Comment 7

[Luca Greco [:rpl] [:luca] [:lgreco]]

By looking at the orangefactor graph, this test file has started to fail intermittently (with an increasing rate of failures), starting from the day after the landing of Bug 1344376, which added some additional test cases to that file.

I've just attached a patch which splits the test file into two test files, the new test file is testing all the scenarios related to the context menu, while the original test file is now testing only the scenarios related to the mouse clicks (which is consistent with the current onCreatedNavigationTarget test files split, where all the tests which are related to the window.open calls are in their own test file).

(The new test file has been created using "hg cp", so that the diff shows the changes applied on both files and it should also make the review easier).

Comment 8

[Shane Caraveo (:mixedpuppy)]

Comment on attachment 8849215 [details]
Bug 1345722 - Split webNavigation onCreatedNavigationTarget tests to prevent them to fail intermittently.

https://reviewboard.mozilla.org/r/122040/#review124072

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/b6fa6328adef
Split webNavigation onCreatedNavigationTarget tests to prevent them to fail intermittently. r=mixedpuppy

Comment 10

[Intermittent Failures Robot]

43 failures in 136 pushes (0.316 failures/push) were associated with this bug yesterday.   

Repository breakdown:
* autoland: 24
* mozilla-inbound: 12
* graphics: 5
* try: 1
* mozilla-central: 1

Platform breakdown:
* linux32: 26
* linux64: 16
* windows8-64: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1345722&startday=2017-03-20&endday=2017-03-20&tree=all

Comment 11

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/b6fa6328adef

Comment 12

[Intermittent Failures Robot]

18 failures in 174 pushes (0.103 failures/push) were associated with this bug yesterday.   

Repository breakdown:
* mozilla-inbound: 10
* try: 4
* mozilla-central: 3
* graphics: 1

Platform breakdown:
* linux32: 11
* linux64: 7

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1345722&startday=2017-03-21&endday=2017-03-21&tree=all

Comment 13

[Luca Greco [:rpl] [:luca] [:lgreco]]

Comment on attachment 8849215 [details]
Bug 1345722 - Split webNavigation onCreatedNavigationTarget tests to prevent them to fail intermittently.

Approval Request Comment
[Feature/Bug causing the regression]:
Bug 1344376 (onCreatedNavigationTarget not called when clicking a target="_blank" link) added to the webNavigation onCreatedNavigationTarget tests some additional test cases to cover the additional scenarios, and this intermittent has started exactly when we landed these additional tests.

This patch splitted the test file and prevented it to fail intermittently on Nightly, and now that Bug 1344376 has been uplifted to aurora, this test-only change should also be uplifted to aurora to prevent the above test from failing intermittently on aurora.

[User impact if declined]:
None, this change is test-only.

[Is this code covered by automated tests?]:
This patchs split the automated tests into 2 sub test files.

[Has the fix been verified in Nightly?]:
It has been landed on Nightly 4 days ago and looking at the orangefactor graph it seems that this intermittent trend graph is now down 0:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1345722

[Needs manual test from QE? If yes, steps to reproduce]:
No

[List of other uplifts needed for the feature/fix]:
None

[Is the change risky?]:
No

[Why is the change risky/not risky?]:
It's a test only change.

[String changes made/needed]:
None

Comment 14

[Intermittent Failures Robot]

75 failures in 898 pushes (0.084 failures/push) were associated with this bug in the last 7 days. 

This is the #11 most frequent failure this week. 

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

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

Repository breakdown:
* mozilla-inbound: 28
* autoland: 24
* try: 12
* graphics: 7
* mozilla-central: 4

Platform breakdown:
* linux32: 43
* linux64: 31
* windows8-64: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1345722&startday=2017-03-20&endday=2017-03-26&tree=all

Comment 15

[Gerry Chang [:gchang]]

Comment on attachment 8849215 [details]
Bug 1345722 - Split webNavigation onCreatedNavigationTarget tests to prevent them to fail intermittently.

This patch is test-only for bug 1344376. Aurora54+.

Comment 16

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/0c7f65b96a48

Comment 17

[Intermittent Failures Robot]

1 failures in 814 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://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1345722&startday=2017-06-12&endday=2017-06-18&tree=all

Comment 18

[Intermittent Failures Robot]

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

Repository breakdown:
* mozilla-inbound: 1

Platform breakdown:
* linux64: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1345722&startday=2017-06-19&endday=2017-06-25&tree=all

Comment 19

[Intermittent Failures Robot]

2 failures in 720 pushes (0.003 failures/push) were associated with this bug in the last 7 days.   

Repository breakdown:
* autoland: 2

Platform breakdown:
* linux32: 2

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1345722&startday=2017-07-10&endday=2017-07-16&tree=all