Closed Bug 846769 Opened 12 years ago Closed 11 years ago

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'

Categories

(Core :: Audio/Video, defect)

x86_64
Linux
defect
Not set
normal

Tracking

()

RESOLVED FIXED
mozilla25
Tracking Status
firefox-esr24 --- unaffected

People

(Reporter: padenot, Assigned: cpearce)

References

Details

(Keywords: assertion, intermittent-failure)

Attachments

(4 files, 1 obsolete file)

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
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)
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'
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'
Attached patch ogg-page-offset-assertion-fix.patch (obsolete) — — Splinter Review
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: 11 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.

Attachment

General

Created:
Updated:
Size: