Closed Bug 1453163 Opened 2 years ago Closed 2 years ago

Intermittent TEST-UNEXPECTED-TIMEOUT | browser/components/extensions/test/browser/browser_ext_connect_and_move_tabs.js | application timed out after 370 seconds with no output

Categories

(WebExtensions :: General, defect)

defect
Not set

Tracking

(firefox61 fixed)

RESOLVED FIXED
mozilla61
Tracking Status
firefox61 --- fixed

People

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

References

Details

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

Attachments

(1 file)

Filed by: ccoroiu [at] mozilla.com

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

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

[task 2018-04-10T21:29:26.611Z] 21:29:26     INFO - TEST-START | browser/components/extensions/test/browser/browser_ext_connect_and_move_tabs.js
[task 2018-04-10T21:29:30.350Z] 21:29:30     INFO - GECKO(1049) | Assertion failure
[task 2018-04-10T21:29:30.352Z] 21:29:30     INFO - GECKO(1049) | assert@resource:///modules/AsyncTabSwitcher.jsm:447:36
[task 2018-04-10T21:29:30.353Z] 21:29:30     INFO - GECKO(1049) | finish@resource:///modules/AsyncTabSwitcher.jsm:300:5
[task 2018-04-10T21:29:30.355Z] 21:29:30     INFO - GECKO(1049) | postActions@resource:///modules/AsyncTabSwitcher.jsm:609:7
[task 2018-04-10T21:29:30.356Z] 21:29:30     INFO - GECKO(1049) | handleEvent@resource:///modules/AsyncTabSwitcher.jsm:968:5
[task 2018-04-10T21:29:30.357Z] 21:29:30     INFO - GECKO(1049) | swapDocShells@chrome://global/content/bindings/browser.xml:1483:11
[task 2018-04-10T21:29:30.359Z] 21:29:30     INFO - GECKO(1049) | _swapBrowserDocShells@chrome://browser/content/tabbrowser.js:3189:5
[task 2018-04-10T21:29:30.360Z] 21:29:30     INFO - GECKO(1049) | swapBrowsersAndCloseOther@chrome://browser/content/tabbrowser.js:3093:7
[task 2018-04-10T21:29:30.362Z] 21:29:30     INFO - GECKO(1049) | onLoad@chrome://browser/content/browser.js:1368:9
[task 2018-04-10T21:29:30.363Z] 21:29:30     INFO - GECKO(1049) | onload@chrome://browser/content/browser.xul:1:1
[task 2018-04-10T21:29:30.594Z] 21:29:30     INFO - GECKO(1049) | JavaScript error: chrome://extensions/content/parent/ext-tabs-base.js, line 0: Error: Invalid window ID: 3
[task 2018-04-10T21:29:30.596Z] 21:29:30     INFO - GECKO(1049) | JavaScript error: chrome://extensions/content/parent/ext-tabs-base.js, line 0: Error: Invalid window ID: 3
[task 2018-04-10T21:35:40.615Z] 21:35:40     INFO - Buffered messages logged at 21:29:26
[task 2018-04-10T21:35:40.616Z] 21:35:40     INFO - Entering test bound contentscript_connect_and_move_tabs
[task 2018-04-10T21:35:40.617Z] 21:35:40     INFO - Extension loaded
[task 2018-04-10T21:35:40.618Z] 21:35:40     INFO - Buffered messages logged at 21:29:27
[task 2018-04-10T21:35:40.620Z] 21:35:40     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_connect_and_move_tabs.js | expected message - Expected: connect_from_contentscript, Actual: connect_from_contentscript - 
[task 2018-04-10T21:35:40.621Z] 21:35:40     INFO - Buffered messages logged at 21:29:28
[task 2018-04-10T21:35:40.622Z] 21:35:40     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_connect_and_move_tabs.js | expected message - Expected: ping, Actual: ping - 
[task 2018-04-10T21:35:40.623Z] 21:35:40     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_connect_and_move_tabs.js | expected message - Expected: disconnect-me, Actual: disconnect-me - 
[task 2018-04-10T21:35:40.623Z] 21:35:40     INFO - Buffered messages logged at 21:29:29
[task 2018-04-10T21:35:40.624Z] 21:35:40     INFO - Leaving test bound contentscript_connect_and_move_tabs
[task 2018-04-10T21:35:40.625Z] 21:35:40     INFO - Entering test bound extension_tab_connect_and_move_tabs
[task 2018-04-10T21:35:40.626Z] 21:35:40     INFO - Extension loaded
[task 2018-04-10T21:35:40.627Z] 21:35:40     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_connect_and_move_tabs.js | expected message - Expected: connect_from_contentscript, Actual: connect_from_contentscript - 
[task 2018-04-10T21:35:40.628Z] 21:35:40     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_connect_and_move_tabs.js | expected message - Expected: open_extension_tab, Actual: open_extension_tab - 
[task 2018-04-10T21:35:40.629Z] 21:35:40     INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_connect_and_move_tabs.js | expected message - Expected: connect_from_contentscript, Actual: connect_from_contentscript - 
[task 2018-04-10T21:35:40.630Z] 21:35:40     INFO - Buffered messages logged at 21:29:30
[task 2018-04-10T21:35:40.631Z] 21:35:40     INFO - Console message: [JavaScript Error: "Error: Invalid window ID: 3" {file: "chrome://extensions/content/parent/ext-tabs-base.js" line: 0}]
[task 2018-04-10T21:35:40.632Z] 21:35:40     INFO - Console message: [JavaScript Error: "Error: Invalid window ID: 3" {file: "chrome://extensions/content/parent/ext-tabs-base.js" line: 0}]
[task 2018-04-10T21:35:40.633Z] 21:35:40     INFO - Buffered messages finished
[task 2018-04-10T21:35:40.634Z] 21:35:40    ERROR - TEST-UNEXPECTED-TIMEOUT | browser/components/extensions/test/browser/browser_ext_connect_and_move_tabs.js | application timed out after 370 seconds with no output
[task 2018-04-10T21:35:40.638Z] 21:35:40    ERROR - Force-terminating active process(es).
[task 2018-04-10T21:35:40.640Z] 21:35:40     INFO - Determining child pids from psutil...
[task 2018-04-10T21:35:40.640Z] 21:35:40     INFO - [1194, 1159, 1223, 1103]
[task 2018-04-10T21:35:40.641Z] 21:35:40     INFO - ==> process 1049 launched child process 1072
[task 2018-04-10T21:35:40.642Z] 21:35:40     INFO - ==> process 1049 launched child process 1103
[task 2018-04-10T21:35:40.643Z] 21:35:40     INFO - ==> process 1049 launched child process 1159
[task 2018-04-10T21:35:40.644Z] 21:35:40     INFO - ==> process 1049 launched child process 1194
[task 2018-04-10T21:35:40.645Z] 21:35:40     INFO - ==> process 1049 launched child process 1223
[task 2018-04-10T21:35:40.645Z] 21:35:40     INFO - Found child pids: set([1072, 1194, 1223, 1103, 1159])
[task 2018-04-10T21:35:40.646Z] 21:35:40     INFO - Failed to get child procs
[task 2018-04-10T21:35:40.648Z] 21:35:40     INFO - Killing process: 1072
The following error message suggests that the initial window is no longer valid.
If this is accurate, then the tab might be the last tab in the window before it was moved, and the bug can be solved by opening a temporary tab before detaching the tab under test.

[task 2018-04-10T21:35:40.631Z] 21:35:40     INFO - Console message: [JavaScript Error: "Error: Invalid window ID: 3" {file: "chrome://extensions/content/parent/ext-tabs-base.js" line: 0}]
[task 2018-04-10T21:35:40.632Z] 21:35:40     INFO - Console message: [JavaScript Error: "Error: Invalid window ID: 3" {file: "chrome://extensions/content/parent/ext-tabs-base.js" line: 0}]
Assignee: nobody → rob
Status: NEW → ASSIGNED
Flags: needinfo?(rob)
(In reply to Rob Wu [:robwu] from comment #1)
> The following error message suggests that the initial window is no longer
> valid.
> If this is accurate, then the tab might be the last tab in the window before
> it was moved, and the bug can be solved by opening a temporary tab before
> detaching the tab under test.

The failure in comment 0 occured in the extension page test, where the new tab is opened with browser.tabs.create().  No windowId argument is passed to create() so the documented behavior is that this should open in the "current window" which should be the window with the main mochitest page open.  The fact that this is an intermittent failure, together with these logs:
https://treeherder.mozilla.org/logviewer.html#?job_id=172957706&repo=autoland&lineNumber=2012-2021
makes me suspect that the theory from comment 1 isn't right, but that this is a race with moving the tab around too quickly confusing AsyncTabSwitcher.
That sounds like a pre-existing bug that this test just uncovered, but could you dig into that a little deeper?
Flags: needinfo?(rob)
The error message "Invalid window ID: 3" is attributed to ext-tabs-base.js, to the getWindow method of WindowTrackerBase.
https://searchfox.org/mozilla-central/rev/9f3da81290054c5b8955bb67ff98cae66676f745/toolkit/components/extensions/parent/ext-tabs-base.js#1426

The error is shown twice. The only way to call windowTracker.getWindow twice from the test is through browser.tabs.move.
Further, the windowId of the initial window is 3.

So the initial window is really closed.


The log files show that before the extension tab is opened, that the background page already receives a message from a script:
... Entering test bound extension_tab_connect_and_move_tabs
... Expected: connect_from_script, Actual: connect_from_script -
... Expected: open_extension_tab, Actual: open_extension_tab -
... Expected: connect_from_script, Actual: connect_from_script -
... [JavaScript Error: "Error: Invalid window ID: 3" {file: "chrome://extensions/content/parent/ext-tabs-base.js" line: 0}]
... [JavaScript Error: "Error: Invalid window ID: 3" {file: "chrome://extensions/content/parent/ext-tabs-base.js" line: 0}]
(based on https://treeherder.mozilla.org/logviewer.html#?job_id=173511409&repo=mozilla-central&lineNumber=4466-4472 )

This likely means that the ?discoTest from the previous test is still open ( https://searchfox.org/mozilla-central/rev/9f3da81290054c5b8955bb67ff98cae66676f745/browser/components/extensions/test/browser/browser_ext_connect_and_move_tabs.js#77 ).

I guess that what happens in browser_ext_connect_and_move_tabs.js is (in chronological order):

1. line 83: BrowserTestUtils.removeTab(gBrowser.selectedTab) removes the initial mochi.test page (instead of ?discoTest).
   (Now contentscript_connect_and_move_tabs ends, and extension_tab_connect_and_move_tabs starts)
2. line 89: extension.startup() loads the extension, which runs a content script at ?discoTest
3. Line 90: starts the extension test, which opens a new extension tab.
   (Now we have two tabs in the window, and two tests are inadvertently running in parallel).
4. Line 27 or line 29 moves the ?discoTest tab to a new window.
5. Line 27 moves the extension tab to a new window. Since this is the last tab, the window is closed.
6. Line 28 and 29 attempt to move the extension tab back to the window, but since it was closed, that fails and the console shows: "Error: Invalid window ID: 3"

This seems plausible, so to work around the unexpected event of line 1, I'm going to not use BrowserTestUtils.removeTab, but browser.tabs.remove to close the tab.
Flags: needinfo?(rob)
Comment on attachment 8966969 [details]
Bug 1453163 - Ensure that the ?discoTest tab is closed

https://reviewboard.mozilla.org/r/235658/#review243074
Attachment #8966969 - Flags: review?(aswan) → review+
Pushed by rob@robwu.nl:
https://hg.mozilla.org/integration/autoland/rev/118b16b6ab5d
Ensure that the ?discoTest tab is closed  r=aswan
https://hg.mozilla.org/mozilla-central/rev/118b16b6ab5d
Status: ASSIGNED → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla61
Blocks: 1453260
Whiteboard: [stockwell disable-recommended] → [stockwell fixed:other]
Flags: qe-verify-
Product: Toolkit → WebExtensions
You need to log in before you can comment on or make changes to this bug.