Closed Bug 1453260 Opened 2 years ago Closed 2 years ago

Intermittent browser/components/extensions/test/browser/test-oop-extensions/browser_ext_connect_and_move_tabs.js | Error: Error: Attempt to postMessage on disconnected port :: @moz-extension://d02e4296-f26d-451b-9e1a-ddf81bc133

Categories

(WebExtensions :: General, defect, P5)

defect

Tracking

(firefox61 fixed)

RESOLVED FIXED
mozilla61
Tracking Status
firefox61 --- fixed

People

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

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

Filed by: apavel [at] mozilla.com

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

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

07:52:57     INFO -  295 INFO Console message: Warning: attempting to write 4961 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.
07:52:57     INFO -  296 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_connect_and_move_tabs.js | expected message - Expected: open_extension_tab, Actual: open_extension_tab -
07:52:57     INFO -  297 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_connect_and_move_tabs.js | expected message - Expected: connect_from_contentscript, Actual: connect_from_contentscript -
07:52:57     INFO -  298 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_connect_and_move_tabs.js | expected message - Expected: connect_from_contentscript, Actual: connect_from_contentscript -
07:52:57     INFO -  Buffered messages logged at 07:52:57
07:52:57     INFO -  299 INFO Console message: [JavaScript Error: "TypeError: win.gBrowser is undefined" {file: "resource:///modules/ProcessHangMonitor.jsm" line: 412}]
07:52:57     INFO -  300 INFO Console message: [JavaScript Error: "TypeError: win.gBrowser is undefined" {file: "resource:///modules/BrowserUsageTelemetry.jsm" line: 100}]
07:52:57     INFO -  301 INFO Console message: [JavaScript Error: "TypeError: win.gBrowser is undefined" {file: "resource:///modules/ProcessHangMonitor.jsm" line: 412}]
07:52:57     INFO -  302 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_connect_and_move_tabs.js | expected message - Expected: ping, Actual: ping -
07:52:57     INFO -  303 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_connect_and_move_tabs.js | expected message - Expected: disconnect-me, Actual: disconnect-me -
07:52:57     INFO -  304 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_connect_and_move_tabs.js | expected message - Expected: disconnect-me, Actual: disconnect-me -
07:52:57     INFO -  Buffered messages finished
07:52:57    ERROR -  305 INFO TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_connect_and_move_tabs.js | Error: Error: Attempt to postMessage on disconnected port :: @moz-extension://d02e4296-f26d-451b-9e1a-ddf81bc13391/%7Bac268a1c-a040-4ca6-b809-16bd40142005%7D.js:17:13
07:52:57     INFO -   -
07:52:57     INFO -  Stack trace:
07:52:57     INFO -      @moz-extension://d02e4296-f26d-451b-9e1a-ddf81bc13391/%7Bac268a1c-a040-4ca6-b809-16bd40142005%7D.js:19:13
07:52:57     INFO -  306 INFO Console message: Ignoring response to aborted listener for 256
07:52:57     INFO -  307 INFO Leaving test bound extension_tab_connect_and_move_tabs
07:52:57     INFO -  Not taking screenshot here: see the one that was previously logged
07:52:57    ERROR -  308 INFO TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_connect_and_move_tabs.js | message queue is empty - Got ["port_ping_ponged_before_disconnect"], expected []
07:52:57     INFO -  Stack trace:
07:52:57     INFO -      chrome://mochikit/content/browser-test.js:test_is:1280
07:52:57     INFO -      chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:27
07:52:57     INFO -      chrome://mochikit/content/browser-test.js:Tester.prototype.nextTest<:675
07:52:57     INFO -      testScope/test_finish/<@chrome://mochikit/content/browser-test.js:1372:11
07:52:57     INFO -      run@chrome://mochikit/content/browser-test.js:1309:9
07:52:57     INFO -  GECKO(7700) | MEMORY STAT | vsize 2099154MB | vsizeMaxContiguous 130240509MB | residentFast 438MB | heapAllocated 204MB
07:52:57     INFO -  309 INFO TEST-OK | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_connect_and_move_tabs.js | took 2955ms
07:52:57     INFO -  310 INFO checking window state
Given the duplicate log entries, I suspect that somewhere, there is an existing tab with URL "http://mochi.test:8888", which causes the content script to run in addition to the extension page.

Consequently, the test in the onConnect handler is run twice, causing the test to fail when the end-of-test signal from the first test instance interrupts the second test instance.

To fix this I am going to make the content script pattern more specific.
Assignee: nobody → rob
Status: NEW → ASSIGNED
Flags: needinfo?(rob)
Comment on attachment 8966960 [details]
Bug 1453260 - run test script in specific page only

https://reviewboard.mozilla.org/r/235646/#review241572

Ah yes, the main window is open on http://mochi.test:8888/

You could just use example.com or something instead but this works too.
Attachment #8966960 - Flags: review?(aswan) → review+
Pushed by rob@robwu.nl:
https://hg.mozilla.org/integration/autoland/rev/22ebb890e8ed
run test script in specific page only r=aswan
https://hg.mozilla.org/mozilla-central/rev/22ebb890e8ed
Status: ASSIGNED → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla61
Given this log https://treeherder.mozilla.org/logviewer.html#?job_id=173737499&repo=autoland&lineNumber=3050 this fails doesn't seem to be fixed. 

01:32:07     INFO -  253 INFO TEST-START | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_connect_and_move_tabs.js
01:32:08     INFO -  GECKO(4752) | JavaScript error: resource:///modules/BrowserUsageTelemetry.jsm, line 100: TypeError: win.gBrowser is undefined
01:32:08     INFO -  GECKO(4752) | JavaScript error: resource:///modules/ProcessHangMonitor.jsm, line 412: TypeError: win.gBrowser is undefined
01:32:09     INFO -  GECKO(4752) | JavaScript error: resource:///modules/ProcessHangMonitor.jsm, line 412: TypeError: win.gBrowser is undefined
01:32:09     INFO -  GECKO(4752) | JavaScript error: resource:///modules/BrowserUsageTelemetry.jsm, line 100: TypeError: win.gBrowser is undefined
01:32:09     INFO -  GECKO(4752) | JavaScript error: resource:///modules/ProcessHangMonitor.jsm, line 412: TypeError: win.gBrowser is undefined
01:32:10     INFO -  TEST-INFO | started process screenshot
01:32:10     INFO -  TEST-INFO | screenshot: exit 0
01:32:10     INFO -  Buffered messages logged at 01:32:07
01:32:10     INFO -  254 INFO Entering test bound contentscript_connect_and_move_tabs
01:32:10     INFO -  255 INFO Extension loaded
01:32:10     INFO -  256 INFO Console message: Warning: attempting to write 4881 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.
01:32:10     INFO -  257 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_connect_and_move_tabs.js | expected message - Expected: connect_from_script, Actual: connect_from_script -
01:32:10     INFO -  Buffered messages logged at 01:32:08
01:32:10     INFO -  258 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_connect_and_move_tabs.js | expected message - Expected: ping, Actual: ping -
01:32:10     INFO -  259 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_connect_and_move_tabs.js | expected message - Expected: disconnect-me, Actual: disconnect-me -
01:32:10     INFO -  260 INFO Leaving test bound contentscript_connect_and_move_tabs
01:32:10     INFO -  261 INFO Entering test bound extension_tab_connect_and_move_tabs
01:32:10     INFO -  262 INFO Extension loaded
01:32:10     INFO -  263 INFO Console message: Warning: attempting to write 4961 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.
01:32:10     INFO -  264 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_connect_and_move_tabs.js | expected message - Expected: open_extension_tab, Actual: open_extension_tab -
01:32:10     INFO -  265 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_connect_and_move_tabs.js | expected message - Expected: connect_from_script, Actual: connect_from_script -
01:32:10     INFO -  266 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_connect_and_move_tabs.js | expected message - Expected: connect_from_script, Actual: connect_from_script -
01:32:10     INFO -  Buffered messages logged at 01:32:09
01:32:10     INFO -  267 INFO Console message: [JavaScript Error: "TypeError: win.gBrowser is undefined" {file: "resource:///modules/BrowserUsageTelemetry.jsm" line: 100}]
01:32:10     INFO -  268 INFO Console message: [JavaScript Error: "TypeError: win.gBrowser is undefined" {file: "resource:///modules/ProcessHangMonitor.jsm" line: 412}]
01:32:10     INFO -  269 INFO Console message: [JavaScript Error: "TypeError: win.gBrowser is undefined" {file: "resource:///modules/ProcessHangMonitor.jsm" line: 412}]
01:32:10     INFO -  Buffered messages logged at 01:32:10
01:32:10     INFO -  270 INFO Console message: [JavaScript Error: "TypeError: win.gBrowser is undefined" {file: "resource:///modules/BrowserUsageTelemetry.jsm" line: 100}]
01:32:10     INFO -  271 INFO Console message: [JavaScript Error: "TypeError: win.gBrowser is undefined" {file: "resource:///modules/ProcessHangMonitor.jsm" line: 412}]
01:32:10     INFO -  272 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_connect_and_move_tabs.js | expected message - Expected: ping, Actual: ping -
01:32:10     INFO -  273 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_connect_and_move_tabs.js | expected message - Expected: disconnect-me, Actual: disconnect-me -
01:32:10     INFO -  274 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_connect_and_move_tabs.js | expected message - Expected: disconnect-me, Actual: disconnect-me -
01:32:10     INFO -  Buffered messages finished
01:32:10    ERROR -  275 INFO TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_connect_and_move_tabs.js | Error: Error: Attempt to postMessage on disconnected port :: @moz-extension://2b477953-e162-4a68-8365-92666154790f/%7Bee58ed18-10d5-4de9-a899-98ae113cad70%7D.js:17:13
01:32:10     INFO -   -
01:32:10     INFO -  Stack trace:
01:32:10     INFO -      @moz-extension://2b477953-e162-4a68-8365-92666154790f/%7Bee58ed18-10d5-4de9-a899-98ae113cad70%7D.js:19:13
01:32:10     INFO -  276 INFO Console message: Ignoring response to aborted listener for 259
01:32:10     INFO -  277 INFO Leaving test bound extension_tab_connect_and_move_tabs
01:32:10     INFO -  Not taking screenshot here: see the one that was previously logged
01:32:10    ERROR -  278 INFO TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_connect_and_move_tabs.js | message queue is empty - Got ["port_ping_ponged_before_disconnect"], expected []
01:32:10     INFO -  Stack trace:
01:32:10     INFO -      chrome://mochikit/content/browser-test.js:test_is:1280
01:32:10     INFO -      chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:27
01:32:10     INFO -      chrome://mochikit/content/browser-test.js:Tester.prototype.nextTest<:675
01:32:10     INFO -      testScope/test_finish/<@chrome://mochikit/content/browser-test.js:1372:11
01:32:10     INFO -      run@chrome://mochikit/content/browser-test.js:1309:9
01:32:10     INFO -  GECKO(4752) | MEMORY STAT | vsize 2099129MB | vsizeMaxContiguous 130434458MB | residentFast 409MB | heapAllocated 184MB
01:32:10     INFO -  279 INFO TEST-OK | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_connect_and_move_tabs.js | took 3355ms
01:32:10     INFO -  280 INFO checking window state
01:32:10     INFO -  281 INFO TEST-START | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_contentscript_animate.js
01:32:11     INFO -  GECKO(4752) | MEMORY STAT | vsize 2099199MB | vsizeMaxContiguous 130434391MB | residentFast 423MB | heapAllocated 168MB
01:32:11     INFO -  282 INFO TEST-OK | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_contentscript_animate.js | took 870ms
01:32:11     INFO -  283 INFO checking window state
01:32:11     INFO -  284 INFO TEST-START | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_contentscript_connect.js
01:32:12     INFO -  GECKO(4752) | MEMORY STAT | vsize 2099112MB | vsizeMaxContiguous 130434492MB | residentFast 411MB | heapAllocated 177MB
01:32:12     INFO -  285 INFO TEST-OK | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_contentscript_connect.js | took 561ms
01:32:12     INFO -  286 INFO checking window state
01:32:12     INFO -  287 INFO TEST-START | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_contextMenus.js
01:32:13     INFO -  GECKO(4752) | console.warn: LoginRecipes: getRecipes: falling back to a synchronous message for: http://mochi.test:8888
01:32:13     INFO -  GECKO(4752) | console.warn: nsLoginManager: searchLogins: `formSubmitURL` or `httpRealm` is recommended
01:32:13     INFO -  GECKO(4752) | console.warn: nsLoginManager: searchLogins: `formSubmitURL` or `httpRealm` is recommended
01:32:13     INFO -  GECKO(4752) | console.warn: nsLoginManager: searchLogins: `formSubmitURL` or `httpRealm` is recommended
01:32:13     INFO -  GECKO(4752) | console.warn: nsLoginManager: searchLogins: `formSubmitURL` or `httpRealm` is recommended
01:32:14     INFO -  GECKO(4752) | console.warn: nsLoginManager: searchLogins: `formSubmitURL` or `httpRealm` is recommended
01:32:14     INFO -  GECKO(4752) | console.warn: nsLoginManager: searchLogins: `formSubmitURL` or `httpRealm` is recommended
01:32:15     INFO -  GECKO(4752) | MEMORY STAT | vsize 2099118MB | vsizeMaxContiguous 130434481MB | residentFast 423MB | heapAllocated 176MB
01:32:15     INFO -  288 INFO TEST-OK | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_contextMenus.js | took 3682ms

Could you please take a look at this?
Flags: needinfo?(rob)
I believe that the new failure is caused by bug 1453163 (for the analysis, see https://bugzilla.mozilla.org/show_bug.cgi?id=1453163#c6 ).

The log before the ultimate error message contains only one entry for the "connect_from_script" message in the first subtest (contentscript_connect_and_move_tabs) (In contrast, when this bug was reported, the "connect_from_contentscript" message appeared twice):

> 254 INFO Entering test bound contentscript_connect_and_move_tabs
> 255 INFO Extension loaded
> 256 ...
> 257 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_connect_and_move_tabs.js | expected message - Expected: connect_from_script, Actual: connect_from_script -
> 258 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_connect_and_move_tabs.js | expected message - Expected: ping, Actual: ping -
> 259 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_connect_and_move_tabs.js | expected message - Expected: disconnect-me, Actual: disconnect-me -

The log immediately before the error shows that the "connect_from_script" message in the second subtest (extension_tab_connect_and_move_tabs) appears twice. This looks like bug 1453163 ( https://bugzilla.mozilla.org/show_bug.cgi?id=1453163#c6 ):

> 260 INFO Leaving test bound contentscript_connect_and_move_tabs
> 261 INFO Entering test bound extension_tab_connect_and_move_tabs
> 262 INFO Extension loaded
> 263 ...
> 264 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_connect_and_move_tabs.js | expected message - Expected: open_extension_tab, Actual: open_extension_tab -
> 265 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_connect_and_move_tabs.js | expected message - Expected: connect_from_script, Actual: connect_from_script -
> 266 INFO TEST-PASS | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_connect_and_move_tabs.js | expected message - Expected: connect_from_script, Actual: connect_from_script -

> 275 INFO TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_connect_and_move_tabs.js | Error: Error: Attempt to postMessage on disconnected port
Flags: needinfo?(rob)
Duplicate of this bug: 1454396
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Bug 1453163 has been resolved.
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Depends on: 1453163
Resolution: --- → FIXED
Flags: qe-verify-
Product: Toolkit → WebExtensions
You need to log in before you can comment on or make changes to this bug.