Closed Bug 1281915 Opened 3 years ago Closed 3 years ago

Near permafailing on beta: test_screenshot.py Chrome.test_secondary_windows | AssertionError: None != 'png' | after NoSuchWindowException: NoSuchWindowException: No such content frame; perhaps the listener was not registered?

Categories

(Testing :: Marionette, defect)

Version 3
defect
Not set

Tracking

(firefox48 fixed, firefox49 fixed, firefox50 fixed)

RESOLVED FIXED
mozilla50
Tracking Status
firefox48 --- fixed
firefox49 --- fixed
firefox50 --- fixed

People

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

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

Not sure what started this. It looked like something that landed this morning that caused this, but then I've retriggered back a week or so and the failures followed it all the way back:
https://treeherder.mozilla.org/#/jobs?repo=mozilla-beta&bugfiler&fromchange=1510116bd5e58a9194731e4b3f715008e06625ee&filter-tier=1&filter-searchStr=4e7bd114d368e4527ef49ca36748f03387cc29e3
Summary: Intermittent test_screenshot.py Chrome.test_secondary_windows | AssertionError: None != 'png' | after NoSuchWindowException: NoSuchWindowException: No such content frame; perhaps the listener was not registered? → Near permafailing on beta: test_screenshot.py Chrome.test_secondary_windows | AssertionError: None != 'png' | after NoSuchWindowException: NoSuchWindowException: No such content frame; perhaps the listener was not registered?
David: any idea who could take a look at this ?
Flags: needinfo?(dburns)
running the tests I get the following geckolog


dburns in ~/development/mozilla-central λ cat gecko.log
1467663103077	Marionette	INFO	Listening on port 2828
1467663104299	Marionette	INFO	startBrowser edc42b0e-6958-9b48-9b9c-0f55efd219ce
1467663104315	Marionette	INFO	sendAsync edc42b0e-6958-9b48-9b9c-0f55efd219ce
1467663104506	Marionette	INFO	startBrowser 0a52a09c-7d17-f549-9cff-3f498ceed726
1467663104513	Marionette	INFO	sendAsync 0a52a09c-7d17-f549-9cff-3f498ceed726
1467663104532	Marionette	INFO	sendAsync 0a52a09c-7d17-f549-9cff-3f498ceed726
1467663104537	Marionette	INFO	sendAsync 0a52a09c-7d17-f549-9cff-3f498ceed726
MARIONETTE LOG: INFO: TEST-START: /Users/dburns/development/mozilla-central/testing/marionette/harness/marionette/tests/unit/test_screenshot.py:test_secondary_windows
1467663104725	Marionette	INFO	startBrowser 0a52a09c-7d17-f549-9cff-3f498ceed726
1467663104725	Marionette	ERROR	Could not load listener into content for page chrome://marionette/content/doesnotexist.xul: TypeError: mm is undefined
1467663335384	Marionette	INFO	sendAsync 0a52a09c-7d17-f549-9cff-3f498ceed726
*************************
A coding exception was thrown and uncaught in a Task.

Full message: TypeError: winEn.getNext(...).messageManager is undefined
Full stack: GeckoDriver.prototype.sessionTearDown@chrome://marionette/content/driver.js:2275:7
GeckoDriver.prototype.deleteSession@chrome://marionette/content/driver.js:2306:3
Dispatcher.prototype.execute/req<@chrome://marionette/content/dispatcher.js:126:20
TaskImpl_run@resource://gre/modules/Task.jsm:319:40
TaskImpl@resource://gre/modules/Task.jsm:280:3
createAsyncFunction/asyncFunction@resource://gre/modules/Task.jsm:254:14
Task_spawn@resource://gre/modules/Task.jsm:168:12
Dispatcher.prototype.execute@chrome://marionette/content/dispatcher.js:120:13
Dispatcher.prototype.onPacket@chrome://marionette/content/dispatcher.js:91:5
DebuggerTransport.prototype._onJSONObjectReady/<@chrome://marionette/content/server.js -> resource://devtools/shared/transport/transport.js:479:9
exports.makeInfallible/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/ThreadSafeDevToolsUtils.js:101:14
exports.makeInfallible/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/ThreadSafeDevToolsUtils.js:101:14

*************************
*************************
A coding exception was thrown in a Promise rejection callback.
See https://developer.mozilla.org/Mozilla/JavaScript_code_modules/Promise.jsm/Promise

Full message: TypeError: winEn.getNext(...).messageManager is undefined
Full stack: GeckoDriver.prototype.sessionTearDown@chrome://marionette/content/driver.js:2275:7
GeckoDriver.prototype.deleteSession@chrome://marionette/content/driver.js:2306:3
Dispatcher.prototype.execute/req<@chrome://marionette/content/dispatcher.js:126:20
TaskImpl_run@resource://gre/modules/Task.jsm:319:40
TaskImpl@resource://gre/modules/Task.jsm:280:3
createAsyncFunction/asyncFunction@resource://gre/modules/Task.jsm:254:14
Task_spawn@resource://gre/modules/Task.jsm:168:12
Dispatcher.prototype.execute@chrome://marionette/content/dispatcher.js:120:13
Dispatcher.prototype.onPacket@chrome://marionette/content/dispatcher.js:91:5
DebuggerTransport.prototype._onJSONObjectReady/<@chrome://marionette/content/server.js -> resource://devtools/shared/transport/transport.js:479:9
exports.makeInfallible/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/ThreadSafeDevToolsUtils.js:101:14
exports.makeInfallible/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/ThreadSafeDevToolsUtils.js:101:14

*************************
Marionette threw an error: TypeError: winEn.getNext(...).messageManager is undefined
GeckoDriver.prototype.sessionTearDown@chrome://marionette/content/driver.js:2275:7
GeckoDriver.prototype.deleteSession@chrome://marionette/content/driver.js:2306:3
Dispatcher.prototype.execute/req<@chrome://marionette/content/dispatcher.js:126:20
TaskImpl_run@resource://gre/modules/Task.jsm:319:40
TaskImpl@resource://gre/modules/Task.jsm:280:3
createAsyncFunction/asyncFunction@resource://gre/modules/Task.jsm:254:14
Task_spawn@resource://gre/modules/Task.jsm:168:12
Dispatcher.prototype.execute@chrome://marionette/content/dispatcher.js:120:13
Dispatcher.prototype.onPacket@chrome://marionette/content/dispatcher.js:91:5
DebuggerTransport.prototype._onJSONObjectReady/<@chrome://marionette/content/server.js -> resource://devtools/shared/transport/transport.js:479:9
exports.makeInfallible/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/ThreadSafeDevToolsUtils.js:101:14
exports.makeInfallible/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/ThreadSafeDevToolsUtils.js:101:14
Flags: needinfo?(dburns)
looks like we trying to inject a message manager into a xul document...

1467663957346	Marionette	TRACE	conn4 <- [1,8,null,{"value":null}]
1467663957428	Marionette	TRACE	conn4 -> [0,9,"switchToWindow",{"name":"foo"}]
1467663957429	Marionette	INFO	startBrowser 8d9c35b4-9ced-1f44-8594-7a2d164ff062
1467663957429	Marionette	ERROR	Could not load listener into content for page chrome://marionette/content/doesnotexist.xul: TypeError: mm is undefined
1467663957430	Marionette	TRACE	conn4 <- [1,9,null,{}]
1467663957436	Marionette	TRACE	conn4 -> [0,10,"findElement",{"using":"css selector","value":":root"}]
1467663957437	Marionette	TRACE	conn4 <- [1,10,null,{"value":{"element-6066-11e4-a52e-4f735466cecf":"2345707b-f23f-1147-9418-5438aecedeb5","ELEMENT":"2345707b-f23f-1147-9418-5438aecedeb5"}}]
1467663957446	Marionette	TRACE	conn4 -> [0,11,"takeScreenshot",{"highlights":null,"full":true,"hash":false,"id":null}]
1467663957467	Marionette	TRACE	conn4 <- [1,11,null,{"value":"iVBORw0KGgoAAAANSUhEUgAAAAEAAAIbCAYAAAAqx/RdAAAAHklEQVRIie3BMQEAAAgDoPX/jWeW2cILSGYbAAB4dbfYAnKdspz7AAAAAElFTkSuQmCC"}]
1467663959231	Marionette	TRACE	conn4 -> [0,12,"getWindowHandle",null]
1467663959232	Marionette	TRACE	conn4 <- [1,12,null,{"value":"12"}]
1467663959233	Marionette	TRACE	conn4 -> [0,13,"switchToWindow",{"name":"7"}]
1467663959235	Marionette	TRACE	conn4 <- [1,13,null,{}]
1467663959236	Marionette	TRACE	conn4 -> [0,14,"getContext",null]
1467663959236	Marionette	TRACE	conn4 <- [1,14,null,{"value":"chrome"}]
1467663959237	Marionette	TRACE	conn4 -> [0,15,"setContext",{"value":"chrome"}]
1467663959238	Marionette	TRACE	conn4 <- [1,15,null,{}]
1467663959239	Marionette	TRACE	conn4 -> [0,16,"executeScript",{"scriptTimeout":null,"newSandbox":true,"args":[],"filename":"test_screenshot.py","script":"\n                let el = document.getElementsByTagName(\"window\")[0];\n                let rect = el.getBoundingClientRect();\n                return [rect.width, rect.height];\n                ","sandbox":"default","line":57}]
1467663959242	Marionette	TRACE	conn4 <- [1,16,null,{"value":[1280,951]}]
1467663959243	Marionette	TRACE	conn4 -> [0,17,"setContext",{"value":"chrome"}]
1467663959244	Marionette	TRACE	conn4 <- [1,17,null,{}]
1467663959245	Marionette	TRACE	conn4 -> [0,18,"switchToWindow",{"name":"12"}]
1467663959246	Marionette	TRACE	conn4 <- [1,18,null,{}]
1467663959247	Marionette	TRACE	conn4 -> [0,19,"switchToWindow",{"name":"7"}]
1467663959248	Marionette	TRACE	conn4 <- [1,19,null,{}]
1467663959250	Marionette	TRACE	conn4 -> [0,20,"getLogs",null]
1467663959250	Marionette	TRACE	conn4 <- [1,20,null,[["INFO","TEST-START: /Users/dburns/development/mozilla-central/testing/marionette/harness/marionette/tests/unit/test_screenshot.py:test_secondary_windows","Mon Jul 04 2016 21:25:57 GMT+0100 (BST)"]]]
1467663959252	Marionette	TRACE	conn4 -> [0,21,"deleteSession",null]
There are times where trying to register the window fails so
we should not try use it when shutting down the session.

Review commit: https://reviewboard.mozilla.org/r/62202/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/62202/
Attachment #8767788 - Flags: review?(ato)
Comment on attachment 8767788 [details]
Bug 1281915: Skip trying to remove a frame script if there no messageManager

https://reviewboard.mozilla.org/r/62202/#review59058

::: testing/marionette/driver.js:2275
(Diff revision 1)
>        }
>      }
>  
>      let winEn = Services.wm.getEnumerator(null);
>      while (winEn.hasMoreElements()) {
> +      try {

If it’s the `messageManager` that is undefined we could turn this into an if-condition:

```js
let win = winEn.getNext();
if (win.messageManager) {
  win.messageManager.removeDelayedFrameScript(FRAME_SCRIPT);
}
```

::: testing/marionette/driver.js:2280
(Diff revision 1)
> +      try {
> -      winEn.getNext().messageManager.removeDelayedFrameScript(FRAME_SCRIPT);
> +        winEn.getNext().messageManager.removeDelayedFrameScript(FRAME_SCRIPT);
> +      } catch (e) {
> +        // there may not always be a content process
> +        logger.error(
> +            `Could not remove listener from page. Error is: ${e}`);

Nit: Remove "Error is:" so that it becomes:

```js
logger.error(`Could not remove listener from page: ${e}`);
```

::: testing/marionette/harness/marionette/tests/unit/test_screenshot.py:99
(Diff revision 1)
>              """)
>          self.marionette.switch_to_window("foo")
> +        # there can be a race between opening and registering the window
> +        # and switching to it. Waiting a tiny amount of time is enough not to
> +        # break anything.
> +        time.sleep(0.1)

This isn’t great, since WebDriver is supposed to provide a blocking API.

If the sleep is for waiting for the window to _open_, perhaps we can put an explicit wait (using the _wait.py_ utilities) for it to appear in the window handles?
Attachment #8767788 - Flags: review?(ato)
https://reviewboard.mozilla.org/r/62202/#review59058

I also forgot, can you improve the commit message?
Comment on attachment 8767788 [details]
Bug 1281915: Skip trying to remove a frame script if there no messageManager

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/62202/diff/1-2/
Attachment #8767788 - Attachment description: Bug 1281915: Fix intermittent test on Marionette → Bug 1281915: Skip trying to remove a frame script if there no messageManager
Attachment #8767788 - Flags: review?(ato)
https://reviewboard.mozilla.org/r/62202/#review59058

> This isn’t great, since WebDriver is supposed to provide a blocking API.
> 
> If the sleep is for waiting for the window to _open_, perhaps we can put an explicit wait (using the _wait.py_ utilities) for it to appear in the window handles?

I totally agree. The window is open and is accepting commands. Since we are just getting a plain chrome window there not a specific item we can wait for. I have reduced the sleep to as low as I could get it... It's a race in registering the window and it actually being usable to the client :/
Comment on attachment 8767788 [details]
Bug 1281915: Skip trying to remove a frame script if there no messageManager

https://reviewboard.mozilla.org/r/62202/#review59712
Attachment #8767788 - Flags: review?(ato) → review+
https://reviewboard.mozilla.org/r/62202/#review59058

> I totally agree. The window is open and is accepting commands. Since we are just getting a plain chrome window there not a specific item we can wait for. I have reduced the sleep to as low as I could get it... It's a race in registering the window and it actually being usable to the client :/

Okay, I see your point.  In that case it’s fine to make the number slightly higher I think.  I saw there was one intermittent failure in your try run.
Pushed by dburns@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/e4bdf6699e5e
Skip trying to remove a frame script if there no messageManager r=ato
https://hg.mozilla.org/mozilla-central/rev/e4bdf6699e5e
Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla50
Whiteboard: [checkin-needed-aurora][checkin-needed-beta]
https://hg.mozilla.org/releases/mozilla-aurora/rev/0e807dd32f40
Whiteboard: [checkin-needed-aurora][checkin-needed-beta] → [checkin-needed-beta]
I can still see this test failure locally with a debug build from latest mozilla-central code. Orangefactor lists failures, and also try is very unhappy when I pushed changes yesterday:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=ac4e4a75e0e7cdc1e560e4da76b2298939b66a04&selectedJob=24067925&bugfiler

I will check what's up with it and file a new bug.
Assignee: nobody → dburns
So this is indeed the `sleep(0.002)` which is causing trouble here for debug builds which are running slower. A bug will be filed soon and I will try to get it fixed.
You need to log in before you can comment on or make changes to this bug.