setTimeout set in injected script is cancelled

RESOLVED FIXED in Firefox 51

Status

Testing
Marionette
RESOLVED FIXED
a year ago
a year ago

People

(Reporter: juangj, Assigned: ato)

Tracking

(Blocks: 1 bug)

unspecified
mozilla53
Points:
---

Firefox Tracking Flags

(firefox51 fixed, firefox52 fixed, firefox53 fixed)

Details

MozReview Requests

Submitter Diff Changes Open Issues Last Updated
Loading...
Error loading review requests:

Attachments

(3 attachments)

(Reporter)

Description

a year ago
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
(Reporter)

Comment 1

a year ago
Created attachment 8784184 [details]
script.py
(Reporter)

Comment 2

a year ago
Created attachment 8784185 [details]
script.html
(Reporter)

Comment 3

a year ago
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.
(Reporter)

Comment 4

a year ago
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.
(Reporter)

Comment 5

a year ago
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.
Flags: needinfo?(dburns)
Flags: needinfo?(ato)
(Assignee)

Comment 6

a year ago
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.
Flags: needinfo?(dburns)
Flags: needinfo?(ato)
(Assignee)

Comment 7

a year ago
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
Assignee: nobody → ato
Status: UNCONFIRMED → ASSIGNED
Ever confirmed: true
Comment hidden (mozreview-request)
(Assignee)

Updated

a year ago
Blocks: 721859
Comment hidden (mozreview-request)
(Assignee)

Updated

a year ago
Summary: Execute Script command causes incorrect JS execution → setTimeout set in injected script is cancelled

Comment 10

a year ago
mozreview-review
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
Attachment #8814452 - Flags: review?(dburns) → review+
(Assignee)

Comment 11

a year ago
mozreview-review
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.
(Assignee)

Comment 12

a year ago
mozreview-review-reply
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

a year ago
Pushed by atolfsen@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/4e9afb28d651
Avoid cancelling content timeout callback; r=automatedtester

Comment 14

a year ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/4e9afb28d651
Status: ASSIGNED → RESOLVED
Last Resolved: a year ago
status-firefox53: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla53
(Assignee)

Comment 15

a year ago
Sheriffs: Test-only uplift since Marionette is hidden behind a flag.
Whiteboard: [checkin-needed-aurora][checkin-needed-beta]

Comment 16

a year ago
bugherderuplift
https://hg.mozilla.org/releases/mozilla-aurora/rev/7a51c6107a4d
status-firefox52: --- → fixed
Whiteboard: [checkin-needed-aurora][checkin-needed-beta] → [checkin-needed-beta]
https://hg.mozilla.org/releases/mozilla-beta/rev/1dad3673be18
status-firefox51: --- → fixed
Whiteboard: [checkin-needed-beta]
You need to log in before you can comment on or make changes to this bug.