Closed Bug 1668452 Opened 4 years ago Closed 3 years ago

Intermittent Assertion failure: mAudioContextOperation == AudioContextOperation::Close (We should be reviving the graph?), at /builds/worker/checkouts/gecko/dom/media/MediaTrackGraph.cpp:3532

Categories

(Core :: Audio/Video: MediaStreamGraph, defect, P5)

defect

Tracking

()

RESOLVED FIXED
100 Branch
Tracking Status
firefox-esr91 --- wontfix
firefox98 --- wontfix
firefox99 --- wontfix
firefox100 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: karlt)

References

(Blocks 2 open bugs, Regression)

Details

(Keywords: assertion, intermittent-failure, regression)

Crash Data

Attachments

(3 files)

Filed by: btara [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=317245526&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/EEwNujshRyaexphOo1l15w/runs/0/artifacts/public/logs/live_backing.log


[task 2020-10-01T05:29:11.479Z] 05:29:11 INFO - TEST-START | dom/media/webaudio/test/test_waveDecoder.html
[task 2020-10-01T05:29:11.564Z] 05:29:11 INFO - GECKO(3975) | Assertion failure: mAudioContextOperation == AudioContextOperation::Close (We should be reviving the graph?), at /builds/worker/checkouts/gecko/dom/media/MediaTrackGraph.cpp:3532
[task 2020-10-01T05:29:11.571Z] 05:29:11 INFO - Initializing stack-fixing for the first stack frame, this may take a while...
[task 2020-10-01T05:29:19.884Z] 05:29:19 INFO - GECKO(3975) | #01: mozilla::MediaTrackGraphImpl::AppendMessage(mozilla::UniquePtr<mozilla::ControlMessage, mozilla::DefaultDelete<mozilla::ControlMessage> >) [dom/media/MediaTrackGraph.cpp:1878]
[task 2020-10-01T05:29:19.884Z] 05:29:19 INFO - GECKO(3975) | #02: mozilla::MediaTrackGraph::ApplyAudioContextOperation(mozilla::MediaTrack*, nsTArray<RefPtr<mozilla::MediaTrack> >, mozilla::dom::AudioContextOperation) [dom/media/MediaTrackGraph.cpp:3630]
[task 2020-10-01T05:29:19.885Z] 05:29:19 INFO - GECKO(3975) | #03: mozilla::dom::AudioContext::ResumeInternal(mozilla::dom::AudioContextOperationFlags) [dom/media/webaudio/AudioContext.cpp:1036]
[task 2020-10-01T05:29:19.885Z] 05:29:19 INFO - GECKO(3975) | #04: mozilla::dom::AudioContext::AudioContext(nsPIDOMWindowInner*, bool, unsigned int, unsigned int, float) [dom/media/webaudio/AudioContext.cpp:187]
[task 2020-10-01T05:29:19.886Z] 05:29:19 INFO - GECKO(3975) | #05: mozilla::dom::AudioContext::Constructor(mozilla::dom::GlobalObject const&, mozilla::dom::AudioContextOptions const&, mozilla::ErrorResult&) [dom/media/webaudio/AudioContext.cpp:294]
[task 2020-10-01T05:29:19.886Z] 05:29:19 INFO - GECKO(3975) | #06: mozilla::dom::AudioContext_Binding::_constructor(JSContext*, unsigned int, JS::Value*) [s3:gecko-generated-sources:d5ddfcc5d6bb56507a57bd339ae48c31d7cc7a9b7c04d206c6ef1cef1f774a7c5a8a2912a2e43979baece5e357af116f9f0def3fa75d15f6fb8718129246d174/dom/bindings/AudioContextBinding.cpp::856]
[task 2020-10-01T05:29:19.886Z] 05:29:19 INFO - GECKO(3975) | #07: CallJSNative(JSContext*, bool ()(JSContext, unsigned int, JS::Value*), js::CallReason, JS::CallArgs const&) [js/src/vm/Interpreter.cpp:508]
[task 2020-10-01T05:29:19.887Z] 05:29:19 INFO - GECKO(3975) | #08: CallJSNativeConstructor(JSContext*, bool ()(JSContext, unsigned int, JS::Value*), JS::CallArgs const&) [js/src/vm/Interpreter.cpp:524]
[task 2020-10-01T05:29:19.887Z] 05:29:19 INFO - GECKO(3975) | #09: InternalConstruct(JSContext*, js::AnyConstructArgs const&) [js/src/vm/Interpreter.cpp:728]
[task 2020-10-01T05:29:19.887Z] 05:29:19 INFO - GECKO(3975) | #10: Interpret(JSContext*, js::RunState&) [js/src/vm/Interpreter.cpp:3327]
[task 2020-10-01T05:29:19.888Z] 05:29:19 INFO - GECKO(3975) | #11: js::RunScript(JSContext*, js::RunState&) [js/src/vm/Interpreter.cpp:469]
[task 2020-10-01T05:29:19.888Z] 05:29:19 INFO - GECKO(3975) | #12: js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) [js/src/vm/Interpreter.cpp:637]
[task 2020-10-01T05:29:19.890Z] 05:29:19 INFO - GECKO(3975) | #13: InternalCall(JSContext*, js::AnyInvokeArgs const&, js::CallReason) [js/src/vm/Interpreter.cpp:665]
[task 2020-10-01T05:29:19.890Z] 05:29:19 INFO - GECKO(3975) | #14: js::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>, js::CallReason) [js/src/vm/Interpreter.cpp:682]
[task 2020-10-01T05:29:19.890Z] 05:29:19 INFO - GECKO(3975) | #15: js::fun_apply(JSContext*, unsigned int, JS::Value*) [js/src/vm/JSFunction.cpp:1209]
[task 2020-10-01T05:29:19.900Z] 05:29:19 INFO - GECKO(3975) | #16: CallJSNative(JSContext*, bool ()(JSContext, unsigned int, JS::Value*), js::CallReason, JS::CallArgs const&) [js/src/vm/Interpreter.cpp:508]
[task 2020-10-01T05:29:19.900Z] 05:29:19 INFO - GECKO(3975) | #17: js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) [js/src/vm/Interpreter.cpp:600]
[task 2020-10-01T05:29:19.901Z] 05:29:19 INFO - GECKO(3975) | #18: InternalCall(JSContext*, js::AnyInvokeArgs const&, js::CallReason) [js/src/vm/Interpreter.cpp:665]
[task 2020-10-01T05:29:19.901Z] 05:29:19 INFO - GECKO(3975) | #19: js::jit::DoCallFallback(JSContext*, js::jit::BaselineFrame*, js::jit::ICCall_Fallback*, unsigned int, JS::Value*, JS::MutableHandle<JS::Value>) [js/src/jit/BaselineIC.cpp:3027]
[task 2020-10-01T05:29:19.902Z] 05:29:19 INFO - GECKO(3975) | #20: ??? (???:???)
[task 2020-10-01T05:29:19.902Z] 05:29:19 INFO - GECKO(3975) | [Parent 3975, Breakpad Server] WARNING: Resource acquired is being released in non-LIFO order; why?
[task 2020-10-01T05:29:19.903Z] 05:29:19 INFO - GECKO(3975) | : file /builds/worker/checkouts/gecko/xpcom/threads/BlockingResourceBase.cpp, line 292
[task 2020-10-01T05:29:19.903Z] 05:29:19 INFO - GECKO(3975) | --- Mutex : dumpSafetyLock (currently acquired)
[task 2020-10-01T05:29:19.904Z] 05:29:19 INFO - GECKO(3975) | calling context
[task 2020-10-01T05:29:19.904Z] 05:29:19 INFO - GECKO(3975) | [stack trace unavailable]
[task 2020-10-01T05:29:19.905Z] 05:29:19 INFO - GECKO(3975) | [Parent 3975, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp, line 511
[task 2020-10-01T05:29:19.905Z] 05:29:19 INFO - GECKO(3975) | [Parent 3975, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp, line 511
[task 2020-10-01T05:29:19.905Z] 05:29:19 INFO - GECKO(3975) | [Parent 3975, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp, line 511
[task 2020-10-01T05:29:19.906Z] 05:29:19 INFO - GECKO(3975) | [Parent 3975, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp, line 511
[task 2020-10-01T05:29:19.906Z] 05:29:19 INFO - GECKO(3975) | [Parent 3975, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp, line 511
[task 2020-10-01T05:29:19.906Z] 05:29:19 INFO - GECKO(3975) | [Parent 3975, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp, line 511
[task 2020-10-01T05:29:19.907Z] 05:29:19 INFO - GECKO(3975) | [Parent 3975, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/workspace/obj-build/dist/include/mozilla/ipc/ProtocolUtils.h, line 295
[task 2020-10-01T05:29:19.907Z] 05:29:19 INFO - GECKO(3975) | [Child 4241, Main Thread] WARNING: NS_ENSURE_TRUE(browserChrome) failed: file /builds/worker/checkouts/gecko/docshell/base/nsDocShell.cpp, line 12090
[task 2020-10-01T05:29:19.908Z] 05:29:19 ERROR - GECKO(3975) | A content process crashed and MOZ_CRASHREPORTER_SHUTDOWN is set, shutting down
[task 2020-10-01T05:29:19.908Z] 05:29:19 INFO - GECKO(3975) | [Parent 3975, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp, line 511
[task 2020-10-01T05:29:19.908Z] 05:29:19 INFO - GECKO(3975) | [Parent 3975, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp, line 511
[task 2020-10-01T05:29:19.909Z] 05:29:19 INFO - GECKO(3975) | [Parent 3975, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/workspace/obj-build/dist/include/mozilla/ipc/ProtocolUtils.h, line 295
[task 2020-10-01T05:29:19.909Z] 05:29:19 INFO - GECKO(3975) | [Parent 3975, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorProtocol.cpp, line 172
[task 2020-10-01T05:29:19.910Z] 05:29:19 INFO - GECKO(3975) | [Parent 3975, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorProtocol.cpp, line 172
[task 2020-10-01T05:29:19.910Z] 05:29:19 INFO - GECKO(3975) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-10-01T05:29:19.910Z] 05:29:19 INFO - GECKO(3975) | [Parent 3975, Main Thread] WARNING: 'aOwner->IsDiscarded()', file /builds/worker/workspace/obj-build/dist/include/mozilla/dom/SyncedContextInlines.h, line 36
[task 2020-10-01T05:29:19.911Z] 05:29:19 INFO - GECKO(3975) | [2020-10-01T05:29:12Z WARN xulstore::persist] tried to remove key that isn't in the store
[task 2020-10-01T05:29:19.911Z] 05:29:19 INFO - GECKO(3975) | [2020-10-01T05:29:12Z WARN xulstore::persist] tried to remove key that isn't in the store
[task 2020-10-01T05:29:19.911Z] 05:29:19 INFO - GECKO(3975) | [5056, Unnamed thread 7fa1fb35d5e0] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/checkouts/gecko/xpcom/base/nsTraceRefcnt.cpp, line 202
[task 2020-10-01T05:29:19.912Z] 05:29:19 INFO - GECKO(3975) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmp2yOlqV.mozrunner/runtests_leaks.log
[task 2020-10-01T05:29:19.912Z] 05:29:19 INFO - GECKO(3975) | [5056, Unnamed thread 7fa1fb35d5e0] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/checkouts/gecko/xpcom/base/nsTraceRefcnt.cpp, line 202
[task 2020-10-01T05:29:19.913Z] 05:29:19 INFO - GECKO(3975) | [5056, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp, line 246
[task 2020-10-01T05:29:19.913Z] 05:29:19 INFO - GECKO(3975) | [Parent 3975, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111 (NS_ERROR_NOT_AVAILABLE): file /builds/worker/checkouts/gecko/netwerk/cache/nsApplicationCacheService.cpp, line 161
[task 2020-10-01T05:29:19.913Z] 05:29:19 INFO - GECKO(3975) | [Child 4147, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2020-10-01T05:29:19.914Z] 05:29:19 INFO - GECKO(3975) | [Child 4147, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp, line 4287
[task 2020-10-01T05:29:19.914Z] 05:29:19 INFO - GECKO(3975) | [Child 5056, Main Thread] WARNING: could not set real-time limit in CubebUtils::InitLibrary: file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp, line 626
[task 2020-10-01T05:29:19.914Z] 05:29:19 INFO - GECKO(3975) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-10-01T05:29:19.915Z] 05:29:19 INFO - GECKO(3975) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-10-01T05:29:19.915Z] 05:29:19 INFO - GECKO(3975) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-10-01T05:29:19.915Z] 05:29:19 INFO - GECKO(3975) | [Child 5056, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2020-10-01T05:29:19.916Z] 05:29:19 INFO - GECKO(3975) | [Child 5056, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp, line 4287
[task 2020-10-01T05:29:19.916Z] 05:29:19 INFO - GECKO(3975) | [Child 4241, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2020-10-01T05:29:19.916Z] 05:29:19 INFO - GECKO(3975) | [Child 4241, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp, line 4287
[task 2020-10-01T05:29:19.917Z] 05:29:19 INFO - GECKO(3975) | [Child 4213, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2020-10-01T05:29:19.917Z] 05:29:19 INFO - GECKO(3975) | [Child 4213, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp, line 4287
[task 2020-10-01T05:29:19.917Z] 05:29:19 INFO - GECKO(3975) | 1601530153760 Marionette TRACE Received observer notification xpcom-will-shutdown
[task 2020-10-01T05:29:19.918Z] 05:29:19 INFO - GECKO(3975) | 1601530153761 Marionette INFO Stopped listening on port 2828
[task 2020-10-01T05:29:19.918Z] 05:29:19 INFO - GECKO(3975) | 1601530153761 Marionette DEBUG Marionette stopped listening
[task 2020-10-01T05:29:19.918Z] 05:29:19 INFO - GECKO(3975) | [RDD 4384, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp, line 4287
[task 2020-10-01T05:29:19.919Z] 05:29:19 INFO - GECKO(3975) | [Parent 3975, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2020-10-01T05:29:19.919Z] 05:29:19 INFO - GECKO(3975) | [Parent 3975, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp, line 4287
[task 2020-10-01T05:29:19.934Z] 05:29:19 INFO - TEST-INFO | Main app process: exit 0

Component: Audio/Video → Audio/Video: MediaStreamGraph
Blocks: 1686742
Blocks: 1690781

in Bug 1755075 we are splitting some of the mochitest media manifests- this makes it easier to see some failures and easier to run specific tests. This assertion/crash was showing up frequently, so disabling this on:
linux asan|debug

this should reduce the frequency a little bit.

A Pernosco session is available here: https://pernos.co/debug/nrRqYkSXjXhU93PFq25u-g/index.html

We are seeing this regularly at low volume while fuzzing.

Flags: needinfo?(karlt)

Thank you for the recording! It may have taken forever to find the cause without that.

Since we shut down the graph when the window is destroyed, we need to use a new graph for a new window, even when it is allocated at the same address. MediaTrackGraph does not keep a reference to prevent a new window having the same address.

Assignee: nobody → karlt
Status: NEW → ASSIGNED
Flags: needinfo?(karlt)
Regressed by: 1642849

(In reply to Joel Maher ( :jmaher ) (UTC -0800) from comment #60)

This assertion/crash was showing up frequently, so disabling this on:
linux asan|debug

https://hg.mozilla.org/mozilla-central/rev/887c82bbb32d4e6cb1440f4811c1a82050509d02#l5.32

Blocks: 1679968

Another Window can be allocated at the same address before its graph removes
itself from the table.

The webspeech special case with no Window no longer exists since
https://hg.mozilla.org/integration/autoland/rev/d71f9e83d6ef#l6.199

Depends on D140620

Instead of accepting a graph with the same hash.

Depends on D140621

Set release status flags based on info from the regressing bug 1642849

Blocks: 1637518
Blocks: domino
Pushed by ktomlinson@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/326a834b357b Get graph nsISerialEventTarget from nsGlobalWindowInner::nsIEventTargetFor() instead of DispatcherTrait::AbstractMainThreadFor() r=alwu https://hg.mozilla.org/integration/autoland/rev/a95ffa44cb94 use Window ID instead of pointer for generating graph hash table keys r=padenot https://hg.mozilla.org/integration/autoland/rev/50bd11c68536 require an exact match of Window, rate, and device when selecting a MediaTrackGraph r=padenot
Blocks: 1737716
Blocks: 1684727, 1715488
No longer blocks: 1684727
Blocks: 1684727

Copying crash signatures from duplicate bugs.

Crash Signature: [@ mozilla::AudioContextOperationControlMessage::RunDuringShutdown()]
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: