Filed by: nfay [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=412173043&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/Lq_-skj1S06xqeEjISPPlg/runs/0/artifacts/public/logs/live_backing.log
[task 2023-04-12T12:44:15.302Z] 12:44:15 INFO - TEST-PASS | /mediacapture-record/MediaRecorder-stop.html | MediaRecorder will fire start event even if stopped synchronously
[task 2023-04-12T12:44:15.302Z] 12:44:15 INFO - TEST-PASS | /mediacapture-record/MediaRecorder-stop.html | MediaRecorder will fire start event even if a track is removed synchronously
[task 2023-04-12T12:44:15.303Z] 12:44:15 INFO - TEST-UNEXPECTED-FAIL | /mediacapture-record/MediaRecorder-stop.html | MediaRecorder will fire only start and stop events in a basic recording flow. - assert_greater_than_equal: Sequence element start is not included in stop expected a number greater than or equal to 0 but got -1
[task 2023-04-12T12:44:15.303Z] 12:44:15 INFO - assertSequenceIn@http://web-platform.test:8000/mediacapture-record/MediaRecorder-stop.html:26:34
[task 2023-04-12T12:44:15.303Z] 12:44:15 INFO - @http://web-platform.test:8000/mediacapture-record/MediaRecorder-stop.html:161:25
[task 2023-04-12T12:44:15.303Z] 12:44:15 INFO - TEST-OK | /mediacapture-record/MediaRecorder-stop.html | took 2043ms
[task 2023-04-12T12:44:15.303Z] 12:44:15 INFO - PID 4210 | 1681303455293 Marionette INFO Stopped listening on port 45017
[task 2023-04-12T12:44:15.323Z] 12:44:15 INFO - PID 4210 | [Child 4322, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-04-12T12:44:15.324Z] 12:44:15 INFO - PID 4210 | [Child 4322, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-04-12T12:44:15.325Z] 12:44:15 INFO - PID 4210 | [Child 4322, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-04-12T12:44:15.327Z] 12:44:15 INFO - PID 4210 | [Child 4322, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-04-12T12:44:15.331Z] 12:44:15 INFO - PID 4210 | [Child 4322, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-04-12T12:44:15.332Z] 12:44:15 INFO - PID 4210 | [Child 4322, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-04-12T12:44:15.337Z] 12:44:15 INFO - PID 4210 | [Child 4322, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-04-12T12:44:15.484Z] 12:44:15 INFO - PID 4210 | WARNING: A blocker encountered an error while we were waiting.
[task 2023-04-12T12:44:15.484Z] 12:44:15 INFO - PID 4210 | Blocker: Waiting for ping task
[task 2023-04-12T12:44:15.485Z] 12:44:15 INFO - PID 4210 | Phase: TelemetryController: Waiting for pending ping activity
[task 2023-04-12T12:44:15.485Z] 12:44:15 INFO - PID 4210 | State: (none)
[task 2023-04-12T12:44:15.485Z] 12:44:15 INFO - PID 4210 | 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-04-12T12:44:15.485Z] 12:44:15 INFO - PID 4210 | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
[task 2023-04-12T12:44:15.489Z] 12:44:15 INFO - PID 4210 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-04-12T12:44:15.489Z] 12:44:15 INFO - PID 4210 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-04-12T12:44:15.489Z] 12:44:15 INFO - PID 4210 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-04-12T12:44:15.489Z] 12:44:15 INFO - PID 4210 | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-04-12T12:44:15.489Z] 12:44:15 INFO - PID 4210 | @resource://gre/modules/osfile.jsm:12:30
[task 2023-04-12T12:44:15.489Z] 12:44:15 INFO - PID 4210 | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-04-12T12:44:15.490Z] 12:44:15 INFO - PID 4210 | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:859:17
[task 2023-04-12T12:44:15.490Z] 12:44:15 INFO - PID 4210 | setup@resource://gre/modules/TelemetrySend.sys.mjs:799:18
[task 2023-04-12T12:44:15.491Z] 12:44:15 INFO - PID 4210 | setup@resource://gre/modules/TelemetrySend.sys.mjs:237:30
[task 2023-04-12T12:44:15.491Z] 12:44:15 INFO - PID 4210 | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:824:36
[task 2023-04-12T12:44:15.491Z] 12:44:15 INFO - PID 4210 | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-04-12T12:44:15.491Z] 12:44:15 INFO - PID 4210 | console.error: "TelemetryScheduler.shutdown - Already shut down"
[task 2023-04-12T12:44:15.497Z] 12:44:15 INFO - PID 4210 | WARNING: A blocker encountered an error while we were waiting.
[task 2023-04-12T12:44:15.497Z] 12:44:15 INFO - PID 4210 | Blocker: Waiting for ping task
[task 2023-04-12T12:44:15.498Z] 12:44:15 INFO - PID 4210 | Phase: TelemetryController: Waiting for pending ping activity
[task 2023-04-12T12:44:15.500Z] 12:44:15 INFO - PID 4210 | State: (none)
[task 2023-04-12T12:44:15.501Z] 12:44:15 INFO - PID 4210 | 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-04-12T12:44:15.502Z] 12:44:15 INFO - PID 4210 | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
[task 2023-04-12T12:44:15.502Z] 12:44:15 INFO - PID 4210 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-04-12T12:44:15.503Z] 12:44:15 INFO - PID 4210 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-04-12T12:44:15.503Z] 12:44:15 INFO - PID 4210 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-04-12T12:44:15.504Z] 12:44:15 INFO - PID 4210 | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-04-12T12:44:15.504Z] 12:44:15 INFO - PID 4210 | @resource://gre/modules/osfile.jsm:12:30
[task 2023-04-12T12:44:15.505Z] 12:44:15 INFO - PID 4210 | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-04-12T12:44:15.508Z] 12:44:15 INFO - PID 4210 | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:859:17
[task 2023-04-12T12:44:15.508Z] 12:44:15 INFO - PID 4210 | setup@resource://gre/modules/TelemetrySend.sys.mjs:799:18
[task 2023-04-12T12:44:15.508Z] 12:44:15 INFO - PID 4210 | setup@resource://gre/modules/TelemetrySend.sys.mjs:237:30
[task 2023-04-12T12:44:15.508Z] 12:44:15 INFO - PID 4210 | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:824:36
[task 2023-04-12T12:44:15.509Z] 12:44:15 INFO - PID 4210 | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-04-12T12:44:15.509Z] 12:44:15 INFO - PID 4210 | WARNING: A blocker encountered an error while we were waiting.
[task 2023-04-12T12:44:15.509Z] 12:44:15 INFO - PID 4210 | Blocker: TelemetryController: shutting down
[task 2023-04-12T12:44:15.509Z] 12:44:15 INFO - PID 4210 | Phase: profile-before-change-telemetry
[task 2023-04-12T12:44:15.510Z] 12:44:15 INFO - PID 4210 | 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-04-12T12:44:15.511Z] 12:44:15 INFO - PID 4210 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-04-12T12:44:15.511Z] 12:44:15 INFO - PID 4210 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-04-12T12:44:15.512Z] 12:44:15 INFO - PID 4210 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-04-12T12:44:15.513Z] 12:44:15 INFO - PID 4210 | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-04-12T12:44:15.513Z] 12:44:15 INFO - PID 4210 | @resource://gre/modules/osfile.jsm:12:30
[task 2023-04-12T12:44:15.514Z] 12:44:15 INFO - PID 4210 | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-04-12T12:44:15.514Z] 12:44:15 INFO - PID 4210 | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:859:17
[task 2023-04-12T12:44:15.515Z] 12:44:15 INFO - PID 4210 | setup@resource://gre/modules/TelemetrySend.sys.mjs:799:18
[task 2023-04-12T12:44:15.516Z] 12:44:15 INFO - PID 4210 | setup@resource://gre/modules/TelemetrySend.sys.mjs:237:30
[task 2023-04-12T12:44:15.516Z] 12:44:15 INFO - PID 4210 | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:824:36
[task 2023-04-12T12:44:15.517Z] 12:44:15 INFO - PID 4210 | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-04-12T12:44:15.517Z] 12:44:15 INFO - PID 4210 | 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-04-12T12:44:15.518Z] 12:44:15 INFO - PID 4210 | WARNING: addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:727:15
[task 2023-04-12T12:44:15.518Z] 12:44:15 INFO - PID 4210 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:523:26
[task 2023-04-12T12:44:15.519Z] 12:44:15 INFO - PID 4210 | addBlocker@resource://gre/modules/AsyncShutdown.sys.mjs:458:15
[task 2023-04-12T12:44:15.519Z] 12:44:15 INFO - PID 4210 | setupShutdown@resource://gre/modules/osfile/osfile_async_front.jsm:1548:28
[task 2023-04-12T12:44:15.520Z] 12:44:15 INFO - PID 4210 | @resource://gre/modules/osfile/osfile_async_front.jsm:1568:16
[task 2023-04-12T12:44:15.520Z] 12:44:15 INFO - PID 4210 | @resource://gre/modules/osfile.jsm:12:30
[task 2023-04-12T12:44:15.521Z] 12:44:15 INFO - PID 4210 | @resource://gre/modules/TelemetryStorage.sys.mjs:10:28
[task 2023-04-12T12:44:15.521Z] 12:44:15 INFO - PID 4210 | _checkPendingPings@resource://gre/modules/TelemetrySend.sys.mjs:859:17
[task 2023-04-12T12:44:15.521Z] 12:44:15 INFO - PID 4210 | setup@resource://gre/modules/TelemetrySend.sys.mjs:799:18
[task 2023-04-12T12:44:15.522Z] 12:44:15 INFO - PID 4210 | setup@resource://gre/modules/TelemetrySend.sys.mjs:237:30
[task 2023-04-12T12:44:15.522Z] 12:44:15 INFO - PID 4210 | setupTelemetry/this._delayedInitTask<@resource://gre/modules/TelemetryControllerParent.sys.mjs:824:36
[task 2023-04-12T12:44:15.523Z] 12:44:15 INFO - PID 4210 | observe@resource://gre/modules/AsyncShutdown.sys.mjs:576:16
[task 2023-04-12T12:44:15.523Z] 12:44:15 INFO - PID 4210 | 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-04-12T12:44:15.524Z] 12:44:15 INFO - PID 4210 | 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-04-12T12:44:15.524Z] 12:44:15 INFO - PID 4210 | 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-04-12T12:44:15.525Z] 12:44:15 INFO - PID 4210 | 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-04-12T12:44:15.526Z] 12:44:15 INFO - PID 4210 | 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-04-12T12:44:15.742Z] 12:44:15 INFO - Browser exited with return code 0
[task 2023-04-12T12:44:15.745Z] 12:44:15 INFO - Closing logging queue
[task 2023-04-12T12:44:15.746Z] 12:44:15 INFO - queue closed
[task 2023-04-12T12:44:15.754Z] 12:44:15 INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox --marionette about:blank -profile /tmp/tmpm72kdd51
[task 2023-04-12T12:44:15.772Z] 12:44:15 INFO - PID 4747 | ATTENTION: default value of option mesa_glthread overridden by environment.
[task 2023-04-12T12:44:15.773Z] 12:44:15 INFO - PID 4747 | ATTENTION: default value of option mesa_glthread overridden by environment.
[task 2023-04-12T12:44:15.773Z] 12:44:15 INFO - PID 4747 | 1681303373070 Marionette INFO Marionette enabled
[task 2023-04-12T12:44:15.774Z] 12:44:15 INFO - PID 4747 | 1681303373072 Marionette INFO Listening on port 41232
[task 2023-04-12T12:44:15.779Z] 12:44:15 INFO - PID 4747 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-04-12T12:44:15.779Z] 12:44:15 INFO - PID 4747 | console.error: ({})
[task 2023-04-12T12:44:15.779Z] 12:44:15 INFO - PID 4747 | [Child 4856, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-04-12T12:44:15.779Z] 12:44:15 INFO - PID 4747 | [Child 4856, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-04-12T12:44:15.779Z] 12:44:15 INFO - PID 4747 | [ERROR glean_core] Error setting metrics feature config: Json(Error("EOF while parsing a value", line: 1, column: 0))
[task 2023-04-12T12:44:15.779Z] 12:44:15 INFO - PID 4747 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-04-12T12:44:15.779Z] 12:44:15 INFO - PID 4747 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-04-12T12:44:15.779Z] 12:44:15 INFO - PID 4747 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-04-12T12:44:15.779Z] 12:44:15 INFO - PID 4747 | ALSA lib seq_hw.c:466:(snd_seq_hw_open) open /dev/snd/seq failed: No such file or directory
[task 2023-04-12T12:44:15.780Z] 12:44:15 INFO - PID 4747 | console.error: (new Error("Polling for changes failed: Unexpected content-type \"text/plain;charset=US-ASCII\".", "resource://services-settings/remote-settings.sys.mjs", 324))
[task 2023-04-12T12:44:15.780Z] 12:44:15 INFO - Starting runner
[task 2023-04-12T12:44:16.343Z] 12:44:16 INFO - TEST-START | /mediacapture-record/idlharness.window.html
Description
•