setTimeout set in injected script is cancelled

RESOLVED FIXED in Firefox 51

Status

defect
RESOLVED FIXED
3 years ago
3 years ago

People

(Reporter: juangj, Assigned: ato)

Tracking

(Blocks 1 bug)

unspecified
mozilla53
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox51 fixed, firefox52 fixed, firefox53 fixed)

Details

Attachments

(3 attachments)

Reporter

Description

3 years 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

3 years ago
Posted file script.py
Reporter

Comment 2

3 years ago
Posted file script.html
Reporter

Comment 3

3 years 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

3 years 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

3 years 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

3 years 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

3 years 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

3 years ago
Blocks: webdriver
Comment hidden (mozreview-request)
Assignee

Updated

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

Comment 10

3 years 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

3 years 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

3 years 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

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

Comment 14

3 years ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/4e9afb28d651
Status: ASSIGNED → RESOLVED
Last Resolved: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla53
Assignee

Comment 15

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

Comment 16

3 years ago
bugherderuplift
https://hg.mozilla.org/releases/mozilla-aurora/rev/7a51c6107a4d
Whiteboard: [checkin-needed-aurora][checkin-needed-beta] → [checkin-needed-beta]
You need to log in before you can comment on or make changes to this bug.