Open Bug 888164 Opened 11 years ago Updated 2 years ago

Intermittent test_bug665540.html | window should be fullscreen, | window state should be fullscreen - got 3, expected 4, etc.

Categories

(Core :: Layout: Form Controls, defect, P5)

Product:
Core
Component:
Layout: Form Controls
Platform:
x86_64
Linux
Type:
defect

Tracking

()

People

(Reporter: philor, Unassigned)

References

(Depends on 1 open bug)

Details

(Keywords: intermittent-failure, Whiteboard: [test disabled on Linux64][leave open])

Attachments

(3 files)

additional logging to debug
1.53 KB, patch
Details | Diff | Splinter Review
test screenshot
647.31 KB, image/png
Details
record wm-state changes
24.27 KB, patch
Details | Diff | Splinter Review 
https://tbpl.mozilla.org/php/getParsedLog.php?id=24693185&tree=Mozilla-Central
Ubuntu VM 12.04 x64 mozilla-central debug test mochitest-other on 2013-06-27 21:24:15 PDT for push 8e3a124c9c1a
slave: tst-linux64-ec2-068

21:36:39     INFO -  12729 INFO TEST-INFO | chrome://mochitests/content/chrome/layout/forms/test/test_bug665540.html | must wait for focus
21:36:39     INFO -  --DOMWINDOW == 86 (0x4462c28) [serial = 2684] [outer = (nil)] [url = chrome://mochitests/content/chrome/layout/base/tests/chrome/test_transformed_scrolling_repaints_3.html]
21:36:39     INFO -  --DOMWINDOW == 85 (0x31bd1f8) [serial = 2689] [outer = (nil)] [url = chrome://mochikit/content/tests/SimpleTest/iframe-between-tests.html]
21:36:39     INFO -  --DOMWINDOW == 84 (0x44b90b8) [serial = 2678] [outer = (nil)] [url = chrome://mochitests/content/chrome/layout/base/tests/chrome/test_scrolling_repaints.html]
21:36:39     INFO -  --DOMWINDOW == 83 (0x3f80068) [serial = 2680] [outer = (nil)] [url = chrome://mochitests/content/chrome/layout/base/tests/chrome/test_transformed_scrolling_repaints.html]
21:36:39     INFO -  --DOMWINDOW == 82 (0x1749ba8) [serial = 2677] [outer = (nil)] [url = chrome://mochikit/content/tests/SimpleTest/iframe-between-tests.html]
21:36:39     INFO -  --DOMWINDOW == 81 (0x4b03638) [serial = 2682] [outer = (nil)] [url = chrome://mochitests/content/chrome/layout/base/tests/chrome/test_transformed_scrolling_repaints_2.html]
21:36:39     INFO -  --DOMWINDOW == 80 (0x555d028) [serial = 2679] [outer = (nil)] [url = chrome://mochikit/content/tests/SimpleTest/iframe-between-tests.html]
21:36:39     INFO -  --DOMWINDOW == 79 (0x54a6e58) [serial = 2683] [outer = (nil)] [url = chrome://mochikit/content/tests/SimpleTest/iframe-between-tests.html]
21:36:39     INFO -  --DOMWINDOW == 78 (0x534be68) [serial = 2681] [outer = (nil)] [url = chrome://mochikit/content/tests/SimpleTest/iframe-between-tests.html]
21:36:39     INFO -  --DOMWINDOW == 77 (0x4ec73c8) [serial = 2702] [outer = (nil)] [url = about:blank]
21:36:39     INFO -  --DOMWINDOW == 76 (0x4124aa8) [serial = 2711] [outer = (nil)] [url = about:blank]
21:36:39     INFO -  --DOMWINDOW == 75 (0x688fb58) [serial = 2699] [outer = (nil)] [url = about:blank]
21:36:39     INFO -  [Parent 2340] WARNING: OpenGL-accelerated layers are not supported on this system: file ../../../widget/xpwidgets/nsBaseWidget.cpp, line 883
21:36:39     INFO -  12730 ERROR TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/layout/forms/test/test_bug665540.html | window should be fullscreen
21:36:39     INFO -  12731 ERROR TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/layout/forms/test/test_bug665540.html | window state should be fullscreen - got 3, expected 4
21:36:40     INFO -  [Parent 2340] WARNING: NS_ENSURE_TRUE(scrollFrame) failed: file ../../../dom/base/nsDOMWindowUtils.cpp, line 1533
21:36:40     INFO -  [Parent 2340] WARNING: OpenGL-accelerated layers are not supported on this system: file ../../../widget/xpwidgets/nsBaseWidget.cpp, line 883
21:36:41     INFO -  12732 ERROR TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/layout/forms/test/test_bug665540.html | event.screenX should match sent event - got 78, expected 77
21:36:41     INFO -  12733 ERROR TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/layout/forms/test/test_bug665540.html | event.screenY should match sent event - got 106, expected 78
21:36:41     INFO -  12734 ERROR TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/layout/forms/test/test_bug665540.html | window state should still be fullscreen - got 3, expected 4
21:36:41     INFO -  12735 INFO TEST-END | chrome://mochitests/content/chrome/layout/forms/test/test_bug665540.html | finished in 2566ms
Priority: -- → P5
I wonder whether this started when these tests moved from Fedora to Ubuntu.
This wasn't reported until almost 5 months after mochitest-other moved to Ubuntu in bug 835955.
This is a pretty regular failure. Karl, do you have time to take another look at this?
Flags: needinfo?(karlt)
http://mozilla-releng-blobs.s3.amazonaws.com/blobs/mozilla-inbound/sha512/8bfbc9b28e86ba8122a72233274cc69a1426cab3d6bfd4aac847bdcf220f2e9f595a2e67a7eefd64fc53cec8a95d6abf26d0d815bf3c3add8b7f7537e45f0e01
from comment 265 shows a very much not fullscreen window, decorated and just large enough to display the select in the body of the xul document.

comments 183, 171, 129, 128, 125, 119, 116, 112 are a bit different to typical.
Apparently the window was fullscreen but is no longer.

In comment 115, the window may have transitioned to fullscreen during the test, or maybe the comment was truncated.

There are also a few outliers where window state is 1, indicating maximized.
3 is normal.

Will see if some logging can provide some hints.
Flags: needinfo?(karlt)
It seems this issue may not be frequent enough to debug on try.
https://treeherder.mozilla.org/#/jobs?repo=try&revision=d929f291c63b

So I guess we need to check-in some logging to get more info.
Keywords: checkin-needed, leave-open
Hardware: x86 → x86_64
Depends on: 1182972
When things go wrong, there can be multiple changes between fullscreen and
normal size mode.

e.g. from Comment 282

win.windowState = 3
win.fullScreen = false
must wait for load
must wait for focus
sizemodechange. windowState = 4 fullScreen = true
fullscreen event. windowState = 4 fullScreen = true
sizemodechange. windowState = 3 fullScreen = false
fullscreen event. windowState = 3 fullScreen = false
sizemodechange. windowState = 4 fullScreen = true
fullscreen event. windowState = 4 fullScreen = true
sizemodechange. windowState = 4 fullScreen = true
TEST-PASS | layout/forms/test/test_bug665540.html | window should be fullscreen
TEST-PASS | layout/forms/test/test_bug665540.html | window state should be fullscreen
sizemodechange. windowState = 3 fullScreen = false
fullscreen event. windowState = 3 fullScreen = false
sizemodechange. windowState = 4 fullScreen = true
fullscreen event. windowState = 4 fullScreen = true
sizemodechange. windowState = 3 fullScreen = false
fullscreen event. windowState = 3 fullScreen = false
TEST-PASS | layout/forms/test/test_bug665540.html | event.screenX should match sent event
TEST-PASS | layout/forms/test/test_bug665540.html | event.screenY should match sent event
TEST-UNEXPECTED-FAIL | layout/forms/test/test_bug665540.html | window state should still be fullscreen - got 3, expected 4

And sometimes maximized.  From comment 324.

must wait for focus
sizemodechange. windowState = 4 fullScreen = true
fullscreen event. windowState = 4 fullScreen = true
sizemodechange. windowState = 3 fullScreen = false
fullscreen event. windowState = 3 fullScreen = false
sizemodechange. windowState = 1 fullScreen = false
TEST-UNEXPECTED-FAIL | layout/forms/test/test_bug665540.html | window should be fullscreen - expected PASS
 screenshot here: see the one that was previously logged
TEST-UNEXPECTED-FAIL | layout/forms/test/test_bug665540.html | window state should be fullscreen - got 1, expected 4
TEST-PASS | layout/forms/test/test_bug665540.html | event.screenX should match sent event
TEST-PASS | layout/forms/test/test_bug665540.html | event.screenY should match sent event
 screenshot here: see the one that was previously logged
TEST-UNEXPECTED-FAIL | layout/forms/test/test_bug665540.html | window state should still be fullscreen - got 1, expected 4

I suspect the oscillations may be due to the Gecko window responding to size
mode changes by requesting further size mode changes.

However, something is triggering the initial switch from fullscreen to normal
size mode.  Despite the increase in frequency of failures, I haven't managed
to reproduce with logging on try.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=8498baac37fa
https://treeherder.mozilla.org/#/jobs?repo=try&revision=0725f2647e8f

Bug 1182972 may be a candidate for the cause of the switch from fullscreen to
normal.  I start with that.
Kyle, this is #1 on OrangeFactor if you're looking for something to try catching in rr.
Flags: needinfo?(khuey)
Attached image test screenshot — 
Just for kicks, here's a screenshot at the point of failure.
The problem was not resolved in bug 1182972.
No longer depends on: 1182972
Caught a failure with some logging at
https://treeherder.mozilla.org/logviewer.html#?job_id=9388894&repo=try

These are all logged within one second:

> 2559 INFO TEST-START | layout/forms/test/test_bug665540.html
> SetSizeMode [0x7fb2bca81510] 0
> SetSizeMode [0x7fb2bca81510] 0

Gecko requests normal mode twice.
SetSizeMode() makes each of these no-ops because a new window already has
normal mode.

> MakeFullScreen [0x7fb2bca81510] aFullScreen 1

Gecko requests full screen mode through MakeFullScreen.

> OnWindowStateEvent [0x7fb2bca81510] changed 16 new_window_state 17

GDK event reports full screen mode on withdrawn (hidden) window.

> SetSizeMode [0x7fb2bca81510] 3

Gecko requests full screen mode, but there is no MakeFullScreen call, indicating that SetSizeMode has ignored the request because the window is considered to already be full screen.

> OnWindowStateEvent [0x7fb2bca81510] changed 16 new_window_state 17

This is the same GDK event reporting full screen mode on the withdrawn window.
This time it is received on a different widget, which is not interested in
size mode changes.

> OnWindowStateEvent [0x7fb2bca81510] changed 1 new_window_state 16
> OnWindowStateEvent [0x7fb2bca81510] changed 1 new_window_state 16

GDK event reports that the window is now shown.

> OnWindowStateEvent [0x7fb2bca81510] changed 16 new_window_state 0
> SetSizeMode [0x7fb2bca81510] 0
> MakeFullScreen [0x7fb2bca81510] aFullScreen 0
> OnWindowStateEvent [0x7fb2bca81510] changed 16 new_window_state 0

GDK event says the window is not full screen.

Apparently the window manager has removed
_NET_WM_STATE_FULLSCREEN from the window's _NET_WM_STATE property.
The window manager is expected to remove the property altogether if the window is withdrawn (hidden), but I don't know why that would be happening, and we don't seem to have the expected window state changes that would be expected with that.

Perhaps the window manager has temporarily removed _NET_WM_STATE_FULLSCREEN, perhaps for a new window or full screen animation, or perhaps Gecko has moved or resized the window.

Gecko responds to the notification by requesting the size mode in the
notification (SetSizeMode ignores this) and also requesting that the window be
restored to its pre-fullscreen mode (which is not ignored by MakeFullScreen).

> OnWindowStateEvent [0x7fb2bca81510] changed 16 new_window_state 16
> SetSizeMode [0x7fb2bca81510] 3
> MakeFullScreen [0x7fb2bca81510] aFullScreen 1
> OnWindowStateEvent [0x7fb2bca81510] changed 16 new_window_state 16

A GDK event says the window is full screen as requested above.

Gecko responds by requesting transition back to full screen again.

> OnWindowStateEvent [0x7fb2bca81510] changed 4 new_window_state 20
> SetSizeMode [0x7fb2bca81510] 3
> OnWindowStateEvent [0x7fb2bca81510] changed 4 new_window_state 20

A GDK event says the window has transitioned to maximized and full screen
modes.

I don't know where maximized mode comes from.

> OnWindowStateEvent [0x7fb2bca81510] changed 16 new_window_state 4
> SetSizeMode [0x7fb2bca81510] 2
> MakeFullScreen [0x7fb2bca81510] aFullScreen 0
> OnWindowStateEvent [0x7fb2bca81510] changed 16 new_window_state 4

A GDK event says the window has transitioned to maximized mode without full
screen.

Gecko responds by requesting maximized mode and exit from full screen.

The screenshot shows a maximized window with no decorations.  The desktop
environment status bar and icons are visible (implying it is not full screen).

Although OnWindowStateEvent logging shows normal mode (0) once only, the windowState logged by the test shows two transitions to normal window state (3):

INFO sizemodechange. windowState = 4 fullScreen = true
INFO fullscreen event. windowState = 4 fullScreen = true
INFO sizemodechange. windowState = 3 fullScreen = false
INFO fullscreen event. windowState = 3 fullScreen = false
INFO sizemodechange. windowState = 4 fullScreen = true
INFO fullscreen event. windowState = 4 fullScreen = true
INFO sizemodechange. windowState = 4 fullScreen = true
INFO sizemodechange. windowState = 3 fullScreen = false
INFO fullscreen event. windowState = 3 fullScreen = false

I don't have an explanation for this inconsistency.
This is an approach I was using to log from a forked process in the hope that
it would not mess with the timing in the Gecko process.

I didn't catch this failure on try
https://treeherder.mozilla.org/#/jobs?repo=try&revision=f423f2b9076e

Don't know why the logging process triggers shutdown issues with a "Hello
world!" "Test app" in mochitest-chrome but not in mochitest-ally or
mochitest-plugins.  This version of the patch forks a little earlier than the
version on try in case there is a sigterm handler or watchdog thread or
something messing up things, but its probably still not early enough to avoid
that, if that is the problem.  I wonder whether having 2 firefox processes
might confuse the test harness. 

Also don't know why there is a
widget/tests/test_wheeltransaction.xul | uncaught exception - TypeError: gCurrentTest is undefined at chrome://mochitests/content/chrome/widget/tests/window_wheeltransaction.xul:1442
at https://treeherder.mozilla.org/logviewer.html#?job_id=9437091&repo=try
(In reply to Karl Tomlinson (ni?:karlt) from comment #633)
> GDK event reports that the window is now shown.

Actually GDK has requested showing the window.  It is not yet shown.

> > OnWindowStateEvent [0x7fb2bca81510] changed 16 new_window_state 0
> > SetSizeMode [0x7fb2bca81510] 0
> > MakeFullScreen [0x7fb2bca81510] aFullScreen 0
> > OnWindowStateEvent [0x7fb2bca81510] changed 16 new_window_state 0
> 
> GDK event says the window is not full screen.
> 
> Apparently the window manager has removed
> _NET_WM_STATE_FULLSCREEN from the window's _NET_WM_STATE property.

> Perhaps the window manager has temporarily removed _NET_WM_STATE_FULLSCREEN,
> perhaps for a new window or full screen animation, or perhaps Gecko has
> moved or resized the window.

The try logs did observe this happening, even with the test passing.
e.g. from [1]

> 0x03600000 ConfigureWindow 0x036235fa x=65 y=24 width=37 height=39
> 0x03600000 ConfigureWindow 0x036235fa x=65 y=24
> 0x03600000 ConfigureWindow 0x036235fa Above
> 0x03600000 ChangeProperty 0x036235fa _NET_WM_STATE _NET_WM_STATE_FULLSCREEN
> 0x03600000 MapWindow 0x036235fa

0x03600000 is the browser setting up the window, requesting focus, fullscreen,
and then showing the window.  Once shown is requested, the window manager
manages the _NET_WM_STATE property.

> 0x03600000 ConfigureNotify 0x036235fa x=65 y=24 width=37 height=39
> 0x03600000 ConfigureNotify 0x036235fa x=1 y=28 width=37 height=39
> 0x00a00000 SendEvent 22 to 0x036235fa propagate=0 mask=0x00020000
> 0x03600000 ConfigureNotify 0x036235fa x=66 y=52 width=37 height=39

0x00a00000 is the window manager informing the new window bounds (not
fullscreen).

> 0x00a00000 ChangeProperty 0x036235fa _NET_WM_STATE

The window manager removes _NET_WM_STATE_FULLSCREEN atom.

If GDK processes this event before the change to indicate full screen below,
it will generating the GDK event to say not full screen, explaining the
intermittent nature.  If the browser is slower than the window manager then we
don't see the bug.

(I see this behavior with kwin too, so it is not specific to compiz.)

> 0x03600000 ConfigureNotify 0x036235fa x=1 y=28 width=1600 height=1200
> 0x03600000 MapNotify 0x036235fa
> 0x00a00000 ChangeProperty 0x036235fa _NET_WM_STATE _NET_WM_STATE_FULLSCREEN

Now the window manager changes the bounds to full screen size (though the
top-left is unexpected), shows the window, and indicates full screen mode.

> 0x00a00000 SetInputFocus 0x036235fa revert-to=PointerRoot time=0x00105e15
> 0x03600000 FocusOut 0x036000e9 Nonlinear Normal
> 0x03600000 FocusOut 0x036000e8 NonlinearVirtual Normal
> 0x03600000 FocusIn 0x036235fa Nonlinear Normal
> 0x00a00000 SendEvent 33 to 0x036235fa propagate=0 mask=0x00000000
>   WM_PROTOCOLS protocol=WM_TAKE_FOCUS time=0x00105e15
> 0x00a00000 ChangeProperty 0x036235fa _NET_WM_STATE _NET_WM_STATE_FULLSCREEN
> 0x00a00000 ChangeProperty 0x036235fa _NET_WM_STATE _NET_WM_STATE_MAXIMIZED_HORZ _NET_WM_STATE_MAXIMIZED_VERT _NET_WM_STATE_FULLSCREEN

Don't know why the window manager is adding maximized.
Perhaps for compat with clients not knowing fullscreen.

> 0x00a00000 SendEvent 18 to 0x0000012d propagate=0 mask=0x00180000
> 0x00a00000 SendEvent 18 to 0x0000012d propagate=0 mask=0x00180000
> 0x03600000 ConfigureNotify 0x036235fa x=0 y=0 width=1600 height=1200

Now we have the bounds we expect.

> Gecko responds to the notification by requesting the size mode in the
> notification (SetSizeMode ignores this) and also requesting that the window
> be restored to its pre-fullscreen mode (which is not ignored by
> MakeFullScreen).

So fixing this would fix this bug.

[1] http://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/ktomlinson@mozilla.com-ff18c6a8f571/try-linux64/try_ubuntu64_vm_test-mochitest-other-bm116-tests1-linux64-build749.txt.gz
Keywords: leave-open
Karl, any eta on the fix from comment 753? I appreciate all the effort you've put into this bug, but this is the #1 desktop Fx orange and it's causing ongoing pain. I'm feeling inclined to skip the test on Linux for the time-being.
Flags: needinfo?(karlt)
I suggest backing out https://hg.mozilla.org/mozilla-central/rev/7b358589aaef at least until we have a fix.  I don't know why, but the frequency of this bug seemed to sky rocket when that logging was added.

Can we try that first to see if that reduces failures to a manageable level?

I expect I could have a fix within a few days, but that depends on what is depending on the broken behaviour and what else comes up.
Flags: needinfo?(ryanvm)
Flags: needinfo?(khuey)
Flags: needinfo?(karlt)
Actually, disabling on amd64 linux only is probably sensible.
There are plenty of other platforms to still run the test.
Disabled on Linux64.
https://hg.mozilla.org/integration/mozilla-inbound/rev/808be045b6f8
Flags: needinfo?(ryanvm)
Whiteboard: [test disabled on Linux64][leave open]
Depends on: 1254448
Severity: normal → S3
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: