Closed
Bug 1453163
Opened 6 years ago
Closed 6 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)
WebExtensions
General
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
Assignee | ||
Comment 1•6 years ago
|
||
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)
Comment hidden (mozreview-request) |
Comment hidden (Intermittent Failures Robot) |
Comment 4•6 years ago
|
||
(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)
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Comment 6•6 years ago
|
||
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 hidden (mozreview-request) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 11•6 years ago
|
||
mozreview-review |
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+
Comment 12•6 years ago
|
||
Pushed by rob@robwu.nl: https://hg.mozilla.org/integration/autoland/rev/118b16b6ab5d Ensure that the ?discoTest tab is closed r=aswan
Comment 13•6 years ago
|
||
bugherder |
https://hg.mozilla.org/mozilla-central/rev/118b16b6ab5d
Status: ASSIGNED → RESOLVED
Closed: 6 years ago
status-firefox61:
--- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla61
Comment hidden (Intermittent Failures Robot) |
Updated•6 years ago
|
Whiteboard: [stockwell disable-recommended] → [stockwell fixed:other]
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Updated•6 years ago
|
Product: Toolkit → WebExtensions
You need to log in
before you can comment on or make changes to this bug.
Description
•