qtdemux: Premature EOS when some files are played in push mode

Submitted by Alicia Boya García @ntrrgc

Link to original bug (#794199)

Description

Created attachment 369503
Test vector

The attached file has 6 frames, in two GOPs, both with I-B-P layout.

It's demuxed correctly in pull mode.

$ gst-launch-1.0 -v filesrc location=ibpibp-non-frag.mp4 ! qtdemux ! fakesink silent=false |egrep 'segment|chain'
/GstPipeline:pipeline0/GstFakeSink:fakesink0: last-message = event ******* (fakesink0:sink) E (type: segment (17934), GstEventSegment, segment=(GstSegment)"GstSegment, flags=(GstSegmentFlags)GST_SEGMENT_FLAG_NONE, rate=(double)1, applied-rate=(double)1, format=(GstFormat)GST_FORMAT_TIME, base=(guint64)0, offset=(guint64)0, start=(guint64)333333333, stop=(guint64)2333333333, time=(guint64)0, position=(guint64)333333333, duration=(guint64)18446744073709551615;";) 0x5649226dcb20
/GstPipeline:pipeline0/GstFakeSink:fakesink0: last-message = chain ******* (fakesink0:sink) (1025 bytes, dts: 0:00:00.000000000, pts: 0:00:00.333333333, duration: 0:00:00.333333333, offset: -1, offset_end: -1, flags: 00000040 discont , meta: none) 0x7ff4c8005340
/GstPipeline:pipeline0/GstFakeSink:fakesink0: last-message = chain ******* (fakesink0:sink) (305 bytes, dts: 0:00:00.333333333, pts: 0:00:01.000000000, duration: 0:00:00.333333333, offset: -1, offset_end: -1, flags: 00002000 delta-unit , meta: none) 0x7ff4c8005120
/GstPipeline:pipeline0/GstFakeSink:fakesink0: last-message = chain ******* (fakesink0:sink) (131 bytes, dts: 0:00:00.666666666, pts: 0:00:00.666666666, duration: 0:00:00.333333334, offset: -1, offset_end: -1, flags: 00002000 delta-unit , meta: none) 0x7ff4c8005010
/GstPipeline:pipeline0/GstFakeSink:fakesink0: last-message = chain ******* (fakesink0:sink) (499 bytes, dts: 0:00:01.000000000, pts: 0:00:01.333333333, duration: 0:00:00.333333333, offset: -1, offset_end: -1, flags: 00000000 , meta: none) 0x7ff4c8005120
/GstPipeline:pipeline0/GstFakeSink:fakesink0: last-message = chain ******* (fakesink0:sink) (487 bytes, dts: 0:00:01.333333333, pts: 0:00:02.000000000, duration: 0:00:00.333333333, offset: -1, offset_end: -1, flags: 00002000 delta-unit , meta: none) 0x7ff4c8005340
/GstPipeline:pipeline0/GstFakeSink:fakesink0: last-message = chain ******* (fakesink0:sink) (215 bytes, dts: 0:00:01.666666666, pts: 0:00:01.666666666, duration: 0:00:00.333333334, offset: -1, offset_end: -1, flags: 00002000 delta-unit , meta: none) 0x7ff4c8005450

On the other hand, it loses the last 2 frames when demuxed in push mode:

$ gst-launch-1.0 -v pushfilesrc location=ibpibp-non-frag.mp4 ! qtdemux ! fakesink silent=false |egrep 'segment|chain'
/GstPipeline:pipeline0/GstFakeSink:fakesink0: last-message = event ******* (fakesink0:sink) E (type: segment (17934), GstEventSegment, segment=(GstSegment)"GstSegment, flags=(GstSegmentFlags)GST_SEGMENT_FLAG_NONE, rate=(double)1, applied-rate=(double)1, format=(GstFormat)GST_FORMAT_TIME, base=(guint64)0, offset=(guint64)0, start=(guint64)0, stop=(guint64)18446744073709551615, time=(guint64)0, position=(guint64)0, duration=(guint64)18446744073709551615;";) 0x5619bebdeea0
/GstPipeline:pipeline0/GstFakeSink:fakesink0: last-message = event ******* (fakesink0:sink) E (type: segment (17934), GstEventSegment, segment=(GstSegment)"GstSegment, flags=(GstSegmentFlags)GST_SEGMENT_FLAG_NONE, rate=(double)1, applied-rate=(double)1, format=(GstFormat)GST_FORMAT_TIME, base=(guint64)0, offset=(guint64)0, start=(guint64)333333333, stop=(guint64)2333333333, time=(guint64)0, position=(guint64)333333333, duration=(guint64)18446744073709551615;";) 0x7f91ec0065c0
/GstPipeline:pipeline0/GstFakeSink:fakesink0: last-message = chain ******* (fakesink0:sink) (1025 bytes, dts: 0:00:00.000000000, pts: 0:00:00.333333333, duration: 0:00:00.333333333, offset: -1, offset_end: -1, flags: 00004040 discont tag-memory , meta: none) 0x7f91ec00a400
/GstPipeline:pipeline0/GstFakeSink:fakesink0: last-message = chain ******* (fakesink0:sink) (305 bytes, dts: 0:00:00.333333333, pts: 0:00:01.000000000, duration: 0:00:00.333333333, offset: -1, offset_end: -1, flags: 00006000 delta-unit tag-memory , meta: none) 0x7f91ec00a510
/GstPipeline:pipeline0/GstFakeSink:fakesink0: last-message = chain ******* (fakesink0:sink) (131 bytes, dts: 0:00:00.666666666, pts: 0:00:00.666666666, duration: 0:00:00.333333334, offset: -1, offset_end: -1, flags: 00006000 delta-unit tag-memory , meta: none) 0x7f91ec00a620
/GstPipeline:pipeline0/GstFakeSink:fakesink0: last-message = chain ******* (fakesink0:sink) (499 bytes, dts: 0:00:01.000000000, pts: 0:00:01.333333333, duration: 0:00:00.333333333, offset: -1, offset_end: -1, flags: 00004000 tag-memory , meta: none) 0x7f91ec00a510

The offending code is this condition:

pts = QTSAMPLE_PTS (stream, sample);
[...]
if (G_UNLIKELY (demux->segment.stop != -1
&& demux->segment.stop <= pts && stream->on_keyframe)) {
GST_DEBUG_OBJECT (demux, "we reached the end of our segment.");

Note that the demux->segment.stop <= pts comparison is wrong because it's comparing buffer time across different GstSegments, instead of translating both to stream time.

The difference is very important because the user requests to play e.g. the range [0, 2) s in stream time; it should not need to care whether the track (buffer) presentation range is actually [0.333, 2.333) because this file already has an edit list to map that to [0, 2) s in stream time.

The stream->on_keyframe check is also interesting. I have not experimented with it too much, but on first glance it looks like it would avoid entering the if body on most files, which would explain why this issue has not been detected before. Since most GOPs are longer than 3 frames and for most files with basic edit lists, like the one attached, the buffer PTS match can only occur in the last GOP, the chances of it happening on both buffer PTS = segment.stop and exactly the next frame after an I-frame are quite low. (EOS is sent later because as a reaction of upstream sending EOS itself when there are no more bytes to read, not because of last frame emission*).

• To make things worse, our WebKit MSE implementation actually relies on EOS not being sent on last frame emission when working on push mode. Today I've learned that is the case most often but not always.

Attachment 369503, "Test vector":
ibpibp-non-frag