Closed Bug 1507193 Opened 6 years ago Closed 5 years ago

Firefox spews AbortError when scrubbing video

Categories

(Core :: Audio/Video: Playback, defect, P2)

Product:
Core
Component:
Audio/Video: Playback
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla70
Tracking Flags:
Tracking Status
firefox63 --- wontfix
firefox64 --- wontfix
firefox65 --- wontfix
firefox70 --- fixed

People

(Reporter: box123, Assigned: pehrsons)

References

(Blocks 1 open bug, Regression)

Details

(Keywords: regression)

Attachments

(1 file)

Bug 1507193 - Don't leave dangling js promises after seeking. r?jya
47 bytes, text/x-phabricator-request
Details | Review
User Agent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0 Steps to reproduce: Dragged progress bar handle along the progress bar in a video element. Example video player code: <!DOCTYPE html> <html> <head> <title>Video.js example</title> <meta charset='UTF-8'> <link href="http://vjs.zencdn.net/7.1.0/video-js.min.css" rel="stylesheet"> <script src="http://vjs.zencdn.net/7.1.0/video.min.js"></script> </head> <body> <video id="videojs_example" class="video-js vjs-default-skin" controls preload="auto" width=640 height=360 data-setup='{ "example_option": true, "controlBar": { "volumePanel": { "inline": false }} }'> <source src="http://commondatastorage.googleapis.com/gtv-videos-bucket/sample/BigBuckBunny.mp4" type="video/mp4"> </video> </body> </html> Actual results: Console repeatedly logged the following error message: AbortError: The operation was aborted. Expected results: No errors should be reported. Console should not be polluted with repeated AbortError.
I managed to reproduce this issue on Firefox 63.0.3, Firefox 64.0b10 and Nightly 65.0a1 (2018-11-19), on Windows 10, Ubuntu 16.04 and Mac OS.
Status: UNCONFIRMED → NEW
status-firefox63: --- → affected
status-firefox64: --- → affected
status-firefox65: --- → affected
Component: Untriaged → Audio/Video: Playback
Ever confirmed: true
OS: Unspecified → All
Product: Firefox → Core
Hardware: Unspecified → All
Version: 63 Branch → Trunk
This is similar to bug 1495904, but for when a seek is aborted [1]. [1] https://searchfox.org/mozilla-central/rev/b03a62c3c82316e733a3b09622c1cb7e59f64cc3/dom/html/HTMLMediaElement.cpp#8242,8249
Rank: 15
Priority: -- → P2
See Also: → 1495904
(In reply to Andreas Pehrson [:pehrsons] from comment #2) > This is similar to bug 1495904, but for when a seek is aborted [1]. I wonder why we need rejected promise to be verbose, especially when they aren't even visible by the JS
This also happens when rewinding audio elements by setting audio.currentTime. In my case, I was doing a Javascript excercise (code at https://github.com/wesbos/JavaScript30/tree/master/01%20-%20JavaScript%20Drum%20Kit) where you hit different keyboard keys to play audio files. Not only is rapidly playing back different audio elements very unresponsive in Firefox compared to for example Chrome or Edge, it also reports these AbortErrors in the console. This is with Firefox 64.0b10, Windows 10 b1809.

I don't see this anymore. Oddeirik, can you confirm on Nightly too?

Flags: needinfo?(oddeirik)

I'm still experencing the issue, only in Firefox Nightly, never on Firefox main or Chrome. I'm using Qunit.js to test a audio webcomponent, any scrubbing operation is plaguing my tests with « AbortError: The operation was aborted. »

Documentation :

Hello,

Running Firefox 68.0 on Android 9, I can reproduce this using a simple HTML5 audio-element. The rendered player behaves normal.

If I tap along the progress bar, the playback resumes at that position without any errors.

However, when I scrub or seek using the progress bar, playback stops, the errors "firefox AbortError: The operation was aborted." is logged and the player freezes.

On my desktop Firefox (68.0.1, Ubuntu 19.04 x64), the error occurs less often, and does not stop playback or freeze the player.

As a simple testcase, I provide this bare-minimum HTML page:
https://fwiep.nl/download/7a5fa6b0-69e9-4715-96b3-b360d7b06fa9/bug-1507193.html

Thanks,
FWieP

So these AbortErrors are from rejected internal Seek promises. We nowadays reported non-handled promise rejections, so these ones that we only use internally are also reported. I'll try to propagate things upward a bit, so we only create a js promise when it'll end up getting exposed.

Note that this most likely wouldn't affect any player freezes per the report in comment 7 though. I'll file a separate bug for that.

Flags: needinfo?(oddeirik)
See Also: → 1574546

(In reply to Andreas Pehrson [:pehrsons] from comment #5)

I don't see this anymore. Oddeirik, can you confirm on Nightly too?

Tested again on Firefox 69.0b12.

Sorry, thought I'd replied to this earlier! I am not seeing this anymore in the scenario I could reliably reproduce it in, at least. Playback is in general much more responsive as well.

Thank you!

Only SeekToNextFrame cares about promises, but prior to this patch the common
method HTMLMediaElement::Seek() would always return a promise.

When the caller was not SeekToNextFrame (e.g., SetCurrentTime, FastSeek), the
promise would end up not being exposed. When later rejected, we would catch
this and write an error to the js console.

This patch lifts the handling of the promise out of Seek() and into
SeekToNextFrame() so that we avoid creating promises that would not get exposed
to js.

Assignee: nobody → apehrson
Status: NEW → ASSIGNED
Pushed by pehrsons@gmail.com: https://hg.mozilla.org/integration/autoland/rev/dd79fbdfac8d Don't leave dangling js promises after seeking. r=jya

Backed out changeset dd79fbdfac8d (bug 1507193) for wpt failures at media-source/mediasource-seek-beyond-duration.html

Backout: https://hg.mozilla.org/integration/autoland/rev/b11b42a2c23909b96a12e5de13ea00913b7285de

Failure push: https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=dd79fbdfac8d9bb645fc954ca8969df73bf5c436

Failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=263887616&repo=autoland&lineNumber=32189

[task 2019-08-28T16:46:13.006Z] 16:46:13 INFO - TEST-START | /media-source/mediasource-seek-beyond-duration.html
[task 2019-08-28T16:46:13.010Z] 16:46:13 INFO - Closing window 125
[task 2019-08-28T16:46:13.135Z] 16:46:13 INFO - PID 19834 | ++DOCSHELL 0x7f56bc9ba000 == 1 [pid = 22883] [id = {f75c2592-52a5-40b8-a023-04f8897a3351}]
[task 2019-08-28T16:46:13.217Z] 16:46:13 INFO - PID 19834 | ++DOMWINDOW == 1 (0x7f56bc9d8f20) [pid = 22883] [serial = 1] [outer = (nil)]
[task 2019-08-28T16:46:13.219Z] 16:46:13 INFO - PID 19834 | ++DOMWINDOW == 2 (0x7f56bc924c00) [pid = 22883] [serial = 2] [outer = 0x7f56bc9d8f20]
[task 2019-08-28T16:46:13.264Z] 16:46:13 INFO - PID 19834 | --DOCSHELL 0x7f3cdc1b9000 == 0 [pid = 22819] [id = {8ac89052-f458-4f7c-9aee-079f33aac652}] [url = http://web-platform.test:8000/media-source/mediasource-removesourcebuffer.html]
[task 2019-08-28T16:46:13.329Z] 16:46:13 INFO - PID 19834 | --DOMWINDOW == 3 (0x7f3cdc002f20) [pid = 22819] [serial = 1] [outer = (nil)] [url = http://web-platform.test:8000/media-source/mediasource-removesourcebuffer.html]
[task 2019-08-28T16:46:13.329Z] 16:46:13 INFO - PID 19834 | --DOMWINDOW == 2 (0x7f3cdc123c00) [pid = 22819] [serial = 2] [outer = (nil)] [url = about:blank]
[task 2019-08-28T16:46:13.329Z] 16:46:13 INFO - PID 19834 | --DOMWINDOW == 1 (0x7f3cdc4af800) [pid = 22819] [serial = 3] [outer = (nil)] [url = about:blank]
[task 2019-08-28T16:46:13.329Z] 16:46:13 INFO - PID 19834 | --DOMWINDOW == 0 (0x7f3cdd6f0800) [pid = 22819] [serial = 4] [outer = (nil)] [url = http://web-platform.test:8000/media-source/mediasource-removesourcebuffer.html]
[task 2019-08-28T16:46:13.371Z] 16:46:13 INFO - PID 19834 | [Child 22819, Main Thread] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/workspace/build/src/xpcom/base/nsTraceRefcnt.cpp, line 198
[task 2019-08-28T16:46:13.371Z] 16:46:13 INFO - PID 19834 | [Child 22819, Main Thread] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/workspace/build/src/xpcom/base/nsTraceRefcnt.cpp, line 198
[task 2019-08-28T16:46:13.374Z] 16:46:13 INFO - PID 19834 | nsStringStats
[task 2019-08-28T16:46:13.374Z] 16:46:13 INFO - PID 19834 | => mAllocCount: 9578
[task 2019-08-28T16:46:13.374Z] 16:46:13 INFO - PID 19834 | => mReallocCount: 0
[task 2019-08-28T16:46:13.374Z] 16:46:13 INFO - PID 19834 | => mFreeCount: 9578
[task 2019-08-28T16:46:13.374Z] 16:46:13 INFO - PID 19834 | => mShareCount: 8712
[task 2019-08-28T16:46:13.374Z] 16:46:13 INFO - PID 19834 | => mAdoptCount: 578
[task 2019-08-28T16:46:13.375Z] 16:46:13 INFO - PID 19834 | => mAdoptFreeCount: 582
[task 2019-08-28T16:46:13.376Z] 16:46:13 INFO - PID 19834 | => Process ID: 22819, Thread ID: 139899822032704
[task 2019-08-28T16:46:13.437Z] 16:46:13 INFO - PID 19834 | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmp6Z6QXv.mozrunner/runtests_leaks_879_tab_pid22925.log
[task 2019-08-28T16:46:13.599Z] 16:46:13 INFO - PID 19834 | ++DOMWINDOW == 3 (0x7f56bd0af800) [pid = 22883] [serial = 3] [outer = 0x7f56bc9d8f20]
[task 2019-08-28T16:46:13.601Z] 16:46:13 INFO - PID 19834 | [Child 22883, Main Thread] WARNING: NS_ENSURE_SUCCESS(mStatus, *this) failed with result 0x80004005: file /builds/worker/workspace/build/src/obj-firefox/dist/include/nsIURIMutator.h, line 489
[task 2019-08-28T16:46:13.678Z] 16:46:13 INFO - PID 19834 | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2019-08-28T16:46:13.774Z] 16:46:13 INFO - PID 19834 | ++DOMWINDOW == 4 (0x7f56bddf0c00) [pid = 22883] [serial = 4] [outer = 0x7f56bc9d8f20]
[task 2019-08-28T16:46:13.835Z] 16:46:13 INFO - PID 19834 | WARN 2019-08-28T16:46:13Z: audio_thread_priority::rt_linux: Could not make thread real-time.
[task 2019-08-28T16:46:13.836Z] 16:46:13 INFO - PID 19834 | WARN 2019-08-28T16:46:13Z: audioipc_client: Could not promote audio threads to real-time during initialization.
[task 2019-08-28T16:46:14.086Z] 16:46:14 INFO - PID 19834 | WARN 2019-08-28T16:46:14Z: audio_thread_priority::rt_linux: Could not make thread real-time.
[task 2019-08-28T16:46:14.086Z] 16:46:14 INFO - PID 19834 | WARN 2019-08-28T16:46:14Z: audioipc_client::context: Could not promote thread to real-time.
[task 2019-08-28T16:46:16.187Z] 16:46:16 INFO - TEST-UNEXPECTED-OK | /media-source/mediasource-seek-beyond-duration.html | expected ERROR
[task 2019-08-28T16:46:16.187Z] 16:46:16 INFO - TEST-INFO expected ERROR | took 3182ms
[task 2019-08-28T16:46:16.209Z] 16:46:16 INFO - PID 19834 | 1567010776205 Marionette INFO Stopped listening on port 47128
[task 2019-08-28T16:46:16.491Z] 16:46:16 INFO - PID 19834 | [Child 22883, Main Thread] WARNING: Can't add a range if the end is older that the start.: file /builds/worker/workspace/build/src/dom/html/TimeRanges.cpp, line 73
[task 2019-08-28T16:46:16.491Z] 16:46:16 INFO - PID 19834 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2019-08-28T16:46:16.491Z] 16:46:16 INFO - PID 19834 | [Child 22883, Main Thread] WARNING: Can't add a range if the end is older that the start.: file /builds/worker/workspace/build/src/dom/html/TimeRanges.cpp, line 73
[task 2019-08-28T16:46:16.608Z] 16:46:16 INFO - PID 19834 | --DOCSHELL 0x7f63f3c22000 == 2 [pid = 19893] [id = {9f60262e-5be8-40f3-bdd3-10a4a027610b}] [url = moz-extension://a0d27693-c8fc-40d5-8457-09ea2d920ed5/_generated_background_page.html]
[task 2019-08-28T16:46:16.608Z] 16:46:16 INFO - PID 19834 | --DOCSHELL 0x7f640d685000 == 1 [pid = 19893] [id = {713e42f0-bfcf-45fa-916c-a8af19c8e843}] [url = moz-extension://aff40fc9-2a12-44e1-8aa9-70f8e72500c3/_generated_background_page.html]
[task 2019-08-28T16:46:16.609Z] 16:46:16 INFO - PID 19834 | --DOCSHELL 0x7f63f3bbd800 == 0 [pid = 19893] [id = {07ecdb2a-4f12-4c0b-8794-e4024e182435}] [url = moz-extension://707f7829-c79a-491f-a581-8d00d1b6b6e2/_generated_background_page.html]
[task 2019-08-28T16:46:16.624Z] 16:46:16 INFO - PID 19834 | WARN 2019-08-28T16:46:16Z: xulstore::persist: tried to remove key that isn't in the store
[task 2019-08-28T16:46:16.625Z] 16:46:16 INFO - PID 19834 | WARN 2019-08-28T16:46:16Z: xulstore::persist: tried to remove key that isn't in the store
[task 2019-08-28T16:46:16.660Z] 16:46:16 INFO - PID 19834 | --DOCSHELL 0x7f56bc9ba000 == 0 [pid = 22883] [id = {f75c2592-52a5-40b8-a023-04f8897a3351}] [url = http://web-platform.test:8000/media-source/mediasource-seek-beyond-duration.html]
[task 2019-08-28T16:46:16.688Z] 16:46:16 INFO - PID 19834 | [Child 22883, Main Thread] WARNING: Wrong inner/outer window combination!: file /builds/worker/workspace/build/src/dom/base/Document.cpp, line 6853
[task 2019-08-28T16:46:16.688Z] 16:46:16 INFO - PID 19834 | [Child 22883, Main Thread] WARNING: Wrong inner/outer window combination!: file /builds/worker/workspace/build/src/dom/base/Document.cpp, line 6853

Flags: needinfo?(apehrson)

Bug 1525554 made two MSE tests fail, that this patch fixes again, apparently. WPT expectations need updating.

Flags: needinfo?(apehrson)
Regressed by: 1525554
Keywords: regression
Blocks: 1564516
Pushed by pehrsons@gmail.com: https://hg.mozilla.org/integration/autoland/rev/03d9cfc6375d Don't leave dangling js promises after seeking. r=jya

https://hg.mozilla.org/mozilla-central/rev/03d9cfc6375d

Status: ASSIGNED → RESOLVED
Closed: 5 years ago
status-firefox70: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla70
See Also: → 1580073

This is still happening on -v69.0.3

That's expected, it's only fixed in 70 and onward.

Has Regression Range: --- → yes
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: