1281915 - 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?

Status: RESOLVED FIXED

(Testing :: Marionette Client and Harness, defect)

Description

[Treeherder Bug Filer]

Filed by: wkocher

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

http://archive.mozilla.org/pub/firefox/tinderbox-builds/mozilla-beta-linux-debug/1466690303/mozilla-beta_ubuntu32_vm-debug_test-marionette-bm05-tests1-linux32-build12.txt.gz

Comment 1

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

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

Comment 2

[Intermittent Failures Robot]

114 automation job failures were associated with this bug yesterday.

Repository breakdown:
* mozilla-beta: 114

Platform breakdown:
* linux32: 114

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1281915&startday=2016-06-23&endday=2016-06-23&tree=all

Comment 3

[Intermittent Failures Robot]

119 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-beta: 118
* fx-team: 1

Platform breakdown:
* linux32: 118
* linux64: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1281915&startday=2016-06-20&endday=2016-06-26&tree=all

Comment 4

[Carsten Book [:Tomcat]]

David: any idea who could take a look at this ?

Comment 5

[Intermittent Failures Robot]

22 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-beta: 20
* fx-team: 1
* autoland: 1

Platform breakdown:
* linux32: 17
* linux64: 5

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1281915&startday=2016-06-27&endday=2016-07-03&tree=all

Comment 6

[David Burns :automatedtester]

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

Comment 7

[David Burns :automatedtester]

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]

Comment 8

[David Burns :automatedtester]

Attachment: Bug 1281915: Skip trying to remove a frame script if there no messageManager

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/

Comment 9

[Andreas Tolfsen ❲: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?

Comment 10

[Andreas Tolfsen ❲:ato❳]

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

I also forgot, can you improve the commit message?

Comment 11

[David Burns :automatedtester]

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/

Comment 12

[David Burns :automatedtester]

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 13

[Andreas Tolfsen ❲: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/#review59712

Comment 14

[Andreas Tolfsen ❲:ato❳]

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.

Comment 15

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/e4bdf6699e5e
Skip trying to remove a frame script if there no messageManager r=ato

Comment 16

[Gregory Szorc [:gps]]

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

Comment 17

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/0e807dd32f40

Comment 18

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-beta/rev/0c33a13a282b

Comment 19

[Intermittent Failures Robot]

27 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-beta: 25
* mozilla-inbound: 1
* mozilla-central: 1

Platform breakdown:
* linux32: 21
* linux64: 6

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1281915&startday=2016-07-04&endday=2016-07-10&tree=all

Comment 20

[Intermittent Failures Robot]

11 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-beta: 8
* mozilla-inbound: 1
* fx-team: 1
* autoland: 1

Platform breakdown:
* linux32: 8
* linux64: 3

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1281915&startday=2016-07-11&endday=2016-07-17&tree=all

Comment 21

[Henrik Skupin [:whimboo][⌚️UTC+2]]

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.

Comment 22

[Henrik Skupin [:whimboo][⌚️UTC+2]]

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.

Comment 23

[Intermittent Failures Robot]

19 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-beta: 18
* mozilla-aurora: 1

Platform breakdown:
* linux32: 12
* linux64: 7

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1281915&startday=2016-07-18&endday=2016-07-24&tree=all

Comment 24

[Intermittent Failures Robot]

8 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-beta: 3
* mozilla-inbound: 2
* autoland: 2
* mozilla-release: 1

Platform breakdown:
* linux64: 4
* linux32: 4

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1281915&startday=2016-07-25&endday=2016-07-31&tree=all

Comment 25

[Intermittent Failures Robot]

5 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-release: 3
* autoland: 2

Platform breakdown:
* windowsxp: 2
* linux64: 2
* linux32: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1281915&startday=2016-08-22&endday=2016-08-28&tree=all

Comment 26

[Intermittent Failures Robot]

10 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-release: 10

Platform breakdown:
* windows7-32: 2
* linux64: 2
* linux32: 2
* windowsxp: 1
* windows8-64: 1
* osx-10-6: 1
* osx-10-10: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1281915&startday=2016-08-29&endday=2016-09-04&tree=all

Comment 27

[BMO Automation]

Moving bug to Testing::Marionette Client and Harness component per bug 1815831.