TEST-UNEXPECTED-ERROR | test_windows.py TestBaseWindow.test_switch_to_and_focus | TimeoutException: Timed out after 5.0 seconds with message: Focus has not been set to chrome window handle "3"

REOPENED
Unassigned

Status

REOPENED
3 years ago
2 years ago

People

(Reporter: whimboo, Unassigned)

Tracking

({intermittent-failure})

45 Branch
intermittent-failure
Points:
---

Firefox Tracking Flags

(firefox45 wontfix, firefox46 wontfix, firefox47 wontfix, firefox48 wontfix, firefox49 affected, firefox-esr45 affected)

Details

(Reporter)

Description

3 years ago
Looks kinda similar to bug 1212811 but fails with a slightly different traceback.

https://treeherder.mozilla.org/logviewer.html#?job_id=689719&repo=mozilla-beta

 14:11:29     INFO - TEST-UNEXPECTED-ERROR | test_windows.py TestBaseWindow.test_switch_to_and_focus | TimeoutException: TimeoutException: Timed out after 5.1 seconds
 14:11:29     INFO - 
 14:11:29     INFO - 
 14:11:29     INFO - Traceback (most recent call last):
 14:11:29     INFO -   File "/home/mozauto/jenkins/workspace/release-mozilla-beta_functional/build/venv/local/lib/python2.7/site-packages/marionette/marionette_test.py", line 344, in run
 14:11:29     INFO -     testMethod()
 14:11:29     INFO -   File "/home/mozauto/jenkins/workspace/release-mozilla-beta_functional/build/venv/local/lib/python2.7/site-packages/firefox_puppeteer/tests/test_windows.py", line 160, in test_switch_to_and_focus
 14:11:29     INFO -     win1.focus()
 14:11:29     INFO -   File "/home/mozauto/jenkins/workspace/release-mozilla-beta_functional/build/venv/local/lib/python2.7/site-packages/firefox_puppeteer/ui/windows.py", line 301, in focus
 14:11:29     INFO -     return self._windows.focus(self.handle)
 14:11:29     INFO -   File "/home/mozauto/jenkins/workspace/release-mozilla-beta_functional/build/venv/local/lib/python2.7/site-packages/firefox_puppeteer/ui/windows.py", line 144, in focus
 14:11:29     INFO -     Wait(self.marionette).until(lambda _: handle == self.focused_chrome_window_handle)
 14:11:29     INFO -   File "/home/mozauto/jenkins/workspace/release-mozilla-beta_functional/build/venv/local/lib/python2.7/site-packages/marionette_driver/wait.py", line 143, in until
 14:11:29     INFO -     cause=last_exc)

An affected machine was mm-ub-1404-32-2 and it also had the crash dialog open for the application keyboard input methods.
(Reporter)

Updated

3 years ago
Keywords: intermittent-failure
6 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-release: 6

Platform breakdown:
* linux32: 4
* linux64: 2

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1234175&startday=2015-12-21&endday=2015-12-27&tree=all
(Assignee)

Updated

3 years ago
Product: Mozilla QA → Testing
12 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-release: 7
* mozilla-beta: 5

Platform breakdown:
* linux64: 8
* linux32: 4

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1234175&startday=2016-01-04&endday=2016-01-10&tree=all
5 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-beta: 5

Platform breakdown:
* linux32: 3
* linux64: 2

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1234175&startday=2016-01-11&endday=2016-01-17&tree=all
7 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-release: 7

Platform breakdown:
* linux64: 4
* linux32: 3

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1234175&startday=2016-01-18&endday=2016-01-24&tree=all
27 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-beta: 16
* mozilla-release: 11

Platform breakdown:
* linux64: 14
* linux32: 13

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1234175&startday=2016-02-08&endday=2016-02-14&tree=all
23 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-beta: 23

Platform breakdown:
* linux32: 12
* linux64: 11

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1234175&startday=2016-02-22&endday=2016-02-28&tree=all
(Reporter)

Comment 7

3 years ago
Something strange is happening here:

TEST-START | test_windows.py TestBaseWindow.test_switch_to_and_focus
Waiting for focus of handle: 3
focused handle: 3
Is focused
Opened window. Setting focus to 47
Waiting for focus of handle: 47
focused handle: 47
Is focused
focused handle: 47
focused handle: 47
focused handle: 47
focused handle: 47
Waiting for focus of handle: 3
focused handle: 47
focused handle: 47
focused handle: 47
TEST-UNEXPECTED-ERROR | test_windows.py TestBaseWindow.test_switch_to_and_focus | TimeoutException: TimeoutException: Timed out after 5.1 seconds

We somewhat fail to initiate the focus() call so we never actually switch it. Not sure yet why this happens.
(Reporter)

Comment 8

3 years ago
The problem here really seems to be the execute_script call in chrome scope when we call window.focus():

https://dxr.mozilla.org/mozilla-central/source/testing/puppeteer/firefox/firefox_puppeteer/ui/windows.py#141

This does not succeed sometimes so no focus change gets initiated. When I run the execute_script call multiple times the problem is gone and the expected window gets the focus.

Mike, not sure if you are the best person to ask this so feel free to forward the ni? request. But do you know why the call to window.focus() can sometimes fail? Especially the window we want to focus is an already open window. Could a specific window state refuse the focus() call?
Flags: needinfo?(mconley)
(Reporter)

Comment 9

3 years ago
(In reply to Henrik Skupin (:whimboo) from comment #8)
> This does not succeed sometimes so no focus change gets initiated. When I
> run the execute_script call multiple times the problem is gone and the
> expected window gets the focus.

It would also work if you sleep 100ms.
(Reporter)

Comment 10

3 years ago
Ok, I got another debug output:

switched to chrome window: 3
switched to chrome window: 46
focused handle: 46
switched to chrome window: 3
Outer window id from execute_script: 46
Waiting for focus of handle: 3

There is definitely something wrong with Marionette here. We correctly switched to the chrome window with the outer id 3, but when I then execute JS code on that chrome window, we still operate on the formerly selected chrome window. 

I strongly believe that this is a bug in Marionette. I will continue investigating on Monday.
Flags: needinfo?(mconley)
19 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-release: 17
* mozilla-esr45: 2

Platform breakdown:
* linux32: 10
* linux64: 9

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1234175&startday=2016-02-29&endday=2016-03-06&tree=all
(Reporter)

Comment 12

3 years ago
As an overview, we are changing the chrome window from window 1 to window 2 by using `self.marionette.switch_to_window(handle_window1)`. Immediately we call into the `execute_script()` which uses `window.focus()` to set the active focus to the newly selected window. Then we wait for the window to be focused. The latter sometimes or mostly fails on our testing boxes in qa.scl3.mozilla.com. The focus doesn't get changes. It only changes if I add a very small delay before the execute_script() call or after switching the window. Here even a sleep value of 0.01 is enough.

Adding debug code to our execute_script call and checking the outer id of the current window shows the one from the old window but not the new one if no sleep has been added. 

Andreas could you imagine that `switch_to_window()` returns too early means before the chrome window has actually been changed?
Flags: needinfo?(ato)
(Reporter)

Comment 13

3 years ago
Oh and I tried to debug Marionette server for switchToWindow() but I always run into a crash (see bug 1225160)
(Reporter)

Comment 14

3 years ago
I can also reproduce this race with a 48.0 nightly build. Given that I cannot debug Marionette due to the crash I tried to get some more output via enabling TRACE output (-vv). But looks like that sending those additional data is enough to make this bug disappear. :( Debug output is actually not enough.
status-firefox45: --- → affected
status-firefox46: --- → affected
status-firefox47: --- → affected
status-firefox48: --- → affected
status-firefox-esr45: --- → affected
(Reporter)

Comment 15

3 years ago
I spent more time on that bug today and noticed that this cannot be a race in Marionette but something is not working correctly in Firefox by focusing the wanted window. Here an example output for two chrome windows:

** window handle before focus() call: 3
** setting focus for handle 3
** currently focused window: 3
* Open new window and get window classes   
** window handle before focus() call: 25   
** setting focus for handle 25
** currently focused window: 25
* Switch to first window
** currently focused window: 25
* Focus first window
** window handle before focus() call: 3
** setting focus for handle 3
** currently focused window: None
** currently focused window: 25
** currently focused window: 25
[..]
** currently focused window: 25
Timeout...

So the second window gets automatically the focus when it gets opened. When switching to the first window handle in Marionette and then calling focus, the outer window id of the chrome window is correct in Firefox. So we clearly call focus() on the correct chrome window. With having `None` first I can see that a focus change event has been triggered, but somehow the second window gets the focus again.

Now comes the curiosity... this only happens when the windows have about:blank shown. If I load e.g. about:newtab the focus change event is always working. No single failure in 100 runs. Not sure what's special with about:blank and how it affects the focus change of chrome windows.

Neil, do you have any idea what could be wrong here? Code references in how we set focus and wait for the focused window can be found here (both are in the Python client of Marionette):

* https://dxr.mozilla.org/mozilla-central/source/testing/puppeteer/firefox/firefox_puppeteer/ui/windows.py#134
* https://dxr.mozilla.org/mozilla-central/source/testing/puppeteer/firefox/firefox_puppeteer/ui/windows.py#42
Flags: needinfo?(ato) → needinfo?(enndeakin)

Comment 16

3 years ago
How are you waiting for the window to be opened and/or focused?
Flags: needinfo?(enndeakin)
(Reporter)

Comment 17

3 years ago
Please see the two links in my last comment. All is done from the marionette python client, so we do not spin the event loop or something else.
Flags: needinfo?(enndeakin)
(Reporter)

Comment 18

3 years ago
So in short we do a `window.focus()` for the wanted chrome window to become the focus. Then we check for the outer window id of the `Services.focus.activeWindow` to be the right one.
7 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-release: 7

Platform breakdown:
* linux32: 4
* linux64: 3

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1234175&startday=2016-03-14&endday=2016-03-20&tree=all
(Reporter)

Comment 20

3 years ago
No more failures for this all the last 2 months. Going to close as WFM for now.
Status: NEW → RESOLVED
Last Resolved: 3 years ago
Flags: needinfo?(enndeakin)
Resolution: --- → WORKSFORME
(Reporter)

Updated

2 years ago
Status: RESOLVED → REOPENED
status-firefox45: affected → wontfix
status-firefox46: affected → wontfix
status-firefox47: affected → wontfix
status-firefox48: affected → wontfix
status-firefox49: --- → affected
Resolution: WORKSFORME → ---
Summary: TEST-UNEXPECTED-ERROR | test_windows.py TestBaseWindow.test_switch_to_and_focus | TimeoutException: TimeoutException: Timed out after 5.1 seconds → TEST-UNEXPECTED-ERROR | test_windows.py TestBaseWindow.test_switch_to_and_focus | TimeoutException: Timed out after 5.0 seconds with message: Focus has not been set to chrome window handle "3"
6 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-beta: 4
* mozilla-release: 1
* mozilla-aurora: 1

Platform breakdown:
* linux64: 3
* linux32: 3

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1234175&startday=2016-09-19&endday=2016-09-25&tree=all
You need to log in before you can comment on or make changes to this bug.