Closed Bug 1827620 Opened 2 years ago Closed 11 months ago

Intermittent /mediacapture-record/MediaRecorder-stop.html | single tracking bug

Categories

(Core :: Audio/Video: Recording, defect, P5)

defect

Tracking

()

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure, intermittent-testcase, Whiteboard: [retriggered])

Attachments

(1 obsolete file)

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

First occurrence, so far: backfill range and retriggers.

Whiteboard: [retriggered]

Could this be regressed by Bug 1823909? The backfill does not show that but I think this might be caused by that bug.
Hi Karl! Can you please take a look at this to see if statement above is true? ^
Thank you!

Flags: needinfo?(karlt)

(In reply to Iulian Moraru from comment #2)

Yes, bug 1823909 introduced the new failing subtest "MediaRecorder will fire only start and stop events in a basic recording flow". The inconsistency in results was initially marked for some builds, but others are also intermittently failing.

Based on the expected events and inconsistent slice logic, "Sequence element start is not included in stop" might imply that "start" was unexpectedly received after (instead of before) "ondataavailable".

If expected is set to [PASS, FAIL] for all platforms, then could that be overwritten by future wpt updates?

Flags: needinfo?(karlt)
Attachment #9383201 - Attachment is obsolete: true
Status: NEW → RESOLVED
Closed: 1 year ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 1 year ago11 months ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: