1297551 - setTimeout set in injected script is cancelled

Status: RESOLVED FIXED

(Remote Protocol :: Marionette, defect)

Description

[Jason Juang (:juangj)]

User Agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/52.0.2743.82 Safari/537.36

Steps to reproduce:

Using the 'Execute Script' command in Marionette cause pending function calls queued by setTimeout to not be executed.

I'll attach an example test in a moment.

I've reproduced this with Geckodriver 0.10.0 and these Firefox versions on Ubuntu:
- Firefox 48.0
- Firefox 49.0 beta 6
- Firefox nightly (51.0a1 2016-08-23)


Actual results:

Python output:
[]
[1]
[1]
[1]
Press Enter to quit

Text content of #log after 10 seconds:
1 6 7 8 9 10


Expected results:

Python output:
[]
[1]
[1, 2]
[1, 2, 3]
Press Enter to quit

Text content of #log after 10 seconds:
1 2 3 4 5 6 7 8 9 10

Comment 1

[Jason Juang (:juangj)]

Attachment: script.py

Comment 2

[Jason Juang (:juangj)]

Attachment: script.html

Comment 3

[Jason Juang (:juangj)]

Interestingly, the bug does not reproduce if I replace the setTimeout with a similar setInterval call like this:
  var n = 1;
  setInterval(function() {
    log.textContent += n + ' ';
    x.push(n++);
  }, 1000);
so perhaps the problem is dependent on the number of pending operations.

Comment 4

[Jason Juang (:juangj)]

Any chance somebody can reproduce/confirm this? I understand there are plenty of other bugs to look at, but I feel like this is pretty severe and it would make me feel better to have an acknowledgment that somebody has looked at the problem.

We consider this a hard blocker for migrating to Marionette, because it can fundamentally muck with the JS that is being tested.

Comment 5

[Jason Juang (:juangj)]

Any progress here? I'm getting really anxious about not being able to run tests in modern versions of Firefox because of this. I also can't think of a good workaround on our end. I'm sorry and don't want to nag -- I know you've got a lot going on.

Just to restate the severity: any WebDriver test that injects JS could cause the page under test to do apparently-impossible things, in a way that's really difficult for a WebDriver user to debug.

Now that some local ends are injecting JS atoms under the hood, the probability of this happening is a bit higher, in general.

Comment 6

[Andreas Tolfsen ❲:ato❳]

That we haven’t responded doesn’t mean we don’t think it’s important.  But there is only a finite amount of resources in this world, and I assure you we will get around to it eventually.

Comment 7

[Andreas Tolfsen ❲:ato❳]

The problem appears to be that we call the `setTimeout` global in the frame script rather than the one for the mutable sandbox when registering the script timeout handler.  As `setTimeout` returns an incrementing integer rather than a unique identifier, the ID later passed to `nsISandbox.window.clearTimeout` incidentally clears the timeouts of the content script.

Here we need to change `setTimeout` to `sb.window.setTimeout`:

    https://github.com/mozilla/gecko-dev/blob/master/testing/marionette/evaluate.js#L147

Comment 8

[Andreas Tolfsen ❲:ato❳]

Attachment: Bug 1297551 - Avoid cancelling content timeout callback;

We need to avoid passing the timeout ID returned from `setTimeout` in the
content frame script that we use to register the script timeout handler
to the sandbox's `clearTimeout` function as this might interfere with any
`window.setTimeout` calls being made in the injected script.

Review commit: https://reviewboard.mozilla.org/r/95684/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/95684/

Comment 9

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8814452 [details]
Bug 1297551 - Avoid cancelling content timeout callback;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/95684/diff/1-2/

Comment 10

[David Burns :automatedtester]

Comment on attachment 8814452 [details]
Bug 1297551 - Avoid cancelling content timeout callback;

https://reviewboard.mozilla.org/r/95684/#review95750

::: testing/marionette/harness/marionette/tests/unit/test_execute_script.py:254
(Diff revision 2)
> +        # first execute script call should not cancel event
> +        self.assertEqual(0, self.marionette.execute_script(
> +            "return window.contentTimeoutTriggered", sandbox=None))
> +
> +        # test that event was not cancelled
> +        time.sleep(1)

why is there a sleep here and not in the next assert

Comment 11

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8814452 [details]
Bug 1297551 - Avoid cancelling content timeout callback;

https://reviewboard.mozilla.org/r/95684/#review95752

::: testing/marionette/harness/marionette/tests/unit/test_execute_script.py:254
(Diff revision 2)
> +        # first execute script call should not cancel event
> +        self.assertEqual(0, self.marionette.execute_script(
> +            "return window.contentTimeoutTriggered", sandbox=None))
> +
> +        # test that event was not cancelled
> +        time.sleep(1)

Because the `setTimeout` call in the script only triggers once, and the next assertion checks that `contentTimeoutID` that was increased as part of this call was indeed increased.

Comment 12

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8814452 [details]
Bug 1297551 - Avoid cancelling content timeout callback;

https://reviewboard.mozilla.org/r/95684/#review95750

> why is there a sleep here and not in the next assert

Because the setTimeout call in the script only triggers once, and the next assertion checks that contentTimeoutID that was increased as part of this call was indeed increased.

Comment 13

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/4e9afb28d651
Avoid cancelling content timeout callback; r=automatedtester

Comment 14

[Phil Ringnalda (:philor)]

https://hg.mozilla.org/mozilla-central/rev/4e9afb28d651

Comment 15

[Andreas Tolfsen ❲:ato❳]

Sheriffs: Test-only uplift since Marionette is hidden behind a flag.

Comment 16

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/7a51c6107a4d

Comment 17

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-beta/rev/1dad3673be18