Closed Bug 1523234 Opened 5 years ago Closed 5 years ago

New window command can timeout because opened window doesn't always receive the focus even with `focus` event emitted

Categories

(Remote Protocol :: Marionette, defect, P2)

defect

Tracking

(firefox67 fixed)

RESOLVED FIXED
mozilla67
Tracking Status
firefox67 --- fixed

People

(Reporter: whimboo, Assigned: whimboo)

References

Details

Attachments

(2 files)

Here an example for bug 1521563:

[task 2019-01-21T15:03:22.070Z] 15:03:22 INFO - 1548083002060 Marionette DEBUG 70 -> [0,12,"WebDriver:NewWindow",{"type":"window","focus":false}]
[task 2019-01-21T15:03:22.107Z] 15:03:22 INFO - 1548083002103 Marionette TRACE Received DOM event activate for [object ChromeWindow]
[task 2019-01-21T15:03:22.109Z] 15:03:22 INFO - 1548083002103 Marionette TRACE Received DOM event focus for [object XULDocument]
[task 2019-01-21T15:03:22.268Z] 15:03:22 INFO - 1548083002255 Marionette TRACE Received observer notification browser-delayed-startup-finished
[task 2019-01-21T15:09:22.143Z] 15:09:22 INFO - 1548083362137 Marionette DEBUG Closed connection 70

Blocks: 1519372
Priority: -- → P3

I would suggest that we land some debug code for this method so that we can check what's actually going wrong here. The failure is low intermittent and I wasn't able to reproduce it yet.

Assignee: nobody → hskupin
Status: NEW → ASSIGNED
Priority: P3 → P2
No longer blocks: 1522790
Comment on attachment 9044710 [details] [diff] [review]
[marionette] Add debug output for handling focus in "WebDriver:NewWindow"

Adds tracing output for focus selection after new window has been opened.
Attachment #9044710 - Flags: review?(ato)

Note that I was not able to catch this failure in all of the try build's Mn jobs, which retriggered a dozen of times. With landing the debug output patch I hope to get a better idea what's going wrong.

Attachment #9044710 - Flags: review?(dburns)
Comment on attachment 9044710 [details] [diff] [review]
[marionette] Add debug output for handling focus in "WebDriver:NewWindow"

Review of attachment 9044710 [details] [diff] [review]:
-----------------------------------------------------------------

::: testing/marionette/browser.js
@@ +337,5 @@
>            activated = waitForEvent(this.window, "activate");
>            focused = waitForEvent(this.window, "focus", {capture: true});
>  
> +          logger.trace("Setting focus back to opening window " +
> +              ` due to focus: ${focus}`);

Space at end of previous string and at beginning of this, makes a
total of two spaces.
Attachment #9044710 - Flags: review?(ato) → review+
Attachment #9044710 - Flags: review?(dburns)

(In reply to Andreas Tolfsen ⦗:ato⦘ from comment #6)

       activated = waitForEvent(this.window, "activate");
       focused = waitForEvent(this.window, "focus", {capture: true});
  •      logger.trace("Setting focus back to opening window " +
    
  •          ` due to focus: ${focus}`);
    

Space at end of previous string and at beginning of this, makes a
total of two spaces.

Ups. I will fix it before pushing to inbound. Thanks.

Pushed by hskupin@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/e18dc4b5dc31
[marionette] Add debug output for handling focus in "WebDriver:NewWindow". r=ato
Keywords: leave-open

The debug information which was landed earlier last week was pretty helpful. Here the details:

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=230185698&repo=autoland&lineNumber=24544

[task 2019-02-24T21:18:49.262Z] 21:18:49 INFO - 1551043129259 Marionette DEBUG 71 -> [0,12,"WebDriver:NewWindow",{"type":"window","focus":false}]
[task 2019-02-24T21:18:49.344Z] 21:18:49 INFO - 1551043129342 Marionette TRACE Received DOM event activate for [object ChromeWindow]
[task 2019-02-24T21:18:49.345Z] 21:18:49 INFO - 1551043129342 Marionette TRACE Received DOM event focus for [object XULDocument]
[task 2019-02-24T21:18:49.515Z] 21:18:49 INFO - 1551043129512 Marionette TRACE Received observer notification browser-delayed-startup-finished
[task 2019-02-24T21:18:49.523Z] 21:18:49 INFO - 1551043129517 Marionette TRACE Opening window is active window: true
[task 2019-02-24T21:18:49.524Z] 21:18:49 INFO - 1551043129519 Marionette TRACE Setting focus back to opening window due to focus: false

It means that the newly opened browser window gets the activate and focus event, but doesn't actually have the focus. Instead the opening window keeps the focus, maybe only for a few number of milliseconds but it's enough to cause a race, when we are trying to focus it again and waiting for the focus and activate events.

Neil, is a behavior like that known? Maybe it is focus manager test mode related? Btw. the intermittent rate is low.

Flags: needinfo?(enndeakin)

Genarally, most focus problems like this happen on GTK as it tends to send asynchronous focus notifications and problems arise when windows are opened/closed/focused in quick succession.

Are you sure that the focus happening after the timeout is occuring? See https://searchfox.org/mozilla-central/source/testing/marionette/browser.js#328

As a side note, the focus event always fires after the activate event, so there isn't any particular reason to wait for the activate event as well.

Flags: needinfo?(enndeakin)

(In reply to Neil Deakin from comment #11)

Genarally, most focus problems like this happen on GTK as it tends to send asynchronous focus notifications and problems arise when windows are opened/closed/focused in quick succession.

Are you sure that the focus happening after the timeout is occuring? See https://searchfox.org/mozilla-central/source/testing/marionette/browser.js#328

When you check the log output from comment 10 we clearly get the activate and focus events, as setup via a Promise before. So the call to focus() should have happened. Also could this ever fail? It would be nice to remove the setTimeout but I cannot do it due to bug 1509234.

As a side note, the focus event always fires after the activate event, so there isn't any particular reason to wait for the activate event as well.

That is what Gijs told me, and which seem to be heavily used for mochitests. If that is the case it could be a larger change.

Flags: needinfo?(enndeakin)
Summary: New window command can timeout because of missing focus events when switching back to original window → New window command can timeout because opened window doesn't always receive the focus even with `focus` event emitted

I will go ahead and just add the check if the original window hasn't the focus yet. Only then really call focus().

try build:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=a543adbeee12494e9fcfc7fb3fce2ef0dd6d626d

Flags: needinfo?(enndeakin)
Pushed by hskupin@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/2b18f28016cf
[marionette] Only focus target window if it isn't already the active window. r=ato
Status: ASSIGNED → RESOLVED
Closed: 5 years ago
Keywords: leave-open
Resolution: --- → FIXED
Target Milestone: --- → mozilla67
Product: Testing → Remote Protocol
You need to log in before you can comment on or make changes to this bug.