A test I'm about to land in bug 879717 hits this assertion at ~50% rate on Linux Debug (at least) - running some more test runs on other machines now to see if it reproduces there. See https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=7819e8e6bc14. For Linux, it's the oranges in M-3. 5 of 10 failed. See the log files for the full assertions, though they all look like this: 07:37:23 INFO - 544 INFO TEST-START | /tests/dom/media/test/test_video_dimensions.html 07:37:23 INFO - ++DOMWINDOW == 20 (0x837e8c00) [pid = 1865] [serial = 376] [outer = 0xa3114c00] 07:37:24 INFO - [1865] WARNING: Failed to unlock the wakelock.: '!rv.Failed()', file /builds/slave/try-lx-d-000000000000000000000/build/src/dom/html/HTMLMediaElement.cpp, line 2312 07:37:27 INFO - [1865] ###!!! ASSERTION: Clock should go forwards if the playback rate is > 0.: 'GetMediaTime() <= clock_time || mPlaybackRate <= 0', file /builds/slave/try-lx-d-000000000000000000000/build/src/dom/media/MediaDecoderStateMachine.cpp, line 2794 07:38:02 INFO - JavaScript error: jar:file:///builds/slave/test/build/application/firefox/omni.ja!/components/nsHandlerService.js, line 891: NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIProperties.get] 07:38:07 INFO - #01: mozilla::MediaDecoderStateMachine::GetClock() const [dom/media/MediaDecoderStateMachine.cpp:2793] 07:38:07 INFO - #02: mozilla::MediaDecoderStateMachine::StopPlayback() [xpcom/ds/TimeStamp.h:387] 07:38:07 INFO - #03: mozilla::MediaDecoderStateMachine::RunStateMachine() [dom/media/MediaDecoderStateMachine.cpp:2476] 07:38:07 INFO - #04: mozilla::MediaDecoderStateMachineScheduler::TimeoutExpired(int) [dom/media/MediaDecoderStateMachineScheduler.cpp:160] 07:38:07 INFO - #05: TimerEvent::Run [dom/media/MediaDecoderStateMachineScheduler.cpp:24] 07:38:07 INFO - #06: nsThreadPool::Run() [xpcom/threads/nsThreadPool.cpp:220] 07:38:07 INFO - #07: nsThread::ProcessNextEvent(bool, bool*) [xpcom/threads/nsThread.cpp:830] 07:38:07 INFO - #08: NS_ProcessNextEvent(nsIThread*, bool) [xpcom/glue/nsThreadUtils.cpp:265] 07:38:07 INFO - #09: mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*) [ipc/glue/MessagePump.cpp:340] 07:38:07 INFO - #10: MessageLoop::RunInternal() [ipc/chromium/src/base/message_loop.cc:233] 07:38:07 INFO - #11: MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:508] 07:38:07 INFO - #12: nsThread::ThreadFunc(void*) [xpcom/threads/nsThread.cpp:350] 07:38:07 INFO - #13: _pt_root [nsprpub/pr/src/pthreads/ptthread.c:215] 07:38:07 INFO - #14: libpthread.so.0 + 0x6d4c 07:38:07 INFO - [1865] WARNING: Audio Buffer is not full by the end of the callback.: 'Available() == 0 || mSampleWriteOffset == 0', file /builds/slave/try-lx-d-000000000000000000000/build/src/dom/media/AudioBufferUtils.h, line 87 07:38:07 INFO - --DOCSHELL 0x837a0400 == 6 [pid = 1865] [id = 22] 07:38:07 INFO - --DOMWINDOW == 19 (0x837ea200) [pid = 1865] [serial = 371] [outer = (nil)] [url = http://mochi.test:8888/tests/dom/media/test/bug461281.ogg] 07:38:07 INFO - --DOMWINDOW == 18 (0x837efc00) [pid = 1865] [serial = 368] [outer = (nil)] [url = http://mochi.test:8888/tests/dom/media/test/test_unseekable.html] 07:38:07 INFO - --DOMWINDOW == 17 (0x837ea600) [pid = 1865] [serial = 369] [outer = (nil)] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html] 07:38:07 INFO - --DOMWINDOW == 16 (0x837ed600) [pid = 1865] [serial = 372] [outer = (nil)] [url = about:blank] 07:38:07 INFO - --DOMWINDOW == 15 (0x837eca00) [pid = 1865] [serial = 370] [outer = (nil)] [url = http://mochi.test:8888/tests/dom/media/test/test_videoDocumentTitle.html] 07:38:07 INFO - [1865] WARNING: Failed to unlock the wakelock.: '!rv.Failed()', file /builds/slave/try-lx-d-000000000000000000000/build/src/dom/html/HTMLMediaElement.cpp, line 2312 07:38:07 INFO - --DOMWINDOW == 14 (0x98bf0c00) [pid = 1865] [serial = 375] [outer = (nil)] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html] 07:38:07 INFO - --DOMWINDOW == 13 (0x98bd5200) [pid = 1865] [serial = 373] [outer = (nil)] [url = http://mochi.test:8888/tests/dom/media/test/320x240.ogv] 07:38:07 INFO - --DOMWINDOW == 12 (0x837eda00) [pid = 1865] [serial = 374] [outer = (nil)] [url = http://mochi.test:8888/tests/dom/media/test/bug461281.ogg] 07:38:07 INFO - 545 INFO TEST-OK | /tests/dom/media/test/test_video_dimensions.html | took 6831ms 07:38:07 INFO - ++DOMWINDOW == 13 (0x837ea400) [pid = 1865] [serial = 377] [outer = 0xa3114c00] 07:38:07 INFO - 546 INFO TEST-UNEXPECTED-ERROR | /tests/dom/media/test/test_video_dimensions.html | Assertion count 1 is greater than expected range 0-0 assertions.

JW, you've been fixing this assertion before. Any ideas what could be wrong or how we could fix it?

Ok, this is more useful. Also printing the pointer of the MediaDecoderStateMachine (to distinguish separate video elements' playback). I've filtered out the prints from other instances - it fails on the first call to GetClock() for this instance. No, actually it fails on the first call to GetClock() that goes into the else statement - hence we use audio or system clock here. But it's on shutdown and we have an output stream. Could the decoded stream have been destroyed a bit too early? See details below: ================== TEST-START | /tests/dom/media/test/test_video_dimensions.html Started Tue Dec 02 2014 15:31:51 GMT+0800 (CST) (1417505511.432s) TEST-PASS | /tests/dom/media/test/test_video_dimensions.html | [started 320x240.ogv-0] Length of array should match number of running tests TEST-PASS | /tests/dom/media/test/test_video_dimensions.html | [started seek.webm-1] Length of array should match number of running tests TEST-PASS | /tests/dom/media/test/test_video_dimensions.html | 320x240.ogv should only fire loadedmetadata once TEST-PASS | /tests/dom/media/test/test_video_dimensions.html | 320x240.ogv video width should be set on loadedmetadata TEST-PASS | /tests/dom/media/test/test_video_dimensions.html | 320x240.ogv video height should be set on loadedmetadata TEST-PASS | /tests/dom/media/test/test_video_dimensions.html | seek.webm should only fire loadedmetadata once TEST-PASS | /tests/dom/media/test/test_video_dimensions.html | seek.webm video width should be set on loadedmetadata TEST-PASS | /tests/dom/media/test/test_video_dimensions.html | seek.webm video height should be set on loadedmetadata TEST-PASS | /tests/dom/media/test/test_video_dimensions.html | 320x240.ogv (Captured) should only fire loadedmetadata once TEST-PASS | /tests/dom/media/test/test_video_dimensions.html | 320x240.ogv (Captured) video width should be set on loadedmetadata TEST-PASS | /tests/dom/media/test/test_video_dimensions.html | 320x240.ogv (Captured) video height should be set on loadedmetadata TEST-PASS | /tests/dom/media/test/test_video_dimensions.html | seek.webm (Captured) should only fire loadedmetadata once TEST-PASS | /tests/dom/media/test/test_video_dimensions.html | seek.webm (Captured) video width should be set on loadedmetadata TEST-PASS | /tests/dom/media/test/test_video_dimensions.html | seek.webm (Captured) video height should be set on loadedmetadata TEST-PASS | /tests/dom/media/test/test_video_dimensions.html | 320x240.ogv (Stream) should only fire loadedmetadata once TEST-PASS | /tests/dom/media/test/test_video_dimensions.html | 320x240.ogv (Stream) video width should be set on loadedmetadata TEST-PASS | /tests/dom/media/test/test_video_dimensions.html | 320x240.ogv (Stream) video height should be set on loadedmetadata ##### 0x11828a800 clock source is VideoStreamPosition ##### 0x11828a800 ASSERTION=FALSE!!! GetMediaTime()=243083, clock_time=238037, mPlaybackRate=1,000000 Some data I collected from the debugger that could be of use: There is an outputstream, but no decoded stream: (lldb) p mDecoder.mRawPtr->mDecodedStream (nsAutoPtr<mozilla::MediaDecoder::DecodedStreamData>) $29 = { mRawPtr = 0x0000000000000000 } (lldb) p mDecoder.mRawPtr->mOutputStreams (nsTArray<mozilla::MediaDecoder::OutputStreamData>) $30 = { [0] = { mStream = { mRawPtr = 0x0000000124f66a80 } mPort = { mRawPtr = 0x0000000000000000 } mFinishWhenEnded = true } } mDecoder is of type OggDecoder: (lldb) p mDecoder.mRawPtr (mozilla::OggDecoder *) $32 = 0x0000000117554d20 The values that fail the assert are built up like this: GetMediaTime() = 243083 { mStartTime = 0 + mCurrentFrameTime = 243083 } clock_time = 238037 { mStartTime = 0 + mPlayDuration = 0 + delta = (infered) 238037 { DurationToUsecs(now - mPlayStartTime (23032932397133)) } }

I can confirm that we are using the DecodedStream for the clock until shutdown. Then (not entirely sure where shutdown comes from, but looking at MediaDecoder::Shutdown, [1]) the DecodedStream is destroyed and shutdown of the state machine is scheduled to another thread. Hence we will always switch to the system clock for the shutdown moment - and sometimes it happens to be behind the media stream equivalent so it appears to go backwards. Not sure what we should focus on fixing here. JW, any ideas? [1] http://dxr.mozilla.org/mozilla-central/source/dom/media/MediaDecoder.cpp#473

Can you paste the call stack? I wonder why the state machine wants to know the clock time after shutdown sequence starts running.

I see. It is called from https://hg.mozilla.org/try/file/7819e8e6bc14/dom/media/MediaDecoderStateMachine.cpp#l2476.

This is the only quick fix I can think of. Not sure at all if it's OK to do though. I also fired off a try run so let's see what that gives: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=22ec3d422fa9

Comment on attachment 8531197 [details] [diff] [review] Don't update play duration when shutting down MediaDecoderStateMachine Review of attachment 8531197 [details] [diff] [review]: ----------------------------------------------------------------- I think we should not switch back to the system clock once it is captured since there is no returning back. Please open another bug to address this issue.