Closed Bug 1574917 Opened 5 years ago Closed 5 years ago

Intermittent mobile/android/components/extensions/test/mochitest/test_ext_tabs_get.html | Test timed out.

Categories

(WebExtensions :: Android, defect, P5)

Product:
WebExtensions
Component:
Android
Type:
defect

Tracking

(firefox-esr60 unaffected, firefox-esr68 unaffected, firefox69 unaffected, firefox70 fixed, firefox71 fixed)

Status:
RESOLVED FIXED
Milestone:
mozilla71
Tracking Flags:
Tracking Status
firefox-esr60 --- unaffected
firefox-esr68 --- unaffected
firefox69 --- unaffected
firefox70 --- fixed
firefox71 --- fixed

People

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

References

(Regression)

Details

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

Attachments

(1 file)

Bug 1574917 - Prevent GeckoSessions from being GC'd in tests
47 bytes, text/x-phabricator-request
RyanVM
: approval-mozilla-beta+
Details | Review

Filed by: aciure [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=262230769&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/ZllsT0SmTLuw5kiNquhy9w/runs/0/artifacts/public/logs/live_backing.log

[task 2019-08-19T11:27:26.499Z] 11:27:26 INFO - 3120 INFO TEST-START | mobile/android/components/extensions/test/mochitest/test_ext_tabs_get.html
[task 2019-08-19T11:29:12.219Z] 11:29:12 INFO - Failed to get top activity, retrying, once...
[task 2019-08-19T11:32:56.599Z] 11:32:56 INFO - Buffered messages logged at 11:27:25
[task 2019-08-19T11:32:56.599Z] 11:32:56 INFO - 3121 INFO add_task | Entering test
[task 2019-08-19T11:32:56.601Z] 11:32:56 INFO - 3122 INFO Extension loaded
[task 2019-08-19T11:32:56.601Z] 11:32:56 INFO - Buffered messages finished
[task 2019-08-19T11:32:56.601Z] 11:32:56 INFO - 3123 INFO TEST-UNEXPECTED-FAIL | mobile/android/components/extensions/test/mochitest/test_ext_tabs_get.html | Test timed out.
[task 2019-08-19T11:32:56.601Z] 11:32:56 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:275:18
[task 2019-08-19T11:32:56.601Z] 11:32:56 INFO - reportError@SimpleTest/TestRunner.js:121:22
[task 2019-08-19T11:32:56.601Z] 11:32:56 INFO - TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:18
[task 2019-08-19T11:32:56.601Z] 11:32:56 INFO - 3124 INFO TEST-UNEXPECTED-FAIL | mobile/android/components/extensions/test/mochitest/test_ext_tabs_get.html | Extension left running at test shutdown
[task 2019-08-19T11:32:56.601Z] 11:32:56 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:275:18
[task 2019-08-19T11:32:56.601Z] 11:32:56 INFO - ExtensionTestUtils.loadExtension/<@SimpleTest/ExtensionTestUtils.js:109:18
[task 2019-08-19T11:32:56.601Z] 11:32:56 INFO - executeCleanupFunction@SimpleTest/SimpleTest.js:1236:19
[task 2019-08-19T11:32:56.601Z] 11:32:56 INFO - SimpleTest.finish@SimpleTest/SimpleTest.js:1249:27
[task 2019-08-19T11:32:56.601Z] 11:32:56 INFO - killTest@SimpleTest/TestRunner.js:130:22
[task 2019-08-19T11:32:56.601Z] 11:32:56 INFO - 3125 INFO TEST-OK | mobile/android/components/extensions/test/mochitest/test_ext_tabs_get.html | took 321766ms
[task 2019-08-19T11:32:56.601Z] 11:32:56 INFO - 3126 ERROR /tests/mobile/android/components/extensions/test/mochitest/test_ext_tabs_get.html logged result after SimpleTest.finish(): Extension left running at test shutdown
[task 2019-08-19T11:32:56.601Z] 11:32:56 INFO - 3127 INFO TEST-START | mobile/android/components/extensions/test/mochitest/test_ext_tabs_insertCSS.html
[task 2019-08-19T11:32:56.601Z] 11:32:56 INFO - 3128 INFO TEST-OK | mobile/android/components/extensions/test/mochitest/test_ext_tabs_insertCSS.html | took 599ms
[task 2019-08-19T11:32:56.601Z] 11:32:56 INFO - 3129 INFO TEST-START | mobile/android/components/extensions/test/mochitest/test_ext_tabs_onUpdated.html
[task 2019-08-19T11:32:56.601Z] 11:32:56 INFO - 3130 INFO TEST-OK | mobile/android/components/extensions/test/mochitest/test_ext_tabs_onUpdated.html | took 2684ms
[task 2019-08-19T11:32:56.601Z] 11:32:56 INFO - 3131 INFO TEST-START | mobile/android/components/extensions/test/mochitest/test_ext_tabs_query.html
[task 2019-08-19T11:32:56.602Z] 11:32:56 INFO - 3132 INFO TEST-OK | mobile/android/components/extensions/test/mochitest/test_ext_tabs_query.html | took 432ms
[task 2019-08-19T11:32:56.602Z] 11:32:56 INFO - 3133 INFO TEST-START | mobile/android/components/extensions/test/mochitest/test_ext_tabs_sendMessage.html
[task 2019-08-19T11:32:56.603Z] 11:32:56 INFO - 3134 INFO TEST-OK | mobile/android/components/extensions/test/mochitest/test_ext_tabs_sendMessage.html | took 949ms
[task 2019-08-19T11:32:56.603Z] 11:32:56 INFO - 3135 INFO TEST-START | mobile/android/components/extensions/test/mochitest/test_ext_webNavigation_onCommitted.html
[task 2019-08-19T11:32:56.603Z] 11:32:56 INFO - 3136 INFO TEST-OK | mobile/android/components/extensions/test/mochitest/test_ext_webNavigation_onCommitted.html | took 352ms
[task 2019-08-19T11:32:56.604Z] 11:32:56 INFO - 3137 INFO TEST-START | Shutdown
[task 2019-08-19T11:32:56.604Z] 11:32:56 INFO - 3138 INFO Passed: 135
[task 2019-08-19T11:32:56.604Z] 11:32:56 WARNING - 3139 INFO Failed: 3
[task 2019-08-19T11:32:56.604Z] 11:32:56 WARNING - One or more unittests failed.
[task 2019-08-19T11:32:56.604Z] 11:32:56 INFO - 3140 INFO Todo: 0
[task 2019-08-19T11:32:56.604Z] 11:32:56 INFO - 3141 INFO Mode: e10s
[task 2019-08-19T11:32:56.604Z] 11:32:56 INFO - 3142 INFO Slowest: 321766ms - /tests/mobile/android/components/extensions/test/mochitest/test_ext_tabs_get.html
[task 2019-08-19T11:32:56.604Z] 11:32:56 INFO - 3143 INFO SimpleTest FINISHED
[task 2019-08-19T11:32:56.604Z] 11:32:56 INFO - wait for org.mozilla.geckoview.test complete; top activity=com.android.launcher3
[task 2019-08-19T11:32:56.710Z] 11:32:56 INFO - remoteautomation.py | Application ran for: 0:05:43.105992
[task 2019-08-19T11:32:59.245Z] 11:32:59 INFO - Stopping web server
[task 2019-08-19T11:32:59.248Z] 11:32:59 INFO - Stopping web socket server
[task 2019-08-19T11:32:59.269Z] 11:32:59 INFO - Stopping ssltunnel
[task 2019-08-19T11:32:59.290Z] 11:32:59 INFO - leakcheck | refcount logging is off, so leaks can't be detected!
[task 2019-08-19T11:32:59.290Z] 11:32:59 INFO - runtests.py | Running tests: end.
[task 2019-08-19T11:33:00.544Z] 11:33:00 INFO - Buffered messages finished
[task 2019-08-19T11:33:00.544Z] 11:33:00 INFO - Running manifest: modules/libjar/test/mochitest/mochitest.ini
[task 2019-08-19T11:33:00.988Z] 11:33:00 INFO - runtests.py | Failed to copy /builds/worker/workspace/build/tests/mochitest/hyphenation to profile
[task 2019-08-19T11:33:01.097Z] 11:33:01 INFO - pk12util: PKCS12 IMPORT SUCCESSFUL

The standard log files are not particularly informative. Look at logcat instead ("Job Details" -> "artifact uploaded: logcat-emulator-5554.log").

Example of failing test: https://taskcluster-artifacts.net/ZllsT0SmTLuw5kiNquhy9w/0/public/test_info//logcat-emulator-5554.log
Example of passing test: https://taskcluster-artifacts.net/IhxTlNTwRNS3JZZ7l71fiA/0/public/test_info//logcat-emulator-5554.log

In the good case, the following line appears eventually:

{"action":"test_status","time":1566552623667,"thread":null,"pid":null,"source":"mochitest","test":"/tests/mobile/android/components/extensions/test/mochitest/test_ext_tabs_get.html","subtest":"tabs.get should return tab with given id - Expected: 10108, Actual: 10108","status":"PASS","js_source":"TestRunner.js"}

In the bad case, this line does not appear. That means that either browser.tabs.create({}) did not resolve, or browser.tabs.get(tab1.id)) did not resolve.
In both log files I see the following, twice:

D GeckoViewNavigation[C]: loadURI: uri=about:blank where=1 flags=0x1 tp=null
D GeckoViewNavigation[C]: shouldLoadURI about:blank

... which suggests that both blank tabs have been created. The second tab would only be created if the first tabs.create({}) call returned, so that strongly suggests that the tabs.create({}) calls were successful (but it is entirely possible that this is merely a coincidence, and that the second tabs.create call got stuck).

The loadURI: uri= message is from GeckoViewNavigationChild.js, so I think that the last part of the tabs.create implementation completed successfully.

When I look at the logs again, I see:

E GeckoConsole: [JavaScript Error: "Error: Invalid tab ID: 10108" {file: "resource://gre/modules/ExtensionUtils.jsm" line: 0}]
I GeckoDump: Console message: [JavaScript Error: "Error: Invalid tab ID: 10108" {file: "resource://gre/modules/ExtensionUtils.jsm" line: 0}]

This means that the test indeed got stuck on the tabs.get call.

When tabs.create returns, the following logic has run: https://searchfox.org/mozilla-central/rev/325c1a707819602feff736f129cb36055ba6d94f/mobile/android/modules/geckoview/GeckoViewTab.jsm#172
Getting there means that the browser window has finished initializing.
Running that logic means that window.BrowserApp should have been set, and that the tabs.get call should eventually end up at https://searchfox.org/mozilla-central/rev/325c1a707819602feff736f129cb36055ba6d94f/mobile/android/components/extensions/ext-utils.js#326

The error message shows that one of the assumptions may be wrong.

Hi Rob, are there any updates here?
Krzysztof did not reply. This is still an ongoing issue, there are 22 total failures in the last 7 days and 136 total failures in the last 30 days on android-em-7-0-x86_64 debug and opt.

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=266458789&repo=autoland&lineNumber=6967

[task 2019-09-13T01:30:00.297Z] 01:30:00 INFO - 3122 INFO TEST-START | mobile/android/components/extensions/test/mochitest/test_ext_tabs_get.html
[task 2019-09-13T01:35:19.928Z] 01:35:19 INFO - Buffered messages logged at 01:29:50
[task 2019-09-13T01:35:19.928Z] 01:35:19 INFO - 3123 INFO add_task | Entering test
[task 2019-09-13T01:35:19.928Z] 01:35:19 INFO - 3124 INFO Extension loaded
[task 2019-09-13T01:35:19.928Z] 01:35:19 INFO - Buffered messages finished
[task 2019-09-13T01:35:19.928Z] 01:35:19 INFO - 3125 INFO TEST-UNEXPECTED-FAIL | mobile/android/components/extensions/test/mochitest/test_ext_tabs_get.html | Test timed out.
[task 2019-09-13T01:35:19.928Z] 01:35:19 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:277:18
[task 2019-09-13T01:35:19.928Z] 01:35:19 INFO - reportError@SimpleTest/TestRunner.js:121:22
[task 2019-09-13T01:35:19.928Z] 01:35:19 INFO - TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:18
[task 2019-09-13T01:35:19.928Z] 01:35:19 INFO - 3126 INFO TEST-UNEXPECTED-FAIL | mobile/android/components/extensions/test/mochitest/test_ext_tabs_get.html | Extension left running at test shutdown
[task 2019-09-13T01:35:19.928Z] 01:35:19 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:277:18
[task 2019-09-13T01:35:19.928Z] 01:35:19 INFO - ExtensionTestUtils.loadExtension/<@SimpleTest/ExtensionTestUtils.js:109:18
[task 2019-09-13T01:35:19.928Z] 01:35:19 INFO - executeCleanupFunction@SimpleTest/SimpleTest.js:1238:19
[task 2019-09-13T01:35:19.928Z] 01:35:19 INFO - SimpleTest.finish@SimpleTest/SimpleTest.js:1251:5
[task 2019-09-13T01:35:19.929Z] 01:35:19 INFO - killTest@SimpleTest/TestRunner.js:130:22
[task 2019-09-13T01:35:19.929Z] 01:35:19 INFO - 3127 INFO TEST-OK | mobile/android/components/extensions/test/mochitest/test_ext_tabs_get.html | took 320704ms
[task 2019-09-13T01:35:19.929Z] 01:35:19 INFO - 3128 ERROR /tests/mobile/android/components/extensions/test/mochitest/test_ext_tabs_get.html logged result after SimpleTest.finish(): Extension left running at test shutdown

Flags: needinfo?(rob)

logcat for comment 9 : https://taskcluster-artifacts.net/fgYTK-qLShWIzyaNMidduA/0/public/test_info//logcat-emulator-5554.log

I see something interesting (which was also present in the log from comment 5):

09-13 02:29:50.830 18047 18062 W Web Content: [JavaScript Warning: "The character encoding of a framed document was not declared. The document may appear different if viewed without the document framing it." {file: "http://mochi.test:8888/tests/mobile/android/components/extensions/test/mochitest/test_ext_tabs_get.html" line: 0}]
09-13 02:29:50.831 17979 17994 I GeckoDump: Console message: [JavaScript Warning: "The character encoding of a framed document was not declared. The document may appear different if viewed without the document framing it." {file: "http://mochi.test:8888/tests/mobile/android/components/extensions/test/mochitest/test_ext_tabs_get.html" line: 0}]
...
09-13 02:29:51.096 17979 17994 E GeckoConsole: [JavaScript Error: "Error: Invalid tab ID: 10108" {file: "resource://gre/modules/ExtensionUtils.jsm" line: 0}]
09-13 02:29:51.096 17979 17994 I GeckoDump: Console message: [JavaScript Error: "Error: Invalid tab ID: 10108" {file: "resource://gre/modules/ExtensionUtils.jsm" line: 0}]

The first digit after the timestamp is the processID.
pid 18047 is a content process that hosts the mochitest page.
pid 17979 is the main process.

The error "Error: Invalid tab ID: 10108" (ignore the "ExtensionUtils.jsm" part due to bug 1491115), together with other circumstancal information suggests that the following stack trace leads to the issue (bottom up):

The last part can only be reached if win, win.BrowserApp or win.BrowserApp.selectedTab is void.
Because the test calls tabs.get after tabs.create, win.BrowserApp.selectedTab has been non-void, at least initially (as BrowserAppShim.getBrowserApp(window).selectedTab was called, and the test code has received the tab ID for the given "window", so the return value was non-void). selectedTab is set once and never cleared, for sure. win.BrowserApp is assigned once (after the browser window has fully loaded, via the BrowserAppShim.getBrowserApp call mentioned before). From this, the conclusion is that win = windowTracker.getWindow(windowId, null, false) was void.

Now, we continue the search in windowTracker.getWindow. It returns void if any of the following conditions is true:

  • window = Services.wm.getOuterWindowWithId(id); is falsey
  • window.closed is true`
  • window.document.readyState === "complete" && window.document.documentElement.getAttribute("windowtype") !== WINDOW_TYPE (= "navigator:geckoview")

In the log, I see that two browser windows have been created (DOMWINDOW 0x7947fd75b000 and 0x7947fe1aa000), as well as two about:blank DOMWINDOWs in the content process (0x7948162b7d40 and 0x7948162b7f20), and that both of them are alive and well at the time of the test failure/timeout. This means that the window should definitely still be existing, so window cannot be null. The geckoview.xul document is still alive, so the third condition cannot be false either.

During development, Krzysztof mentioned that he saw that window.closed was sometimes true. I guess that we need to investigate whether window.closed (of the browser window) is reliable in GeckoView.

(keeping needinfo so that this stays in my queue)

Flags: needinfo?(krzysztof.modras)

After running geckoview-mochitests-e10s-3 over a hundred times, I managed to get a failure on try (with logging code that I added). That confirmed that window.closed was indeed true. I also ran the test in isolation with --verify (TV), and there was no failure, so the test failure might be caused by an interaction with a previous test.

Before the test started, win.close() was called from a different test (on a window that the test itself created with window.open) - https://searchfox.org/mozilla-central/rev/d1e33e3e11f559952d7d80e722d26a6cf5dd80ac/mobile/android/components/extensions/test/mochitest/test_ext_tabs_executeScript_runAt.html#128 . It seems that window.close() may result in the destruction of an unrelated browser window on GeckoView.

09-16 11:11:43.326 18031 18046 D GeckoViewContent[C]: handleEvent: DOMWindowClose
09-16 11:11:43.327 18031 18046 I GeckoDump: ⰲ겿{"action":"log","time":1568628703327,"thread":null,"pid":null,"source":"mochitest","level":"INFO","message":"add_task | Leaving test testExecuteScript","js_source":"TestRunner.js"}ⰲ겿
09-16 11:11:43.328 17960 18013 D EGL_emulation: eglMakeCurrent: 0x783546db6a80: ver 2 0 (tinfo 0x783538c9f0a0)
09-16 11:11:43.329 18031 18046 I GeckoDump: MEMORY STAT | vsize 3535MB | residentFast 123MB | heapAllocated 22MB
09-16 11:11:43.331 17960 17975 D GeckoViewNavigation: onDisable
09-16 11:11:43.331 17960 17975 D GeckoViewProcessHangMonitor: onDisable
09-16 11:11:43.332 17960 17975 D GeckoViewModule: unregisterListener
09-16 11:11:43.332 17960 17975 D GeckoViewProcessHangMonitor: onDestroy
09-16 11:11:43.333 17960 18013 D EGL_emulation: eglMakeCurrent: 0x783546db6a80: ver 2 0 (tinfo 0x783538c9f0a0)
09-16 11:11:43.333 18031 18046 D GeckoViewContent[C]: onDisable
09-16 11:11:43.334 18031 18046 D GeckoViewContent[C]: handleEvent: pagehide
09-16 11:11:43.334 18031 18046 D GeckoViewAutoFill: Clearing auto-fill
09-16 11:11:43.335 18031 18046 D GeckoViewContent[C]: handleEvent: pagehide
09-16 11:11:43.337 18031 18046 I GeckoDump: ⰲ겿{"action":"test_end","time":1568628703337,"thread":null,"pid":null,"source":"mochitest","test":"/tests/mobile/android/components/extensions/test/mochitest/test_ext_tabs_executeScript_runAt.html","status":"OK","message":"Finished in 4318ms","stack":{"runtime":4318},"js_source":"TestRunner.js"}ⰲ겿
09-16 11:11:43.338 18031 18046 D GeckoViewNavigation[C]: shouldLoadURI http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html
09-16 11:11:43.341 18031 18046 D GeckoViewSelectionAction[C]: handleEvent: visibilitychange
09-16 11:11:43.341 18031 18046 D GeckoViewContent[C]: handleEvent: pagehide
09-16 11:11:43.345 17960 17975 D GeckoViewNavigation: onLocationChange
09-16 11:11:43.345 17960 18013 D EGL_emulation: eglMakeCurrent: 0x783546db6120: ver 2 0 (tinfo 0x783538c9f0a0)
09-16 11:11:43.345 17960 17960 D GeckoSession: handleMessage GeckoView:LocationChange uri=http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html
09-16 11:11:43.347 18031 18046 W Web Content: [JavaScript Warning: "The character encoding of a framed document was not declared. The document may appear different if viewed without the document framing it." {file: "http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html" line: 0}]
09-16 11:11:43.348 18031 18046 D GeckoViewContent[C]: handleEvent: DOMTitleChanged
09-16 11:11:43.348 18031 18046 D GeckoViewContent[C]: handleEvent: DOMContentLoaded
09-16 11:11:43.349 18031 18046 I GeckoDump: ⰲ겿{"action":"test_start","time":1568628703350,"thread":null,"pid":null,"source":"mochitest","test":"/tests/mobile/android/components/extensions/test/mochitest/test_ext_tabs_get.html","js_source":"TestRunner.js"}ⰲ겿

This is the part of the test that got stuck - https://searchfox.org/mozilla-central/rev/d1e33e3e11f559952d7d80e722d26a6cf5dd80ac/mobile/android/components/extensions/test/mochitest/test_ext_tabs_get.html#23

09-16 11:11:43.606 17960 17975 I GeckoDump: BEFORE tabs.get(10108) - first
09-16 11:11:43.608 17960 17975 D GeckoViewNavigation: onDisable
09-16 11:11:43.608 18031 18046 D GeckoViewContent[C]: onEnable
09-16 11:11:43.609 17960 17975 D GeckoViewProcessHangMonitor: onDisable
09-16 11:11:43.609 17960 17975 D GeckoViewModule: unregisterListener
09-16 11:11:43.609 17960 17975 D GeckoViewProcessHangMonitor: onDestroy
09-16 11:11:43.609 18031 18046 D GeckoViewSettings[C]: onSettingsUpdate {"useMultiprocess":true,"chromeUri":null,"screenId":0,"userAgentOverride":null,"allowJavascript":true,"userAgentMode":0,"viewportMode":0,"useTrackingProtection":false,"suspendMediaWhenInactive":false,"usePrivateMode":false,"unsafeSessionContextId":null,"displayMode":0,"sessionContextId":null,"fullAccessibilityTree":false}
09-16 11:11:43.610 17960 17975 D GeckoViewNavigation: onDisable
09-16 11:11:43.610 17960 17975 D GeckoViewProcessHangMonitor: onDisable
09-16 11:11:43.610 17960 17975 D GeckoViewModule: unregisterListener
09-16 11:11:43.611 18031 18046 D GeckoViewContent[C]: handleEvent: DOMTitleChanged
09-16 11:11:43.611 17960 17975 D GeckoViewProcessHangMonitor: onDestroy
09-16 11:11:43.611 18031 18046 D GeckoViewContent[C]: handleEvent: DOMContentLoaded
09-16 11:11:43.611 18031 18046 D GeckoViewContent[C]: handleEvent: pageshow
09-16 11:11:43.612 18031 18046 D GeckoViewContent[C]: onDisable
09-16 11:11:43.612 18031 18046 D GeckoViewContent[C]: handleEvent: pagehide
09-16 11:11:43.612 18031 18046 D GeckoViewAutoFill: Clearing auto-fill
09-16 11:11:43.612 17960 18013 D EGL_emulation: eglMakeCurrent: 0x783546db6440: ver 2 0 (tinfo 0x783538c9f0a0)
09-16 11:11:43.613 18031 18046 D GeckoViewContent[C]: onDisable
09-16 11:11:43.614 18031 18046 D GeckoViewContent[C]: handleEvent: pagehide
09-16 11:11:43.614 18031 18046 D GeckoViewAutoFill: Clearing auto-fill
09-16 11:11:43.614 17960 17975 E GeckoConsole: [JavaScript Error: "TypeError: browser.ownerGlobal is null" {file: "chrome://geckoview/content/ext-tabs.js" line: 36}]
09-16 11:11:43.614 17960 17975 E GeckoConsole: [JavaScript Error: "RemoteWebProgress failed to call onLocationChange: [Exception... "[JavaScript Error: "browser.ownerGlobal is null" {file: "chrome://geckoview/content/ext-tabs.js" line: 36}]'[JavaScript Error: "browser.ownerGlobal is null" {file: "chrome://geckoview/content/ext-tabs.js" line: 36}]' when calling method: [nsIWebProgressListener::onLocationChange]"  nsresult: "0x80570021 (NS_ERROR_XPC_JAVASCRIPT_ERROR_WITH_DETAILS)"  location: "JS frame :: resource://gre/modules/RemoteWebProgress.jsm :: _callProgressListeners :: line 75"  data: yes]
09-16 11:11:43.614 17960 17975 E GeckoConsole: " {file: "resource://gre/modules/RemoteWebProgress.jsm" line: 77}]
09-16 11:11:43.614 17960 17975 E GeckoConsole: _callProgressListeners@resource://gre/modules/RemoteWebProgress.jsm:77:14
09-16 11:11:43.614 17960 17975 E GeckoConsole: onLocationChange@resource://gre/modules/RemoteWebProgress.jsm:117:10
09-16 11:11:43.615 18031 18046 W GeckoEditableChild: No editable parent
09-16 11:11:43.615 17960 17975 I GeckoDump: getWindow - 108 window=[object ChromeWindow] closed=true readyState=complete windowtype=navigator:geckoview BrowserApp=[object Object] selectedTab=[object Object]
09-16 11:11:43.616 17960 17975 I GeckoDump: Console message: [JavaScript Error: "TypeError: browser.ownerGlobal is null" {file: "chrome://geckoview/content/ext-tabs.js" line: 36}]
09-16 11:11:43.617 17960 17975 I GeckoDump: Console message: [JavaScript Error: "RemoteWebProgress failed to call onLocationChange: [Exception... "[JavaScript Error: "browser.ownerGlobal is null" {file: "chrome://geckoview/content/ext-tabs.js" line: 36}]'[JavaScript Error: "browser.ownerGlobal is null" {file: "chrome://geckoview/content/ext-tabs.js" line: 36}]' when calling method: [nsIWebProgressListener::onLocationChange]"  nsresult: "0x80570021 (NS_ERROR_XPC_JAVASCRIPT_ERROR_WITH_DETAILS)"  location: "JS frame :: resource://gre/modules/RemoteWebProgress.jsm :: _callProgressListeners :: line 75"  data: yes]
09-16 11:11:43.617 17960 17975 I GeckoDump: " {file: "resource://gre/modules/RemoteWebProgress.jsm" line: 77}]
09-16 11:11:43.617 17960 17975 I GeckoDump: _callProgressListeners@resource://gre/modules/RemoteWebProgress.jsm:77:14
09-16 11:11:43.617 17960 17975 I GeckoDump: onLocationChange@resource://gre/modules/RemoteWebProgress.jsm:117:10
09-16 11:11:43.617 17960 17975 I GeckoDump:
09-16 11:11:43.617 17960 17975 E GeckoConsole: [JavaScript Error: "Error: Invalid tab ID: 10108" {file: "resource://gre/modules/ExtensionUtils.jsm" line: 0}]
09-16 11:11:43.617 17960 17975 I GeckoDump: Console message: [JavaScript Error: "Error: Invalid tab ID: 10108" {file: "resource://gre/modules/ExtensionUtils.jsm" line: 0}]

The window is closed by garbage collection.

Reliable steps to reproduce, modify test case as follows:
https://searchfox.org/mozilla-central/rev/7ed8e2d3d1d7a1464ba42763a33fd2e60efcaedc/mobile/android/components/extensions/test/mochitest/test_ext_tabs_get.html#21-22

      const tab1 = await browser.tabs.create({});
// ADD THIS #1
      await new Promise(resolve => {
        browser.test.onMessage.addListener(resolve);
        browser.test.sendMessage("windows");
      });
// END ADDITION #1
      const tab2 = await browser.tabs.create({});

  await extension.startup();
// ADD THIS #2
  await extension.awaitMessage("windows");
  for (let i = 0; i < 100; ++i) { // Can probably be less, but this is lots of garbage.
    window.open("about:blank").close();
    await new Promise(resolve => setTimeout(resolve));
  }
  extension.sendMessage("resume");
// END ADDITION #2
  await extension.awaitFinish("tabs.get");
Assignee: nobody → rob
Status: NEW → ASSIGNED
Flags: needinfo?(rob)

... and document that the onNewSession/WebExtensionController.onNewTab
delegates are responsible for maintaining the lifetime of the returned
GeckoSession references.

Currently, the consequence of not keeping the reference is that the
browser window can be closed at an unpredictable moment, as seen in the
linked bug report.

This patch has been verified using the STR at
https://bugzilla.mozilla.org/show_bug.cgi?id=1574917#c13

Ooh, this is dangerous territory. I think that https://phabricator.services.mozilla.com/D46074 will certainly address this issue (at least, for a while -- until something else regresses) but I'd like to at least have the GeckoView experts capture about what the expectation is here. Is it desirable for foo = Gecko.giveMeAFoo() to have an implicit "drop Gecko-side foo" when foo goes out of scope on the JVM side?

Is it true that every pattern looks like, or should look like, that? I would expect some kind of .close()/try-with-resources pattern to be needed at least some of the time, which means that GeckoView has to know how to keep strong JVM references to at least some Gecko-side resources. Why aren't we using that here?

(In reply to Nick Alexander :nalexander [he/him] from comment #15)

Ooh, this is dangerous territory. I think that https://phabricator.services.mozilla.com/D46074 will certainly address this issue (at least, for a while -- until something else regresses) but I'd like to at least have the GeckoView experts capture about what the expectation is here. Is it desirable for foo = Gecko.giveMeAFoo() to have an implicit "drop Gecko-side foo" when foo goes out of scope on the JVM side?

We only do it in this one instance because it's so costly to leak the Gecko side of a GeckoSession (an entire window and <browser>). It's considered bad to use finalizers at all in Java these days, so we'll probably do this differently at some point (WeakReference).

Is it true that every pattern looks like, or should look like, that? I would expect some kind of .close()/try-with-resources pattern to be needed at least some of the time, which means that GeckoView has to know how to keep strong JVM references to at least some Gecko-side resources. Why aren't we using that here?

As I said, GeckoSession is special. The ownership of other things is dictated by a few different strategies which you can read about here: https://searchfox.org/mozilla-central/source/widget/android/jni/Natives.h#45

Pushed by rob@robwu.nl:
https://hg.mozilla.org/integration/autoland/rev/d632d4e80696
Prevent GeckoSessions from being GC'd in tests r=agi

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

Status: ASSIGNED → RESOLVED
Closed: 5 years ago
status-firefox71: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla71

Comment on attachment 9093137 [details]
Bug 1574917 - Prevent GeckoSessions from being GC'd in tests

Beta/Release Uplift Approval Request

  • User impact if declined: Extension mochitests on GeckoView that create new windows fail intermittently, when the window is unexpectedly closed by the garbage collector.

Affected tests:

  • mobile/android/components/extensions/test/mochitest/test_ext_tabs_events.html
  • mobile/android/components/extensions/test/mochitest/test_ext_tabs_executeScript.html
  • mobile/android/components/extensions/test/mochitest/test_ext_tabs_get.html
  • mobile/android/components/extensions/test/mochitest/test_ext_tabs_onUpdated.html
  • mobile/android/components/extensions/test/mochitest/test_ext_tabs_sendMessage.html
  • mobile/android/components/extensions/test/mochitest/test_ext_webNavigation_onCommitted.html
  • Is this code covered by automated tests?: No
  • Has the fix been verified in Nightly?: No
  • Needs manual test from QE?: No
  • If yes, steps to reproduce:
  • List of other uplifts needed: None
  • Risk to taking this patch: Low
  • Why is the change risky/not risky? (and alternatives if risky): small test-only change that only affects some extension tests on geckoview.
  • String changes made/needed: none
Attachment #9093137 - Flags: approval-mozilla-beta?

Comment on attachment 9093137 [details]
Bug 1574917 - Prevent GeckoSessions from being GC'd in tests

Improves GV test reliability. Approved for GV70.

Attachment #9093137 - Flags: approval-mozilla-beta? → approval-mozilla-beta+
Has Regression Range: --- → yes
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: