1808841 - High freq /resource-timing/response-status-code.html | This test validates the response status of resources. 272 - promise_test: Unhandled rejection with value: object "TypeError: can't access property "responseStatus", entry is undefined"

Reporter

Description

•

1 year ago

treeherder

Filed by: ctuns [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=401543459&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/fBxEIMaaTBGl-20nty8F-A/runs/0/artifacts/public/logs/live_backing.log

[task 2023-01-06T05:00:11.586Z] 05:00:11     INFO - TEST-FAIL | /resource-timing/response-status-code.html | This test validates the response status of resources. 271 - promise_test: Unhandled rejection with value: object "TypeError: can't access property "responseStatus", entry is undefined"
[task 2023-01-06T05:00:11.587Z] 05:00:11     INFO - TEST-UNEXPECTED-FAIL | /resource-timing/response-status-code.html | This test validates the response status of resources. 272 - promise_test: Unhandled rejection with value: object "TypeError: can't access property "responseStatus", entry is undefined"
[task 2023-01-06T05:00:11.587Z] 05:00:11     INFO - TEST-INFO | expected TIMEOUT
[task 2023-01-06T05:00:11.588Z] 05:00:11     INFO - 
[task 2023-01-06T05:00:11.588Z] 05:00:11     INFO - TEST-UNEXPECTED-TIMEOUT | /resource-timing/response-status-code.html | This test validates the response status of resources. 273 - Test timed out
[task 2023-01-06T05:00:11.588Z] 05:00:11     INFO - TEST-INFO | expected NOTRUN
[task 2023-01-06T05:00:11.597Z] 05:00:11     INFO - ..........................
[task 2023-01-06T05:00:11.597Z] 05:00:11     INFO - TEST-TIMEOUT | /resource-timing/response-status-code.html | took 180887ms
[task 2023-01-06T05:00:11.598Z] 05:00:11     INFO - PID 22803 | 1672981211536	Marionette	INFO	Stopped listening on port 50033
[task 2023-01-06T05:00:11.599Z] 05:00:11     INFO - PID 22803 | [Child 22908, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:44
[task 2023-01-06T05:00:11.600Z] 05:00:11     INFO - PID 22803 | [Child 22908, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:44
[task 2023-01-06T05:00:11.601Z] 05:00:11     INFO - PID 22803 | [Child 22908, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:44
[task 2023-01-06T05:00:11.602Z] 05:00:11     INFO - PID 22803 | [Child 22908, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:44
[task 2023-01-06T05:00:11.608Z] 05:00:11     INFO - PID 22803 | [Child 22908, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:44
[task 2023-01-06T05:00:11.609Z] 05:00:11     INFO - PID 22803 | [Child 22908, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:44
[task 2023-01-06T05:00:11.615Z] 05:00:11     INFO - PID 22803 | [Child 22908, Main Thread] WARNING: '!CanSend() || !mManager || !mManager->CanSend()', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:44
[task 2023-01-06T05:00:11.717Z] 05:00:11     INFO - PID 22803 | [Parent 22803, Compositor] WARNING: Possibly dropping task posted to updater thread: file /builds/worker/checkouts/gecko/gfx/layers/apz/src/APZUpdater.cpp:371
[task 2023-01-06T05:00:11.733Z] 05:00:11     INFO - PID 22803 | [Parent 22803, 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-06T05:00:11.736Z] 05:00:11     INFO - PID 22803 | [Parent 22803, 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:1927
[task 2023-01-06T05:00:11.737Z] 05:00:11     INFO - PID 22803 | [Parent 22803, 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-06T05:00:11.755Z] 05:00:11     INFO - PID 22803 | [Parent 22803, 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:1927
[task 2023-01-06T05:00:11.755Z] 05:00:11     INFO - PID 22803 | [Parent 22803, 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-06T05:00:11.759Z] 05:00:11     INFO - PID 22803 | [Parent 22803, 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:1927
[task 2023-01-06T05:00:11.776Z] 05:00:11     INFO - PID 22803 | [Parent 22803, Socket Thread] WARNING: cannot post event if not initialized: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnectionMgr.cpp:204
[task 2023-01-06T05:00:11.777Z] 05:00:11     INFO - PID 22803 | [Parent 22803, Socket Thread] WARNING: cannot post event if not initialized: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnectionMgr.cpp:204
[task 2023-01-06T05:00:11.777Z] 05:00:11     INFO - PID 22803 | [Parent 22803, Socket Thread] WARNING: cannot post event if not initialized: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnectionMgr.cpp:204
[task 2023-01-06T05:00:11.778Z] 05:00:11     INFO - PID 22803 | [Parent 22803, Socket Thread] WARNING: cannot post event if not initialized: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnectionMgr.cpp:204
[task 2023-01-06T05:00:11.778Z] 05:00:11     INFO - PID 22803 | [Parent 22803, Socket Thread] WARNING: cannot post event if not initialized: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnectionMgr.cpp:204
[task 2023-01-06T05:00:11.779Z] 05:00:11     INFO - PID 22803 | [Parent 22803, Socket Thread] WARNING: cannot post event if not initialized: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnectionMgr.cpp:204
[task 2023-01-06T05:00:11.779Z] 05:00:11     INFO - PID 22803 | [Parent 22803, Socket Thread] WARNING: cannot post event if not initialized: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnectionMgr.cpp:204
[task 2023-01-06T05:00:11.779Z] 05:00:11     INFO - PID 22803 | [Parent 22803, Socket Thread] WARNING: cannot post event if not initialized: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnectionMgr.cpp:204
[task 2023-01-06T05:00:11.780Z] 05:00:11     INFO - PID 22803 | [Parent 22803, Socket Thread] WARNING: cannot post event if not initialized: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnectionMgr.cpp:204
[task 2023-01-06T05:00:11.780Z] 05:00:11     INFO - PID 22803 | [Parent 22803, Socket Thread] WARNING: cannot post event if not initialized: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnectionMgr.cpp:204
[task 2023-01-06T05:00:11.781Z] 05:00:11     INFO - PID 22803 | [Parent 22803, Socket Thread] WARNING: cannot post event if not initialized: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnectionMgr.cpp:204
[task 2023-01-06T05:00:11.782Z] 05:00:11     INFO - PID 22803 | [Parent 22803, Socket Thread] WARNING: cannot post event if not initialized: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnectionMgr.cpp:204
[task 2023-01-06T05:00:11.782Z] 05:00:11     INFO - PID 22803 | [Parent 22803, Socket Thread] WARNING: cannot post event if not initialized: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnectionMgr.cpp:204
[task 2023-01-06T05:00:11.783Z] 05:00:11     INFO - PID 22803 | [Parent 22803, Socket Thread] WARNING: cannot post event if not initialized: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnectionMgr.cpp:204
[task 2023-01-06T05:00:11.783Z] 05:00:11     INFO - PID 22803 | [Parent 22803, Socket Thread] WARNING: cannot post event if not initialized: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnectionMgr.cpp:204
[task 2023-01-06T05:00:11.784Z] 05:00:11     INFO - PID 22803 | [Parent 22803, Socket Thread] WARNING: cannot post event if not initialized: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnectionMgr.cpp:204
[task 2023-01-06T05:00:11.785Z] 05:00:11     INFO - PID 22803 | [Parent 22803, Socket Thread] WARNING: cannot post event if not initialized: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnectionMgr.cpp:204
[task 2023-01-06T05:00:11.785Z] 05:00:11     INFO - PID 22803 | [Parent 22803, Socket Thread] WARNING: cannot post event if not initialized: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnectionMgr.cpp:204
[task 2023-01-06T05:00:11.786Z] 05:00:11     INFO - PID 22803 | [Parent 22803, Socket Thread] WARNING: cannot post event if not initialized: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnectionMgr.cpp:204
[task 2023-01-06T05:00:11.787Z] 05:00:11     INFO - PID 22803 | [Parent 22803, Socket Thread] WARNING: cannot post event if not initialized: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnectionMgr.cpp:204
[task 2023-01-06T05:00:11.833Z] 05:00:11     INFO - PID 22803 | [Child 22948, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3384
[task 2023-01-06T05:00:11.837Z] 05:00:11     INFO - PID 22803 | [Child 22948, Main Thread] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file /builds/worker/workspace/obj-build/dist/include/mozilla/Preferences.h:129
[task 2023-01-06T05:00:11.845Z] 05:00:11     INFO - PID 22803 | [Child 22948, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4663
[task 2023-01-06T05:00:11.898Z] 05:00:11     INFO - PID 22803 | [Child 22908, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3384
[task 2023-01-06T05:00:11.903Z] 05:00:11     INFO - PID 22803 | [Child 22908, Main Thread] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file /builds/worker/workspace/obj-build/dist/include/mozilla/Preferences.h:129
[task 2023-01-06T05:00:11.905Z] 05:00:11     INFO - PID 22803 | [Child 27780, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3384
[task 2023-01-06T05:00:11.909Z] 05:00:11     INFO - PID 22803 | [Child 27780, Main Thread] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file /builds/worker/workspace/obj-build/dist/include/mozilla/Preferences.h:129
[task 2023-01-06T05:00:11.915Z] 05:00:11     INFO - PID 22803 | [Child 22908, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4663
[task 2023-01-06T05:00:11.917Z] 05:00:11     INFO - PID 22803 | [Child 27780, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4663
[task 2023-01-06T05:00:12.225Z] 05:00:12     INFO - PID 22803 | [Parent 22803, 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:1927
[task 2023-01-06T05:00:12.235Z] 05:00:12     INFO - PID 22803 | [Child 27897, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3384
[task 2023-01-06T05:00:12.237Z] 05:00:12     INFO - PID 22803 | [Child 27897, Main Thread] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file /builds/worker/workspace/obj-build/dist/include/mozilla/Preferences.h:129
[task 2023-01-06T05:00:12.247Z] 05:00:12     INFO - PID 22803 | [Child 27897, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4663
[task 2023-01-06T05:00:12.263Z] 05:00:12     INFO - PID 22803 | [Parent 22803, IPDL Background] WARNING: quota manager shutdown step: '0.000006s: startCrashBrowserTimer', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-06T05:00:12.263Z] 05:00:12     INFO - PID 22803 | [Parent 22803, IPDL Background] WARNING: quota manager shutdown step: '0.000052s: initiateShutdownWorkThreads', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-06T05:00:12.264Z] 05:00:12     INFO - PID 22803 | [Parent 22803, IPDL Background] WARNING: idb: '0.000062s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-06T05:00:12.264Z] 05:00:12     INFO - PID 22803 | [Parent 22803, IPDL Background] WARNING: cache: '0.000074s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-06T05:00:12.265Z] 05:00:12     INFO - PID 22803 | [Parent 22803, IPDL Background] WARNING: sdb: '0.000082s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-06T05:00:12.265Z] 05:00:12     INFO - PID 22803 | [Parent 22803, IPDL Background] WARNING: fs: '0.000096s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-06T05:00:12.268Z] 05:00:12     INFO - PID 22803 | [Parent 22803, IPDL Background] WARNING: ls: '0.000103s: starting', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-06T05:00:12.268Z] 05:00:12     INFO - PID 22803 | [Parent 22803, IPDL Background] WARNING: quota manager shutdown step: '0.000114s: startKillActorsTimer', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-06T05:00:12.269Z] 05:00:12     INFO - PID 22803 | [Parent 22803, IPDL Background] WARNING: idb: '0.002368s: Live database entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-06T05:00:12.269Z] 05:00:12     INFO - PID 22803 | [Parent 22803, IPDL Background] WARNING: idb: '0.002394s: gLiveDatabaseHashtable entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-06T05:00:12.269Z] 05:00:12     INFO - PID 22803 | [Parent 22803, IPDL Background] WARNING: idb: '0.002477s: Live database entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-06T05:00:12.270Z] 05:00:12     INFO - PID 22803 | [Parent 22803, IPDL Background] WARNING: idb: '0.002522s: Live database entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-06T05:00:12.271Z] 05:00:12     INFO - PID 22803 | [Parent 22803, IPDL Background] WARNING: idb: '0.002529s: gLiveDatabaseHashtable entry removed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-06T05:00:12.271Z] 05:00:12     INFO - PID 22803 | [Parent 22803, IPDL Background] WARNING: quota manager shutdown step: '0.006500s: stopKillActorsTimer', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-06T05:00:12.271Z] 05:00:12     INFO - PID 22803 | [Parent 22803, IPDL Background] WARNING: quota manager shutdown step: '0.006540s: shutdownAndJoinWorkThreads', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-06T05:00:12.271Z] 05:00:12     INFO - PID 22803 | [Parent 22803, IPDL Background] WARNING: idb: '0.006566s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-06T05:00:12.271Z] 05:00:12     INFO - PID 22803 | [Parent 22803, IPDL Background] WARNING: cache: '0.006634s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-06T05:00:12.272Z] 05:00:12     INFO - PID 22803 | [Parent 22803, IPDL Background] WARNING: sdb: '0.006641s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-06T05:00:12.272Z] 05:00:12     INFO - PID 22803 | [Parent 22803, IPDL Background] WARNING: fs: '0.006647s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-06T05:00:12.274Z] 05:00:12     INFO - PID 22803 | [Parent 22803, IPDL Background] WARNING: ls: '0.006654s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-06T05:00:12.275Z] 05:00:12     INFO - PID 22803 | [Parent 22803, IPDL Background] WARNING: quota manager shutdown step: '0.006668s: shutdownAndJoinIOThread', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-06T05:00:12.275Z] 05:00:12     INFO - PID 22803 | [Parent 22803, IPDL Background] WARNING: quota manager shutdown step: '0.007028s: invalidatePendingDirectoryLocks', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-06T05:00:12.276Z] 05:00:12     INFO - PID 22803 | [Parent 22803, IPDL Background] WARNING: quota manager shutdown step: '0.007038s: stopCrashBrowserTimer', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3298
[task 2023-01-06T05:00:12.325Z] 05:00:12     INFO - PID 22803 | WARNING: A blocker encountered an error while we were waiting.
[task 2023-01-06T05:00:12.326Z] 05:00:12     INFO - PID 22803 |           Blocker:  Waiting for ping task
[task 2023-01-06T05:00:12.327Z] 05:00:12     INFO - PID 22803 |           Phase: TelemetryController: Waiting for pending ping activity
[task 2023-01-06T05:00:12.328Z] 05:00:12     INFO - PID 22803 |           State: (none)
[task 2023-01-06T05:00:12.329Z] 05:00:12     INFO - PID 22803 | 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-06T05:00:12.329Z] 05:00:12     INFO - PID 22803 | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
[task 2023-01-06T05:00:12.330Z] 05:00:12     INFO - PID 22803 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-01-06T05:00:12.331Z] 05:00:12     INFO - PID 22803 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-01-06T05:00:12.331Z] 05:00:12     INFO - PID 22803 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-01-06T05:00:12.332Z] 05:00:12     INFO - PID 22803 | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-01-06T05:00:12.332Z] 05:00:12     INFO - PID 22803 | @resource://gre/modules/osfile.jsm:12:30
[task 2023-01-06T05:00:12.333Z] 05:00:12     INFO - PID 22803 | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-01-06T05:00:12.333Z] 05:00:12     INFO - PID 22803 | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:863:17
[task 2023-01-06T05:00:12.334Z] 05:00:12     INFO - PID 22803 | setup@resource://gre/modules/TelemetrySend.sys.mjs:803:18
[task 2023-01-06T05:00:12.334Z] 05:00:12     INFO - PID 22803 | setup@resource://gre/modules/TelemetrySend.sys.mjs:241:30
[task 2023-01-06T05:00:12.335Z] 05:00:12     INFO - PID 22803 | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:829:36
[task 2023-01-06T05:00:12.336Z] 05:00:12     INFO - PID 22803 | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-01-06T05:00:12.373Z] 05:00:12     INFO - PID 22803 | WARNING: A blocker encountered an error while we were waiting.
[task 2023-01-06T05:00:12.374Z] 05:00:12     INFO - PID 22803 |           Blocker:  Waiting for ping task
[task 2023-01-06T05:00:12.375Z] 05:00:12     INFO - PID 22803 |           Phase: TelemetryController: Waiting for pending ping activity
[task 2023-01-06T05:00:12.375Z] 05:00:12     INFO - PID 22803 |           State: (none)
[task 2023-01-06T05:00:12.376Z] 05:00:12     INFO - PID 22803 | 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-06T05:00:12.377Z] 05:00:12     INFO - PID 22803 | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
[task 2023-01-06T05:00:12.377Z] 05:00:12     INFO - PID 22803 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-01-06T05:00:12.378Z] 05:00:12     INFO - PID 22803 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-01-06T05:00:12.380Z] 05:00:12     INFO - PID 22803 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-01-06T05:00:12.381Z] 05:00:12     INFO - PID 22803 | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-01-06T05:00:12.381Z] 05:00:12     INFO - PID 22803 | @resource://gre/modules/osfile.jsm:12:30
[task 2023-01-06T05:00:12.382Z] 05:00:12     INFO - PID 22803 | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-01-06T05:00:12.383Z] 05:00:12     INFO - PID 22803 | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:863:17
[task 2023-01-06T05:00:12.383Z] 05:00:12     INFO - PID 22803 | setup@resource://gre/modules/TelemetrySend.sys.mjs:803:18
[task 2023-01-06T05:00:12.384Z] 05:00:12     INFO - PID 22803 | setup@resource://gre/modules/TelemetrySend.sys.mjs:241:30
[task 2023-01-06T05:00:12.384Z] 05:00:12     INFO - PID 22803 | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:829:36
[task 2023-01-06T05:00:12.385Z] 05:00:12     INFO - PID 22803 | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-01-06T05:00:12.386Z] 05:00:12     INFO - PID 22803 | WARNING: A blocker encountered an error while we were waiting.
[task 2023-01-06T05:00:12.386Z] 05:00:12     INFO - PID 22803 |           Blocker:  TelemetryController: shutting down
[task 2023-01-06T05:00:12.387Z] 05:00:12     INFO - PID 22803 |           Phase: profile-before-change-telemetry
[task 2023-01-06T05:00:12.388Z] 05:00:12     INFO - PID 22803 |           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-06T05:00:12.388Z] 05:00:12     INFO - PID 22803 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-01-06T05:00:12.389Z] 05:00:12     INFO - PID 22803 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-01-06T05:00:12.389Z] 05:00:12     INFO - PID 22803 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-01-06T05:00:12.390Z] 05:00:12     INFO - PID 22803 | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-01-06T05:00:12.392Z] 05:00:12     INFO - PID 22803 | @resource://gre/modules/osfile.jsm:12:30
[task 2023-01-06T05:00:12.392Z] 05:00:12     INFO - PID 22803 | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-01-06T05:00:12.392Z] 05:00:12     INFO - PID 22803 | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:863:17
[task 2023-01-06T05:00:12.393Z] 05:00:12     INFO - PID 22803 | setup@resource://gre/modules/TelemetrySend.sys.mjs:803:18
[task 2023-01-06T05:00:12.393Z] 05:00:12     INFO - PID 22803 | setup@resource://gre/modules/TelemetrySend.sys.mjs:241:30
[task 2023-01-06T05:00:12.393Z] 05:00:12     INFO - PID 22803 | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:829:36
[task 2023-01-06T05:00:12.393Z] 05:00:12     INFO - PID 22803 | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-01-06T05:00:12.394Z] 05:00:12     INFO - PID 22803 | 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-06T05:00:12.394Z] 05:00:12     INFO - PID 22803 | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
[task 2023-01-06T05:00:12.399Z] 05:00:12     INFO - PID 22803 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-01-06T05:00:12.399Z] 05:00:12     INFO - PID 22803 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-01-06T05:00:12.399Z] 05:00:12     INFO - PID 22803 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-01-06T05:00:12.399Z] 05:00:12     INFO - PID 22803 | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-01-06T05:00:12.399Z] 05:00:12     INFO - PID 22803 | @resource://gre/modules/osfile.jsm:12:30
[task 2023-01-06T05:00:12.399Z] 05:00:12     INFO - PID 22803 | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-01-06T05:00:12.399Z] 05:00:12     INFO - PID 22803 | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:863:17
[task 2023-01-06T05:00:12.400Z] 05:00:12     INFO - PID 22803 | setup@resource://gre/modules/TelemetrySend.sys.mjs:803:18
[task 2023-01-06T05:00:12.400Z] 05:00:12     INFO - PID 22803 | setup@resource://gre/modules/TelemetrySend.sys.mjs:241:30
[task 2023-01-06T05:00:12.400Z] 05:00:12     INFO - PID 22803 | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:829:36
[task 2023-01-06T05:00:12.400Z] 05:00:12     INFO - PID 22803 | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-01-06T05:00:12.400Z] 05:00:12     INFO - PID 22803 | 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-06T05:00:12.401Z] 05:00:12     INFO - PID 22803 | 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-06T05:00:12.401Z] 05:00:12     INFO - PID 22803 | 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-06T05:00:12.402Z] 05:00:12     INFO - PID 22803 | 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-06T05:00:12.407Z] 05:00:12     INFO - PID 22803 | 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-06T05:00:12.408Z] 05:00:12     INFO - PID 22803 | [Parent 22803, 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-06T05:00:12.421Z] 05:00:12     INFO - PID 22803 | [Parent 22803, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.cpp:209
[task 2023-01-06T05:00:12.510Z] 05:00:12     INFO - PID 28643 | (stun/INFO) STUN-CLIENT(consent): Received response; processing
[task 2023-01-06T05:00:12.511Z] 05:00:12     INFO - PID 28643 | (ice/INFO) ICE(PC:{7b456a1f-499d-4175-817b-1c4a5b166610} 1672981163040588 (id=25769803778 url=https://web-platform.test:8443/webrtc/RTCPeerConnec)/STREAM(PC:{7b456a1f-499d-4175-817b-1c4a5b166610} 1672981163040588 (id=25769803778 url=https://web-platform.test:8443/webrtc/RTCPeerConnec transport-id=transport_0 - ea9924b2:ad4360686eb782a8bcfa46d43e3ce320)/COMP(1): Consent refreshed
[task 2023-01-06T05:00:13.189Z] 05:00:13     INFO - PID 22803 | [Parent 22803, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3384
[task 2023-01-06T05:00:13.220Z] 05:00:13     INFO - PID 22803 | [Parent 22803, Main Thread] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file /builds/worker/workspace/obj-build/dist/include/mozilla/Preferences.h:129
[task 2023-01-06T05:00:13.244Z] 05:00:13     INFO - PID 22803 | [Parent 22803, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4663
[task 2023-01-06T05:00:13.265Z] 05:00:13     INFO - Browser exited with return code 0
[task 2023-01-06T05:00:13.265Z] 05:00:13     INFO - PROCESS LEAKS /tmp/tmplwvwxp67/runtests_leaks_1159.log
[task 2023-01-06T05:00:13.265Z] 05:00:13     INFO - leakcheck | Processing log file /tmp/tmplwvwxp67/runtests_leaks_1159.log for scope /resource-timing
[task 2023-01-06T05:00:13.266Z] 05:00:13     INFO - TEST-INFO | leakcheck | default process: leak threshold set at 51200 bytes
[task 2023-01-06T05:00:13.266Z] 05:00:13     INFO - TEST-INFO | leakcheck | tab process: leak threshold set at 10000 bytes
[task 2023-01-06T05:00:13.267Z] 05:00:13     INFO - TEST-INFO | leakcheck | gmplugin process: leak threshold set at 20000 bytes
[task 2023-01-06T05:00:13.267Z] 05:00:13     INFO - TEST-INFO | leakcheck | gpu process: leak threshold set at 10000 bytes
[task 2023-01-06T05:00:13.268Z] 05:00:13     INFO - TEST-INFO | leakcheck | vr process: leak threshold set at 0 bytes
[task 2023-01-06T05:00:13.268Z] 05:00:13     INFO - TEST-INFO | leakcheck | rdd process: leak threshold set at 400 bytes
[task 2023-01-06T05:00:13.268Z] 05:00:13     INFO - TEST-INFO | leakcheck | socket process: leak threshold set at 0 bytes
[task 2023-01-06T05:00:13.269Z] 05:00:13     INFO - TEST-INFO | leakcheck | sandboxbroker process: leak threshold set at 0 bytes
[task 2023-01-06T05:00:13.270Z] 05:00:13     INFO - TEST-INFO | leakcheck | forkserver process: leak threshold set at 0 bytes
[task 2023-01-06T05:00:13.270Z] 05:00:13     INFO - TEST-INFO | leakcheck | utility process: leak threshold set at 0 bytes
[task 2023-01-06T05:00:13.271Z] 05:00:13     INFO - leakcheck | Processing leak log file /tmp/tmplwvwxp67/runtests_leaks_1159_tab_pid26972.log
[task 2023-01-06T05:00:13.271Z] 05:00:13     INFO - TEST-PASS | leakcheck | tab no leaks detected!

BugBot [:suhaib / :marco/ :calixte]

Comment 1

•

1 year ago

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

status-firefox108: --- → unaffected

status-firefox109: --- → unaffected

status-firefox110: --- → affected

status-firefox-esr102: --- → unaffected

Comment hidden (Intermittent Failures Robot)

Cosmin Sabou [:CosminS]

Comment 4

•

1 year ago

Frank, could you have a look over these failures? The subtests in question look to be 271, 272, 273 and 274.

Flags: needinfo?(fdoty)

Frank Doty [:fdoty]

Comment 5

•

1 year ago

Reviewing this ticket and will post an update shortly

Flags: needinfo?(fdoty)

Frank Doty [:fdoty]

Comment 6

•

1 year ago

:sefeng, do you happen to have any opinions on the above failures? We're not sure if this is an actual problem with the perf code or some echo bug

Flags: needinfo?(sefeng)

Sean Feng [:sefeng]

Assignee

Comment 7

•

1 year ago

So the first thing is we don't have response code implemented in resource timing, so these test are not meant to be passing, the bug for implementing it is bug 1796785.

Secondly, this particular subset is being flaky because the resource timing buffer is going to be full while running this test (it'll create a lot of subtests and each of them is going to create an entry), so instead of returning an entry that doesn't have response code, it times out.

I am trying to update the test to fix the resource timing buffer full issue, so the test is not going to be flaky anymore.

Sean Feng [:sefeng]

Assignee

Comment 8

•

1 year ago

Attached file Bug 1808841 - Make resource timing entires always be queued regardless the size of the buffer r=valentin — Details

Somehow we have a bug in Gecko such that if the resource timing buffer
is full, no further resource entries will be queued unless you clear
the clear or increase the buffer size. This is wrong because the spec
specifies the entry should always be queued regardless the size of
the buffer.

Spec: https://w3c.github.io/resource-timing/#dfn-mark-resource-timing

Phabricator Automation

Updated

•

1 year ago

Assignee: nobody → sefeng

Status: NEW → ASSIGNED

Sean Feng [:sefeng]

Assignee

Comment 9

•

1 year ago

Secondly, this particular subset is being flaky because the resource timing buffer is going to be full while running this test (it'll create a lot of subtests and each of them is going to create an entry), so instead of returning an entry that doesn't have response code, it times out.

It turns out there's a bug in Gecko such that if the buffer size is full, further resource timing entries are not going to be queued. The buffer size should have no impact to the result of this test. The patch I attached to this bug is going to fix this.

Flags: needinfo?(sefeng)

Pulsebot

Comment 10

•

1 year ago

Pushed by sefeng@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/a2c7e0b750e4
Make resource timing entires always be queued regardless the size of the buffer r=valentin

Web Platform Test Sync Bot (Matrix: #interop:mozilla.org)

Comment 11

•

1 year ago

Created web-platform-tests PR https://github.com/web-platform-tests/wpt/pull/37939 for changes under testing/web-platform/tests

Treeherder Bug Filer

Reporter

Updated

•

1 year ago

Regressions: 1810187

Iulian Moraru

Comment 12

•

1 year ago

bugherder

https://hg.mozilla.org/mozilla-central/rev/a2c7e0b750e4

Status: ASSIGNED → RESOLVED

Closed: 1 year ago

status-firefox110: affected → fixed

Resolution: --- → FIXED

Target Milestone: --- → 110 Branch

Sandor Molnar[:smolnar]

Updated

•

1 year ago

Regressions: 1810295

Web Platform Test Sync Bot (Matrix: #interop:mozilla.org)

Comment 13

•

1 year ago

Upstream PR merged by moz-wptsync-bot

Comment hidden (Intermittent Failures Robot)

Web Platform Test Sync Bot (Matrix: #interop:mozilla.org)

Comment 15

•

1 year ago

Created web-platform-tests PR https://github.com/web-platform-tests/wpt/pull/37981 for changes under testing/web-platform/tests

Iulian Moraru

Comment 16

•

1 year ago

Backout merged to central: https://bugherder.mozilla.org/?cset=36ca6ab936799a65a43aacb4ee1040ffd01af0df&tree=mozilla-central

Status: RESOLVED → REOPENED

status-firefox110: fixed → affected

Flags: needinfo?(sefeng)

Resolution: FIXED → ---

Target Milestone: 110 Branch → ---

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

Comment 17

•

1 year ago

When this relands, the change from bug 1810187 should be included.

Pulsebot

Comment 18

•

1 year ago

Pushed by sefeng@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/d7d2feb4a8ba
Make resource timing entires always be queued regardless the size of the buffer r=valentin

Sean Feng [:sefeng]

Assignee

Updated

•

1 year ago

Flags: needinfo?(sefeng)

BugBot [:suhaib / :marco/ :calixte]

Comment 19

•

1 year ago

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

status-firefox111: --- → affected

Marian-Vasile Laza

Comment 20

•

1 year ago

bugherder

https://hg.mozilla.org/mozilla-central/rev/d7d2feb4a8ba

Status: REOPENED → RESOLVED

Closed: 1 year ago → 1 year ago

status-firefox111: affected → fixed

Resolution: --- → FIXED

Target Milestone: --- → 111 Branch

BugBot [:suhaib / :marco/ :calixte]

Comment 21

•

1 year ago

The patch landed in nightly and beta is affected.
:sefeng, is this bug important enough to require an uplift?

If yes, please nominate the patch for beta approval.Also, don't forget to request an uplift for the patches in the regressions caused by this fix.
If no, please set status-firefox110 to wontfix.

For more information, please visit auto_nag documentation.

Flags: needinfo?(sefeng)

Sean Feng [:sefeng]

Assignee

Comment 22

•

1 year ago

No need for uplift.

status-firefox110: affected → wontfix

Flags: needinfo?(sefeng)

Sean Feng [:sefeng]

Assignee

Updated

•

1 year ago

Duplicate of this bug: 1809959