Closed Bug 1547719 Opened 5 years ago Closed 4 years ago

Intermittent QuantumRender Linux64 threw an error: TypeError: this.mm is null

Categories

(Testing :: Marionette Client and Harness, defect, P5)

Product:
Testing
Component:
Marionette Client and Harness
Version:
Version 3
Platform:
x86_64
Linux
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED DUPLICATE of bug 1663429

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure, regression)

#[markdown(off)]
Filed by: csabou [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=243180705&repo=mozilla-central

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

[task 2019-04-28T12:01:43.940Z] 12:01:43 INFO - TEST-OK | /html/browsers/the-window-object/apis-for-creating-and-navigating-browsing-contexts-by-name/open-features-tokenization-noreferrer.html | took 51586ms
[task 2019-04-28T12:01:43.941Z] 12:01:43 INFO - TEST-START | /html/browsers/the-window-object/security-window/window-security.https.html
[task 2019-04-28T12:01:44.187Z] 12:01:44 INFO - Closing window 21474836481
[task 2019-04-28T12:01:44.228Z] 12:01:44 INFO - Closing window 23622320132
[task 2019-04-28T12:01:44.244Z] 12:01:44 INFO - PID 26082 | Marionette threw an error: TypeError: this.mm is null
[task 2019-04-28T12:01:44.245Z] 12:01:44 INFO - PID 26082 | WebElementEventTarget@chrome://marionette/content/dom.js:44:5
[task 2019-04-28T12:01:44.246Z] 12:01:44 INFO - PID 26082 | switchToTab@chrome://marionette/content/browser.js:472:26
[task 2019-04-28T12:01:44.247Z] 12:01:44 INFO - PID 26082 | GeckoDriver.prototype.setWindowHandle@chrome://marionette/content/driver.js:1614:23
[task 2019-04-28T12:01:44.248Z] 12:01:44 INFO - PID 26082 | GeckoDriver.prototype.switchToWindow@chrome://marionette/content/driver.js:1524:16
[task 2019-04-28T12:01:44.249Z] 12:01:44 INFO - PID 26082 | despatch@chrome://marionette/content/server.js:289:40
[task 2019-04-28T12:01:44.250Z] 12:01:44 INFO - PID 26082 | execute@chrome://marionette/content/server.js:262:16
[task 2019-04-28T12:01:44.250Z] 12:01:44 INFO - PID 26082 | onPacket/<@chrome://marionette/content/server.js:235:20
[task 2019-04-28T12:01:44.251Z] 12:01:44 INFO - PID 26082 | onPacket@chrome://marionette/content/server.js:236:9
[task 2019-04-28T12:01:44.251Z] 12:01:44 INFO - PID 26082 | _onJSONObjectReady/<@chrome://marionette/content/transport.js:492:20
[task 2019-04-28T12:01:44.259Z] 12:01:44 INFO - PID 26082 | Assertion failure
[task 2019-04-28T12:01:44.260Z] 12:01:44 INFO - PID 26082 | assert@resource:///modules/AsyncTabSwitcher.jsm:458:36
[task 2019-04-28T12:01:44.260Z] 12:01:44 INFO - PID 26082 | finish@resource:///modules/AsyncTabSwitcher.jsm:311:10
[task 2019-04-28T12:01:44.261Z] 12:01:44 INFO - PID 26082 | postActions@resource:///modules/AsyncTabSwitcher.jsm:642:12
[task 2019-04-28T12:01:44.261Z] 12:01:44 INFO - PID 26082 | handleEvent@resource:///modules/AsyncTabSwitcher.jsm:1067:10
[task 2019-04-28T12:01:44.262Z] 12:01:44 INFO - PID 26082 | EventListener.handleEvent*AsyncTabSwitcher@resource:///modules/AsyncTabSwitcher.jsm:139:17
[task 2019-04-28T12:01:44.262Z] 12:01:44 INFO - PID 26082 | _getSwitcher@chrome://browser/content/tabbrowser.js:4149:24
[task 2019-04-28T12:01:44.263Z] 12:01:44 INFO - PID 26082 | updateCurrentBrowser@chrome://browser/content/tabbrowser.js:922:14
[task 2019-04-28T12:01:44.263Z] 12:01:44 INFO - PID 26082 | _setupEventListeners/<@chrome://browser/content/tabbrowser.js:4516:14
[task 2019-04-28T12:01:44.267Z] 12:01:44 CRITICAL - Traceback (most recent call last):
[task 2019-04-28T12:01:44.268Z] 12:01:44 CRITICAL - File "/builds/worker/workspace/build/tests/web-platform/tests/tools/wptrunner/wptrunner/testrunner.py", line 115, in run_test
[task 2019-04-28T12:01:44.268Z] 12:01:44 CRITICAL - return self.executor.run_test(test)
[task 2019-04-28T12:01:44.268Z] 12:01:44 CRITICAL - File "/builds/worker/workspace/build/tests/web-platform/tests/tools/wptrunner/wptrunner/executors/base.py", line 190, in run_test
[task 2019-04-28T12:01:44.269Z] 12:01:44 CRITICAL - self.on_environment_change(test.environment)
[task 2019-04-28T12:01:44.269Z] 12:01:44 CRITICAL - File "/builds/worker/workspace/build/tests/web-platform/tests/tools/wptrunner/wptrunner/executors/executormarionette.py", line 674, in on_environment_change
[task 2019-04-28T12:01:44.270Z] 12:01:44 CRITICAL - self.protocol.testharness.load_runner(new_environment["protocol"])
[task 2019-04-28T12:01:44.270Z] 12:01:44 CRITICAL - File "/builds/worker/workspace/build/tests/web-platform/tests/tools/wptrunner/wptrunner/executors/executormarionette.py", line 127, in load_runner
[task 2019-04-28T12:01:44.270Z] 12:01:44 CRITICAL - self._close_windows()
[task 2019-04-28T12:01:44.271Z] 12:01:44 CRITICAL - File "/builds/worker/workspace/build/tests/web-platform/tests/tools/wptrunner/wptrunner/executors/executormarionette.py", line 162, in _close_windows
[task 2019-04-28T12:01:44.271Z] 12:01:44 CRITICAL - self.marionette.switch_to_window(handle)
[task 2019-04-28T12:01:44.273Z] 12:01:44 CRITICAL - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1356, in switch_to_window
[task 2019-04-28T12:01:44.273Z] 12:01:44 CRITICAL - {"focus": focus, "name": handle, "handle": handle})
[task 2019-04-28T12:01:44.274Z] 12:01:44 CRITICAL - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 26, in _
[task 2019-04-28T12:01:44.274Z] 12:01:44 CRITICAL - return func(*args, **kwargs)
[task 2019-04-28T12:01:44.275Z] 12:01:44 CRITICAL - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 598, in _send_message
[task 2019-04-28T12:01:44.275Z] 12:01:44 CRITICAL - self._handle_error(err)
[task 2019-04-28T12:01:44.275Z] 12:01:44 CRITICAL - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 618, in _handle_error
[task 2019-04-28T12:01:44.276Z] 12:01:44 CRITICAL - raise errors.lookup(error)(message, stacktrace=stacktrace)
[task 2019-04-28T12:01:44.277Z] 12:01:44 CRITICAL - UnknownException: TypeError: this.mm is null
[task 2019-04-28T12:01:44.277Z] 12:01:44 CRITICAL - stacktrace:
[task 2019-04-28T12:01:44.278Z] 12:01:44 CRITICAL - WebElementEventTarget@chrome://marionette/content/dom.js:44:5
[task 2019-04-28T12:01:44.278Z] 12:01:44 CRITICAL - switchToTab@chrome://marionette/content/browser.js:472:26
[task 2019-04-28T12:01:44.280Z] 12:01:44 CRITICAL - GeckoDriver.prototype.setWindowHandle@chrome://marionette/content/driver.js:1614:23
[task 2019-04-28T12:01:44.282Z] 12:01:44 CRITICAL - GeckoDriver.prototype.switchToWindow@chrome://marionette/content/driver.js:1524:16
[task 2019-04-28T12:01:44.283Z] 12:01:44 CRITICAL - despatch@chrome://marionette/content/server.js:289:40
[task 2019-04-28T12:01:44.283Z] 12:01:44 CRITICAL - execute@chrome://marionette/content/server.js:262:16
[task 2019-04-28T12:01:44.284Z] 12:01:44 CRITICAL - onPacket/<@chrome://marionette/content/server.js:235:20
[task 2019-04-28T12:01:44.284Z] 12:01:44 CRITICAL - onPacket@chrome://marionette/content/server.js:236:9
[task 2019-04-28T12:01:44.285Z] 12:01:44 CRITICAL - _onJSONObjectReady/<@chrome://marionette/content/transport.js:492:20

this happens on the wpt tests, and specifically on TEST-START | /html/browsers/the-window-object/security-window/window-security.https.html
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=243285276&repo=mozilla-central&lineNumber=4058
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=243288646&repo=mozilla-central&lineNumber=4064

and started with this merge: https://hg.mozilla.org/mozilla-central/pushloghtml?changeset=8f9398c8c37d81bd0c3816ac852c475ac802cabf

james, could you please take a look over this? thank you

Flags: needinfo?(james)
Component: Marionette → web-platform-tests
Summary: Intermittent Marionette threw an error: TypeError: this.mm is null → Intermittent threw an error: TypeError: this.mm is null

This is pretty clearly a bug in marionette; if you look at the stack trace it's just doing switch_to_window, which shouldn't fail in this way. Still needs investigation, but it doesn't look like wptrunner is doing anything unusual here.

Component: web-platform-tests → Marionette
Flags: needinfo?(james)

This is actually Quantum Render on Linux64 only.

OS: Unspecified → Linux
Hardware: Unspecified → x86_64
Summary: Intermittent threw an error: TypeError: this.mm is null → Intermittent QuantumRender Linux64 threw an error: TypeError: this.mm is null

If this suddenly flares up it's almost certainly the fault of my patches in Bug 1547351.

Although if we're really confident this is a bug in marionette and not Webrender(BridgeParent?), it would nice to not be backed out? (just my 2 cents, I defer to the triage experts...)

We will see. Basically the failure means that the constructor for WebElementEventTarget receives null for the messageManager. This can only happen if there is no content browser at this time [1]. I wonder which tab it actually tries to switch to, and if that has been unloaded maybe.

Or is waiting for the TabSelect event not enough, and we should better wait for something else? Checking other usages of gBrowser.selectedTab shows me that this API is even synchronous? Mike, do you have an idea?

[1] https://searchfox.org/mozilla-central/rev/40e889be8ff926e32f7567957f4c316f14f6fbef/testing/marionette/browser.js#191-196

Flags: needinfo?(mconley)

Additional context if useful: there's a high chance the problematic part of the patchset is this one: https://phabricator.services.mozilla.com/D38597

In particular nsClassHashTable.LookupForAdd(key).OrInsert(...) was indirectly changed to return nsAutoPtr<T>& instead of T*, which is a nasty footgun if the return value is assigned to an auto location, because it will strip the reference and copy-construct the nsAutoPtr. That might lead to something randomly getting nulled out in an obscure path? I thought I found all the cases where this happens, but I wouldn't be surprised to be wrong.

Hi whimboo,

gBrowser.selectedTab is synchronous, in that it will immediately return gBrowser's latest notion of what the selected tab is.

I suppose it is theoretically possible that we are early or late enough in the lifecycle of a tab such that the message manager hasn't yet been created, or has already been torn down. I believe the former is more likely, because we tend to switch the selected tab before tearing down the <browser> for it.

This can maybe happen if, for example, the tab switch has completed, but we're showing the tab switch spinner because we haven't yet received any painted content for that tab. In that case, the selected tab will be the right one, but if the content process for that tab is still being constructed, I suppose it's possible that the message manager doesn't exist yet.

Hey farre, do you remember other cases when the message manager might not yet exist, or has stopped existing?

Flags: needinfo?(mconley) → needinfo?(afarre)

Does it mean that we should better wait for the content process to be ready, or should that basically be done by selectedTab and variants internally?

Flags: needinfo?(mconley)

Probably best to wait for the content process to be ready (the former).

Flags: needinfo?(mconley)

(In reply to Intermittent Failures Robot from comment #39)

39 failures in 4207 pushes (0.009 failures/push) were associated with this bug in the last 7 days.

Nearly all of those failures are wrongly tagged. I wonder if it would still make sense to correct that.

Flags: needinfo?(aryx.bugmail)

That failure has been fixed by my patch on bug 1663429.

Status: NEW → RESOLVED
Closed: 4 years ago
Flags: needinfo?(afarre)
Resolution: --- → DUPLICATE
Product: Testing → Remote Protocol
Moving bug to Testing::Marionette Client and Harness component per bug 1815831.
Component: Marionette → Marionette Client and Harness
Product: Remote Protocol → Testing
You need to log in before you can comment on or make changes to this bug.