1800643 - PERMA TEST-UNEXPECTED-TIMEOUT | /event-timing/buffered-flag.html | PerformanceObserver with buffered flag sees previous Event Timing entries - Test timed out when Gecko 109 merges to Beta on 2022-12-12

Status: VERIFIED FIXED

(Core :: DOM: Core & HTML, defect)

Description

[Serban Stanca [:SerbanS]]

[Tracking Requested - why for this release]:

Central-as-beta-simulation

How to run these simulations

Failure log

[task 2022-11-15T11:46:16.376Z] 11:46:16     INFO - TEST-OK | /event-timing/buffered-and-duration-threshold.html | took 1435ms
[task 2022-11-15T11:46:16.376Z] 11:46:16     INFO - TEST-START | /event-timing/buffered-flag.html
[task 2022-11-15T11:46:16.388Z] 11:46:16     INFO - Closing window b672cd84-2b19-4087-b393-ee72e3d862e7
[task 2022-11-15T11:46:29.048Z] 11:46:29     INFO - PID 9739 | [Child 9982, Main Thread] WARNING: IPC message 'PSessionStore::Msg_SessionStoreUpdate' discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:504
[task 2022-11-15T11:46:30.175Z] 11:46:30     INFO - PID 9739 | [Child 9982, Main Thread] WARNING: IPC message 'PSessionStore::Msg_SessionStoreUpdate' discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:504
[task 2022-11-15T11:46:31.304Z] 11:46:31     INFO - PID 9739 | ALSA lib seq_hw.c:466:(snd_seq_hw_open) open /dev/snd/seq failed: No such file or directory
[task 2022-11-15T11:46:46.943Z] 11:46:46     INFO - 
[task 2022-11-15T11:46:46.943Z] 11:46:46     INFO - TEST-UNEXPECTED-TIMEOUT | /event-timing/buffered-flag.html | PerformanceObserver with buffered flag sees previous Event Timing entries - Test timed out
[task 2022-11-15T11:46:46.944Z] 11:46:46     INFO - TEST-UNEXPECTED-TIMEOUT | /event-timing/buffered-flag.html | expected OK
[task 2022-11-15T11:46:46.944Z] 11:46:46     INFO - TEST-INFO took 30567ms
[task 2022-11-15T11:46:46.945Z] 11:46:46     INFO - PID 9739 | 1668512806944	Marionette	INFO	Stopped listening on port 42507
[task 2022-11-15T11:46:46.993Z] 11:46:46     INFO - PID 9739 | [Child 9867, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:44
[task 2022-11-15T11:46:46.994Z] 11:46:46     INFO - PID 9739 | [Child 9867, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:44
[task 2022-11-15T11:46:47.003Z] 11:46:47     INFO - PID 9739 | [Child 9867, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:44
[task 2022-11-15T11:46:47.011Z] 11:46:47     INFO - PID 9739 | [Child 9867, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:44
[task 2022-11-15T11:46:47.014Z] 11:46:47     INFO - PID 9739 | [Child 9867, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:44
[task 2022-11-15T11:46:47.015Z] 11:46:47     INFO - PID 9739 | [Child 9867, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:44
[task 2022-11-15T11:46:47.020Z] 11:46:47     INFO - PID 9739 | [Child 9867, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:44
[task 2022-11-15T11:46:47.098Z] 11:46:47     INFO - PID 9739 | [Child 9982, Main Thread] WARNING: DispatchEvent called on non-current inner window, dropping. Please check the window in the caller instead.: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowInner.cpp:4353
[task 2022-11-15T11:46:47.098Z] 11:46:47     INFO - PID 9739 | [Child 9909, Main Thread] WARNING: DispatchEvent called on non-current inner window, dropping. Please check the window in the caller instead.: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowInner.cpp:4353
[task 2022-11-15T11:46:47.120Z] 11:46:47     INFO - PID 9739 | ALSA lib seq_hw.c:466:(snd_seq_hw_open) open /dev/snd/seq failed: No such file or directory
[task 2022-11-15T11:46:47.145Z] 11:46:47     INFO - PID 9739 | [Parent 9739, Compositor] WARNING: Possibly dropping task posted to updater thread: file /builds/worker/checkouts/gecko/gfx/layers/apz/src/APZUpdater.cpp:371
[task 2022-11-15T11:46:47.170Z] 11:46:47     INFO - PID 9739 | [Parent 9739, 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:1883
[task 2022-11-15T11:46:47.178Z] 11:46:47     INFO - PID 9739 | [Parent 9739, Compositor] WARNING: IPC Connection Error: [Parent][PCompositorManagerParent] RunMessage(msgname=PCompositorBridge::Msg___delete__) Channel closing: too late to send/recv, messages will be lost: file /builds/worker/checkouts/gecko/ipc/glue/MessageChannel.cpp:1883
[task 2022-11-15T11:46:47.180Z] 11:46:47     INFO - PID 9739 | [Child 9982, Main Thread] WARNING: IPC message 'PContent::Msg_StoreUserInteractionAsPermission' discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:504
[task 2022-11-15T11:46:47.203Z] 11:46:47     INFO - PID 9739 | [Parent 9739, Socket Thread] WARNING: cannot post event if not initialized: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnectionMgr.cpp:200
[task 2022-11-15T11:46:47.230Z] 11:46:47     INFO - PID 9739 | [Child 9909, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3387
[task 2022-11-15T11:46:47.230Z] 11:46:47     INFO - PID 9739 | [Child 9909, Main Thread] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file /builds/worker/workspace/obj-build/dist/include/mozilla/Preferences.h:129
[task 2022-11-15T11:46:47.236Z] 11:46:47     INFO - PID 9739 | [Child 9909, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4628
[task 2022-11-15T11:46:47.314Z] 11:46:47     INFO - PID 9739 | [Child 9982, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3387
[task 2022-11-15T11:46:47.318Z] 11:46:47     INFO - PID 9739 | [Child 9982, Main Thread] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file /builds/worker/workspace/obj-build/dist/include/mozilla/Preferences.h:129
[task 2022-11-15T11:46:47.329Z] 11:46:47     INFO - PID 9739 | [Child 9982, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4628
[task 2022-11-15T11:46:47.344Z] 11:46:47     INFO - PID 9739 | [Child 9867, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3387
[task 2022-11-15T11:46:47.347Z] 11:46:47     INFO - PID 9739 | [Child 9867, Main Thread] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file /builds/worker/workspace/obj-build/dist/include/mozilla/Preferences.h:129
[task 2022-11-15T11:46:47.354Z] 11:46:47     INFO - PID 9739 | [Child 9867, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4628
[task 2022-11-15T11:46:47.587Z] 11:46:47     INFO - PID 9739 | [Parent 9739, Compositor] WARNING: IPC Connection Error: [Parent][PCompositorManagerParent] RunMessage(msgname=PCompositorBridge::Msg___delete__) Channel closing: too late to send/recv, messages will be lost: file /builds/worker/checkouts/gecko/ipc/glue/MessageChannel.cpp:1883
[task 2022-11-15T11:46:47.587Z] 11:46:47     INFO - PID 9739 | [Parent 9739, 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:1883
[task 2022-11-15T11:46:47.587Z] 11:46:47     INFO - PID 9739 | [Parent 9739, Compositor] WARNING: IPC Connection Error: [Parent][PCompositorManagerParent] RunMessage(msgname=PCompositorBridge::Msg___delete__) Channel closing: too late to send/recv, messages will be lost: file /builds/worker/checkouts/gecko/ipc/glue/MessageChannel.cpp:1883
[task 2022-11-15T11:46:47.589Z] 11:46:47     INFO - PID 9739 | [Parent 9739, Compositor] WARNING: IPC Connection Error: [Parent][PCompositorManagerParent] RunMessage(msgname=PCompositorBridge::Msg___delete__) Channel closing: too late to send/recv, messages will be lost: file /builds/worker/checkouts/gecko/ipc/glue/MessageChannel.cpp:1883
[task 2022-11-15T11:46:47.593Z] 11:46:47     INFO - PID 9739 | [Parent 9739, 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:1883
[task 2022-11-15T11:46:47.603Z] 11:46:47     INFO - PID 9739 | [Child 9991, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3387
[task 2022-11-15T11:46:47.604Z] 11:46:47     INFO - PID 9739 | [Child 9986, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3387
[task 2022-11-15T11:46:47.608Z] 11:46:47     INFO - PID 9739 | [Child 9991, Main Thread] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file /builds/worker/workspace/obj-build/dist/include/mozilla/Preferences.h:129
[task 2022-11-15T11:46:47.608Z] 11:46:47     INFO - PID 9739 | [Child 9986, Main Thread] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file /builds/worker/workspace/obj-build/dist/include/mozilla/Preferences.h:129
[task 2022-11-15T11:46:47.610Z] 11:46:47     INFO - PID 9739 | [Child 10198, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3387
[task 2022-11-15T11:46:47.610Z] 11:46:47     INFO - PID 9739 | [Child 10198, Main Thread] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file /builds/worker/workspace/obj-build/dist/include/mozilla/Preferences.h:129
[task 2022-11-15T11:46:47.614Z] 11:46:47     INFO - PID 9739 | [Child 9986, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4628
[task 2022-11-15T11:46:47.614Z] 11:46:47     INFO - PID 9739 | [Child 10198, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4628
[task 2022-11-15T11:46:47.616Z] 11:46:47     INFO - PID 9739 | [Child 9991, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4628
[task 2022-11-15T11:46:47.625Z] 11:46:47     INFO - PID 9739 | [Parent 9739, IPDL Background] WARNING: quota manager shutdown step: '0.000005s: startCrashBrowserTimer', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-15T11:46:47.626Z] 11:46:47     INFO - PID 9739 | [Parent 9739, IPDL Background] WARNING: quota manager shutdown step: '0.000049s: initiateShutdownWorkThreads', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-15T11:46:47.627Z] 11:46:47     INFO - PID 9739 | [Parent 9739, IPDL Background] WARNING: idb: '0.000072s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-15T11:46:47.628Z] 11:46:47     INFO - PID 9739 | [Parent 9739, IPDL Background] WARNING: cache: '0.000085s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-15T11:46:47.629Z] 11:46:47     INFO - PID 9739 | [Parent 9739, IPDL Background] WARNING: sdb: '0.000221s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-15T11:46:47.630Z] 11:46:47     INFO - PID 9739 | [Parent 9739, IPDL Background] WARNING: fs: '0.000232s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-15T11:46:47.630Z] 11:46:47     INFO - PID 9739 | [Parent 9739, IPDL Background] WARNING: ls: '0.000241s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-15T11:46:47.633Z] 11:46:47     INFO - PID 9739 | [Parent 9739, IPDL Background] WARNING: quota manager shutdown step: '0.000252s: startKillActorsTimer', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-15T11:46:47.633Z] 11:46:47     INFO - PID 9739 | [Parent 9739, IPDL Background] WARNING: idb: '0.000297s: Live database entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-15T11:46:47.634Z] 11:46:47     INFO - PID 9739 | [Parent 9739, IPDL Background] WARNING: idb: '0.000304s: gLiveDatabaseHashtable entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-15T11:46:47.634Z] 11:46:47     INFO - PID 9739 | [Parent 9739, IPDL Background] WARNING: idb: '0.003756s: Live database entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-15T11:46:47.635Z] 11:46:47     INFO - PID 9739 | [Parent 9739, IPDL Background] WARNING: idb: '0.003864s: Live database entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-15T11:46:47.636Z] 11:46:47     INFO - PID 9739 | [Parent 9739, IPDL Background] WARNING: idb: '0.003877s: gLiveDatabaseHashtable entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-15T11:46:47.637Z] 11:46:47     INFO - PID 9739 | [Parent 9739, IPDL Background] WARNING: quota manager shutdown step: '0.007712s: stopKillActorsTimer', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-15T11:46:47.637Z] 11:46:47     INFO - PID 9739 | [Parent 9739, IPDL Background] WARNING: quota manager shutdown step: '0.007757s: shutdownAndJoinWorkThreads', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-15T11:46:47.637Z] 11:46:47     INFO - PID 9739 | [Parent 9739, IPDL Background] WARNING: idb: '0.007769s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-15T11:46:47.638Z] 11:46:47     INFO - PID 9739 | [Parent 9739, IPDL Background] WARNING: cache: '0.007830s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-15T11:46:47.638Z] 11:46:47     INFO - PID 9739 | [Parent 9739, IPDL Background] WARNING: sdb: '0.007840s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-15T11:46:47.638Z] 11:46:47     INFO - PID 9739 | [Parent 9739, IPDL Background] WARNING: fs: '0.007846s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-15T11:46:47.638Z] 11:46:47     INFO - PID 9739 | [Parent 9739, IPDL Background] WARNING: ls: '0.007855s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-15T11:46:47.638Z] 11:46:47     INFO - PID 9739 | [Parent 9739, IPDL Background] WARNING: quota manager shutdown step: '0.007864s: shutdownAndJoinIOThread', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-15T11:46:47.639Z] 11:46:47     INFO - PID 9739 | [Parent 9739, IPDL Background] WARNING: quota manager shutdown step: '0.008000s: invalidatePendingDirectoryLocks', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-15T11:46:47.640Z] 11:46:47     INFO - PID 9739 | [Parent 9739, IPDL Background] WARNING: quota manager shutdown step: '0.008011s: stopCrashBrowserTimer', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3297
[task 2022-11-15T11:46:47.725Z] 11:46:47     INFO - PID 9739 | WARNING: A blocker encountered an error while we were waiting.
[task 2022-11-15T11:46:47.727Z] 11:46:47     INFO - PID 9739 |           Blocker:  Waiting for ping task
[task 2022-11-15T11:46:47.728Z] 11:46:47     INFO - PID 9739 |           Phase: TelemetryController: Waiting for pending ping activity
[task 2022-11-15T11:46:47.729Z] 11:46:47     INFO - PID 9739 |           State: (none)
[task 2022-11-15T11:46:47.729Z] 11:46:47     INFO - PID 9739 | 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 2022-11-15T11:46:47.730Z] 11:46:47     INFO - PID 9739 | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.jsm:703:15
[task 2022-11-15T11:46:47.731Z] 11:46:47     INFO - PID 9739 | addBlocker@resource://gre/modules/AsyncShutdown.jsm:511:26
[task 2022-11-15T11:46:47.731Z] 11:46:47     INFO - PID 9739 | addBlocker@resource://gre/modules/AsyncShutdown.jsm:450:15
[task 2022-11-15T11:46:47.732Z] 11:46:47     INFO - PID 9739 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1563:28
[task 2022-11-15T11:46:47.733Z] 11:46:47     INFO - PID 9739 | @resource://gre/modules/osfile/osfile_async_front.jsm:1583:16
[task 2022-11-15T11:46:47.733Z] 11:46:47     INFO - PID 9739 | @resource://gre/modules/osfile.jsm:12:30
[task 2022-11-15T11:46:47.734Z] 11:46:47     INFO - PID 9739 | @resource://gre/modules/TelemetryStorage.jsm:19:28
[task 2022-11-15T11:46:47.735Z] 11:46:47     INFO - PID 9739 | promiseArchivePing@resource://gre/modules/TelemetryArchive.jsm:103:5
[task 2022-11-15T11:46:47.735Z] 11:46:47     INFO - PID 9739 | promiseArchivePing@resource://gre/modules/TelemetryArchive.jsm:63:33
[task 2022-11-15T11:46:47.736Z] 11:46:47     INFO - PID 9739 | _submitPingLogic@resource://gre/modules/TelemetryControllerParent.jsm:540:48
[task 2022-11-15T11:46:47.736Z] 11:46:47     INFO - PID 9739 | send@resource://gre/modules/TelemetryControllerParent.jsm:628:24
[task 2022-11-15T11:46:47.737Z] 11:46:47     INFO - PID 9739 | submitExternalPing@resource://gre/modules/TelemetryControllerParent.jsm:182:17
[task 2022-11-15T11:46:47.738Z] 11:46:47     INFO - PID 9739 | sendPing@resource://gre/modules/EventPing.jsm:51:30
[task 2022-11-15T11:46:47.738Z] 11:46:47     INFO - PID 9739 | _submitPing@resource://gre/modules/EventPing.jsm:229:12
[task 2022-11-15T11:46:47.739Z] 11:46:47     INFO - PID 9739 | shutdown@resource://gre/modules/EventPing.jsm:112:10
[task 2022-11-15T11:46:47.739Z] 11:46:47     INFO - PID 9739 | _cleanupOnShutdown@resource://gre/modules/TelemetryControllerParent.jsm:940:31
[task 2022-11-15T11:46:47.740Z] 11:46:47     INFO - PID 9739 | shutdown/<@resource://gre/modules/TelemetryControllerParent.jsm:1010:24
[task 2022-11-15T11:46:47.741Z] 11:46:47     INFO - PID 9739 | observe@resource://gre/modules/AsyncShutdown.jsm:560:16
[task 2022-11-15T11:46:47.776Z] 11:46:47     INFO - PID 9739 | WARNING: A blocker encountered an error while we were waiting.
[task 2022-11-15T11:46:47.777Z] 11:46:47     INFO - PID 9739 |           Blocker:  Waiting for ping task
[task 2022-11-15T11:46:47.778Z] 11:46:47     INFO - PID 9739 |           Phase: TelemetryController: Waiting for pending ping activity
[task 2022-11-15T11:46:47.779Z] 11:46:47     INFO - PID 9739 |           State: (none)
[task 2022-11-15T11:46:47.780Z] 11:46:47     INFO - PID 9739 | 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 2022-11-15T11:46:47.781Z] 11:46:47     INFO - PID 9739 | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.jsm:703:15
[task 2022-11-15T11:46:47.782Z] 11:46:47     INFO - PID 9739 | addBlocker@resource://gre/modules/AsyncShutdown.jsm:511:26
[task 2022-11-15T11:46:47.782Z] 11:46:47     INFO - PID 9739 | addBlocker@resource://gre/modules/AsyncShutdown.jsm:450:15
[task 2022-11-15T11:46:47.783Z] 11:46:47     INFO - PID 9739 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1563:28
[task 2022-11-15T11:46:47.783Z] 11:46:47     INFO - PID 9739 | @resource://gre/modules/osfile/osfile_async_front.jsm:1583:16
[task 2022-11-15T11:46:47.784Z] 11:46:47     INFO - PID 9739 | @resource://gre/modules/osfile.jsm:12:30
[task 2022-11-15T11:46:47.784Z] 11:46:47     INFO - PID 9739 | @resource://gre/modules/TelemetryStorage.jsm:19:28
[task 2022-11-15T11:46:47.785Z] 11:46:47     INFO - PID 9739 | promiseArchivePing@resource://gre/modules/TelemetryArchive.jsm:103:5
[task 2022-11-15T11:46:47.785Z] 11:46:47     INFO - PID 9739 | promiseArchivePing@resource://gre/modules/TelemetryArchive.jsm:63:33
[task 2022-11-15T11:46:47.786Z] 11:46:47     INFO - PID 9739 | _submitPingLogic@resource://gre/modules/TelemetryControllerParent.jsm:540:48
[task 2022-11-15T11:46:47.786Z] 11:46:47     INFO - PID 9739 | send@resource://gre/modules/TelemetryControllerParent.jsm:628:24
[task 2022-11-15T11:46:47.787Z] 11:46:47     INFO - PID 9739 | submitExternalPing@resource://gre/modules/TelemetryControllerParent.jsm:182:17
[task 2022-11-15T11:46:47.787Z] 11:46:47     INFO - PID 9739 | saveShutdownPings@resource://gre/modules/TelemetrySession.jsm:982:34
[task 2022-11-15T11:46:47.788Z] 11:46:47     INFO - PID 9739 | shutdownChromeProcess/cleanup/<@resource://gre/modules/TelemetrySession.jsm:1232:20
[task 2022-11-15T11:46:47.788Z] 11:46:47     INFO - PID 9739 | cleanup@resource://gre/modules/TelemetrySession.jsm:1239:9
[task 2022-11-15T11:46:47.789Z] 11:46:47     INFO - PID 9739 | shutdownChromeProcess@resource://gre/modules/TelemetrySession.jsm:1256:14
[task 2022-11-15T11:46:47.789Z] 11:46:47     INFO - PID 9739 | shutdown@resource://gre/modules/TelemetrySession.jsm:247:17
[task 2022-11-15T11:46:47.790Z] 11:46:47     INFO - PID 9739 | _cleanupOnShutdown@resource://gre/modules/TelemetryControllerParent.jsm:959:35
[task 2022-11-15T11:46:47.790Z] 11:46:47     INFO - PID 9739 | observe@resource://gre/modules/AsyncShutdown.jsm:560:16
[task 2022-11-15T11:46:47.808Z] 11:46:47     INFO - PID 9739 | WARNING: A blocker encountered an error while we were waiting.
[task 2022-11-15T11:46:47.808Z] 11:46:47     INFO - PID 9739 |           Blocker:  TelemetryController: shutting down
[task 2022-11-15T11:46:47.808Z] 11:46:47     INFO - PID 9739 |           Phase: profile-before-change-telemetry
[task 2022-11-15T11:46:47.808Z] 11:46:47     INFO - PID 9739 |           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.jsm:703:15
[task 2022-11-15T11:46:47.809Z] 11:46:47     INFO - PID 9739 | addBlocker@resource://gre/modules/AsyncShutdown.jsm:511:26
[task 2022-11-15T11:46:47.809Z] 11:46:47     INFO - PID 9739 | addBlocker@resource://gre/modules/AsyncShutdown.jsm:450:15
[task 2022-11-15T11:46:47.811Z] 11:46:47     INFO - PID 9739 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1563:28
[task 2022-11-15T11:46:47.811Z] 11:46:47     INFO - PID 9739 | @resource://gre/modules/osfile/osfile_async_front.jsm:1583:16
[task 2022-11-15T11:46:47.812Z] 11:46:47     INFO - PID 9739 | @resource://gre/modules/osfile.jsm:12:30
[task 2022-11-15T11:46:47.812Z] 11:46:47     INFO - PID 9739 | @resource://gre/modules/TelemetryStorage.jsm:19:28
[task 2022-11-15T11:46:47.813Z] 11:46:47     INFO - PID 9739 | getShutdownState@resource://gre/modules/TelemetrySend.jsm:1687:7
[task 2022-11-15T11:46:47.814Z] 11:46:47     INFO - PID 9739 | getShutdownState@resource://gre/modules/TelemetrySend.jsm:369:30
[task 2022-11-15T11:46:47.814Z] 11:46:47     INFO - PID 9739 | _getState@resource://gre/modules/TelemetryControllerParent.jsm:1058:38
[task 2022-11-15T11:46:47.815Z] 11:46:47     INFO - PID 9739 | setupTelemetry/<@resource://gre/modules/TelemetryControllerParent.jsm:917:18
[task 2022-11-15T11:46:47.815Z] 11:46:47     INFO - PID 9739 | safeGetState@resource://gre/modules/AsyncShutdown.jsm:242:17
[task 2022-11-15T11:46:47.816Z] 11:46:47     INFO - PID 9739 | Barrier/addBlocker/promise<@resource://gre/modules/AsyncShutdown.jsm:751:20
[task 2022-11-15T11:46:47.816Z] 11:46:47     INFO - PID 9739 | observe@resource://gre/modules/AsyncShutdown.jsm:560:16
[task 2022-11-15T11:46:47.817Z] 11:46:47     INFO - PID 9739 | 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 2022-11-15T11:46:47.818Z] 11:46:47     INFO - PID 9739 | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.jsm:703:15
[task 2022-11-15T11:46:47.818Z] 11:46:47     INFO - PID 9739 | addBlocker@resource://gre/modules/AsyncShutdown.jsm:511:26
[task 2022-11-15T11:46:47.819Z] 11:46:47     INFO - PID 9739 | addBlocker@resource://gre/modules/AsyncShutdown.jsm:450:15
[task 2022-11-15T11:46:47.819Z] 11:46:47     INFO - PID 9739 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1563:28
[task 2022-11-15T11:46:47.820Z] 11:46:47     INFO - PID 9739 | @resource://gre/modules/osfile/osfile_async_front.jsm:1583:16
[task 2022-11-15T11:46:47.820Z] 11:46:47     INFO - PID 9739 | @resource://gre/modules/osfile.jsm:12:30
[task 2022-11-15T11:46:47.821Z] 11:46:47     INFO - PID 9739 | @resource://gre/modules/TelemetryStorage.jsm:19:28
[task 2022-11-15T11:46:47.821Z] 11:46:47     INFO - PID 9739 | removeAbortedSessionPing@resource://gre/modules/TelemetryControllerParent.jsm:721:5
[task 2022-11-15T11:46:47.822Z] 11:46:47     INFO - PID 9739 | removeAbortedSessionPing@resource://gre/modules/TelemetryControllerParent.jsm:249:17
[task 2022-11-15T11:46:47.822Z] 11:46:47     INFO - PID 9739 | shutdownChromeProcess/cleanup/<@resource://gre/modules/TelemetrySession.jsm:1235:42
[task 2022-11-15T11:46:47.823Z] 11:46:47     INFO - PID 9739 | observe@resource://gre/modules/AsyncShutdown.jsm:560:16
[task 2022-11-15T11:46:47.827Z] 11:46:47     INFO - PID 9739 | JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 703: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2022-11-15T11:46:47.828Z] 11:46:47     INFO - PID 9739 | JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 703: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2022-11-15T11:46:47.828Z] 11:46:47     INFO - PID 9739 | JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 703: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2022-11-15T11:46:47.829Z] 11:46:47     INFO - PID 9739 | JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 703: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2022-11-15T11:46:47.829Z] 11:46:47     INFO - PID 9739 | JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 703: Error: Phase "profile-before-change" is finished, it is too late to register completion condition "OS.File: flush I/O queued before profileBeforeChange"
[task 2022-11-15T11:46:47.840Z] 11:46:47     INFO - PID 9739 | [Parent 9739, 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:1883
[task 2022-11-15T11:46:48.600Z] 11:46:48     INFO - PID 9739 | [Parent 9739, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3387
[task 2022-11-15T11:46:48.631Z] 11:46:48     INFO - PID 9739 | [Parent 9739, Main Thread] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file /builds/worker/workspace/obj-build/dist/include/mozilla/Preferences.h:129
[task 2022-11-15T11:46:48.652Z] 11:46:48     INFO - PID 9739 | [Parent 9739, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4628
[task 2022-11-15T11:46:48.672Z] 11:46:48     INFO - Browser exited with return code 0
[task 2022-11-15T11:46:48.673Z] 11:46:48     INFO - PROCESS LEAKS /tmp/tmpy569t6rv/runtests_leaks_1186.log
[task 2022-11-15T11:46:48.673Z] 11:46:48     INFO - leakcheck | Processing log file /tmp/tmpy569t6rv/runtests_leaks_1186.log for scope /event-timing
[task 2022-11-15T11:46:48.674Z] 11:46:48     INFO - TEST-INFO | leakcheck | default process: leak threshold set at 16000 bytes
[task 2022-11-15T11:46:48.674Z] 11:46:48     INFO - TEST-INFO | leakcheck | tab process: leak threshold set at 10000 bytes
[task 2022-11-15T11:46:48.675Z] 11:46:48     INFO - TEST-INFO | leakcheck | gmplugin process: leak threshold set at 20000 bytes
[task 2022-11-15T11:46:48.676Z] 11:46:48     INFO - TEST-INFO | leakcheck | gpu process: leak threshold set at 10000 bytes
[task 2022-11-15T11:46:48.676Z] 11:46:48     INFO - TEST-INFO | leakcheck | vr process: leak threshold set at 0 bytes
[task 2022-11-15T11:46:48.677Z] 11:46:48     INFO - TEST-INFO | leakcheck | rdd process: leak threshold set at 400 bytes
[task 2022-11-15T11:46:48.677Z] 11:46:48     INFO - TEST-INFO | leakcheck | socket process: leak threshold set at 0 bytes
[task 2022-11-15T11:46:48.678Z] 11:46:48     INFO - TEST-INFO | leakcheck | sandboxbroker process: leak threshold set at 0 bytes
[task 2022-11-15T11:46:48.678Z] 11:46:48     INFO - TEST-INFO | leakcheck | forkserver process: leak threshold set at 0 bytes
[task 2022-11-15T11:46:48.679Z] 11:46:48     INFO - TEST-INFO | leakcheck | utility process: leak threshold set at 0 bytes
[task 2022-11-15T11:46:48.679Z] 11:46:48     INFO - leakcheck | Processing leak log file /tmp/tmpy569t6rv/runtests_leaks_1186.log
[task 2022-11-15T11:46:48.680Z] 11:46:48     INFO - TEST-PASS | leakcheck | default no leaks detected!

Comment 1

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Sean, please identify what started these failures or redirect the request. Push log last good to first bad build: https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=20e2590324e26b5ebc2f86ade34286967e0a58a8&tochange=8495494c57f82b71854b362bfbd40f9998933908

Comment 2

[Intermittent Failures Robot]

44 failures in 686 pushes (0.064 failures/push) were associated with this bug yesterday.

Repository breakdown:

• try: 44

Platform and build breakdown:

• linux1804-64-qr: 15
  • debug: 15
• macosx1015-64-qr: 1
  • debug: 1
• windows10-64-2004-qr: 4
  • debug: 4
• linux1804-64-asan-qr: 2
  • opt: 2
• linux1804-32-shippable-qr: 6
  • opt: 6
• linux1804-64-devedition-qr: 2
  • opt: 2
• linux1804-64-shippable-qr: 2
  • opt: 2
• windows10-32-2004-shippable-qr: 2
  • opt: 2
• windows10-64-2004-shippable-qr: 2
  • opt: 2
• windows10-64-2004-devedition-qr: 2
  • opt: 2
• windows10-32-2004-qr: 2
  • debug: 2
• android-em-7-0-x86_64-shippable-qr: 2
  • opt: 2
• android-em-7-0-x86_64-shippable-lite-qr: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1800643&startday=2022-11-15&endday=2022-11-15&tree=all

Comment 3

[Sean Feng [:sefeng]]

Okay, I don't see anything obvious that can cause this. I am running some try pushes to bisect this.

Comment 4

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Please reach out if you need helping hands with the bisection.

Comment 5

[Intermittent Failures Robot]

44 failures in 3589 pushes (0.012 failures/push) were associated with this bug in the last 7 days.

This is the #32 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• try: 44

Platform and build breakdown:

• linux1804-64-qr: 15
  • debug: 15
• macosx1015-64-qr: 1
  • debug: 1
• windows10-32-2004-qr: 2
  • debug: 2
• windows10-64-2004-qr: 4
  • debug: 4
• linux1804-64-asan-qr: 2
  • opt: 2
• linux1804-64-shippable-qr: 2
  • opt: 2
• linux1804-64-devedition-qr: 2
  • opt: 2
• linux1804-32-shippable-qr: 6
  • opt: 6
• windows10-32-2004-shippable-qr: 2
  • opt: 2
• windows10-64-2004-devedition-qr: 2
  • opt: 2
• windows10-64-2004-shippable-qr: 2
  • opt: 2
• android-em-7-0-x86_64-shippable-qr: 2
  • opt: 2
• android-em-7-0-x86_64-shippable-lite-qr: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1800643&startday=2022-11-14&endday=2022-11-20&tree=all

Comment 6

[Sean Feng [:sefeng]]

Looks like 0f30447455dcbf2c99259f763a443f79fa521757 Kagami Sascha Rosylight — Bug 1799565 - Allow pointer events on disabled form elements on Nightly r=smaug is the one.

Try push without this commit doesn't have the failures, and starts to fail with this commit.

It's not clear to me about how this can make the test fails. The test does uses the pointerdown event, however AFAIC, the Beta behaviour should be unchanged.

Kagami, do you notice something?

Comment 7

[Kagami Rosylight [:saschanaz] (they/them)]

It should have already been fixed by https://bugzilla.mozilla.org/show_bug.cgi?id=1800772. Does this still happen on the latest build?

Comment 8

[Cosmin Sabou [:CosminS]]

No longer reproduces on today's beta-sim.

Comment 9

[Kagami Rosylight [:saschanaz] (they/them)]

Thanks, and sorry for the noise!