test_videocontrols.html,test_bug495300.html | Assertion count 1 is greater than expected range 0-0 assertions, ###!!! ASSERTION: Page read cursor should be inside range: 'mPageOffset <= endOffset'

RESOLVED FIXED in mozilla25

Status

()

defect
RESOLVED FIXED
7 years ago
6 years ago

People

(Reporter: padenot, Assigned: cpearce)

Tracking

({assertion, intermittent-failure})

unspecified
mozilla25
x86_64
Linux
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox-esr24 unaffected)

Details

Attachments

(4 attachments, 1 obsolete attachment)

This happens sometimes when running content/html/content/test_seek.html on try, for now only on Mac. The assertions happens one time per run, with this on the output:

07:43:14     INFO -  SEEK-TEST: Started seek.ogv seek test 10
07:43:14     INFO -  191998 INFO TEST-PASS | /tests/content/media/test/test_seek.html | seek.ogv seek test 10: Video currentTime should be around 1.983: 3.5999640000000004
07:43:14     INFO -  [Parent 468] ###!!! ASSERTION: Page read cursor should be inside range: 'mPageOffset <= endOffset', file ../../../../content/media/ogg/OggReader.cpp, line 1675
07:43:14     INFO -  mozilla::OggReader::SeekInBufferedRange(long long, long long, long long, long long, nsTArray<mozilla::OggReader::SeekRange> const&, mozilla::OggReader::SeekRange const&) [content/media/ogg/OggReader.cpp:1273]
07:43:14     INFO -  mozilla::OggReader::Seek(long long, long long, long long, long long) [content/media/ogg/OggReader.cpp:1403]
07:43:14     INFO -  mozilla::MediaDecoderStateMachine::DecodeSeek() [content/media/MediaDecoderStateMachine.cpp:1944]
07:43:14     INFO -  mozilla::MediaDecoderStateMachine::DecodeThreadRun() [content/media/MediaDecoderStateMachine.cpp:494]
07:43:14     INFO -  nsRunnableMethodImpl<void (mozilla::MediaDecoderStateMachine::*)(), true>::Run() [obj-firefox/dist/include/nsThreadUtils.h:367]
07:43:14     INFO -  nsThread::ProcessNextEvent(bool, bool*) [xpcom/threads/nsThread.cpp:627]
07:43:14     INFO -  NS_ProcessNextEvent_P(nsIThread*, bool) [obj-firefox/xpcom/build/nsThreadUtils.cpp:238]
07:43:14     INFO -  nsThread::ThreadFunc(void*) [xpcom/threads/nsThread.h:63]
07:43:14     INFO -  _pt_root [nsprpub/pr/src/pthreads/ptthread.c:194]
07:43:14     INFO -  libsystem_c.dylib + 0x4e8bf
07:43:14     INFO -  [Parent 468] WARNING: NS_ENSURE_SUCCESS(rv, PAGE_SYNC_ERROR) failed with result 0x80004005: file ../../../../content/media/ogg/OggReader.cpp, line 1457
07:43:14     INFO -  [Parent 468] WARNING: NS_ENSURE_TRUE(res != PAGE_SYNC_ERROR) failed: file ../../../../content/media/ogg/OggReader.cpp, line 1613
07:43:14     INFO -  [Parent 468] WARNING: NS_ENSURE_SUCCESS(res, res) failed with result 0x80004005: file ../../../../content/media/ogg/OggReader.cpp, line 1404

Let's mark this assertion as expected on Mac, so we don't give sheriffs too much work.
This conservatively expects the assertions only on Mac. If it starts happening
on Linux, we can adjust as necessary.
Attachment #719977 - Flags: review?(ryanvm)
Assignee: nobody → paul
Attachment #719977 - Flags: review?(ryanvm) → review+
Whiteboard: [leave open]
This assertion seems to be more frequent on Mac, but can happen on Linux.
Attachment #719988 - Flags: review?(ryanvm)
Attachment #719988 - Flags: review?(ryanvm) → review+
Chris, any idea what is happening here?
Flags: needinfo?(cpearce)
I have no idea why this is happening.
Flags: needinfo?(cpearce)
If Chris does not know, not sure I can do something.
Assignee: paul → nobody
https://tbpl.mozilla.org/php/getParsedLog.php?id=22451948&tree=Mozilla-Inbound

Roc, can you help find an owner for this?
Flags: needinfo?(roc)
Eeny meeny miney mo...
Assignee: nobody → chris.double
Flags: needinfo?(roc)
This seems to have gotten more frequent in the last day.
https://tbpl.mozilla.org/php/getParsedLog.php?id=22764565&tree=Mozilla-Inbound
Flags: needinfo?(chris.double)
I won't be able to look at this until my Android workload is reduced. Just letting you know to remove the needinfo since I have no info to give at this stage. I'll try to look at it after the workweek in Taipai at the end of May.
Flags: needinfo?(chris.double)
https://tbpl.mozilla.org/php/getParsedLog.php?id=23010146&tree=Mozilla-Inbound&full=1
Summary: ###!!! ASSERTION: Page read cursor should be inside range: 'mPageOffset <= endOffset' → test_videocontrols.html | Assertion count 1 is greater than expected range 0-0 assertions, ###!!! ASSERTION: Page read cursor should be inside range: 'mPageOffset <= endOffset'
https://tbpl.mozilla.org/php/getParsedLog.php?id=23172022&tree=Mozilla-Inbound&full=1#error0
Summary: test_videocontrols.html | Assertion count 1 is greater than expected range 0-0 assertions, ###!!! ASSERTION: Page read cursor should be inside range: 'mPageOffset <= endOffset' → test_videocontrols.html,test_bug495300.html | Assertion count 1 is greater than expected range 0-0 assertions, ###!!! ASSERTION: Page read cursor should be inside range: 'mPageOffset <= endOffset'
The problem here is that we're trying to maintain the offset of the page we last read in OggReader::mPageOffset, and we're failing. We only use mPageOffset to mark frames with a byte stream offset so that the MediaDecoder can determine how far through the stream the decoders have consumed, so we can just use MediaResource::Tell() instead. Most other backends do it this way.

We can then remove the assertion 'mPageOffset <= endOffset "Page read cursor should be inside range"'.
Assignee: chris.double → cpearce
Status: NEW → ASSIGNED
Attachment #781290 - Flags: review?(giles)
The other assertion we have failing (on test_seek) is:

###!!! ASSERTION: Seek target should lie inside the first frame after seek, unless it's the last frame.: '(video->mTime <= seekTime && seekTime <= vide
o->mEndTime) || mReader->VideoQueue().IsFinished()', file c:/Users/Bob/src/orange/content/media/MediaDecoderStateMachine.cpp, line 2048

This can be independently reproduced with this testcase:

<video src="http://pearce.org.nz/video/seek.ogg" preload onloadedmetadata="this.currentTime=2.102511" controls></video>

The problem here is that our seek bisection is converting the Ogg Theora's page's granule time to the *start* timestamp of the frame that can be decoded from that page (by subtracting 1 from granuletime). Using granuleTime-1 leads the bisection to believe that if it starts decoding there, it can reach the target. This is not true, as data required to decode the frame with granuletime-1 may lie before the page that the bisection lands on.
Attachment #781296 - Flags: review?(giles)
I missed updating a couple of the ReadOggPage() calls after changing its return value. Ooops.
Attachment #781290 - Attachment is obsolete: true
Attachment #781290 - Flags: review?(giles)
Attachment #781389 - Flags: review?(giles)
Comment on attachment 781389 [details] [diff] [review]
ogg-page-offset-assertion-fix.patch v2

Review of attachment 781389 [details] [diff] [review]:
-----------------------------------------------------------------

Looks good. r=me.

NesteggPacketHolder::mOffset doesn't have this problem because it's set correctly?

::: content/media/ogg/OggReader.cpp
@@ +904,1 @@
>    

Might as well remove the trailing whitespace here.

@@ +1679,5 @@
>        if ((HasAudio() && audioTime == -1) ||
>            (HasVideo() && videoTime == -1)) 
>        {
>          // We don't have timestamps for all active tracks...
> +        if (pageOffset == startOffset + startLength && pageOffset + pageLength >= endOffset) {

Please linebreak after the &&.
Attachment #781389 - Flags: review?(giles) → review+
Comment on attachment 781296 [details] [diff] [review]
fix-seek-frame-time-assertion.patch

Review of attachment 781296 [details] [diff] [review]:
-----------------------------------------------------------------

Patch looks correct, but doesn't resolve the assert for me.
Attachment #781296 - Flags: review?(giles) → review+
I put the reproduction snippet from comment #50 on a page for testing. http://people.mozilla.org/~rgiles/2013/bug846769.html
(In reply to Ralph Giles (:rillian) away until Aug 5. from comment #52)
> NesteggPacketHolder::mOffset doesn't have this problem because it's set
> correctly?

Yes.

I think the difference is that NesteggPacketHolder directly associates each undecoded packet with the offset at which it was read, i.e. *this* packet was read at *that* offset. Whereas the OggReader stamps decoded frames/samples with OggReader::mPageOffset, which is the offset of the last page demuxed. If the last page demuxed is not the one we just decoded we'll stamp decoded frames with the wrong offset. Which is why the assertion was failing.

We'll still have this issue with this patch, but the offset will be close enough that it won't mess up the logic that uses the offset, and we won't fail an assertion.
https://hg.mozilla.org/integration/mozilla-inbound/rev/6558e79080bd
https://hg.mozilla.org/integration/mozilla-inbound/rev/2d7d821c792d

[leave open] because test_seek isn't re-enabled yet. There's some failures in the GStreamer backend that will need to be fixed.
Depends on: 898910
Adjusted the assertion annotations for these tests on m-b since it's unlikely any fixes for this will be uplifted to Fx24.
https://hg.mozilla.org/releases/mozilla-beta/rev/dbc291263ed3
All of the stars in December are actually "ASSERTION: Start time must be before end time: 'startTime < endTime'", not "ASSERTION: Page read cursor should be inside range: 'mPageOffset <= endOffset'".

Chris, do you want them spun off to a new bug or should we repurpose this one instead?
Flags: needinfo?(cpearce)
New bug please Ryan, thanks.
Flags: needinfo?(cpearce)
Calling this one fixed then. I have no idea what the October 29 star was, but no other occurrences tell me that this is resolved.
Status: ASSIGNED → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
Whiteboard: [leave open]
Target Milestone: --- → mozilla25
You need to log in before you can comment on or make changes to this bug.