Intermittent test_switch_remote_frame.py TestSwitchRemoteFrame.test_remote_frame | ScriptTimeoutException: Timed out

RESOLVED FIXED in Firefox 50

Status

defect
RESOLVED FIXED
3 years ago
3 years ago

People

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

Tracking

({intermittent-failure})

Version 3
mozilla51
Points:
---

Firefox Tracking Flags

(firefox50 fixed, firefox51 fixed)

Details

Attachments

(1 attachment)

From gecko.log:

1471406493759	Marionette	TRACE	conn851 -> [0,44,"executeAsyncScript",{"scriptTimeout":null,"sandbox":"system","debug_script":false,"script":"\n                let start = new Date();\n                let end = new Date(start.valueOf() + 5000);\n                let wait = function() {\n                  let now = new Date();\n                  if (window.wrappedJSObject.permChanged || end >= now) {\n                    marionetteScriptFinished();\n                  }\n                };\n                window.setTimeout(wait, 100);\n                ","newSandbox":true,"line":891,"args":[],"filename":"marionette.py"}]
[..]
1471406503804	Marionette	TRACE	conn851 <- [1,44,{"error":"script timeout","message":"Timed out","stacktrace":""},null]

We timed out after the 10s when calling:

> self.marionette.push_permission('browser', True)

That means the issue is somewhere in here:

https://dxr.mozilla.org/mozilla-central/rev/fe895421dfbe1f1f8f1fc6a39bb20774423a6d74/testing/marionette/client/marionette_driver/marionette.py#880

Interestingly this method sets a timeout of 5000ms, but the following if condition puzzles me:

> if (window.wrappedJSObject.permChanged || end >= now) {
>   marionetteScriptFinished();
> }

If the permission has not been changed yet, we would end-up in the second condition. But that should always be true, and cause us to return immediately. What I would expect is "now >= end". But why do we do the internal timeout at all? We have the timeout for asynchronous script already set to 10s, which should have the same affect. The above code has been added by bug 1123506 for lasting side-effects.

Andreas, is there any reason why you have chosen an internal timer beside the timer of the execute_async_script?

The underlying issue might still be that we haven't set the permission correctly. Personally I would catch the scripttimeout exception and throw a more meaningful one.
Flags: needinfo?(ato)
The explanation for the changes in https://github.com/mozilla/gecko-dev/blob/master/testing/marionette/client/marionette_driver/marionette.py#L880-L891, from using waitFor to hard-coding the perm check with a timer, is that bug 1123506 changed how sandboxes were set up.

Sandboxes used to have all sort of functionality exposed to them.  The waitFor function comes from the simpletest harness and the code is reproduced from what https://github.com/mozilla/gecko-dev/blob/master/testing/marionette/simpletest.js#L191 does.  waitFor is following bug 1123506 no longer exposed in in the default- or system sandboxes: it is only exposed in the "simpletest" sandbox.  Because this code needs system privileges to run we need to use the "system" sandbox, but it does not have waitFor.
Flags: needinfo?(ato)
> Andreas, is there any reason why you have chosen an internal timer beside the timer of the execute_async_script?

I think there is _probably_ not a good reason for this.  This is likely an oversight and sloppiness introduced when I was fixing uses of execute_async_script.
Comment on attachment 8788162 [details]
Bug 1296175 - Remove broken timout code when pushing new permissions.

https://reviewboard.mozilla.org/r/76752/#review75946
Attachment #8788162 - Flags: review?(ato) → review+
Pushed by hskupin@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/5d854c8d0765
Remove broken timout code when pushing new permissions. r=ato
https://hg.mozilla.org/mozilla-central/rev/5d854c8d0765
Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla51
I don't see any instances of this on Aurora, but is the underlying code defect there? Should we uplift this?
Assignee: nobody → hskupin
Flags: needinfo?(hskupin)
(In reply to Ryan VanderMeulen [:RyanVM] from comment #8)
> I don't see any instances of this on Aurora, but is the underlying code
> defect there? Should we uplift this?

Yes, it's also present on mozilla-aurora. We should be able to uplift this change if necessary without modifications.
Flags: needinfo?(hskupin)
Whiteboard: [checkin-needed-aurora]
You need to log in before you can comment on or make changes to this bug.