Bug 217713 – [GTK][WPE] currentTime reported as NaN shortly after seeking for MSE playback

• Component: Media
• Status: RESOLVED CONFIGURATION CHANGED

Created attachment 411335 [details]
web page to reproduce the issue

It looks that media element may return currentTime equals to NaN shortly after seeking. The bug was reproduced on an embedded Linux device, but is not normally seen on the desktop version. Webkit GTK 2.30.1 was used to reproduce the issue.

To reproduce on the desktop:
1. Prepare a media sample, in the test it was MP4/AAC LC audio file. This snippet can be used to make it working for MSE: ffmpeg -i input.mp4 -movflags frag_keyframe+empty_moov -movflags frag_keyframe+empty_moov+default_base_moof output.mp4
2. Patch Webkit by adding a sleep before posting an event to handle end of append:
--- AppendPipeline.cpp.orig	2020-10-14 15:44:50.917918291 +0100
+++ AppendPipeline.cpp	2020-10-14 15:42:30.395406822 +0100
@@ -319,6 +319,7 @@
     }
 
     GST_TRACE_OBJECT(m_pipeline.get(), "Posting end-of-append task to the main thread");
+    sleep(1);
     m_taskQueue.enqueueTask([this]() {
         handleEndOfAppend();
     });

3. In Javascript, add a media source. To the media source add a sourcebuffer.
4. Append a buffer of audio data to the sourcebuffer.
5. After 10ms, check currentTime, it's 0.0.
6. Seek to 0.0 by setting the currentTime attribute.
7. After 10ms, check currentTime, it's NaN.
8. After 3s, check currentTime, it's equal to the duration value - it was seeked until the end.

An HTML file with Javascript code is appended to this bug report and it can be used to reproduce the issue as described above.

After looking a bit in the code, it looks that the problem is in the HTMLMediaElement::seekTask function:

HTMLMediaElement::seekTask
...
time = seekableRanges->ranges().nearest(time);

The PlatformTimeRanges::nearest function returns invalidTime when there are no ranges buffered:

MediaTime PlatformTimeRanges::nearest(const MediaTime& time) const
...
    if (!count)
        return MediaTime::invalidTime();

Then, going back to HTMLMediaElement::seekTask, invalidTime is set as the last seek time:

HTMLMediaElement::seekTask
...
m_lastSeekTime = time;

Then, when asking about the current time, invalidTime will be returned, which is later converted to NaN:

MediaTime HTMLMediaElement::currentMediaTime() const
...
    if (m_seeking) {
        ALWAYS_LOG(LOGIDENTIFIER, "seeking, returning", m_lastSeekTime);
        return m_lastSeekTime;
    }

It looks that there is a race condition between seeking and handling the AppendPipeline::handleEndOfAppend function. AppendPipeline::handleEndOfAppend updates the ranges after they were appended:

AppendPipeline::handleEndOfAppend
->SourceBufferPrivateGStreamer::didReceiveAllPendingSamples
-->SourceBuffer::sourceBufferPrivateAppendComplete
--->SourceBuffer::updateBufferedFromTrackBuffers // ranges are updated here

When the seek occurs before AppendPipeline::handleEndOfAppend is called, it may set the current time to invalidTime due to lack of ranges.

There is similar code in Chromium. Not sure if the code below is responsible that this issue cannot be reproduced using Chromium, but one difference is that when there are no ranges available, then 0.0 is returned instead of invalidTime for the 'nearest' function.

https://github.com/chromium/chromium/blob/2420378bc7c24eee30c48455f0c54aa4c7390aa2/third_party/blink/renderer/core/html/media/html_media_element.cc#L2095

void HTMLMediaElement::Seek(double time) {
...
time = seekable_ranges.Nearest(time, now);

https://github.com/chromium/chromium/blob/085b61f6a13d59f59bd39b2eb2b8797849d730f4/third_party/blink/renderer/platform/exported/web_time_range.cc#L130

double WebTimeRanges::Nearest(double new_playback_position,
                              double current_playback_position) const {
  double best_match = 0;
  double best_delta = std::numeric_limits<double>::infinity();
  for (const WebTimeRange& range : *this) {
...
  return best_match;
}

Another issue connected with returning invalidTime as the current time, is when injecting endOfStream. The current position will be set to the duration of the media file:

MediaSource::endOfStream
->MediaSource::streamEndedWithError
-->MediaSource::setDurationInternal
--->MediaSourceGStreamer::durationChanged
---->MediaPlayerPrivateGStreamerMSE::durationChanged
----->MediaPlayer::durationChanged
------>HTMLMediaElement::mediaPlayerDurationChanged

void HTMLMediaElement::mediaPlayerDurationChanged()
...
    MediaTime now = currentMediaTime();
    MediaTime dur = durationMediaTime();
    ALWAYS_LOG(LOGIDENTIFIER, "duration = ", dur, ", current time = ", now);
    if (now > dur)
        seekInternal(dur);

In this case current time (now) is invalidTime and the condition 'now > dur' will be satisfied, hence the position will be set to the duration value.

The change below causes that the current time won't be set as invalidTime:

--- HTMLMediaElement.cpp.orig	2020-10-14 17:01:28.677475426 +0100
+++ HTMLMediaElement.cpp     2020-10-14 17:02:13.788998928 +0100
@@ -2983,7 +2983,10 @@
         clearSeeking();
         return;
     }
-    time = seekableRanges->ranges().nearest(time);
+    if(seekableRanges->ranges().length())
+        time = seekableRanges->ranges().nearest(time);
+    else
+        time = MediaTime::zeroTime();
 
     m_sentEndEvent = false;
     m_lastSeekTime = time;

[Alexey Proskuryakov]

The report is filed against Gtk, however the proposed change is cross platform. Not sure who would look at this for Gtk, but CC'ing some Apple folks just in case.

Yes, it's not GTK specific. The issue has been seen on WPE too.

Anyway, the issue can be also reproduced on Webkit GTK 2.30.1 without any patches (the 1 second sleep). It was also reproduced on GNOME Web 3.28.6. To do it, timings in the Javascript code must be adjusted.

The usual flow between appending a buffer and seeking is as follows:

1. SourceBuffer::appendBuffer appending a buffer.
2. AppendPipeline::appsrcEndOfAppendCheckerProbe, posting a task to handle end of buffer.
3. AppendPipeline::handleEndOfAppend is called, it updates buffered ranges.
4. We are setting the current position. There is logic in HTMLMediaElement::seekWithTolerance which posts a task HTMLMediaElement::seekTask to the queue when the seek was from DOM.
5. HTMLMediaElement::seekTask is executed. There are buffered ranges available (because they were updated while executing AppendPipeline::handleEndOfAppend), it sets the m_lastSeekTime to some valid value.
6. HTMLMediaElement::currentMediaTime is called. Because we are still seeking, then the value of m_lastSeekTime is returned as the current time.

To reproduce the issue, HTMLMediaElement::seekTask must be called before AppendPipeline::handleEndOfAppend. It's possible to do it with short timeouts in Javascript code like the seek will happen 1ms after calling SourceBuffer::appendBuffer. Additionaly, after the issue will happen, the controls of HTML audio element are unusable and the audio can't be played.

The updated way to reproduce the issue:
1. Prepare audio media:
gst-launch-1.0 audiotestsrc num-buffers=3000 ! avenc_aac ! mp4mux ! filesink location=audio.mp4
ffmpeg -i audio.mp4 -movflags frag_keyframe+empty_moov -movflags frag_keyframe+empty_moov+default_base_moof output.mp4
2. Use the updated attached HTML file with MSE code.
3. Try to launch the browser a few times or refresh and at some point it should happen.

When the race condition is not hit, then everything works fine. The current time returned is always 0.0 and audio can be played. However, when the issue is reproduced, the current time right after seeking is returned as NaN (it is often also the value of duration if EOS was injected quicker). After injecting EOS, the position is seeked to the end and the audio element becomes unusable during interaction.

I attached screenshots from GNOME Web when the issue was reproduced and also when everything went fine.

The issue can't be reproduced with Chrome 84.

Created attachment 411423 [details]
updated web page to reproduce the issue

Attaching the updated web page to reproduce the issue

Created attachment 411424 [details]
GNOME Web failed test

Attaching a failed test when using GNOME Web

Created attachment 411426 [details]
GNOME Web passed test

Attaching a passed test when using GNOME Web

Another observation is that the issue is more easily reproducible, when the appended buffer to the sourcebuffer is bigger. It makes AppendPipeline to post the task for AppendPipeline::handleEndOfAppend later.

[Alicia Boya García]

Thank you very much for such a very complete bug report.

(In reply to sycy700 from comment #0)
> There is similar code in Chromium. Not sure if the code below is responsible
> that this issue cannot be reproduced using Chromium, but one difference is
> that when there are no ranges available, then 0.0 is returned instead of
> invalidTime for the 'nearest' function.
> 
> https://github.com/chromium/chromium/blob/
> 2420378bc7c24eee30c48455f0c54aa4c7390aa2/third_party/blink/renderer/core/
> html/media/html_media_element.cc#L2095
> 
> void HTMLMediaElement::Seek(double time) {
> ...
> time = seekable_ranges.Nearest(time, now);

This is not entirely accurate. While Nearest() in Chromium will indeed return 0.0 in this case, that is not actually relevant because the function returns early in the case where there are no seekable ranges:

void HTMLMediaElement::Seek(double time) {
  [...]
  if (seekable_ranges.empty()) {
    seeking_ = false;
    return;
  }
  time = seekable_ranges.Nearest(time, now);

The proposed solution of setting time to zero in the case where there are not seekable ranges is not ideal because it discards the previously requested seek time, and it just happens that it's zero in this case.

I assume the empty seekable ranges is a consequence of not yet knowing the duration of the media (which changes after either setting it manually or when parsing the media). Some things I wonder at the moment are:

I still wonder how come a seek is allowed to happen before there were any seekable ranges.

Thanks for the comment. As it was described previously, there is a short time window between appending a segment and until the processed segment data is visible in seekableRanges->ranges() in the function HTMLMediaElement::seekTask.

Segment processing is done in AppendPipeline, in a different thread than the one where seek is done in HTMLMediaElement.

It's possible to inject a seek request in that time window and then the issue can be reproduced.

[Ahmad Saleem]

I am unable to reproduce this in Safari Technology Preview 187 using `updated web page...` on macOS 14.3 Sonoma.

Is it fixed down the line and now only reproducible on WebKitGTK or other ports? Or we can mark it as 'RESOLVED CONFIGURATION CHANGED'.

*** Safari Technology Preview 187 ***

>>> appended buffer
>>> currentTime: 0
>>> currentTime: 0
>>> currentTime: 0

Same as Chrome Canary 123.

[Enrique Ocaña]

I've tested the updated use case against latest WebKitGTK on desktop and I can't reproduce the issue anymore, even after several tries. I added the AppendPipeline.cpp sleep() call to force things even more, with identical results.

Closing bug as 'RESOLVED CONFIGURATION CHANGED'. sycy700, please feel free to reopen it in case it's still reproducible for you.