Closed Bug 1234175 Opened 9 years ago Closed 5 years ago

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"

Categories

(Testing :: Firefox UI Tests, defect)

Product:
Testing
Component:
Firefox UI Tests
Version:
45 Branch
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

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

Status:
RESOLVED INCOMPLETE
Tracking Flags:
Tracking Status
firefox45 --- wontfix
firefox46 --- wontfix
firefox47 --- wontfix
firefox48 --- wontfix
firefox49 --- wontfix
firefox-esr45 --- wontfix

People

(Reporter: whimboo, Unassigned)

References

Details

(Keywords: intermittent-failure) 

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.
Product: Mozilla QA → Testing
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.
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)
(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.
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)
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)
Oh and I tried to debug Marionette server for switchToWindow() but I always run into a crash (see bug 1225160)
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
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)
How are you waiting for the window to be opened and/or focused?
Flags: needinfo?(enndeakin)
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)
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.
No more failures for this all the last 2 months. Going to close as WFM for now.
Status: NEW → RESOLVED
Closed: 8 years ago
Flags: needinfo?(enndeakin)
Resolution: --- → WORKSFORME
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"
Status: REOPENED → RESOLVED
Closed: 8 years ago → 5 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.