Closed Bug 708927 Opened 13 years ago Closed 12 years ago

Intermittent test_focus_menu.xul | Test timed out, sometimes followed by tens of thousands of gA11yEventListeners is undefined exceptions

Categories

(Core :: Disability Access APIs, defect)

Product:
Core
Component:
Disability Access APIs
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla19

People

(Reporter: philor, Assigned: surkov)

References

(Blocks 1 open bug)

Details

(Keywords: intermittent-failure)

Attachments

(3 files)

Turn on logging
(deleted), patch
surkov
: review+
Details | Diff | Splinter Review
More logging capabilities, enable test partially
(deleted), patch
tbsaunde
: review+
Details | Diff | Splinter Review
fix the test
(deleted), patch
tbsaunde
: review+
Details | Diff | Splinter Review
I think this has been going on for a while, a week or two anyway, but nobody is willing to file (anything at all, including) an orange with 67369 failing tests. https://tbpl.mozilla.org/php/getParsedLog.php?id=7833888&tree=Mozilla-Inbound Rev3 Fedora 12 mozilla-inbound debug test mochitest-other on 2011-12-08 12:33:47 PST for push a150aea6c244 https://tbpl.mozilla.org/php/getParsedLog.php?id=7835335&tree=Mozilla-Inbound Rev3 Fedora 12 mozilla-inbound debug test mochitest-other on 2011-12-08 13:35:34 PST for push 3c620a2f8919 3498 INFO TEST-PASS | chrome://mochitests/content/a11y/accessible/events/test_focus_menu.xul | test with ID = ' 'cycle' mouse move' failed. There is unexpected focus event. 3499 ERROR TEST-UNEXPECTED-FAIL | chrome://mochitests/content/a11y/accessible/events/test_focus_menu.xul | Test timed out. XScreenSaver state: Disabled User input has been idle for 3559 seconds args: ['/home/cltbld/talos-slave/test/build/bin/screentopng'] (screenshot) 3500 INFO TEST-END | chrome://mochitests/content/a11y/accessible/events/test_focus_menu.xul | finished in 329195ms ... 3501 INFO TEST-START | chrome://mochitests/content/a11y/accessible/events/test_focus_name.html ++DOMWINDOW == 90 (0x96ec2f8) [serial = 145] [outer = 0xa962f48] JavaScript error: chrome://mochitests/content/a11y/accessible/events.js, line 1438: gA11yEventListeners is undefined JavaScript error: chrome://mochitests/content/a11y/accessible/events.js, line 1438: gA11yEventListeners is undefined JavaScript error: chrome://mochitests/content/a11y/accessible/events.js, line 1438: gA11yEventListeners is undefined 3502 INFO TEST-INFO | chrome://mochitests/content/a11y/accessible/events/test_focus_name.html | must wait for load WARNING: NS_ENSURE_SUCCESS(rv, false) failed with result 0x8000FFFF: file ../../../../content/base/src/nsContentUtils.cpp, line 2579 WARNING: NS_ENSURE_TRUE(pusher.Push(aBoundElement)) failed: file ../../../../content/xbl/src/nsXBLProtoImplMethod.cpp, line 355 WARNING: NS_ENSURE_SUCCESS(rv, false) failed with result 0x8000FFFF: file ../../../../content/base/src/nsContentUtils.cpp, line 2579 WARNING: NS_ENSURE_TRUE(pusher.Push(aBoundElement)) failed: file ../../../../content/xbl/src/nsXBLProtoImplMethod.cpp, line 355 WARNING: NS_ENSURE_SUCCESS(rv, false) failed with result 0x8000FFFF: file ../../../../content/base/src/nsContentUtils.cpp, line 2579 WARNING: NS_ENSURE_TRUE(pusher.Push(aBoundElement)) failed: file ../../../../content/xbl/src/nsXBLProtoImplMethod.cpp, line 355 WARNING: NS_ENSURE_SUCCESS(rv, false) failed with result 0x8000FFFF: file ../../../../content/base/src/nsContentUtils.cpp, line 2579 WARNING: NS_ENSURE_TRUE(pusher.Push(aBoundElement)) failed: file ../../../../content/xbl/src/nsXBLProtoImplMethod.cpp, line 355 3503 ERROR TEST-UNEXPECTED-FAIL | chrome://mochitests/content/a11y/accessible/events/test_focus_name.html | an unexpected uncaught JS exception reported through window.onerror - gA11yEventListeners is undefined at chrome://mochitests/content/a11y/accessible/events.js:1438 JavaScript error: chrome://mochitests/content/a11y/accessible/events.js, line 1438: gA11yEventListeners is undefined 3504 ERROR TEST-UNEXPECTED-FAIL | chrome://mochitests/content/a11y/accessible/events/test_focus_name.html | an unexpected uncaught JS exception reported through window.onerror - gA11yEventListeners is undefined at chrome://mochitests/content/a11y/accessible/events.js:1438 JavaScript error: chrome://mochitests/content/a11y/accessible/events.js, line 1438: gA11yEventListeners is undefined 3505 ERROR TEST-UNEXPECTED-FAIL | chrome://mochitests/content/a11y/accessible/events/test_focus_name.html | an unexpected uncaught JS exception reported through window.onerror - gA11yEventListeners is undefined at chrome://mochitests/content/a11y/accessible/events.js:1438 JavaScript error: chrome://mochitests/content/a11y/accessible/events.js, line 1438: gA11yEventListeners is undefined 3506 ERROR TEST-UNEXPECTED-FAIL | chrome://mochitests/content/a11y/accessible/events/test_focus_name.html | an unexpected uncaught JS exception reported through window.onerror - gA11yEventListeners is undefined at chrome://mochitests/content/a11y/accessible/events.js:1438 JavaScript error: chrome://mochitests/content/a11y/accessible/events.js, line 1438: gA11yEventListeners is undefined 3507 ERROR TEST-UNEXPECTED-FAIL | chrome://mochitests/content/a11y/accessible/events/test_focus_name.html | an unexpected uncaught JS exception reported through window.onerror - gA11yEventListeners is undefined at chrome://mochitests/content/a11y/accessible/events.js:1438 JavaScript error: chrome://mochitests/content/a11y/accessible/events.js, line 1438: gA11yEventListeners is undefined 3508 INFO TEST-END | chrome://mochitests/content/a11y/accessible/events/test_focus_name.html | finished in 411ms and so on and so on and on and on.
Blocks: a11yrandomorange
Depends on: 718239
Summary: Intermittent test_focus_menu.xul | Test timed out. followed by tens of thousands of gA11yEventListeners is undefined exceptions → Intermittent test_focus_menu.xul | Test timed out, sometimes followed by tens of thousands of gA11yEventListeners is undefined exceptions
Appears to be linux only.
Whiteboard: [orange] → [orange][stop the bleeding]
Attached patch Turn on logging (deleted) — — Splinter Review
Attachment #614782 - Flags: review?(surkov.alexander)
Comment on attachment 614782 [details] [diff] [review] Turn on logging Review of attachment 614782 [details] [diff] [review]: ----------------------------------------------------------------- ::: accessible/tests/mochitest/events/test_focus_menu.xul @@ +20,5 @@ > <script type="application/javascript" > src="../events.js" /> > > <script type="application/javascript"> > + gA11yEventDumpID = "eventdump"; // debug stuff don't enable this one
Attachment #614782 - Flags: review?(surkov.alexander) → review+
log: registered: event type: focus, target: 'tricycle' registered unexpected: event type: focus, target: any target different from expected events Event queue: invoke: 'cycle' 'right ' key 4811 INFO TEST-INFO | chrome://mochitests/content/a11y/accessible/events/test_focus_menu.xul | Invoke the ' 'cycle' 'right ' key' test { expected 'focus' event; unexpected 'focus' event; } Event type: show. Target: ['menuitem@id="tricycle" node', address: 0x6a70800, role: menuitem, name: 'tricycle', address: 0xbed9990] Event type: reorder. Target: ['menupopup node', address: 0x6a70740, role: menupopup, name: 'cycle', address: 0xb0095f0] WARNING: Nv3DVStreaming CoCreateInstance failed (disabled).: file e:/builds/moz2_slave/m-cen-w32-dbg/build/gfx/layers/d3d9/Nv3DVUtils.cpp, line 53 Event type: menupopup start. Target: ['menupopup node', address: 0x6a70740, role: menupopup, name: 'cycle', address: 0xb0095f0] --DOMWINDOW == 12 (0B4A6420) [serial = 172] [outer = 00000000] [url = chrome://mochitests/content/a11y/accessible/events/test_focus_listcontrols.xul]
log on success: registered: event type: focus, target: 'tricycle' registered unexpected: event type: focus, target: any target different from expected events Event queue: invoke: 'cycle' 'right ' key Event type: show. Target: ['menuitem@id="tricycle" node', address: 0xd073998, role: menuitem, name: 'tricycle', address: 0xd21c7c0] Event type: reorder. Target: ['menupopup node', address: 0xd087798, role: menupopup, name: 'cycle', address: 0x4032168] Event type: focus. Target: ['menuitem@id="tricycle" node', address: 0xd073998, role: menuitem, name: 'tricycle', address: 0xd21c7c0]. Listeners count: 1 ***** EQ matched: focus ***** WARNING: NS_ENSURE_TRUE(caretSelection) failed: file c:/mozilla/1909/accessible/src/base/nsCaretAccessible.cpp, line 296 WARNING: Nv3DVStreaming CoCreateInstance failed (disabled).: file c:/mozilla/1909/gfx/layers/d3d9/Nv3DVUtils.cpp, line 53 WARNING: Direct3D 9-accelerated layers are not supported on this system.: file c:/mozilla/1909/gfx/layers/d3d9/LayerManagerD3D9.cpp, line 55 Event type: menupopup start. Target: ['menupopup node', address: 0xd087798, role: menupopup, name: 'cycle', address: 0x4032168]
We need more logging, bug 759133
Depends on: 759133
https://hg.mozilla.org/mozilla-central/rev/75227ca51671
Assignee: nobody → surkov.alexander
Status: NEW → RESOLVED
Closed: 12 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla18
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
This is currently the number 2 toporange as of the last few days. Please can we disable the test on trunk for now; and try out a fix on Try first?
Disabled on Linux: https://hg.mozilla.org/integration/mozilla-inbound/rev/33fc8988282d
Whiteboard: [orange][stop the bleeding] → [orange][test disabled on Linux][leave open]
Ok log: registered: event type: focus, target: 'tricycle' registered unexpected: event type: focus, target: any target different from expected events Event queue: invoke: 'cycle' 'right ' key 4769 INFO TEST-INFO | chrome://mochitests/content/a11y/accessible/events/test_focus_menu.xul | Invoke the ' 'cycle' 'right ' key' test { expected 'focus' event; unexpected 'focus' event; } A11Y TREE: content inserted; 51:16.658 { container: 06517308, menupopup@id='', idx in parent: 0 content: 066B8140, menuitem@id='tricycle', idx in parent: 0 } A11Y DOMEvents: event 'DOMMenuItemActive' handled; 51:16.658 { Not accessible Target: 066B8140, menuitem@id='tricycle', idx in parent: 0 } WARNING: Nv3DVStreaming CoCreateInstance failed (disabled).: file e:/builds/moz2_slave/try-w32-dbg/build/gfx/layers/d3d9/Nv3DVUtils.cpp, line 53 A11Y DOMEvents: event 'popupshown' handled; 51:16.705 { Target: 0C1FACC8; role: menupopup, name: 'cycle'; Target node: 06517308, menupopup@id='', idx in parent: 0 Document: 1094B5B8, document node: 0C86D748 Document uri: chrome://mochitests/content/a11y/accessible/events/test_focus_menu.xul } A11Y TREE: process content insertion; 51:16.705 { container: 06517308, menupopup@id='', idx in parent: 0 child: 066B8140, menuitem@id='tricycle', idx in parent: 0 child accessible: 1073CFE8, node: 066B8140 document: 1094B5B8, node: 0C86D748 uri: chrome://mochitests/content/a11y/accessible/events/test_focus_menu.xul } A11Y DOMEvents: event 'DOMMenuItemActive' processed; 51:16.705 { Target: 1073CFE8; role: menuitem, name: 'tricycle'; Target node: 066B8140, menuitem@id='tricycle', idx in parent: 0 Document: 1094B5B8, document node: 0C86D748 Document uri: chrome://mochitests/content/a11y/accessible/events/test_focus_menu.xul } A11Y FOCUS: active item changed; 51:16.705 { Item: 1073CFE8; role: menuitem, name: 'tricycle'; Item node: 066B8140, menuitem@id='tricycle', idx in parent: 0 Document: 1094B5B8, document node: 0C86D748 Document uri: chrome://mochitests/content/a11y/accessible/events/test_focus_menu.xul } { Widget: 0C1FACC8; role: menupopup, name: 'cycle'; Widget node: 06517308, menupopup@id='', idx in parent: 0 Document: 1094B5B8, document node: 0C86D748 Document uri: chrome://mochitests/content/a11y/accessible/events/test_focus_menu.xul Widget is active: true, has operable items: true } { A11y target: 1073CFE8; role: menuitem, name: 'tricycle'; A11y target node: 066B8140, menuitem@id='tricycle', idx in parent: 0 Document: 1094B5B8, document node: 0C86D748 Document uri: chrome://mochitests/content/a11y/accessible/events/test_focus_menu.xul } { Caused by: DOMMenuItemActive Item: 1073CFE8; role: menuitem, name: 'tricycle'; Item node: 066B8140, menuitem@id='tricycle', idx in parent: 0 Document: 1094B5B8, document node: 0C86D748 Document uri: chrome://mochitests/content/a11y/accessible/events/test_focus_menu.xul } A11Y DOMEvents: event 'popupshown' processed; 51:16.705 { Target: 0C1FACC8; role: menupopup, name: 'cycle'; Target node: 06517308, menupopup@id='', idx in parent: 0 Document: 1094B5B8, document node: 0C86D748 Document uri: chrome://mochitests/content/a11y/accessible/events/test_focus_menu.xul } Event type: menupopup start. Target: ['menupopup node', address: 0x6517308, role: menupopup, name: 'cycle', address: 0xc1facc8] Event type: show. Target: ['menuitem@id="tricycle" node', address: 0x66b8140, role: menuitem, name: 'tricycle', address: 0x1073cfe8] Event type: reorder. Target: ['menupopup node', address: 0x6517308, role: menupopup, name: 'cycle', address: 0xc1facc8] A11Y FOCUS: fire focus event; 51:16.720 { Target: 1073CFE8; role: menuitem, name: 'tricycle'; Target node: 066B8140, menuitem@id='tricycle', idx in parent: 0 Document: 1094B5B8, document node: 0C86D748 Document uri: chrome://mochitests/content/a11y/accessible/events/test_focus_menu.xul } Event type: focus. Target: ['menuitem@id="tricycle" node', address: 0x66b8140, role: menuitem, name: 'tricycle', address: 0x1073cfe8]. Listeners count: 1 ***** EQ matched: focus ***** 4770 INFO TEST-PASS | chrome://mochitests/content/a11y/accessible/events/test_focus_menu.xul | wrong state bits for ['menuitem@id="tricycle" node', address: 0x66b8140, role: menuitem, name: 'tricycle', address: 0x1073cfe8]! 4771 INFO TEST-PASS | chrome://mochitests/content/a11y/accessible/events/test_focus_menu.xul | Focussed ['menuitem@id="tricycle" node', address: 0x66b8140, role: menuitem, name: 'tricycle', address: 0x1073cfe8] must be focusable! WARNING: NS_ENSURE_TRUE(caretSelection) failed: file e:/builds/moz2_slave/try-w32-dbg/build/accessible/src/base/nsCaretAccessible.cpp, line 296 4772 INFO TEST-PASS | chrome://mochitests/content/a11y/accessible/events/test_focus_menu.xul | test with ID = ' 'cycle' 'right ' key' failed. No focus event. 4773 INFO TEST-PASS | chrome://mochitests/content/a11y/accessible/events/test_focus_menu.xul | test with ID = ' 'cycle' 'right ' key' failed. There is unexpected focus event.
Not ok log: registered: event type: focus, target: 'tricycle' registered unexpected: event type: focus, target: any target different from expected events Event queue: invoke: 'cycle' 'right ' key 4772 INFO TEST-INFO | chrome://mochitests/content/a11y/accessible/events/test_focus_menu.xul | Invoke the ' 'cycle' 'right ' key' test { expected 'focus' event; unexpected 'focus' event; } A11Y TREE: content inserted; 37:03.557 { container: 0x2011e60, menupopup@id='', idx in parent: 0 content: 0x40d3770, menuitem@id='tricycle', idx in parent: 0 } A11Y TREE: process content insertion; 37:03.565 { container: 0x49825c0, menu@id='cycle', idx in parent: 0 child: 0x40d3770, menuitem@id='tricycle', idx in parent: 0 child accessible: 0x7803040, node: 0x40d3770 document: 0x46637f0, node: 0x65021c0 uri: chrome://mochitests/content/a11y/accessible/events/test_focus_menu.xul } Event type: show. Target: ['menuitem@id="tricycle" node', address: 0x40d3770, role: menuitem, name: 'tricycle', address: 0x7803040] Event type: reorder. Target: ['menu@id="cycle" node', address: 0x49825c0, role: parent menuitem, name: 'cycle', address: 0x519e0c0] A11Y DOMEvents: event 'popupshown' handled; 37:03.620 { Not accessible Target: 0x2011e60, menupopup@id='', idx in parent: 0 } sync notification processing A11Y DOMEvents: event 'popupshown' processed; 37:03.621 { Not accessible Target: 0x2011e60, menupopup@id='', idx in parent: 0 } WARNING: 1 sort operation has occurred for the SQL statement '0x7fb40404f9b8'. See https://developer.mozilla.org/En/Storage/Warnings details.: file ../../../storage/src/mozStoragePrivateHelpers.cpp, line 110 WARNING: 1 sort operation has occurred for the SQL statement '0x7fb404096768'. See https://developer.mozilla.org/En/Storage/Warnings details.: file ../../../storage/src/mozStoragePrivateHelpers.cpp, line 110 WARNING: 1 sort operation has occurred for the SQL statement '0x7fb404082e68'. See https://developer.mozilla.org/En/Storage/Warnings details.: file ../../../storage/src/mozStoragePrivateHelpers.cpp, line 110 4773 ERROR TEST-UNEXPECTED-FAIL | chrome://mochitests/content/a11y/accessible/events/test_focus_menu.xul | Test timed out.
The difference between them is 'DOMMenuItemActive' event is not delivered. However 'popupshown' event is fired. It seems popup was open but menuitem wasn't selected. Enn, ideas, how it can happen that pressing right key when menu item 'cycle' has keyboard focus doesn't make menuitem 'tricycle' from submenu selected? <menu id="vehicle" label="Vehicle"> <menupopup> <menu id="cycle" label="cycle"> <menupopup> <menuitem id="tricycle" label="tricycle"/> </menupopup> </menu> <menuitem id="car" label="Car" disabled="true"/> </menupopup> </menu>
Attachment #667841 - Flags: review?(trev.saunders)
Comment on attachment 667841 [details] [diff] [review] More logging capabilities, enable test partially >+logging::AccessibleNNode(const char* aDescr, nsINode* aNode) >+{ >+ DocAccessible* document = >+ GetAccService()->GetDocAccessible(aNode->OwnerDoc()); as per irc would be nice if that didn't use the nsIDocument -> DocAccessible cache >+ >+ //enableLogging("focus,DOMEvents,tree"); // logging for bug708927 >+ //gQueue.onFinish = function() { disableLogging(); } not sure what what's about >+
Attachment #667841 - Flags: review?(trev.saunders) → review+
(In reply to Trevor Saunders (:tbsaunde) from comment #362) > >+logging::AccessibleNNode(const char* aDescr, nsINode* aNode) > >+{ > >+ DocAccessible* document = > >+ GetAccService()->GetDocAccessible(aNode->OwnerDoc()); > > as per irc would be nice if that didn't use the nsIDocument -> DocAccessible > cache yes but we didn't agree what to use instead :) I see we have a bunch of them in the code so I would live it as is I guess. > >+ > >+ //enableLogging("focus,DOMEvents,tree"); // logging for bug708927 > >+ //gQueue.onFinish = function() { disableLogging(); } > > not sure what what's about I didn't get it. What do you mean?
The only thing I can think of is: gQueue.push(new synthClick("vehicle", new focusChecker("vehicle"))); gQueue.push(new synthMouseMove("cycle", new focusChecker("cycle"))); // open submenu gQueue.push(new synthRightKey("cycle", new focusChecker("tricycle"))); The mousemove on 'cycle' menuitem will highlight the 'cycle' item then open the submenu after a short delay (around 200-300ms). You may be getting into a race when you then try to open the submenu again by pressing the right key where it fails depending on whether that timer has fired or not. You could either wait for the menu to open, or synthesize a down keypress instead of moving the mouse over 'cycle' and see if the problem goes away.
Attached patch fix the test (deleted) — — Splinter Review
Attachment #672674 - Flags: review?(trev.saunders)
(In reply to Neil Deakin from comment #368) > The mousemove on 'cycle' menuitem will highlight the 'cycle' item then open > the submenu after a short delay (around 200-300ms). You may be getting into > a race when you then try to open the submenu again by pressing the right key > where it fails depending on whether that timer has fired or not. Isn't it something that should be fixed? I see it might be hard reproducible by the user but it doesn't seem an expected behavior. > You could either wait for the menu to open, or synthesize a down keypress > instead of moving the mouse over 'cycle' and see if the problem goes away. Yeah, arrow down is what I should do I think. Thank you!
(In reply to alexander :surkov from comment #370) > Isn't it something that should be fixed? I see it might be hard reproducible > by the user but it doesn't seem an expected behavior. Sure, feel free to file a bug.
(In reply to Neil Deakin from comment #371) > (In reply to alexander :surkov from comment #370) > > Isn't it something that should be fixed? I see it might be hard reproducible > > by the user but it doesn't seem an expected behavior. > > Sure, feel free to file a bug. I filed bug 803081
Attachment #672674 - Flags: review?(trev.saunders) → review+
http://hg.mozilla.org/integration/mozilla-inbound/rev/b089778d19bd
Whiteboard: [orange][test disabled on Linux][leave open] → [orange]
Target Milestone: mozilla18 → mozilla19
https://hg.mozilla.org/mozilla-central/rev/b089778d19bd
Status: REOPENED → RESOLVED
Closed: 12 years ago → 12 years ago
Flags: in-testsuite+
Resolution: --- → FIXED
Whiteboard: [orange]
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: