1027105 - Too Much Recursion error on marionetteScriptEnd() when waiting for homescreen to load in web-platfom-tests on Firefox OS 1.4

Status: RESOLVED WONTFIX

(Remote Protocol :: Marionette, defect)

Description

[James Graham [:jgraham]]

The web-platform-tests harness runs the following script to try and determine when the homescreen has loaded:

let manager = window.wrappedJSObject.AppWindowManager || window.wrappedJSObject.WindowManager;
log(manager);
let app = null;
if (manager) {
  app = ('getActiveApp' in manager) ? manager.getActiveApp() : manager.getCurrentDisplayedApp();
}
log(app);
if (app) {
  log('Already loaded home screen');
  marionetteScriptFinished();
} else {
  log('waiting for mozbrowserloadend');
  window.addEventListener('mozbrowserloadend', function loaded(aEvent) {
    log('received mozbrowserloadend for ' + aEvent.target.src);
    if (aEvent.target.src.indexOf('ftu') != -1 || aEvent.target.src.indexOf('homescreen') != -1) {
      window.removeEventListener('mozbrowserloadend', loaded);
      marionetteScriptFinished();
    }
  });
}

It has previously imported app_management.js.

With 1.3 this seems to work fine (or at least work OKish). With 1.4 it fails with a "Too much Recursion" error.

JavascriptException: JavascriptException: InternalError: too much recursion
stacktrace:
	execute_async_script @b2g.py, line 298
	inline javascript, line 10
	src: "  marionetteScriptFinished();"

The relevant part of the log is:

 1:57.67 LOG: Thread-Log INFO STDOUT: 1403103754331	Marionette	DEBUG	Got request: setContext, data: {"to":"0","sessionId":{"rotatable":true,"browserVersion":"30.0","takesScreenshot":true,"appBuildId":"20140520000201","cssSelectorsEnabled":true,"javascriptEnabled":true,"XULappId":"{3c2e2abc-06d4-11e1-ac3b-374f68613e61}","secureSsl":false,"platform":"ANDROID","browserName":"B2G","version":"30.0","device":"inari","b2g":true,"nativeEvents":false,"platformVersion":"30.0","takesElementScreenshot":true,"platformName":"ANDROID","handlesAlerts":false},"name":"setContext","parameters":{"value":"content"}}, id: {c5d4e0a6-081d-4e35-bcfc-446a1d40bb3f}
 1:57.67 LOG: Thread-Log INFO STDOUT: 1403103754332	Marionette	INFO	sendToClient: {"from":"0","ok":true}, {c5d4e0a6-081d-4e35-bcfc-446a1d40bb3f}, {c5d4e0a6-081d-4e35-bcfc-446a1d40bb3f}
 1:57.67 LOG: Thread-Log INFO STDOUT: 1403103754352	Marionette	DEBUG	Got request: executeWithCallback, data: {"to":"0","sessionId":{"rotatable":true,"browserVersion":"30.0","takesScreenshot":true,"appBuildId":"20140520000201","cssSelectorsEnabled":true,"javascriptEnabled":true,"XULappId":"{3c2e2abc-06d4-11e1-ac3b-374f68613e61}","secureSsl":false,"platform":"ANDROID","browserName":"B2G","version":"30.0","device":"inari","b2g":true,"nativeEvents":false,"platformVersion":"30.0","takesElementScreenshot":true,"platformName":"ANDROID","handlesAlerts":false},"name":"executeAsyncScript","parameters":{"scriptTimeout":30000,"specialPowers":false,"script":"\nlet manager = window.wrappedJSObject.AppWindowManager || window.wrappedJSObject.WindowManager;\nlog(manager);\nlet app = null;\nif (manager) {\n  app = ('getActiveApp' in manager) ? manager.getActiveApp() : manager.getCurrentDisplayedApp();\n}\nlog(app);\nif (app) {\n  log('Already loaded home screen');\n  marionetteScriptFinished();\n} else {\n  log('waiting for mozbrowserloadend');\n  window.addEventListener('mozbrowserloadend', function loaded(aEvent) {\n    log('received mozbrowserloadend for ' + aEvent.target.src);\n    if (aEvent.target.src.indexOf('ftu') != -1 || aEvent.target.src.indexOf('homescreen') != -1) {\n      window.removeEventListener('mozbrowserloadend', loaded);\n      marionetteScriptFinished();\n    }\n  });\n}","newSandbox":true,"args":[],"filename":"b2g.py","line":298}}, id: {8004e797-fddb-42c8-a54a-d6a00ba97a83}
 1:57.67 LOG: Thread-Log INFO STDOUT: MARIONETTE LOG: INFO: [object Object]
 1:57.67 LOG: Thread-Log INFO STDOUT: MARIONETTE LOG: INFO: [object Object]
 1:57.67 LOG: Thread-Log INFO STDOUT: MARIONETTE LOG: INFO: Already loaded home screen
 2:26.67 LOG: Thread-Log INFO STDOUT: 1403103783076	Marionette	INFO	sendToClient: {"from":"0","error":{"message":"InternalError: too much recursion","status":17,"stacktrace":"execute_async_script @b2g.py, line 298\ninline javascript, line 10\nsrc: \"  marionetteScriptFinished();\""}}, {8004e797-fddb-42c8-a54a-d6a00ba97a83}, {8004e797-fddb-42c8-a54a-d6a00ba97a83}

Comment 1

[Jonathan Griffin (:jgriffin)]

This is very likely caused by the line:

log(app);

If 'app' is an object that contains a reference to itself (as many JS objects do), trying to serialize this (via log()) will fail.

Comment 2

[Jonathan Griffin (:jgriffin)]

Hmm, as James points out, this error actually occurs when the script calls marionetteScriptFinished(), which is really puzzling.

Comment 3

[Dave Hunt [:davehunt] [he/him] ⌚BST]

Incidentally, waiting for #homescreen to have a loading-state of false has proven to be a good way in master to wait for the Homescreen. I'm not certain if this works with the new vertical homescreen as the commit is yet to land. I don't expect this to work in v1.3 though. See: https://github.com/davehunt/gaia/commit/0652aea7685d5ab18faa182677af5e54bdbf4b22

Comment 4

[James Graham [:jgraham]]

So the original bug here is that log(foo) causes foo to be converted to a webdriver return value and then shipped over to the marionette-server in case someone later calls getLogs. This is problematic in a number of ways. Most obviously the webdriver return value conversion doesn't consider the possibility of cyclic objects. I have raised a spec bug on this (along with other problems in that algorithm). The other issue is that doing this for every object that you log() is very surprising behaviour. I assumed that log() would simply do a string conversion which, in the absence of a custom toString(), is a much safer operation since it won't cause side effects from getters, won't go into infinite loops, and won't leak large objects.

Do we have a use case for using the logger as a way of shipping non-string objects over the wire? If not I suggest we change this behaviour.

Comment 5

[Malini Das [:mdas] - Away, not checking bugmail]

(In reply to James Graham [:jgraham] from comment #4)
> So the original bug here is that log(foo) causes foo to be converted to a
> webdriver return value and then shipped over to the marionette-server in
> case someone later calls getLogs. This is problematic in a number of ways.
> Most obviously the webdriver return value conversion doesn't consider the
> possibility of cyclic objects. I have raised a spec bug on this (along with
> other problems in that algorithm). The other issue is that doing this for
> every object that you log() is very surprising behaviour. I assumed that
> log() would simply do a string conversion which, in the absence of a custom
> toString(), is a much safer operation since it won't cause side effects from
> getters, won't go into infinite loops, and won't leak large objects.
> 
> Do we have a use case for using the logger as a way of shipping non-string
> objects over the wire? If not I suggest we change this behaviour.

I don't believe there is a usecase for that, we should just do string conversion

Comment 6

[Malini Das [:mdas] - Away, not checking bugmail]

Does this no longer affect certsuite? I can then reduce the priority on this as it's non-blocking.

Comment 7

[James Graham [:jgraham]]

This doesn't block anymore.

Comment 8

[David Burns :automatedtester]

Closing out B2G related bugs. If these still happen and are valuable, please reopen with details again and how this affects Desktop/Fennec