Open Bug 1808737 Opened 3 years ago Updated 5 days ago

Frequent accessible/tests/mochitest/events/test_focus_menu.xhtml | single tracking bug

Categories

(Core :: Disability Access APIs, defect, P5)

defect

Tracking

()

Tracking Status
firefox-esr102 --- unaffected
firefox-esr140 --- unaffected
firefox108 --- unaffected
firefox109 --- unaffected
firefox110 --- wontfix
firefox111 --- fix-optional
firefox144 --- unaffected
firefox145 --- unaffected
firefox146 --- affected
firefox147 --- affected

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Regression)

Details

(Keywords: intermittent-failure, leave-open, regression, Whiteboard: [stockwell disabled])

Attachments

(1 file, 1 obsolete file)

Filed by: nfay [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=401467660&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/GfIFzmbdSI-TZLCb_MBRng/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/GfIFzmbdSI-TZLCb_MBRng/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1


[task 2023-01-05T14:51:53.360Z] 14:51:53     INFO - TEST-START | accessible/tests/mochitest/events/test_focus_menu.xhtml
[task 2023-01-05T14:51:53.366Z] 14:51:53     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/chrome/nsChromeRegistry.cpp:180
[task 2023-01-05T14:51:53.367Z] 14:51:53     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/checkouts/gecko/chrome/nsChromeProtocolHandler.cpp:73
[task 2023-01-05T14:51:53.587Z] 14:51:53     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/dom/base/nsContentUtils.cpp:4294
[task 2023-01-05T14:51:54.339Z] 14:51:54     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: 'event->mOriginalTarget != this', file /builds/worker/checkouts/gecko/dom/xul/XULButtonElement.cpp:349
[task 2023-01-05T14:51:54.378Z] 14:51:54     INFO - GECKO(2776) | [2023-01-05T14:51:54Z WARN  webrender::renderer::init] asking to enable_gpu_markers but no supporting extension was found
[task 2023-01-05T14:51:54.459Z] 14:51:54     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: 'event->mOriginalTarget != this', file /builds/worker/checkouts/gecko/dom/xul/XULButtonElement.cpp:349
[task 2023-01-05T14:51:54.465Z] 14:51:54     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: 'event->mOriginalTarget != this', file /builds/worker/checkouts/gecko/dom/xul/XULButtonElement.cpp:349
[task 2023-01-05T14:51:54.468Z] 14:51:54     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: 'event->mOriginalTarget != this', file /builds/worker/checkouts/gecko/dom/xul/XULButtonElement.cpp:349
[task 2023-01-05T14:51:54.471Z] 14:51:54     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: 'event->mOriginalTarget != this', file /builds/worker/checkouts/gecko/dom/xul/XULButtonElement.cpp:349
[task 2023-01-05T14:51:54.482Z] 14:51:54     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: 'event->mOriginalTarget != this', file /builds/worker/checkouts/gecko/dom/xul/XULButtonElement.cpp:349
[task 2023-01-05T14:51:54.494Z] 14:51:54     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: 'event->mOriginalTarget != this', file /builds/worker/checkouts/gecko/dom/xul/XULButtonElement.cpp:349
[task 2023-01-05T14:51:54.523Z] 14:51:54     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: 'event->mOriginalTarget != this', file /builds/worker/checkouts/gecko/dom/xul/XULButtonElement.cpp:349
[task 2023-01-05T14:51:54.526Z] 14:51:54     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: 'event->mOriginalTarget != this', file /builds/worker/checkouts/gecko/dom/xul/XULButtonElement.cpp:349
[task 2023-01-05T14:51:54.549Z] 14:51:54     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: 'event->mOriginalTarget != this', file /builds/worker/checkouts/gecko/dom/xul/XULButtonElement.cpp:349
[task 2023-01-05T14:51:54.576Z] 14:51:54     INFO - GECKO(2776) | [2023-01-05T14:51:54Z WARN  webrender::renderer::init] asking to enable_gpu_markers but no supporting extension was found
[task 2023-01-05T14:51:54.647Z] 14:51:54     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: '!mayShowResult', file /builds/worker/checkouts/gecko/layout/xul/nsXULPopupManager.cpp:728
[task 2023-01-05T14:51:54.649Z] 14:51:54     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: 'event->mOriginalTarget != this', file /builds/worker/checkouts/gecko/dom/xul/XULButtonElement.cpp:349
[task 2023-01-05T14:51:54.651Z] 14:51:54     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: 'event->mOriginalTarget != this', file /builds/worker/checkouts/gecko/dom/xul/XULButtonElement.cpp:349
[task 2023-01-05T14:51:54.661Z] 14:51:54     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: 'event->mOriginalTarget != this', file /builds/worker/checkouts/gecko/dom/xul/XULButtonElement.cpp:349
[task 2023-01-05T14:51:56.765Z] 14:51:56     INFO - GECKO(2776) | ALSA lib seq_hw.c:466:(snd_seq_hw_open) open /dev/snd/seq failed: No such file or directory
[task 2023-01-05T14:56:53.373Z] 14:56:53     INFO - TEST-INFO | started process screentopng
[task 2023-01-05T14:56:53.517Z] 14:56:53     INFO - TEST-INFO | screentopng: exit 0
[task 2023-01-05T14:56:53.518Z] 14:56:53     INFO - Buffered messages logged at 14:51:53
[task 2023-01-05T14:56:53.518Z] 14:56:53     INFO - must wait for load
[task 2023-01-05T14:56:53.519Z] 14:56:53     INFO - TEST-FAIL | accessible/tests/mochitest/events/test_focus_menu.xhtml | focus is fired for 'cycle' menuitem 
[task 2023-01-05T14:56:53.520Z] 14:56:53     INFO - Invoke the ' 'fruit'  mouse move' test { scenario #0: un }
[task 2023-01-05T14:56:53.521Z] 14:56:53     INFO - Buffered messages logged at 14:51:54
[task 2023-01-05T14:56:53.522Z] 14:56:53     INFO - TEST-PASS | accessible/tests/mochitest/events/test_focus_menu.xhtml | Test with ID = ' 'fruit'  mouse move' succeed. There's no unexpected 'focus' event. 
[task 2023-01-05T14:56:53.523Z] 14:56:53     INFO - Invoke the ' 'fruit'  click' test { scenario #0: expected 'focus' event;  }
[task 2023-01-05T14:56:53.524Z] 14:56:53     INFO - TEST-PASS | accessible/tests/mochitest/events/test_focus_menu.xhtml | wrong state bits for ['menu@id="fruit" node', address: [object XULMenuElement], role: parent menuitem, name: 'Fruit', address: 0x7f11cb0ede00]! 
[task 2023-01-05T14:56:53.525Z] 14:56:53     INFO - TEST-PASS | accessible/tests/mochitest/events/test_focus_menu.xhtml | Focused ['menu@id="fruit" node', address: [object XULMenuElement], role: parent menuitem, name: 'Fruit', address: 0x7f11cb0ede00] must be focusable! 
[task 2023-01-05T14:56:53.526Z] 14:56:53     INFO - TEST-PASS | accessible/tests/mochitest/events/test_focus_menu.xhtml | Collapsed or expanded ['menu@id="fruit" node', address: [object XULMenuElement], role: parent menuitem, name: 'Fruit', address: 0x7f11cb0ede00] must be expandable! 
[task 2023-01-05T14:56:53.526Z] 14:56:53     INFO - TEST-PASS | accessible/tests/mochitest/events/test_focus_menu.xhtml | Expanded ['menu@id="fruit" node', address: [object XULMenuElement], role: parent menuitem, name: 'Fruit', address: 0x7f11cb0ede00] cannot be collapsed! 
[task 2023-01-05T14:56:53.527Z] 14:56:53     INFO - TEST-PASS | accessible/tests/mochitest/events/test_focus_menu.xhtml | Test with ID = ' 'fruit'  click' succeed.  Event 'focus' was handled. 
[task 2023-01-05T14:56:53.528Z] 14:56:53     INFO - Invoke the ' 'apple'  mouse move' test { scenario #0: expected 'focus' event;  }
[task 2023-01-05T14:56:53.529Z] 14:56:53     INFO - TEST-PASS | accessible/tests/mochitest/events/test_focus_menu.xhtml | wrong state bits for ['menuitem@id="apple" node', address: [object XULElement], role: menuitem, name: 'Apple', address: 0x7f11cb9ebdc0]! 
[task 2023-01-05T14:56:53.530Z] 14:56:53     INFO - TEST-PASS | accessible/tests/mochitest/events/test_focus_menu.xhtml | Focused ['menuitem@id="apple" node', address: [object XULElement], role: menuitem, name: 'Apple', address: 0x7f11cb9ebdc0] must be focusable! 
[task 2023-01-05T14:56:53.531Z] 14:56:53     INFO - TEST-PASS | accessible/tests/mochitest/events/test_focus_menu.xhtml | Test with ID = ' 'apple'  mouse move' succeed.  Event 'focus' was handled. 
[task 2023-01-05T14:56:53.532Z] 14:56:53     INFO - Invoke the ' 'vehicle'  mouse move' test { scenario #0: expected 'focus' event;  }
[task 2023-01-05T14:56:53.533Z] 14:56:53     INFO - TEST-PASS | accessible/tests/mochitest/events/test_focus_menu.xhtml | wrong state bits for ['menu@id="vehicle" node', address: [object XULMenuElement], role: parent menuitem, name: 'Vehicle', address: 0x7f11cbb75b00]! 
[task 2023-01-05T14:56:53.534Z] 14:56:53     INFO - TEST-PASS | accessible/tests/mochitest/events/test_focus_menu.xhtml | Focused ['menu@id="vehicle" node', address: [object XULMenuElement], role: parent menuitem, name: 'Vehicle', address: 0x7f11cbb75b00] must be focusable! 
[task 2023-01-05T14:56:53.536Z] 14:56:53     INFO - TEST-PASS | accessible/tests/mochitest/events/test_focus_menu.xhtml | Collapsed or expanded ['menu@id="vehicle" node', address: [object XULMenuElement], role: parent menuitem, name: 'Vehicle', address: 0x7f11cbb75b00] must be expandable! 
[task 2023-01-05T14:56:53.536Z] 14:56:53     INFO - TEST-PASS | accessible/tests/mochitest/events/test_focus_menu.xhtml | Collapsed ['menu@id="vehicle" node', address: [object XULMenuElement], role: parent menuitem, name: 'Vehicle', address: 0x7f11cbb75b00] cannot be expanded! 
[task 2023-01-05T14:56:53.536Z] 14:56:53     INFO - TEST-PASS | accessible/tests/mochitest/events/test_focus_menu.xhtml | Test with ID = ' 'vehicle'  mouse move' succeed.  Event 'focus' was handled. 
[task 2023-01-05T14:56:53.537Z] 14:56:53     INFO - Invoke the ' 'vehicle'  'down ' key' test { scenario #0: expected 'focus' event;  }
[task 2023-01-05T14:56:53.537Z] 14:56:53     INFO - Buffered messages finished
[task 2023-01-05T14:56:53.537Z] 14:56:53     INFO - TEST-UNEXPECTED-FAIL | accessible/tests/mochitest/events/test_focus_menu.xhtml | Test timed out. - 
[task 2023-01-05T14:56:54.378Z] 14:56:54     INFO - GECKO(2776) | MEMORY STAT | vsize 3520MB | residentFast 503MB | heapAllocated 215MB
[task 2023-01-05T14:56:54.396Z] 14:56:54     INFO - TEST-OK | accessible/tests/mochitest/events/test_focus_menu.xhtml | took 301034ms
[task 2023-01-05T14:56:54.405Z] 14:56:54     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/chrome/nsChromeRegistry.cpp:180
[task 2023-01-05T14:56:54.406Z] 14:56:54     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/checkouts/gecko/chrome/nsChromeProtocolHandler.cpp:73
[task 2023-01-05T14:56:54.483Z] 14:56:54     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: Failed to retarget HTML data delivery to the parser thread.: file /builds/worker/checkouts/gecko/parser/html/nsHtml5StreamParser.cpp:1234
[task 2023-01-05T14:56:54.499Z] 14:56:54     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: 'event->mOriginalTarget != this', file /builds/worker/checkouts/gecko/dom/xul/XULButtonElement.cpp:349
[task 2023-01-05T14:56:54.710Z] 14:56:54     INFO - TEST-START | Shutdown
[task 2023-01-05T14:56:54.712Z] 14:56:54     INFO - Passed:  89
[task 2023-01-05T14:56:54.713Z] 14:56:54     INFO - Failed:  0
[task 2023-01-05T14:56:54.714Z] 14:56:54     INFO - Todo:    4
[task 2023-01-05T14:56:54.716Z] 14:56:54     INFO - Mode:    non-e10s
[task 2023-01-05T14:56:54.717Z] 14:56:54     INFO - Slowest: 301034ms - chrome://mochitests/content/a11y/accessible/tests/mochitest/events/test_focus_menu.xhtml
[task 2023-01-05T14:56:54.718Z] 14:56:54     INFO - TEST-INFO | Ran 4 Loops
[task 2023-01-05T14:56:54.719Z] 14:56:54     INFO - SimpleTest FINISHED
[task 2023-01-05T14:56:54.733Z] 14:56:54     INFO - Not taking screenshot here: see the one that was previously logged
[task 2023-01-05T14:56:54.735Z] 14:56:54     INFO - TEST-UNEXPECTED-FAIL | accessible/tests/mochitest/events/test_focus_menu.xhtml | Unique type focus event was handled. 
[task 2023-01-05T14:56:54.735Z] 14:56:54     INFO - SimpleTest.ok@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:404:16
[task 2023-01-05T14:56:54.735Z] 14:56:54     INFO - eventQueue_handleEvent@chrome://mochitests/content/a11y/accessible/tests/mochitest/events.js:583:15
[task 2023-01-05T14:56:54.735Z] 14:56:54     INFO - observe@chrome://mochitests/content/a11y/accessible/tests/mochitest/events.js:2436:29
[task 2023-01-05T14:56:54.804Z] 14:56:54     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorProtocol.cpp:163
[task 2023-01-05T14:56:54.805Z] 14:56:54     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorProtocol.cpp:163
[task 2023-01-05T14:56:54.833Z] 14:56:54     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorProtocol.cpp:163
[task 2023-01-05T14:56:54.835Z] 14:56:54     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorProtocol.cpp:163
[task 2023-01-05T14:56:54.851Z] 14:56:54     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorProtocol.cpp:163
[task 2023-01-05T14:56:54.852Z] 14:56:54     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorProtocol.cpp:163
[task 2023-01-05T14:56:54.871Z] 14:56:54     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorProtocol.cpp:163
[task 2023-01-05T14:56:54.872Z] 14:56:54     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorProtocol.cpp:163
[task 2023-01-05T14:56:54.896Z] 14:56:54     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorProtocol.cpp:163
[task 2023-01-05T14:56:54.898Z] 14:56:54     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorProtocol.cpp:163
[task 2023-01-05T14:56:54.974Z] 14:56:54     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:44
[task 2023-01-05T14:56:54.976Z] 14:56:54     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:44
[task 2023-01-05T14:56:54.989Z] 14:56:54     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:44
[task 2023-01-05T14:56:55.002Z] 14:56:55     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:44
[task 2023-01-05T14:56:55.019Z] 14:56:55     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:44
[task 2023-01-05T14:56:55.020Z] 14:56:55     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:44
[task 2023-01-05T14:56:55.044Z] 14:56:55     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:44
[task 2023-01-05T14:56:55.133Z] 14:56:55     INFO - GECKO(2776) | 1672930615131	Marionette	TRACE	Received observer notification quit-application
[task 2023-01-05T14:56:55.135Z] 14:56:55     INFO - GECKO(2776) | 1672930615133	Marionette	INFO	Stopped listening on port 2828
[task 2023-01-05T14:56:55.136Z] 14:56:55     INFO - GECKO(2776) | 1672930615135	Marionette	DEBUG	Marionette stopped listening
[task 2023-01-05T14:56:55.170Z] 14:56:55     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorProtocol.cpp:163
[task 2023-01-05T14:56:55.172Z] 14:56:55     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorProtocol.cpp:163
[task 2023-01-05T14:56:55.203Z] 14:56:55     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorProtocol.cpp:163
[task 2023-01-05T14:56:55.205Z] 14:56:55     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorProtocol.cpp:163
[task 2023-01-05T14:56:55.372Z] 14:56:55     INFO - GECKO(2776) | [Parent 2776, Socket Thread] WARNING: cannot post event if not initialized: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnectionMgr.cpp:204
[task 2023-01-05T14:56:55.372Z] 14:56:55     INFO - GECKO(2776) | [Parent 2776, Socket Thread] WARNING: cannot post event if not initialized: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnectionMgr.cpp:204
[task 2023-01-05T14:56:55.372Z] 14:56:55     INFO - GECKO(2776) | [Parent 2776, Socket Thread] WARNING: cannot post event if not initialized: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnectionMgr.cpp:204
[task 2023-01-05T14:56:55.807Z] 14:56:55     INFO - GECKO(2776) | [Parent 2776, IPDL Background] WARNING: quota manager shutdown step: '0.000005s: startCrashBrowserTimer', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-05T14:56:55.809Z] 14:56:55     INFO - GECKO(2776) | [Parent 2776, IPDL Background] WARNING: quota manager shutdown step: '0.000048s: initiateShutdownWorkThreads', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-05T14:56:55.810Z] 14:56:55     INFO - GECKO(2776) | [Parent 2776, IPDL Background] WARNING: idb: '0.000058s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-05T14:56:55.811Z] 14:56:55     INFO - GECKO(2776) | [Parent 2776, IPDL Background] WARNING: cache: '0.000073s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-05T14:56:55.813Z] 14:56:55     INFO - GECKO(2776) | [Parent 2776, IPDL Background] WARNING: sdb: '0.000080s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-05T14:56:55.813Z] 14:56:55     INFO - GECKO(2776) | [Parent 2776, IPDL Background] WARNING: fs: '0.000086s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-05T14:56:55.813Z] 14:56:55     INFO - GECKO(2776) | [Parent 2776, IPDL Background] WARNING: ls: '0.000093s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-05T14:56:55.814Z] 14:56:55     INFO - GECKO(2776) | [Parent 2776, IPDL Background] WARNING: quota manager shutdown step: '0.000102s: startKillActorsTimer', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-05T14:56:55.814Z] 14:56:55     INFO - GECKO(2776) | [Parent 2776, IPDL Background] WARNING: idb: '0.005769s: Live database entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-05T14:56:55.815Z] 14:56:55     INFO - GECKO(2776) | [Parent 2776, IPDL Background] WARNING: idb: '0.008866s: Live database entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-05T14:56:55.816Z] 14:56:55     INFO - GECKO(2776) | [Parent 2776, IPDL Background] WARNING: idb: '0.008925s: gLiveDatabaseHashtable entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-05T14:56:55.818Z] 14:56:55     INFO - GECKO(2776) | [Parent 2776, IPDL Background] WARNING: idb: '0.011437s: Live database entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-05T14:56:55.818Z] 14:56:55     INFO - GECKO(2776) | [Parent 2776, IPDL Background] WARNING: idb: '0.011459s: gLiveDatabaseHashtable entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-05T14:56:55.820Z] 14:56:55     INFO - GECKO(2776) | [Parent 2776, IPDL Background] WARNING: quota manager shutdown step: '0.013594s: stopKillActorsTimer', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-05T14:56:55.821Z] 14:56:55     INFO - GECKO(2776) | [Parent 2776, IPDL Background] WARNING: quota manager shutdown step: '0.013626s: shutdownAndJoinWorkThreads', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-05T14:56:55.821Z] 14:56:55     INFO - GECKO(2776) | [Parent 2776, IPDL Background] WARNING: idb: '0.013633s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-05T14:56:55.824Z] 14:56:55     INFO - GECKO(2776) | [Parent 2776, IPDL Background] WARNING: cache: '0.016917s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-05T14:56:55.825Z] 14:56:55     INFO - GECKO(2776) | [Parent 2776, IPDL Background] WARNING: sdb: '0.016939s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-05T14:56:55.826Z] 14:56:55     INFO - GECKO(2776) | [Parent 2776, IPDL Background] WARNING: fs: '0.016949s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-05T14:56:55.826Z] 14:56:55     INFO - GECKO(2776) | [Parent 2776, IPDL Background] WARNING: ls: '0.016956s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-05T14:56:55.827Z] 14:56:55     INFO - GECKO(2776) | [Parent 2776, IPDL Background] WARNING: quota manager shutdown step: '0.016962s: shutdownAndJoinIOThread', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-05T14:56:55.828Z] 14:56:55     INFO - GECKO(2776) | [Parent 2776, IPDL Background] WARNING: quota manager shutdown step: '0.018912s: invalidatePendingDirectoryLocks', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-05T14:56:55.829Z] 14:56:55     INFO - GECKO(2776) | [Parent 2776, IPDL Background] WARNING: quota manager shutdown step: '0.018939s: stopCrashBrowserTimer', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-05T14:56:55.894Z] 14:56:55     INFO - GECKO(2776) | WARNING: A blocker encountered an error while we were waiting.
[task 2023-01-05T14:56:55.896Z] 14:56:55     INFO - GECKO(2776) |           Blocker:  Waiting for ping task
[task 2023-01-05T14:56:55.897Z] 14:56:55     INFO - GECKO(2776) |           Phase: TelemetryController: Waiting for pending ping activity
[task 2023-01-05T14:56:55.898Z] 14:56:55     INFO - GECKO(2776) |           State: (none)
[task 2023-01-05T14:56:55.899Z] 14:56:55     INFO - GECKO(2776) | WARNING: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-01-05T14:56:55.900Z] 14:56:55     INFO - GECKO(2776) | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
[task 2023-01-05T14:56:55.901Z] 14:56:55     INFO - GECKO(2776) | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-01-05T14:56:55.902Z] 14:56:55     INFO - GECKO(2776) | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-01-05T14:56:55.903Z] 14:56:55     INFO - GECKO(2776) | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-01-05T14:56:55.904Z] 14:56:55     INFO - GECKO(2776) | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-01-05T14:56:55.905Z] 14:56:55     INFO - GECKO(2776) | @resource://gre/modules/osfile.jsm:12:30
[task 2023-01-05T14:56:55.906Z] 14:56:55     INFO - GECKO(2776) | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-01-05T14:56:55.907Z] 14:56:55     INFO - GECKO(2776) | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:863:17
[task 2023-01-05T14:56:55.907Z] 14:56:55     INFO - GECKO(2776) | setup@resource://gre/modules/TelemetrySend.sys.mjs:803:18
[task 2023-01-05T14:56:55.908Z] 14:56:55     INFO - GECKO(2776) | setup@resource://gre/modules/TelemetrySend.sys.mjs:241:30
[task 2023-01-05T14:56:55.909Z] 14:56:55     INFO - GECKO(2776) | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:829:36
[task 2023-01-05T14:56:55.910Z] 14:56:55     INFO - GECKO(2776) | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-01-05T14:56:55.941Z] 14:56:55     INFO - GECKO(2776) | WARNING: A blocker encountered an error while we were waiting.
[task 2023-01-05T14:56:55.942Z] 14:56:55     INFO - GECKO(2776) |           Blocker:  Waiting for ping task
[task 2023-01-05T14:56:55.943Z] 14:56:55     INFO - GECKO(2776) |           Phase: TelemetryController: Waiting for pending ping activity
[task 2023-01-05T14:56:55.944Z] 14:56:55     INFO - GECKO(2776) |           State: (none)
[task 2023-01-05T14:56:55.945Z] 14:56:55     INFO - GECKO(2776) | WARNING: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-01-05T14:56:55.945Z] 14:56:55     INFO - GECKO(2776) | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
[task 2023-01-05T14:56:55.946Z] 14:56:55     INFO - GECKO(2776) | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-01-05T14:56:55.947Z] 14:56:55     INFO - GECKO(2776) | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-01-05T14:56:55.947Z] 14:56:55     INFO - GECKO(2776) | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-01-05T14:56:55.948Z] 14:56:55     INFO - GECKO(2776) | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-01-05T14:56:55.949Z] 14:56:55     INFO - GECKO(2776) | @resource://gre/modules/osfile.jsm:12:30
[task 2023-01-05T14:56:55.949Z] 14:56:55     INFO - GECKO(2776) | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-01-05T14:56:55.950Z] 14:56:55     INFO - GECKO(2776) | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:863:17
[task 2023-01-05T14:56:55.951Z] 14:56:55     INFO - GECKO(2776) | setup@resource://gre/modules/TelemetrySend.sys.mjs:803:18
[task 2023-01-05T14:56:55.951Z] 14:56:55     INFO - GECKO(2776) | setup@resource://gre/modules/TelemetrySend.sys.mjs:241:30
[task 2023-01-05T14:56:55.952Z] 14:56:55     INFO - GECKO(2776) | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:829:36
[task 2023-01-05T14:56:55.953Z] 14:56:55     INFO - GECKO(2776) | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-01-05T14:56:55.954Z] 14:56:55     INFO - GECKO(2776) | WARNING: A blocker encountered an error while we were waiting.
[task 2023-01-05T14:56:55.955Z] 14:56:55     INFO - GECKO(2776) |           Blocker:  TelemetryController: shutting down
[task 2023-01-05T14:56:55.956Z] 14:56:55     INFO - GECKO(2776) |           Phase: profile-before-change-telemetry
[task 2023-01-05T14:56:55.958Z] 14:56:55     INFO - GECKO(2776) |           State: Error getting state: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange" at addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
[task 2023-01-05T14:56:55.959Z] 14:56:55     INFO - GECKO(2776) | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-01-05T14:56:55.959Z] 14:56:55     INFO - GECKO(2776) | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-01-05T14:56:55.960Z] 14:56:55     INFO - GECKO(2776) | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-01-05T14:56:55.960Z] 14:56:55     INFO - GECKO(2776) | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-01-05T14:56:55.961Z] 14:56:55     INFO - GECKO(2776) | @resource://gre/modules/osfile.jsm:12:30
[task 2023-01-05T14:56:55.962Z] 14:56:55     INFO - GECKO(2776) | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-01-05T14:56:55.962Z] 14:56:55     INFO - GECKO(2776) | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:863:17
[task 2023-01-05T14:56:55.963Z] 14:56:55     INFO - GECKO(2776) | setup@resource://gre/modules/TelemetrySend.sys.mjs:803:18
[task 2023-01-05T14:56:55.963Z] 14:56:55     INFO - GECKO(2776) | setup@resource://gre/modules/TelemetrySend.sys.mjs:241:30
[task 2023-01-05T14:56:55.966Z] 14:56:55     INFO - GECKO(2776) | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:829:36
[task 2023-01-05T14:56:55.967Z] 14:56:55     INFO - GECKO(2776) | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-01-05T14:56:55.967Z] 14:56:55     INFO - GECKO(2776) | WARNING: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-01-05T14:56:55.967Z] 14:56:55     INFO - GECKO(2776) | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
[task 2023-01-05T14:56:55.967Z] 14:56:55     INFO - GECKO(2776) | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-01-05T14:56:55.968Z] 14:56:55     INFO - GECKO(2776) | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-01-05T14:56:55.968Z] 14:56:55     INFO - GECKO(2776) | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-01-05T14:56:55.968Z] 14:56:55     INFO - GECKO(2776) | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-01-05T14:56:55.969Z] 14:56:55     INFO - GECKO(2776) | @resource://gre/modules/osfile.jsm:12:30
[task 2023-01-05T14:56:55.969Z] 14:56:55     INFO - GECKO(2776) | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-01-05T14:56:55.969Z] 14:56:55     INFO - GECKO(2776) | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:863:17
[task 2023-01-05T14:56:55.970Z] 14:56:55     INFO - GECKO(2776) | setup@resource://gre/modules/TelemetrySend.sys.mjs:803:18
[task 2023-01-05T14:56:55.970Z] 14:56:55     INFO - GECKO(2776) | setup@resource://gre/modules/TelemetrySend.sys.mjs:241:30
[task 2023-01-05T14:56:55.971Z] 14:56:55     INFO - GECKO(2776) | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:829:36
[task 2023-01-05T14:56:55.971Z] 14:56:55     INFO - GECKO(2776) | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-01-05T14:56:55.972Z] 14:56:55     INFO - GECKO(2776) | JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-01-05T14:56:55.973Z] 14:56:55     INFO - GECKO(2776) | JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-01-05T14:56:55.974Z] 14:56:55     INFO - GECKO(2776) | JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-01-05T14:56:55.975Z] 14:56:55     INFO - GECKO(2776) | JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-01-05T14:56:55.976Z] 14:56:55     INFO - GECKO(2776) | JavaScript error: resource://gre/modules/AsyncShutdown.sys.mjs, line 727: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2023-01-05T14:56:55.994Z] 14:56:55     INFO - GECKO(2776) | [Parent 2776, IPDL Background] WARNING: IPC Connection Error: [Parent][PBackgroundParent] RunMessage(msgname=PRemoteWorkerService::Msg___delete__) Channel closing: too late to send/recv, messages will be lost: file /builds/worker/checkouts/gecko/ipc/glue/MessageChannel.cpp:1927
[task 2023-01-05T14:56:56.019Z] 14:56:56     INFO - GECKO(2776) | [Parent 2776, Compositor] WARNING: IPC Connection Error: [Parent][PImageBridgeParent] RunMessage(msgname=PImageBridge::Msg_WillClose) Channel closing: too late to send/recv, messages will be lost: file /builds/worker/checkouts/gecko/ipc/glue/MessageChannel.cpp:1927
[task 2023-01-05T14:56:56.884Z] 14:56:56     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3384
[task 2023-01-05T14:56:56.913Z] 14:56:56     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file /builds/worker/workspace/obj-build/dist/include/mozilla/Preferences.h:129
[task 2023-01-05T14:56:56.940Z] 14:56:56     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: OOPDeinit() without successful OOPInit(): file /builds/worker/checkouts/gecko/toolkit/crashreporter/nsExceptionHandler.cpp:3376
[task 2023-01-05T14:56:56.941Z] 14:56:56     INFO - GECKO(2776) | [Parent 2776, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4663
[task 2023-01-05T14:56:56.961Z] 14:56:56     INFO - TEST-INFO | Main app process: exit 0

:emilio, since you are the author of the regressor, bug 1808624, could you take a look?

For more information, please visit auto_nag documentation.

Flags: needinfo?(emilio)

Same, probably won't be looking at TV failures on these old tests unless they also manifest in non-TV.

Flags: needinfo?(emilio)
Summary: Intermittent TV accessible/tests/mochitest/events/test_focus_menu.xhtml | single tracking bug → Intermittent accessible/tests/mochitest/events/test_focus_menu.xhtml | single tracking bug

Set release status flags based on info from the regressing bug 1808624

Set release status flags based on info from the regressing bug 1808624

Attachment #9384902 - Attachment is obsolete: true
Flags: needinfo?(emilio)
Regressed by: 1994879
No longer regressed by: 1808624
Summary: Intermittent accessible/tests/mochitest/events/test_focus_menu.xhtml | single tracking bug → Frequent accessible/tests/mochitest/events/test_focus_menu.xhtml | single tracking bug

Set release status flags based on info from the regressing bug 1994879

Set release status flags based on info from the regressing bug 1994879

Sorry for not getting to this sooner. I think bug 1992198 might help with this but I'm not super familiar with this test... Jamie, given this spike was caused by a timing difference in when the native window is closed for popup, do you have any good sense on where the unstable code might be? Or maybe we're just getting focus from the compositor sooner?

Flags: needinfo?(emilio) → needinfo?(jteh)

I'm not really sure, but I can give you a few things to consider:

  1. Enabling a11y focus logging will probably help to debug this. You should be able to do this with enableLogging("focus") in the test. Alternatively, you can set the environment variable A11YLOG=focus.
  2. XUL menus are a special case for accessibility. Accessibility wants menu items to get focus, but as far as DOM is concerned, they don't get focus, so we manage a11y focus using DOM{MenuBar,Menu,MenuItem}{Active,Inactive} DOM events.
  3. As I understand it, the failure here is caused by a double focus event on the document. I haven't tested this at all, but my guess is that we're getting a DOMMenuBarInactive event, and then in the next tick, DOM is also firing focus on the document. If it happened in the same tick, we'd coalesce away the duplicate event, but that won't happen across ticks.
  4. If that's the case, my question is: why are we firing DOM focus on the document? I thought XUL menus never messed with DOM focus?
  5. If XUL menus do in fact mess with DOM focus, we'd need to re-evaluate the handling of Menu*Inactive events and whether they should manage a11y focus themselves or rely on DOM to do that.
Flags: needinfo?(jteh)

(In reply to James Teh [:Jamie] from comment #156)

  1. If that's the case, my question is: why are we firing DOM focus on the document? I thought XUL menus never messed with DOM focus?

Maybe this has something to do with the native window closing, so the document's native window gets focus, causing DOM to fire focus? But this is all speculation.

Hello,
Do you have any updates? There are 87 failures in the last 7 days.

Set release status flags based on info from the regressing bug 1994879

Assignee: nobody → chorotan
Status: NEW → ASSIGNED
Assignee: chorotan → nobody
Status: ASSIGNED → NEW
Keywords: leave-open
Whiteboard: [stockwell disable-recommended]
Attachment #9526014 - Attachment description: Bug 1808737 - disable test_focus_menu.xhtml on linux for frquent failures. r=#intermittent-reviewers → Bug 1808737 - disable test_focus_menu.xhtml on linux for frequent failures. r=#intermittent-reviewers
Pushed by archaeopteryx@coole-files.de: https://github.com/mozilla-firefox/firefox/commit/19b25c433ca7 https://hg.mozilla.org/integration/autoland/rev/0b4f67c893f2 disable test_focus_menu.xhtml on linux for frequent failures. r=intermittent-reviewers,tnikkel,ahal DONTBUILD
Whiteboard: [stockwell disable-recommended] → [stockwell disabled]
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: