Open Bug 888164 Opened 12 years ago Updated 3 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: