1519777 - TimedPromise timed out after 5000 ms in "WebDriver:FullscreenWindow"

Status: RESOLVED WORKSFORME

(Remote Protocol :: Marionette, defect, P3)

Comment 1

[Henrik Skupin [:whimboo][⌚️UTC+2]]

(In reply to Intermittent Failures Robot from bug 1506245 comment #10)

2 failures in 2627 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1
• mozilla-inbound: 1

Platform breakdown:

• osx-10-10: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1506245&startday=2019-01-07&endday=2019-01-13&tree=all

There is a timeout when switching into fullscreen mode:

02:47:41 INFO - 1547117261987 Marionette DEBUG 105 -> [0,8,"WebDriver:FullscreenWindow",{}]
02:47:43 INFO - 1547117263493 Marionette WARN TimedPromise timed out after 1500 ms: stacktrace:
02:47:43 INFO - bail@chrome://marionette/content/sync.js:196:64

Comment 2

[Henrik Skupin [:whimboo][⌚️UTC+2]]

The default timeout for the TimedPromise is 1.5s, which means that restoreWindow() cannot be the problem here, because it has a timeout of 2s and would also raise an error. As such only switching into fullscreen is problematic here:

https://searchfox.org/mozilla-central/rev/b29663c6c9c61b0bf29e8add490cbd6bad293a67/testing/marionette/driver.js#3139-3144

I tested locally on my system and whether I'm using an opt or debug build the switch into fullscreen takes about 0.7s. So the type of build isn't the problem here, but the animation from MacOS. By using the default timeout of 1.5s for going into fullscreen is way short, and I can expect that our test machines which are older Mac Minis, might need a bit more time. As such raising the timeout would be a good idea.

Beside that I checked mochitests and others in how they detect when the switch into fullscreen mode is done. Here two more events are coming into play:

1. There is a fullscreen event which is fired on the window when the browser enters or leaves fullscreen: https://developer.mozilla.org/en-US/docs/Web/Events/fullscreen. This doesn't seem to be the right choice here.

2. Also a resize event is fired similar when calling moveTo(), or resizeTo(): https://developer.mozilla.org/en-US/docs/Web/API/Window/fullScreen. As MDN notes: Switching between regular window and full screen will fire the "resize" event on the corresponding window.

3. Currently we only use the sizemodechange event, and assume that this can fire a couple of times. But when checking various tests none of them expect to see multiple of those events. So we may consider to get rid of the DebounceCallback usage.

To see in which order, and in which delays those events are fired I added event listeners for all of them. Here the result from a debug build:

1547552560897 Marionette DEBUG 4 -> [0,2,"WebDriver:FullscreenWindow",{}]
** 1547552560898: before win.fullScreen = true;
** 1547552561010: after win.fullScreen = true;
[..]
** 1547552561588: sizemodechange event for fullscreen for [object ChromeWindow]
** 1547552561595: fullscreen event for fullscreen for [object ChromeWindow]
** 1547552561604: resize event for fullscreen for [object ChromeWindow]
1547552561859 Marionette DEBUG 4 <- [1,2,null,{"x":0,"y":0,"width":1680,"height":1050}]

As observed all of them really fire only once, and in this specific order. Interesting is that sizemodechange fires before fullscreen, whereby the latter is intended to fire before the browser goes into full screen. Maybe the documentation on MDN is wrong here?

Maybe the best choice here is to actually wait for the resize event, which is fired as last one. That way we might also not have to spin the event loop because all necessary events have already been fired. Removing the call to IdlePromise() gives:

** 1547553142099: sizemodechange event for fullscreen for [object ChromeWindow]
** 1547553142105: fullscreen event for fullscreen for [object ChromeWindow]
** 1547553142115: resize event for fullscreen for [object ChromeWindow]
1547553142116 Marionette DEBUG 4 <- [1,2,null,{"x":0,"y":0,"width":1680,"height":1050}]

And using it:

1547553242668 Marionette DEBUG 4 -> [0,2,"WebDriver:FullscreenWindow",{}]
** 1547553243405: sizemodechange event for fullscreen for [object ChromeWindow]
** 1547553243421: fullscreen event for fullscreen for [object ChromeWindow]
** 1547553243429: resize event for fullscreen for [object ChromeWindow]
1547553243449 Marionette DEBUG 4 <- [1,2,null,{"x":0,"y":0,"width":1680,"height":1050}]

It means we have a difference of about 20ms, but in both cases would return immediately.

The huge benefit from getting rid of the DebounceCallback is the timing improvement. There is no need anymore to wait 250ms for a possible next sizemodechange event, which speeds-up the method by about 20%.

Comment 3

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Here a try build with some debug output to check the behavior on different platforms:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=458888f88dae183bba2a7170fac0eb02e1ebeea7

Comment 4

[Henrik Skupin [:whimboo][⌚️UTC+2]]

1. On Windows switching to fullscreen mode is way fast and takes about 40ms:

14:02:31 INFO - 1547560951360 Marionette DEBUG 92 -> [0,8,"WebDriver:FullscreenWindow",{}]
14:02:31 INFO - ** 1547560951361: before setting fullscreen
14:02:31 INFO - ** 1547560951367: sizemodechange event for fullscreen for [object ChromeWindow]
14:02:31 INFO - ** 1547560951376: fullscreen event for fullscreen for [object ChromeWindow]
14:02:31 INFO - ** 1547560951377: after setting fullscreen
14:02:31 INFO - ** 1547560951391: resize event for fullscreen for [object ChromeWindow]
14:02:31 INFO - 1547560951407 Marionette DEBUG 92 <- [1,8,null,{"x":0,"y":0,"width":1024,"height":768}]

2. Here for Linux, which shows similar timings:

[task 2019-01-15T14:04:14.641Z] 14:04:14 INFO - 1547561054636 Marionette DEBUG 99 -> [0,8,"WebDriver:FullscreenWindow",{}]
[task 2019-01-15T14:04:14.641Z] 14:04:14 INFO - ** 1547561054637: before setting fullscreen
[task 2019-01-15T14:04:14.641Z] 14:04:14 INFO - ** 1547561054637: after setting fullscreen
[task 2019-01-15T14:04:14.646Z] 14:04:14 INFO - ** 1547561054642: sizemodechange event for fullscreen for [object ChromeWindow]
[task 2019-01-15T14:04:14.656Z] 14:04:14 INFO - ** 1547561054651: fullscreen event for fullscreen for [object ChromeWindow]
[task 2019-01-15T14:04:14.675Z] 14:04:14 INFO - ** 1547561054664: resize event for fullscreen for [object ChromeWindow]
[task 2019-01-15T14:04:14.691Z] 14:04:14 INFO - 1547561054685 Marionette DEBUG 99 <- [1,8,null,{"x":0,"y":0,"width":1600,"height":1200}]

3. Only on Mac we have a really delayed return of the command due to the MacOS wide animation when enabling fullscreen mode:

06:01:12 INFO - 1547560872974 Marionette DEBUG 100 -> [0,8,"WebDriver:FullscreenWindow",{}]
06:01:12 INFO - ** 1547560872976: before setting fullscreen
06:01:13 INFO - ** 1547560873069: after setting fullscreen
06:01:14 INFO - ** 1547560874034: sizemodechange event for fullscreen for [object ChromeWindow]
06:01:14 INFO - ** 1547560874042: fullscreen event for fullscreen for [object ChromeWindow]
06:01:14 INFO - ** 1547560874045: resize event for fullscreen for [object ChromeWindow]
06:01:14 INFO - [Parent 811, Main Thread] WARNING: NS_ENSURE_TRUE(!aStringURI.IsEmpty()) failed: file /builds/worker/workspace/build/src/docshell/base/nsDefaultURIFixup.cpp, line 136
06:01:14 INFO - 1547560874064 Marionette DEBUG 100 <- [1,8,null,{"x":0,"y":0,"width":1600,"height":1200}]

4. Mn headless across all platforms:

06:00:40 INFO - 1547560840913 Marionette DEBUG 100 -> [0,8,"WebDriver:FullscreenWindow",{}]
06:00:40 INFO - ** 1547560840915: before setting fullscreen
06:00:40 INFO - ** 1547560840916: sizemodechange event for fullscreen for [object ChromeWindow]
06:00:40 INFO - ** 1547560840925: fullscreen event for fullscreen for [object ChromeWindow]
06:00:40 INFO - ** 1547560840926: after setting fullscreen
06:00:40 INFO - ** 1547560840938: resize event for fullscreen for [object ChromeWindow]
06:00:40 INFO - 1547560840963 Marionette DEBUG 100 <- [1,8,null,{"x":4,"y":4,"width":1600,"height":1200}]

With headless mode the events are coming in way faster also on MacOS, and the order of those is still the same.

Comment 5

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Andreas mentioned to me that I also have to test with xvfb on Linux given that lots of users are still using this method instead of headless. That was pretty informative given that it showed some differences.

With xvfb there is no such sizemodechange event fired, and as such would always fire the timeout error, but it's actually ignored. Also I don't see the resize events. Only the fullscreen events are reliably fired on the current window.

That means that we cannot listen for the sizemodechange event, but have to use fullscreen. This will save nearly 1500ms for each call to fullscreen on Linux when using xvfb!

Further win.windowState is not correctly reported when using xvfb, but is always set to maximized (1). Even when going into fullscreen and win.fullScreen returns true, it is still 1. As result trying to do a fullscreen for an already fullscreened window will cause a timeout too, because no events are fired at all. Given that this sounds like a major problem affecting all the tests, I filed bug 1520302.

Comment 6

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Actually this is a hidden timeout error. So updating the summary.

Comment 7

[Henrik Skupin [:whimboo][⌚️UTC+2]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=2e9db12acd4484401a52106535bb28a39ca3bf7c

Comment 8

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Attachment: Bug 1519777 - [marionette] Make "WebDriver:FullscreenWindow" more reliable.

The only reliable event to detect if the window has been switched
into fullscreen is the `fullscreen` event. When using xvfb it's
even the only event which gets fired. Currently the TimedPromise
always times out after 1500ms.

Further the `fullscreen` event is fired only once, which eliminates
the usage of the DebounceCallback, and even the TimedPromise. A
better solution is to use the "waitForEvent()" promise, because we
can be sure to see this event.

Also the "windowState" property of the window is unreliable when
using xvfb and cannot be used to detect if the fullscreen mode is
already enabled. It's better to use "fullScreen" instead.

Comment 9

[Henrik Skupin [:whimboo][⌚️UTC+2]]

When fixing the code for entering fullscreen mode with this bug it would be also good to fix all instances of fullscreen detection, and how it exits fullscreen. I will push some more revisions.

Comment 10

[Henrik Skupin [:whimboo][⌚️UTC+2]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=9334c89916b372679b4b2d30e61b0c5a44977ac5

Comment 11

[Henrik Skupin [:whimboo][⌚️UTC+2]]

For this command we will most likely use the window.fullScreen flag to determine if we are in fullscreen mode or not. Also the timeout has been increased to 5000ms by bug 1521527.

Comment 12

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Currently I'm not working on this bug, and it's also blocked by another bug, which needs to be fixed first.

Comment 13

[Henrik Skupin [:whimboo][⌚️UTC+2]]

I checked again and cannot see this TimedPromise error anymore in the logs.