Closed Bug 1499903 Opened 1 year ago Closed 1 year ago

Correct the events order when we're in the seamless looping

Categories

(Core :: Audio/Video: Playback, enhancement, P3)

enhancement

Tracking

()

RESOLVED FIXED
mozilla65
Tracking Status
firefox65 --- fixed

People

(Reporter: alwu, Assigned: alwu)

References

(Blocks 1 open bug)

Details

Attachments

(4 files, 1 obsolete file)

When the media which has `loop` attribute is playing to the end , the spec mentions that media should do seek to the start position [1].

During seeking, the dispatched events order [2] for MediaElement should be 
1. seeking 
2. timeupdate
3. seeked 

However, our current behavior is,
1. timeupdate
2. seeking
3. seeked

When MDSM's `mCurrentPosition` changed [3], it would notify MediaDecoder's mirror with DirectTask. However, the way which we use to notify MediaDecoder to dispatch `seeking` and `seek` is a RegularTask [4].

As RegularTask would always be dispatched after DirectTask, we can't dispatch `seeking` before `timeupdate` in our current implementation.

[1] https://html.spec.whatwg.org/multipage/media.html#playing-the-media-resource:attr-media-loop-2

[2] https://html.spec.whatwg.org/multipage/media.html#seeking:dom-media-seek

[3] https://searchfox.org/mozilla-central/rev/eef79962ba73f7759fd74da658f6e5ceae0fc730/dom/media/MediaDecoderStateMachine.cpp#2973

[4] https://searchfox.org/mozilla-central/rev/eef79962ba73f7759fd74da658f6e5ceae0fc730/dom/media/MediaDecoderStateMachine.cpp#2362
Hi, jya,
Here is my preliminary idea, could you give me any suggestion?
Thank you.
Attachment #9018102 - Flags: feedback?(jyavenard)
Priority: -- → P2
I'm not sure you need a looping state, and if you could just piggy-back on the decoding state. Or use a new decoding state object that seek back to the first frame when reaching EOS)
Attachment #9018102 - Flags: feedback?(jyavenard)
Priority: P2 → P3
(In reply to Jean-Yves Avenard [:jya] from comment #2)
> I'm not sure you need a looping state, and if you could just piggy-back on
> the decoding state. Or use a new decoding state object that seek back to the
> first frame when reaching EOS)
It may be out of topic here, but I like the idea about adding a looping state more. The first attempt to implement seamless looping(bug 654787) is to add the code in decoding state, but it needs to add many specific functions for looping. To keep the logic for decoding as simple as possible, the logic for looping is moved to ReaderProxy. It aims to minimize the complexity for decoding.

The benefit for adding a new state is that it won't affect the playback if looping is disabled. It sounds reasonable to me.
(In reply to Chun-Min Chang[:chunmin] from comment #3)
> (In reply to Jean-Yves Avenard [:jya] from comment #2)
> > I'm not sure you need a looping state, and if you could just piggy-back on
> > the decoding state. Or use a new decoding state object that seek back to the
> > first frame when reaching EOS)
> It may be out of topic here, but I like the idea about adding a looping
> state more. The first attempt to implement seamless looping(bug 654787) is
> to add the code in decoding state, but it needs to add many specific
> functions for looping. To keep the logic for decoding as simple as possible,
> the logic for looping is moved to ReaderProxy. It aims to minimize the
> complexity for decoding.
> 
> The benefit for adding a new state is that it won't affect the playback if
> looping is disabled. It sounds reasonable to me.

you don't need to add a new state, you can just inherit a new one from decoding which handle EOS differently... I don't see how that would be much more complex than doing it from the ReaderProxy, quite the opposite
When the media which has `loop` attribute is playing to the end, the spec mentions that media should do seek to the start position [1].

During seeking, the dispatched events order [2] for MediaElement should be
1. seeking
2. timeupdate
3. seeked

[1] https://html.spec.whatwg.org/multipage/media.html#playing-the-media-resource:attr-media-loop-2
[2] https://html.spec.whatwg.org/multipage/media.html#seeking:dom-media-seek
Nobody is mirroring to 'mLogicallySeeking', so we can just use boolean instead.
Attachment #9019642 - Attachment description: Bug 1499903 - part3 : change 'mLogicallySeeking' to boolean → Bug 1499903 - part3 : change 'mLogicallySeeking' to Watchable
Pushed by alwu@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/3f6d3c425b42
part1 : correct the events order when we're in the seamless looping. r=chunmin
https://hg.mozilla.org/integration/autoland/rev/106752b77131
part2 : add test. r=chunmin
https://hg.mozilla.org/integration/autoland/rev/3c7165875616
part3 : change 'mLogicallySeeking' to Watchable r=chunmin
Backed out 3 changesets (Bug 1499903) for causing Bug 1502637

Push with failures: https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=3c7165875616d4b9250815f1a2d324469d5d2a36

Backout link: https://hg.mozilla.org/integration/autoland/rev/c6d1a860e5275fe442ef6319bbc330723e82aa7e

Failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=208182731&repo=mozilla-central&lineNumber=5689

[task 2018-10-27T12:25:12.765Z] 12:25:12     INFO - GECKO(1711) | [Child 1796, MediaPDecoder #2] WARNING: No previous granule position to use for Opus end trimming.: file /builds/worker/workspace/build/src/dom/media/ogg/OggCodecState.cpp, line 1232
[task 2018-10-27T12:25:12.780Z] 12:25:12     INFO - GECKO(1711) | [Child 1796, MediaPDecoder #2] WARNING: No previous granule position to use for Opus end trimming.: file /builds/worker/workspace/build/src/dom/media/ogg/OggCodecState.cpp, line 1232
[task 2018-10-27T12:25:13.864Z] 12:25:13     INFO - GECKO(1711) | [Child 1796, MediaPDecoder #2] WARNING: No previous granule position to use for Opus end trimming.: file /builds/worker/workspace/build/src/dom/media/ogg/OggCodecState.cpp, line 1232
[task 2018-10-27T12:25:14.074Z] 12:25:14     INFO - GECKO(1711) | [Child 1796, MediaPlayback #4] WARNING: Decoder=7f38e0bd2800 state=SEEKING Audio not synced after seek, maybe a poorly muxed file?: file /builds/worker/workspace/build/src/dom/media/MediaDecoderStateMachine.cpp, line 1213
[task 2018-10-27T12:25:14.448Z] 12:25:14     INFO - GECKO(1711) | [Child 1796, MediaPlayback #2] WARNING: Decoder=7f38e0bd2800 state=SEEKING Audio not synced after seek, maybe a poorly muxed file?: file /builds/worker/workspace/build/src/dom/media/MediaDecoderStateMachine.cpp, line 1213
[task 2018-10-27T12:25:15.272Z] 12:25:15     INFO - GECKO(1711) | --DOCSHELL 0x7f38e1b05800 == 3 [pid = 1796] [id = {f855ddbf-814d-434c-aae1-b5268777a264}]
[task 2018-10-27T12:25:18.878Z] 12:25:18     INFO - GECKO(1711) | Assertion failure: ((bool)(__builtin_expect(!!(!NS_FAILED_impl(rv)), 1))), at /builds/worker/workspace/build/src/dom/media/ReaderProxy.cpp:227
[task 2018-10-27T12:26:50.699Z] 12:26:50     INFO - GECKO(1711) | #01: mozilla::ReaderProxy::OnAudioDataRequestFailed(mozilla::MediaResult const&) [dom/media/ReaderProxy.cpp:0]
[task 2018-10-27T12:26:50.699Z] 12:26:50     INFO - 
[task 2018-10-27T12:26:50.699Z] 12:26:50     INFO - GECKO(1711) | #02: mozilla::EnableIf<true, void>::Type mozilla::MozPromise<RefPtr<mozilla::AudioData>, mozilla::MediaResult, true>::InvokeCallbackMethod<true, mozilla::ReaderProxy, RefPtr<mozilla::MozPromise<RefPtr<mozilla::AudioData>, mozilla::MediaResult, true> > (mozilla::ReaderProxy::*)(mozilla::MediaResult const&), mozilla::MediaResult, RefPtr<mozilla::MozPromise<RefPtr<mozilla::AudioData>, mozilla::MediaResult, true>::Private> >(mozilla::ReaderProxy*, RefPtr<mozilla::MozPromise<RefPtr<mozilla::AudioData>, mozilla::MediaResult, true> > (mozilla::ReaderProxy::*)(mozilla::MediaResult const&), mozilla::MediaResult&&, RefPtr<mozilla::MozPromise<RefPtr<mozilla::AudioData>, mozilla::MediaResult, true>::Private>&&) [mfbt/RefPtr.h:331]
[task 2018-10-27T12:26:50.699Z] 12:26:50     INFO - 
[task 2018-10-27T12:26:50.699Z] 12:26:50     INFO - GECKO(1711) | #03: mozilla::MozPromise<RefPtr<mozilla::AudioData>, mozilla::MediaResult, true>::ThenValue<mozilla::ReaderProxy*, RefPtr<mozilla::MozPromise<RefPtr<mozilla::AudioData>, mozilla::MediaResult, true> > (mozilla::ReaderProxy::*)(RefPtr<mozilla::AudioData>), RefPtr<mozilla::MozPromise<RefPtr<mozilla::AudioData>, mozilla::MediaResult, true> > (mozilla::ReaderProxy::*)(mozilla::MediaResult const&)>::DoResolveOrRejectInternal(mozilla::MozPromise<RefPtr<mozilla::AudioData>, mozilla::MediaResult, true>::ResolveOrRejectValue&) [mfbt/RefPtr.h:69]
[task 2018-10-27T12:26:50.700Z] 12:26:50     INFO - 
[task 2018-10-27T12:26:50.701Z] 12:26:50     INFO - GECKO(1711) | #04: mozilla::MozPromise<RefPtr<mozilla::AudioData>, mozilla::MediaResult, true>::ThenValueBase::ResolveOrRejectRunnable::Run() [mfbt/RefPtr.h:69]
[task 2018-10-27T12:26:50.702Z] 12:26:50     INFO - 
[task 2018-10-27T12:26:50.702Z] 12:26:50     INFO - GECKO(1711) | #05: mozilla::AutoTaskDispatcher::TaskGroupRunnable::Run() [mfbt/ThreadLocal.h:177]
[task 2018-10-27T12:26:50.703Z] 12:26:50     INFO - 
[task 2018-10-27T12:26:50.704Z] 12:26:50     INFO - GECKO(1711) | #06: mozilla::TaskQueue::Runner::Run() [xpcom/threads/TaskQueue.cpp:236]
[task 2018-10-27T12:26:50.704Z] 12:26:50     INFO - 
[task 2018-10-27T12:26:50.706Z] 12:26:50     INFO - GECKO(1711) | #07: nsThreadPool::Run() [xpcom/threads/nsThreadPool.cpp:244]
Flags: needinfo?(alwu)
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Target Milestone: mozilla65 → ---
I don't think the root cause of this intermittent failure is my patch, it seems to me that there is another problem which coincidentally appears. 

However, we can postpone to land this bug and wait for landing bug 1498440 first which changes ReaderProxy's behaviors a lots and might fix the intermittent failure.
Flags: needinfo?(alwu)
Depends on: 1498440
Pushed by alwu@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/ed4236eceb1a
part1 : correct the events order when we're in the seamless looping. r=chunmin
Pushed by alwu@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/634b4c2dad35
part3 : change 'mLogicallySeeking' to Watchable r=chunmin
Backed out 3 changesets (bug 1499903) for frequently asserting at dom/media/MediaDecoderStateMachine.cpp

Log:
https://treeherder.mozilla.org/logviewer.html#?job_id=210231807&repo=autoland&lineNumber=5163

INFO - TEST-INFO | Main app process: exit 0
[task 2018-11-07T02:58:27.417Z] 02:58:27     INFO - runtests.py | Application ran for: 0:08:53.976891
[task 2018-11-07T02:58:27.417Z] 02:58:27     INFO - zombiecheck | Reading PID log: /tmp/tmpCLPsdEpidlog
[task 2018-11-07T02:58:27.418Z] 02:58:27     INFO - ==> process 1752 launched child process 1772
[task 2018-11-07T02:58:27.418Z] 02:58:27     INFO - ==> process 1752 launched child process 1834
[task 2018-11-07T02:58:27.419Z] 02:58:27     INFO - ==> process 1752 launched child process 1859
[task 2018-11-07T02:58:27.419Z] 02:58:27     INFO - ==> process 1752 launched child process 1908
[task 2018-11-07T02:58:27.419Z] 02:58:27     INFO - ==> process 1752 launched child process 3141
[task 2018-11-07T02:58:27.420Z] 02:58:27     INFO - zombiecheck | Checking for orphan process with PID: 1908
[task 2018-11-07T02:58:27.421Z] 02:58:27     INFO - zombiecheck | Checking for orphan process with PID: 1834
[task 2018-11-07T02:58:27.421Z] 02:58:27     INFO - zombiecheck | Checking for orphan process with PID: 1859
[task 2018-11-07T02:58:27.421Z] 02:58:27     INFO - zombiecheck | Checking for orphan process with PID: 1772
[task 2018-11-07T02:58:27.422Z] 02:58:27     INFO - zombiecheck | Checking for orphan process with PID: 3141
[task 2018-11-07T02:58:27.422Z] 02:58:27     INFO - mozcrash Copy/paste: /usr/local/bin/linux64-minidump_stackwalk /tmp/tmpdMClOC.mozrunner/minidumps/76ae00ce-9100-07e2-b107-d35eaa2cd45c.dmp /builds/worker/workspace/build/symbols
[task 2018-11-07T02:58:38.645Z] 02:58:38     INFO - mozcrash Saved minidump as /builds/worker/workspace/build/blobber_upload_dir/76ae00ce-9100-07e2-b107-d35eaa2cd45c.dmp
[task 2018-11-07T02:58:38.647Z] 02:58:38     INFO - mozcrash Saved app info as /builds/worker/workspace/build/blobber_upload_dir/76ae00ce-9100-07e2-b107-d35eaa2cd45c.extra
[task 2018-11-07T02:58:38.756Z] 02:58:38     INFO - PROCESS-CRASH | Main app process exited normally | application crashed [@ mozilla::MediaDecoderStateMachine::LoopingDecodingState::HandleError(mozilla::MediaResult const&)]
[task 2018-11-07T02:58:38.758Z] 02:58:38     INFO - Crash dump filename: /tmp/tmpdMClOC.mozrunner/minidumps/76ae00ce-9100-07e2-b107-d35eaa2cd45c.dmp
[task 2018-11-07T02:58:38.758Z] 02:58:38     INFO - Operating system: Linux
[task 2018-11-07T02:58:38.759Z] 02:58:38     INFO -                   0.0.0 Linux 4.4.0-1014-aws #14taskcluster1-Ubuntu SMP Tue Apr 3 10:27:00 UTC 2018 x86_64
[task 2018-11-07T02:58:38.759Z] 02:58:38     INFO - CPU: amd64
[task 2018-11-07T02:58:38.760Z] 02:58:38     INFO -      family 6 model 62 stepping 4
[task 2018-11-07T02:58:38.761Z] 02:58:38     INFO -      2 CPUs
[task 2018-11-07T02:58:38.762Z] 02:58:38     INFO - 
[task 2018-11-07T02:58:38.762Z] 02:58:38     INFO - GPU: UNKNOWN
[task 2018-11-07T02:58:38.763Z] 02:58:38     INFO - 
[task 2018-11-07T02:58:38.763Z] 02:58:38     INFO - Crash reason:  SIGSEGV
[task 2018-11-07T02:58:38.764Z] 02:58:38     INFO - Crash address: 0x0
[task 2018-11-07T02:58:38.766Z] 02:58:38     INFO - Process uptime: not available
[task 2018-11-07T02:58:38.767Z] 02:58:38     INFO - 
[task 2018-11-07T02:58:38.767Z] 02:58:38     INFO - Thread 28 (crashed)
[task 2018-11-07T02:58:38.768Z] 02:58:38     INFO -  0  libxul.so!mozilla::MediaDecoderStateMachine::LoopingDecodingState::HandleError(mozilla::MediaResult const&) [MediaDecoderStateMachine.cpp:a15aa42f102ea8c042eff3d5e8e2b08f22f01663 : 932 + 0x0]
[task 2018-11-07T02:58:38.770Z] 02:58:38     INFO -     rax = 0x0000000000000000   rdx = 0x0000000000000000
[task 2018-11-07T02:58:38.771Z] 02:58:38     INFO -     rcx = 0x0000000000000000   rbx = 0x00007f2cad73b7c0
[task 2018-11-07T02:58:38.773Z] 02:58:38     INFO -     rsi = 0x00007f2ccf4ab770   rdi = 0x00007f2ccf4aa540
[task 2018-11-07T02:58:38.773Z] 02:58:38     INFO -     rbp = 0x00007f2cae48c600   rsp = 0x00007f2cae48c5b0
[task 2018-11-07T02:58:38.775Z] 02:58:38     INFO -      r8 = 0x00007f2ccf4ab770    r9 = 0x00007f2cae48d700
[task 2018-11-07T02:58:38.776Z] 02:58:38     INFO -     r10 = 0x0000000000000000   r11 = 0x0000000000000000
[task 2018-11-07T02:58:38.777Z] 02:58:38     INFO -     r12 = 0x00007f2cad73b808   r13 = 0x00007f2cad793200
[task 2018-11-07T02:58:38.778Z] 02:58:38     INFO -     r14 = 0x00007f2caa60b1c0   r15 = 0x00007f2cad793200
[task 2018-11-07T02:58:38.778Z] 02:58:38     INFO -     rip = 0x00007f2cc02922a9
[task 2018-11-07T02:58:38.779Z] 02:58:38     INFO -     Found by: given as instruction pointer in context
[task 2018-11-07T02:58:38.781Z] 02:58:38     INFO -  1  libxul.so!mozilla::MozPromise<RefPtr<mozilla::AudioData>, mozilla::MediaResult, true>::ThenValue<mozilla::MediaDecoderStateMachine::LoopingDecodingState::HandleEndOfAudio()::{lambda()#1}::operator()() const::{lambda(RefPtr<mozilla::AudioData>)#1}, mozilla::MediaDecoderStateMachine::LoopingDecodingState::HandleEndOfAudio()::{lambda()#1}::operator()() const::{lambda(mozilla::MediaResult const&)#1}>::DoResolveOrRejectInternal(mozilla::MozPromise<RefPtr<mozilla::AudioData>, mozilla::MediaResult, true>::ResolveOrRejectValue&) [MediaDecoderStateMachine.cpp:a15aa42f102ea8c042eff3d5e8e2b08f22f01663 : 917 + 0xb]
[task 2018-11-07T02:58:38.782Z] 02:58:38     INFO -     rbx = 0x00007f2cad73b7c0   rbp = 0x00007f2cae48c630
[task 2018-11-07T02:58:38.783Z] 02:58:38     INFO -     rsp = 0x00007f2cae48c610   r12 = 0x00007f2cad73b808
[task 2018-11-07T02:58:38.783Z] 02:58:38     INFO -     r13 = 0x0000000000000000   r14 = 0x00007f2caa60b1c0
[task 2018-11-07T02:58:38.784Z] 02:58:38     INFO -     r15 = 0x00007f2cad793200   rip = 0x00007f2cc0291ce4
[task 2018-11-07T02:58:38.785Z] 02:58:38     INFO -     Found by: call frame info
[task 2018-11-07T02:58:38.786Z] 02:58:38     INFO -  2  libxul.so!mozilla::MozPromise<RefPtr<mozilla::AudioData>, mozilla::MediaResult, true>::ThenValueBase::ResolveOrRejectRunnable::Run() [MozPromise.h:a15aa42f102ea8c042eff3d5e8e2b08f22f01663 : 411 + 0xb]
[task 2018-11-07T02:58:38.788Z] 02:58:38     INFO -     rbx = 0x00007f2ca95fc578   rbp = 0x00007f2cae48c660
[task 2018-11-07T02:58:38.788Z] 02:58:38     INFO -     rsp = 0x00007f2cae48c640   r12 = 0x0000000000000008
[task 2018-11-07T02:58:38.789Z] 02:58:38     INFO -     r13 = 0x0000000000000000   r14 = 0x00007f2ca95fc540
[task 2018-11-07T02:58:38.791Z] 02:58:38     INFO -     r15 = 0x00007f2cad73b7c0   rip = 0x00007f2cc0292877
[task 2018-11-07T02:58:38.791Z] 02:58:38     INFO -     Found by: call frame info
[task 2018-11-07T02:58:38.792Z] 02:58:38     INFO -  3  libxul.so!mozilla::AutoTaskDispatcher::TaskGroupRunnable::Run() [TaskDispatcher.h:a15aa42f102ea8c042eff3d5e8e2b08f22f01663 : 214 + 0x9]
[task 2018-11-07T02:58:38.792Z] 02:58:38     INFO -     rbx = 0x0000000000000000   rbp = 0x00007f2cae48c690
[task 2018-11-07T02:58:38.793Z] 02:58:38     INFO -     rsp = 0x00007f2cae48c670   r12 = 0x0000000000000008
[task 2018-11-07T02:58:38.793Z] 02:58:38     INFO -     r13 = 0x0000000000000000   r14 = 0x00007f2cb56a2000
[task 2018-11-07T02:58:38.793Z] 02:58:38     INFO -     r15 = 0x00007f2cad714518   rip = 0x00007f2cbe6f64a4
[task 2018-11-07T02:58:38.794Z] 02:58:38     INFO -     Found by: call frame info
[task 2018-11-07T02:58:38.794Z] 02:58:38     INFO -  4  libxul.so!mozilla::TaskQueue::Runner::Run() [TaskQueue.cpp:a15aa42f102ea8c042eff3d5e8e2b08f22f01663 : 235 + 0x9]
[task 2018-11-07T02:58:38.794Z] 02:58:38     INFO -     rbx = 0x00007f2cae48c730   rbp = 0x00007f2cae48c760
[task 2018-11-07T02:58:38.794Z] 02:58:38     INFO -     rsp = 0x00007f2cae48c6a0   r12 = 0x00007f2cad73c188
[task 2018-11-07T02:58:38.796Z] 02:58:38     INFO -     r13 = 0x0000000000000000   r14 = 0x00007f2cad7144f0
[task 2018-11-07T02:58:38.796Z] 02:58:38     INFO -     r15 = 0x00007f2cae48c6a8   rip = 0x00007f2cbe6fb194
[task 2018-11-07T02:58:38.796Z] 02:58:38     INFO -     Found by: call frame info
[task 2018-11-07T02:58:38.796Z] 02:58:38     INFO -  5  libxul.so!nsThreadPool::Run() [nsThreadPool.cpp:a15aa42f102ea8c042eff3d5e8e2b08f22f01663 : 245 + 0x9]
[task 2018-11-07T02:58:38.797Z] 02:58:38     INFO -     rbx = 0x00007f2cae48c7d8   rbp = 0x00007f2cae48c830
[task 2018-11-07T02:58:38.797Z] 02:58:38     INFO -     rsp = 0x00007f2cae48c770   r12 = 0x00007f2cae48c7c0
[task 2018-11-07T02:58:38.798Z] 02:58:38     INFO -     r13 = 0x00007f2cb58b43a8   r14 = 0x00007f2cb58b4310
[task 2018-11-07T02:58:38.798Z] 02:58:38     INFO -     r15 = 0x00007f2cae48c7e8   rip = 0x00007f2cbe7090d8
[task 2018-11-07T02:58:38.798Z] 02:58:38     INFO -     Found by: call frame info
[task 2018-11-07T02:58:38.798Z] 02:58:38     INFO -  6  libxul.so!non-virtual thunk to nsThreadPool::Run() [nsThreadPool.cpp:a15aa42f102ea8c042eff3d5e8e2b08f22f01663 : 0 + 0x5]
[task 2018-11-07T02:58:38.798Z] 02:58:38     INFO -     rbx = 0x00007f2cb58b42f0   rbp = 0x00007f2cae48c840
[task 2018-11-07T02:58:38.798Z] 02:58:38     INFO -     rsp = 0x00007f2cae48c840   r12 = 0x00007f2cb569a860
[task 2018-11-07T02:58:38.798Z] 02:58:38     INFO -     r13 = 0x0000000000000001   r14 = 0x00007f2cb569a7c0
[task 2018-11-07T02:58:38.798Z] 02:58:38     INFO -     r15 = 0x00000000ffffffff   rip = 0x00007f2cbe7091c7
[task 2018-11-07T02:58:38.798Z] 02:58:38     INFO -     Found by: call frame info
[task 2018-11-07T02:58:38.798Z] 02:58:38     INFO -  7  libxul.so!nsThread::ProcessNextEvent(bool, bool*) [nsThread.cpp:a15aa42f102ea8c042eff3d5e8e2b08f22f01663 : 1246 + 0x9]
[task 2018-11-07T02:58:38.798Z] 02:58:38     INFO -     rbx = 0x00007f2cb58b42f0   rbp = 0x00007f2cae48cda0
[task 2018-11-07T02:58:38.799Z] 02:58:38     INFO -     rsp = 0x00007f2cae48c850   r12 = 0x00007f2cb569a860
[task 2018-11-07T02:58:38.799Z] 02:58:38     INFO -     r13 = 0x0000000000000001   r14 = 0x00007f2cb569a7c0
[task 2018-11-07T02:58:38.799Z] 02:58:38     INFO -     r15 = 0x00000000ffffffff   rip = 0x00007f2cbe705553
[task 2018-11-07T02:58:38.799Z] 02:58:38     INFO -     Found by: call frame info
[task 2018-11-07T02:58:38.799Z] 02:58:38     INFO -  8  libxul.so!NS_ProcessNextEvent(nsIThread*, bool) [nsThreadUtils.cpp:a15aa42f102ea8c042eff3d5e8e2b08f22f01663 : 530 + 0x10]
[task 2018-11-07T02:58:38.799Z] 02:58:38     INFO -     rbx = 0x0000000000000001   rbp = 0x00007f2cae48cdd0
[task 2018-11-07T02:58:38.799Z] 02:58:38     INFO -     rsp = 0x00007f2cae48cdb0   r12 = 0x0000000000000000
[task 2018-11-07T02:58:38.799Z] 02:58:38     INFO -     r13 = 0x00007f2cad8390a0   r14 = 0x00007f2cae48cdbf
[task 2018-11-07T02:58:38.800Z] 02:58:38     INFO -     r15 = 0x00007f2cb569a7c0   rip = 0x00007f2cbe7078a7
[task 2018-11-07T02:58:38.800Z] 02:58:38     INFO -     Found by: call frame info
[task 2018-11-07T02:58:38.800Z] 02:58:38     INFO -  9  libxul.so!mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*) [MessagePump.cpp:a15aa42f102ea8c042eff3d5e8e2b08f22f01663 : 364 + 0xd]
[task 2018-11-07T02:58:38.800Z] 02:58:38     INFO -     rbx = 0x00007f2cb56c2ae0   rbp = 0x00007f2cae48ce20
[task 2018-11-07T02:58:38.800Z] 02:58:38     INFO -     rsp = 0x00007f2cae48cde0   r12 = 0x0000000000000000
[task 2018-11-07T02:58:38.800Z] 02:58:38     INFO -     r13 = 0x00007f2cad8390a0   r14 = 0x00007f2cad839080
[task 2018-11-07T02:58:38.800Z] 02:58:38     INFO -     r15 = 0x00007f2cb569a7c0   rip = 0x00007f2cbeb8bb90
[task 2018-11-07T02:58:38.800Z] 02:58:38     INFO -     Found by: call frame info
[task 2018-11-07T02:58:38.800Z] 02:58:38     INFO - 10  libxul.so!MessageLoop::Run() [message_loop.cc:a15aa42f102ea8c042eff3d5e8e2b08f22f01663 : 318 + 0x8]
[task 2018-11-07T02:58:38.800Z] 02:58:38     INFO -     rbx = 0x00007f2cb56c2ae0   rbp = 0x00007f2cae48ce60
[task 2018-11-07T02:58:38.800Z] 02:58:38     INFO -     rsp = 0x00007f2cae48ce30   r12 = 0x00007f2cae48ce90
[task 2018-11-07T02:58:38.800Z] 02:58:38     INFO -     r13 = 0x00007f2cb569a7c0   r14 = 0x00007f2cae48ce38
[task 2018-11-07T02:58:38.800Z] 02:58:38     INFO -     r15 = 0x00007f2cb56c2ae0   rip = 0x00007f2cbeb56a5f
[task 2018-11-07T02:58:38.801Z] 02:58:38     INFO -     Found by: call frame info
[task 2018-11-07T02:58:38.801Z] 02:58:38     INFO - 11  libxul.so!nsThread::ThreadFunc(void*) [nsThread.cpp:a15aa42f102ea8c042eff3d5e8e2b08f22f01663 : 505 + 0x8]
[task 2018-11-07T02:58:38.801Z] 02:58:38     INFO -     rbx = 0x00007f2cc54878f8   rbp = 0x00007f2cae48cec0
[task 2018-11-07T02:58:38.801Z] 02:58:38     INFO -     rsp = 0x00007f2cae48ce70   r12 = 0x00007f2cae48ce90
[task 2018-11-07T02:58:38.801Z] 02:58:38     INFO -     r13 = 0x00007f2cb569a7c0   r14 = 0x00007f2cb569a800
[task 2018-11-07T02:58:38.801Z] 02:58:38     INFO -     r15 = 0x00007f2cb56c2ae0   rip = 0x00007f2cbe7033f3
[task 2018-11-07T02:58:38.801Z] 02:58:38     INFO -     Found by: call frame info
[task 2018-11-07T02:58:38.801Z] 02:58:38     INFO - 12  libnspr4.so!_pt_root [ptthread.c:a15aa42f102ea8c042eff3d5e8e2b08f22f01663 : 201 + 0x3]
[task 2018-11-07T02:58:38.801Z] 02:58:38     INFO -     rbx = 0x00007f2caca865e0   rbp = 0x00007f2cae48cf10
[task 2018-11-07T02:58:38.801Z] 02:58:38     INFO -     rsp = 0x00007f2cae48ced0   r12 = 0x00007f2cae48d670
[task 2018-11-07T02:58:38.801Z] 02:58:38     INFO -     r13 = 0x0000000000000000   r14 = 0x0000000000000c3e
[task 2018-11-07T02:58:38.801Z] 02:58:38     INFO -     r15 = 0x00007f2cae48d700   rip = 0x00007f2cd0547d6e
[task 2018-11-07T02:58:38.801Z] 02:58:38     INFO -     Found by: call frame info
[task 2018-11-07T02:58:38.801Z] 02:58:38     INFO - 13  libpthread-2.23.so + 0x76ba
[task 2018-11-07T02:58:38.801Z] 02:58:38     INFO -     rbx = 0x0000000000000000   rbp = 0x0000000000000000
[task 2018-11-07T02:58:38.801Z] 02:58:38     INFO -     rsp = 0x00007f2cae48cf20   r12 = 0x0000000000000000
[task 2018-11-07T02:58:38.801Z] 02:58:38     INFO -     r13 = 0x00007ffcb30ef1bf   r14 = 0x0000000000040000
[task 2018-11-07T02:58:38.802Z] 02:58:38     INFO -     r15 = 0x00007f2cb5b98930   rip = 0x00007f2cd01636ba
[task 2018-11-07T02:58:38.802Z] 02:58:38     INFO -     Found by: call frame info
[task 2018-11-07T02:58:38.802Z] 02:58:38     INFO - 14  libc-2.23.so + 0x10741d
[task 2018-11-07T02:58:38.802Z] 02:58:38     INFO -     rsp = 0x00007f2cae48cfc0   rip = 0x00007f2ccf1ec41d
[task 2018-11-07T02:58:38.802Z] 02:58:38     INFO -     Found by: stack scanning

Push with failures:
https://treeherder.mozilla.org/#/jobs?repo=autoland&group_state=expanded&revision=ed4236eceb1a4cae6b50523b019934bda58dcd8b

Backout:
https://hg.mozilla.org/integration/autoland/rev/88469512befe15042bbdbd6d7d6eb012c20900ee
Flags: needinfo?(alwu)
Hi, Jya,

Comment16 pointed out that sometime we would hit the assertion when running `test_looping_eventsOrder.html` on Linux, and I can't reproduce it on desktop.

I have no idea why we would get EOS after seeking to the head position, the only situation I can image is that the audio track only contains audio sample with negative start time. 

However, it's apparently not a case I assumed because I checked all files in `gSmallTests`, none of them are this kind of file.

Do you have any idea? If not, I would like to remove the assertion first as a solution.

Thank you.
Flags: needinfo?(alwu) → needinfo?(jyavenard)
Problem resolved.

This can now reland.
Flags: needinfo?(jyavenard)
The failure still exists, there are 3 fails from 50 times on try. I still have no idea about this failure, so I'm going to remove the assertion as temporary solution.

[1] https://treeherder.mozilla.org/#/jobs?repo=try&revision=4599edbdde02bea581c4cc4b8338e7a96befcc4a
Now the problem is that we would hit a assertion which is that we can't get data after seeking to 0s when we use `gSmallTests` in `test_looping_eventsOrder.html`.

That assertion is not easy to find the root cause, I can only reproduce it on try server. In order not to block following implementation of seamless looping, I decide not to use `gSmallTests` in `test_looping_eventsOrder.html.`, and choose the video and audio which will not hit the assertion, and then land this bug first. I tried to push only test part on try server without patch1 and patch2, and I still got the assertion fail which means the assertion is not part of this bug, I will continue investigating it on bug1508501.
Attachment #9025821 - Attachment is obsolete: true
Pushed by alwu@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/55b9e352f46d
part1 : correct the events order when we're in the seamless looping. r=chunmin
https://hg.mozilla.org/integration/autoland/rev/7b73044f0618
part2 : add test. r=chunmin
https://hg.mozilla.org/integration/autoland/rev/0f223b4c9a71
part3 : change 'mLogicallySeeking' to Watchable r=chunmin
https://hg.mozilla.org/mozilla-central/rev/55b9e352f46d
https://hg.mozilla.org/mozilla-central/rev/7b73044f0618
https://hg.mozilla.org/mozilla-central/rev/0f223b4c9a71
Status: REOPENED → RESOLVED
Closed: 1 year ago1 year ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla65
You need to log in before you can comment on or make changes to this bug.