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
Description
•