1273612 - Assertion failure: !mIsDormant (should be out of dormant by now)

Status: RESOLVED FIXED

(Core :: Audio/Video: Playback, defect, P2)

Description

[Kamil Jozwiak [:kjozwiak]]

While scrolling through Facebook using the latest m-c in debug mode, sometimes the tab will completely crash with "Assertion failure: !mIsDormant" (stack listed below). I'm not sure if this is related to some specific content that's causing the crash, or just a general issue. It's pretty difficult to reproduce and requires a lot of scrolling through the Facebook timeline. Sometimes I can get it to reproduce in a few minutes, and sometimes it takes me at least an hour or so of consistently scrolling through the timeline.

STR (not easy to reproduce):

* run m-c under debug mode (ac_add_options --enable-debug)
* load/login into Facebook (using e10s)
* start scrolling up/down the Facebook timeline

Stack from the console:
=======================

Assertion failure: !mIsDormant (should be out of dormant by now), at /Users/kjozwiak/projects/m-c-containers/dom/media/MediaDecoder.cpp:824
#01: mozilla::MediaDecoder::Seek(double, mozilla::SeekTarget::Type)[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x36cd4d4]
#02: mozilla::dom::HTMLMediaElement::Seek(double, mozilla::SeekTarget::Type, mozilla::ErrorResult&)[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x35319af]
#03: mozilla::dom::HTMLMediaElement::SetCurrentTime(double, mozilla::ErrorResult&)[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x3531a8e]
#04: mozilla::dom::HTMLMediaElement::SetCurrentTime(double)[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x3531e78]
#05: mozilla::dom::HTMLMediaElement::MetadataLoaded(mozilla::MediaInfo const*, nsAutoPtr<nsDataHashtable<nsCStringHashKey, nsCString> const>)[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x3538761]
#06: mozilla::MediaDecoder::MetadataLoaded(nsAutoPtr<mozilla::MediaInfo>, nsAutoPtr<nsDataHashtable<nsCStringHashKey, nsCString> >, mozilla::MediaDecoderEventVisibility)[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x36ccfed]
#07: mozilla::EnableIf<TakeArgs<void (mozilla::MediaDecoder::*)(nsAutoPtr<mozilla::MediaInfo>, nsAutoPtr<nsDataHashtable<nsCStringHashKey, nsCString> >, mozilla::MediaDecoderEventVisibility)>::value, mozilla::MediaEventListener>::Type mozilla::MediaEventSource[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x3736635]
#08: void mozilla::detail::ListenerHelper<mozilla::AbstractThread, mozilla::EnableIf<TakeArgs<void (mozilla::MediaDecoder::*)(nsAutoPtr<mozilla::MediaInfo>, nsAutoPtr<nsDataHashtable<nsCStringHashKey, nsCString> >, mozilla::MediaDecoderEventVisibility)>::value[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x373655b]
#09: mozilla::detail::ListenerHelper<mozilla::AbstractThread, mozilla::EnableIf<TakeArgs<void (mozilla::MediaDecoder::*)(nsAutoPtr<mozilla::MediaInfo>, nsAutoPtr<nsDataHashtable<nsCStringHashKey, nsCString> >, mozilla::MediaDecoderEventVisibility)>::value, moz[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x3736327]
#10: mozilla::AutoTaskDispatcher::TaskGroupRunnable::Run()[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x1b57f5]
#11: nsThread::ProcessNextEvent(bool, bool*)[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x1a75a1]
#12: NS_ProcessPendingEvents(nsIThread*, unsigned int)[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x22db6c]
#13: nsBaseAppShell::NativeEventCallback()[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x4369d7e]
#14: nsAppShell::ProcessGeckoEvents(void*)[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x4401b62]
#15: __CFRUNLOOP_IS_CALLING_OUT_TO_A_SOURCE0_PERFORM_FUNCTION__[/System/Library/Frameworks/CoreFoundation.framework/Versions/A/CoreFoundation +0xaa881]
#16: __CFRunLoopDoSources0[/System/Library/Frameworks/CoreFoundation.framework/Versions/A/CoreFoundation +0x89fbc]
#17: __CFRunLoopRun[/System/Library/Frameworks/CoreFoundation.framework/Versions/A/CoreFoundation +0x894df]
#18: CFRunLoopRunSpecific[/System/Library/Frameworks/CoreFoundation.framework/Versions/A/CoreFoundation +0x88ed8]
#19: RunCurrentEventLoopInMode[/System/Library/Frameworks/Carbon.framework/Versions/A/Frameworks/HIToolbox.framework/Versions/A/HIToolbox +0x30935]
#20: ReceiveNextEventCommon[/System/Library/Frameworks/Carbon.framework/Versions/A/Frameworks/HIToolbox.framework/Versions/A/HIToolbox +0x3076f]
#21: _BlockUntilNextEventMatchingListInModeWithFilter[/System/Library/Frameworks/Carbon.framework/Versions/A/Frameworks/HIToolbox.framework/Versions/A/HIToolbox +0x305af]
#22: _DPSNextEvent[/System/Library/Frameworks/AppKit.framework/Versions/C/AppKit +0x48efa]
#23: -[NSApplication _nextEventMatchingEventMask:untilDate:inMode:dequeue:][/System/Library/Frameworks/AppKit.framework/Versions/C/AppKit +0x4832a]
#24: -[GeckoNSApplication nextEventMatchingMask:untilDate:inMode:dequeue:][/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x4400654]
#25: -[NSApplication run][/System/Library/Frameworks/AppKit.framework/Versions/C/AppKit +0x3ce84]
#26: nsAppShell::Run()[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x440252c]
#27: nsAppStartup::Run()[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x55583ab]
#28: XREMain::XRE_mainRun()[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x560eae6]
#29: XREMain::XRE_main(int, char**, nsXREAppData const*)[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x560f97c]
#30: XRE_main[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x560fe57]
#31: do_main(int, char**, char**, nsIFile*)[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/firefox +0x2acd]
#32: main[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/firefox +0x1e55]

Comment 1

[JW Wang [:jwwang] [:jw_wang]]

Can you catch logs with "NSPR_LOG_MODULES=timestamp:1,MediaDecoder:4,nsMediaElement:4"?

Comment 2

[Kamil Jozwiak [:kjozwiak]]

Attachment: crashLog.txt

(In reply to JW Wang [:jwwang] from comment #1)
> Can you catch logs with
> "NSPR_LOG_MODULES=timestamp:1,MediaDecoder:4,nsMediaElement:4"?

I spent about 3 hours attempting to reproduce this crash without any luck. When I originally created this bug, I could reproduce this pretty consistently by just scrolling through the Facebook timeline while snapping/moving tabs between different windows. I've managed to get the following assertions (listed below), but I'm pretty sure these have nothing to do with the original one that I mentioned in comment #0.

I'll leave this bug opened for a week or two more, and if I don't see this happening anymore while testing containers, I'll just mark the bug WFM.

JW Wang, mind taking a quick look at the attached log to see if there's anything there that's related to the original assertion from comment #0?

First Assertion (more information in the crashLog.txt file attached)

Assertion failure: !!compositor, at /Users/kjozwiak/projects/m-c-containers/gfx/layers/basic/BasicCompositor.cpp:716
#01: mozilla::layers::AssertBasicCompositor(mozilla::layers::Compositor*)[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x1deae6c]

Second Assertion (more information in the crashLog.txt file attached)

Assertion failure: mDestroyed, at /Users/kjozwiak/projects/m-c-containers/gfx/layers/IPDLActor.h:43
[Child 87166] ###!!! ABORT: Aborting on channel error.: file /Users/kjozwiak/projects/m-c-containers/ipc/glue/MessageChannel.cpp, line 2052
#01: mozilla::layers::ChildActor<mozilla::layers::PCompositableChild>::~ChildActor()[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x1e26ca6]
#01: mozilla::ipc::MessageChannel::OnChannelErrorFromLink()[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0xba4f52]

Comment 3

[Kamil Jozwiak [:kjozwiak]]

I've finally managed to reproduce the crash that I was getting originally with the logging enabled that was suggested in comment # 1. I've dumped the entire log into pastebin:

* https://pastebin.mozilla.org/8874578

Stack:
======

Assertion failure: !mIsDormant (should be out of dormant by now), at /Users/kjozwiak/projects/m-c-containers/dom/media/MediaDecoder.cpp:824
#01: mozilla::MediaDecoder::Seek(double, mozilla::SeekTarget::Type)[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x3b1d584]
#02: mozilla::dom::HTMLMediaElement::Seek(double, mozilla::SeekTarget::Type, mozilla::ErrorResult&)[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x3975f5f]
#03: mozilla::dom::HTMLMediaElement::SetCurrentTime(double, mozilla::ErrorResult&)[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x397607e]
#04: mozilla::dom::HTMLMediaElementBinding::set_currentTime(JSContext*, JS::Handle<JSObject*>, mozilla::dom::HTMLMediaElement*, JSJitSetterCallArgs)[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x3454bba]
#05: mozilla::dom::GenericBindingSetter(JSContext*, unsigned int, JS::Value*)[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x35a8d52]
#06: js::CallJSNative(JSContext*, bool (*)(JSContext*, unsigned int, JS::Value*), JS::CallArgs const&)[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x76cc44d]
#07: js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct)[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x76b16ae]
#08: InternalCall(JSContext*, js::AnyInvokeArgs const&)[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x76b1a77]
#09: js::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>)[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x768fd76]
#10: js::CallSetter(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, JS::Handle<JS::Value>)[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x76b24f9]
#11: SetExistingProperty(JSContext*, JS::Handle<js::NativeObject*>, JS::Handle<jsid>, JS::Handle<JS::Value>, JS::Handle<JS::Value>, JS::Handle<js::NativeObject*>, JS::Handle<js::Shape*>, JS::ObjectOpResult&)[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x7729558]
#12: js::NativeSetProperty(JSContext*, JS::Handle<js::NativeObject*>, JS::Handle<jsid>, JS::Handle<JS::Value>, JS::Handle<JS::Value>, js::QualifiedBool, JS::ObjectOpResult&)[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x7728bde]
#13: js::SetProperty(JSContext*, JS::Handle<JSObject*>, JS::Handle<jsid>, JS::Handle<JS::Value>, JS::Handle<JS::Value>, JS::ObjectOpResult&)[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x76f1c4f]
#14: SetPropertyOperation(JSContext*, JSOp, JS::Handle<JS::Value>, JS::Handle<jsid>, JS::Handle<JS::Value>)[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x76bd77a]
#15: Interpret(JSContext*, js::RunState&)[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x76a4fbd]
#16: js::RunScript(JSContext*, js::RunState&)[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x769c382]
#17: js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct)[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x76b177b]
#18: InternalCall(JSContext*, js::AnyInvokeArgs const&)[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x76b1a77]
#19: js::CallFromStack(JSContext*, JS::CallArgs const&)[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x76b187d]
#20: js::jit::DoCallFallback(JSContext*, js::jit::BaselineFrame*, js::jit::ICCall_Fallback*, unsigned int, JS::Value*, JS::MutableHandle<JS::Value>)[/Users/kjozwiak/projects/m-c-containers/objdir-ff-debug/dist/NightlyDebug.app/Contents/MacOS/XUL +0x6f5becf]

Comment 4

[JW Wang [:jwwang] [:jw_wang]]

Thanks for the hard work! I will start analyzing the logs now.

Comment 5

[JW Wang [:jwwang] [:jw_wang]]

The assertion is added in https://hg.mozilla.org/integration/mozilla-inbound/rev/37e78e0926ff#l1.12.

However, it was not there in the previous commit https://hg.mozilla.org/integration/mozilla-inbound/rev/707a87454058 in bug 1229987 comment 18.

Hi Jya,
Is that an accident to add the assertion that didn't appear in the previous commit?

Comment 6

[Jean-Yves Avenard [:jya]]

I don't recall. it may be.

I'm surprised we could still still be in dormant mode however by the time MediaDecoder::Seek is called however, especially as UpdateDormantState(false /* aDormantTimeout */, true /* aActivity */); is called just above which should have gotten out of dormant.

Comment 7

[JW Wang [:jwwang] [:jw_wang]]

Here is the log provided by Kamil:
2016-06-02 23:32:07.563792 UTC - [Main Thread]: D/nsMediaElement 12e989000 SetCurrentTime(0.148000) starting seek
2016-06-02 23:32:07.563814 UTC - [Main Thread]: D/MediaDecoder Decoder=187508c00 UpdateDormantState aTimeout=0 aActivity=1 mIsDormant=1 ownerActive=0 mIsVisible=0 mIsHeuristicDormant=0 mPlayState=PLAY_STATE_LOADING encrypted=0
Assertion failure: !mIsDormant (should be out of dormant by now), at /Users/kjozwiak/projects/m-c-containers/dom/media/MediaDecoder.cpp:824

It didn't come out of dormant state because the document is inactive and invisible (ownerActive=0 mIsVisible=0) while Seek() was called.

Comment 8

[Sotaro Ikeda [:sotaro]]

Attachment: patch - Do not enter dormant when MediaDecoder is not paused

Comment 9

[JW Wang [:jwwang] [:jw_wang]]

Comment on attachment 8764448 [details] [diff] [review]
patch - Do not enter dormant when MediaDecoder is not paused

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

Please change the comment to "Do not enter dormant when MediaDecoder is not paused" which means we don't enter dormant while loading metadata or seeking.

Comment 10

[Sotaro Ikeda [:sotaro]]

Attachment: patch - Do not enter dormant when MediaDecoder is not paused

Update a comment.

Comment 11

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/40861df31651
Do not enter dormant when MediaDecoder is not paused r=jwwang

Comment 12

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/40861df31651