Closed Bug 1345722 Opened 3 years ago Closed 3 years ago

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.

Categories

(WebExtensions :: Request Handling, defect)

defect
Not set

Tracking

(firefox54 fixed, firefox55 fixed)

RESOLVED FIXED
mozilla55
Tracking Status
firefox54 --- fixed
firefox55 --- fixed

People

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

References

Details

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

Attachments

(1 file)

: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.
Component: WebExtensions: Untriaged → WebExtensions: Request Handling
Flags: needinfo?(lgreco)
Whiteboard: [stockwell needswork]
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.
Attachment #8849215 - Flags: review?(mixedpuppy)
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).
Assignee: nobody → lgreco
Status: NEW → ASSIGNED
Flags: needinfo?(lgreco)
Comment on attachment 8849215 [details]
Bug 1345722 - Split webNavigation onCreatedNavigationTarget tests to prevent them to fail intermittently.

https://reviewboard.mozilla.org/r/122040/#review124072
Attachment #8849215 - Flags: review?(mixedpuppy) → review+
Pushed by ryanvm@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/b6fa6328adef
Split webNavigation onCreatedNavigationTarget tests to prevent them to fail intermittently. r=mixedpuppy
Keywords: checkin-needed
Whiteboard: [stockwell needswork] → [stockwell fixed]
https://hg.mozilla.org/mozilla-central/rev/b6fa6328adef
Status: ASSIGNED → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla55
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
Attachment #8849215 - Flags: approval-mozilla-aurora?
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+.
Attachment #8849215 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
Product: Toolkit → WebExtensions
You need to log in before you can comment on or make changes to this bug.