Closed Bug 1577537 Opened 3 months ago Closed 3 months ago

Intermittent dom/media/test/crashtests/1411322.html | application crashed [@ mozilla::(anonymous namespace)::MediaStreamGraphStableStateRunnable::Run()]

Categories

(Core :: Audio/Video: MediaStreamGraph, defect, P2, critical)

defect

Tracking

()

RESOLVED FIXED
mozilla71
Tracking Status
firefox-esr60 --- unaffected
firefox-esr68 --- unaffected
firefox68 --- unaffected
firefox69 --- unaffected
firefox70 --- fixed
firefox71 --- fixed

People

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

References

(Regression)

Details

(Keywords: crash, intermittent-failure, regression)

Crash Data

Attachments

(2 files)

Filed by: apavel [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=264062649&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/Cq2ocgvhSNquSIRfrEHTtQ/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://queue.taskcluster.net/v1/task/Cq2ocgvhSNquSIRfrEHTtQ/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1


[task 2019-08-29T14:43:32.654Z] 14:43:32 INFO - REFTEST TEST-START | file:///Users/cltbld/tasks/task_1567089628/build/tests/reftest/tests/dom/media/test/crashtests/1411322.html
[task 2019-08-29T14:43:32.654Z] 14:43:32 INFO - REFTEST TEST-LOAD | file:///Users/cltbld/tasks/task_1567089628/build/tests/reftest/tests/dom/media/test/crashtests/1411322.html | 635 / 3808 (16%)
[task 2019-08-29T14:43:33.032Z] 14:43:33 ERROR - A content process crashed and MOZ_CRASHREPORTER_SHUTDOWN is set, shutting down
[task 2019-08-29T14:43:33.139Z] 14:43:33 INFO - !!! error running onStopped callback: TypeError: callback is not a function
[task 2019-08-29T14:43:33.259Z] 14:43:33 INFO - 1567089813239 Marionette TRACE Received observer notification xpcom-will-shutdown
[task 2019-08-29T14:43:33.259Z] 14:43:33 INFO - 1567089813239 Marionette INFO Stopped listening on port 2828
[task 2019-08-29T14:43:33.259Z] 14:43:33 INFO - 1567089813239 Marionette DEBUG Remote service is inactive
[task 2019-08-29T14:43:33.607Z] 14:43:33 INFO - REFTEST INFO | Downloading symbols from: https://queue.taskcluster.net/v1/task/Xu28JW6nTc2hetNs9W0DfA/artifacts/public/build/target.crashreporter-symbols.zip
[task 2019-08-29T14:43:36.662Z] 14:43:36 INFO - REFTEST INFO | Copy/paste: /Users/cltbld/tasks/task_1567089628/build/macosx64-minidump_stackwalk /var/folders/5g/1kptcbp1615_5s2v8rdwr8qw000017/T/tmpoLVzrk.mozrunner/minidumps/DE1F5C40-FBD7-4F90-9DDD-4E184E9C4CE8.dmp /var/folders/5g/1kptcbp1615_5s2v8rdwr8qw000017/T/tmpwnXwJB
[task 2019-08-29T14:43:40.531Z] 14:43:40 INFO - REFTEST INFO | Saved minidump as /Users/cltbld/tasks/task_1567089628/build/blobber_upload_dir/DE1F5C40-FBD7-4F90-9DDD-4E184E9C4CE8.dmp
[task 2019-08-29T14:43:40.531Z] 14:43:40 INFO - REFTEST INFO | Saved app info as /Users/cltbld/tasks/task_1567089628/build/blobber_upload_dir/DE1F5C40-FBD7-4F90-9DDD-4E184E9C4CE8.extra
[task 2019-08-29T14:43:40.650Z] 14:43:40 INFO - REFTEST PROCESS-CRASH | file:///Users/cltbld/tasks/task_1567089628/build/tests/reftest/tests/dom/media/test/crashtests/1411322.html | application crashed [@ mozilla::(anonymous namespace)::MediaStreamGraphStableStateRunnable::Run()]
[task 2019-08-29T14:43:40.650Z] 14:43:40 INFO - Crash dump filename: /var/folders/5g/1kptcbp1615_5s2v8rdwr8qw000017/T/tmpoLVzrk.mozrunner/minidumps/DE1F5C40-FBD7-4F90-9DDD-4E184E9C4CE8.dmp
[task 2019-08-29T14:43:40.650Z] 14:43:40 INFO - Operating system: Mac OS X
[task 2019-08-29T14:43:40.650Z] 14:43:40 INFO - 10.14.5 18F132
[task 2019-08-29T14:43:40.650Z] 14:43:40 INFO - CPU: amd64
[task 2019-08-29T14:43:40.650Z] 14:43:40 INFO - family 6 model 69 stepping 1
[task 2019-08-29T14:43:40.650Z] 14:43:40 INFO - 4 CPUs
[task 2019-08-29T14:43:40.650Z] 14:43:40 INFO -
[task 2019-08-29T14:43:40.650Z] 14:43:40 INFO - GPU: UNKNOWN
[task 2019-08-29T14:43:40.650Z] 14:43:40 INFO -
[task 2019-08-29T14:43:40.650Z] 14:43:40 INFO - Crash reason: EXC_BAD_ACCESS / KERN_INVALID_ADDRESS
[task 2019-08-29T14:43:40.650Z] 14:43:40 INFO - Crash address: 0x0
[task 2019-08-29T14:43:40.650Z] 14:43:40 INFO - Process uptime: 76 seconds
[task 2019-08-29T14:43:40.650Z] 14:43:40 INFO -
[task 2019-08-29T14:43:40.650Z] 14:43:40 INFO - Thread 0 (crashed)
[task 2019-08-29T14:43:40.650Z] 14:43:40 INFO - 0 XUL!mozilla::(anonymous namespace)::MediaStreamGraphStableStateRunnable::Run() [MediaStreamGraph.cpp:3b11b55b1c97e81a38268a308d9ab422835ff79d : 1595 + 0x3bd]
[task 2019-08-29T14:43:40.650Z] 14:43:40 INFO - rax = 0x000000010b7dd1eb rdx = 0x0000000000000008
[task 2019-08-29T14:43:40.651Z] 14:43:40 INFO - rcx = 0x00000001100cfe30 rbx = 0x0000000000000000
[task 2019-08-29T14:43:40.651Z] 14:43:40 INFO - rsi = 0x0000000149b12180 rdi = 0x0000000117236548
[task 2019-08-29T14:43:40.651Z] 14:43:40 INFO - rbp = 0x00007ffeeaf66020 rsp = 0x00007ffeeaf65f80
[task 2019-08-29T14:43:40.651Z] 14:43:40 INFO - r8 = 0x00000001102000d8 r9 = 0x0000000000001a5e
[task 2019-08-29T14:43:40.651Z] 14:43:40 INFO - r10 = 0x0000000000000000 r11 = 0xffff8002218d4019
[task 2019-08-29T14:43:40.651Z] 14:43:40 INFO - r12 = 0x5c09b1ef162be8d4 r13 = 0x00000001172299c0
[task 2019-08-29T14:43:40.651Z] 14:43:40 INFO - r14 = 0x0000000149b12000 r15 = 0x0000000000000660
[task 2019-08-29T14:43:40.651Z] 14:43:40 INFO - rip = 0x0000000107c89167
[task 2019-08-29T14:43:40.651Z] 14:43:40 INFO - Found by: given as instruction pointer in context
[task 2019-08-29T14:43:40.651Z] 14:43:40 INFO - 1 XUL!mozilla::CycleCollectedJSContext::ProcessStableStateQueue() [CycleCollectedJSContext.cpp:3b11b55b1c97e81a38268a308d9ab422835ff79d : 435 + 0x9]
[task 2019-08-29T14:43:40.651Z] 14:43:40 INFO - rbp = 0x00007ffeeaf66060 rsp = 0x00007ffeeaf66030
[task 2019-08-29T14:43:40.651Z] 14:43:40 INFO - rip = 0x00000001051185c0
[task 2019-08-29T14:43:40.651Z] 14:43:40 INFO - Found by: previous frame's frame pointer
[task 2019-08-29T14:43:40.651Z] 14:43:40 INFO - 2 XUL!mozilla::CycleCollectedJSContext::AfterProcessTask(unsigned int) [CycleCollectedJSContext.cpp:3b11b55b1c97e81a38268a308d9ab422835ff79d : 494 + 0x8]
[task 2019-08-29T14:43:40.651Z] 14:43:40 INFO - rbp = 0x00007ffeeaf660a0 rsp = 0x00007ffeeaf66070
[task 2019-08-29T14:43:40.651Z] 14:43:40 INFO - rip = 0x0000000105119a7f
[task 2019-08-29T14:43:40.651Z] 14:43:40 INFO - Found by: previous frame's frame pointer
[task 2019-08-29T14:43:40.651Z] 14:43:40 INFO - 3 XUL!XPCJSContext::AfterProcessTask(unsigned int) [XPCJSContext.cpp:3b11b55b1c97e81a38268a308d9ab422835ff79d : 1313 + 0xb]
[task 2019-08-29T14:43:40.651Z] 14:43:40 INFO - rbp = 0x00007ffeeaf660c0 rsp = 0x00007ffeeaf660b0
[task 2019-08-29T14:43:40.651Z] 14:43:40 INFO - rip = 0x0000000105ed591f
[task 2019-08-29T14:43:40.651Z] 14:43:40 INFO - Found by: previous frame's frame pointer
[task 2019-08-29T14:43:40.651Z] 14:43:40 INFO - 4 XUL!nsThread::ProcessNextEvent(bool, bool*) [nsThread.cpp:3b11b55b1c97e81a38268a308d9ab422835ff79d : 1283 + 0xa]
[task 2019-08-29T14:43:40.651Z] 14:43:40 INFO - rbp = 0x00007ffeeaf665b0 rsp = 0x00007ffeeaf660d0
[task 2019-08-29T14:43:40.652Z] 14:43:40 INFO - rip = 0x00000001051ece4d
[task 2019-08-29T14:43:40.652Z] 14:43:40 INFO - Found by: previous frame's frame pointer
[task 2019-08-29T14:43:40.652Z] 14:43:40 INFO - 5 XUL!NS_ProcessNextEvent(nsIThread*, bool) [nsThreadUtils.cpp:3b11b55b1c97e81a38268a308d9ab422835ff79d : 486 + 0xd]
[task 2019-08-29T14:43:40.652Z] 14:43:40 INFO - rbp = 0x00007ffeeaf665e0 rsp = 0x00007ffeeaf665c0
[task 2019-08-29T14:43:40.652Z] 14:43:40 INFO - rip = 0x00000001051ef189
[task 2019-08-29T14:43:40.652Z] 14:43:40 INFO - Found by: previous frame's frame pointer
[task 2019-08-29T14:43:40.652Z] 14:43:40 INFO - 6 XUL!mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) [MessagePump.cpp:3b11b55b1c97e81a38268a308d9ab422835ff79d : 88 + 0x7]
[task 2019-08-29T14:43:40.652Z] 14:43:40 INFO - rbp = 0x00007ffeeaf66630 rsp = 0x00007ffeeaf665f0
[task 2019-08-29T14:43:40.652Z] 14:43:40 INFO - rip = 0x000000010590bb01
[task 2019-08-29T14:43:40.652Z] 14:43:40 INFO - Found by: previous frame's frame pointer
[task 2019-08-29T14:43:40.652Z] 14:43:40 INFO - 7 XUL!nsBaseAppShell::Run() [nsBaseAppShell.cpp:3b11b55b1c97e81a38268a308d9ab422835ff79d : 137 + 0x45]
[task 2019-08-29T14:43:40.652Z] 14:43:40 INFO - rbp = 0x00007ffeeaf66670 rsp = 0x00007ffeeaf66640
[task 2019-08-29T14:43:40.652Z] 14:43:40 INFO - rip = 0x00000001085e0ecc
[task 2019-08-29T14:43:40.652Z] 14:43:40 INFO - Found by: previous frame's frame pointer
[task 2019-08-29T14:43:40.652Z] 14:43:40 INFO - 8 XUL!nsAppShell::Run() [nsAppShell.mm:3b11b55b1c97e81a38268a308d9ab422835ff79d : 705 + 0x8]
[task 2019-08-29T14:43:40.652Z] 14:43:40 INFO - rbp = 0x00007ffeeaf666b0 rsp = 0x00007ffeeaf66680
[task 2019-08-29T14:43:40.652Z] 14:43:40 INFO - rip = 0x0000000108668a7c
[task 2019-08-29T14:43:40.652Z] 14:43:40 INFO - Found by: previous frame's frame pointer
[task 2019-08-29T14:43:40.652Z] 14:43:40 INFO - 9 XUL!XRE_RunAppShell() [nsEmbedFunctions.cpp:3b11b55b1c97e81a38268a308d9ab422835ff79d : 934 + 0xa]
[task 2019-08-29T14:43:40.652Z] 14:43:40 INFO - rbp = 0x00007ffeeaf66710 rsp = 0x00007ffeeaf666c0
[task 2019-08-29T14:43:40.652Z] 14:43:40 INFO - rip = 0x0000000109caddbf
[task 2019-08-29T14:43:40.652Z] 14:43:40 INFO - Found by: previous frame's frame pointer
[task 2019-08-29T14:43:40.652Z] 14:43:40 INFO - 10 XUL!XRE_InitChildProcess(int, char**, XREChildData const*) [message_loop.cc:3b11b55b1c97e81a38268a308d9ab422835ff79d : 315 + 0xc]
[task 2019-08-29T14:43:40.652Z] 14:43:40 INFO - rbp = 0x00007ffeeaf66a10 rsp = 0x00007ffeeaf66720
[task 2019-08-29T14:43:40.652Z] 14:43:40 INFO - rip = 0x0000000109cad9e2
[task 2019-08-29T14:43:40.652Z] 14:43:40 INFO - Found by: previous frame's frame pointer
[task 2019-08-29T14:43:40.652Z] 14:43:40 INFO - 11 plugin-container!main [MozillaRuntimeMain.cpp:3b11b55b1c97e81a38268a308d9ab422835ff79d : 23 + 0x2c]
[task 2019-08-29T14:43:40.653Z] 14:43:40 INFO - rbp = 0x00007ffeeaf66a50 rsp = 0x00007ffeeaf66a20
[task 2019-08-29T14:43:40.653Z] 14:43:40 INFO - rip = 0x0000000104c98f07
[task 2019-08-29T14:43:40.653Z] 14:43:40 INFO - Found by: previous frame's frame pointer
[task 2019-08-29T14:43:40.653Z] 14:43:40 INFO - 12 0x7fff7a8693d5
[task 2019-08-29T14:43:40.653Z] 14:43:40 INFO - rbp = 0x00007ffeeaf66a60 rsp = 0x00007ffeeaf66a60
[task 2019-08-29T14:43:40.653Z] 14:43:40 INFO - rip = 0x00007fff7a8693d5
[task 2019-08-29T14:43:40.653Z] 14:43:40 INFO - Found by: previous frame's frame pointer

See Also: → 524410

(In reply to Sebastian Hengst [:aryx] (needinfo on intermittent or backout) from comment #1)

Andreas, is this from bug 1574965?

Doesn't seem unlikely, but like karlt said it's hard to tell from this stack. I'll try to get something more useful out of try.

Assignee: nobody → apehrson
Status: NEW → ASSIGNED
Component: Audio/Video: Playback → Audio/Video: MediaStreamGraph
Flags: needinfo?(apehrson)
Priority: -- → P2
See Also: → 1577755

Bug 1577755 suggests the crash is on line 1688:

[task 2019-08-30T11:41:57.532Z] 11:41:57 INFO - 0 libxul.so!mozilla::MediaStreamGraphImpl::RunInStableState(bool) [MediaStreamGraph.cpp:07dcdba72b8d48431774c1a1d6df8e44bdf5c0fa : 1688 + 0x48]

The assert also shows up:

[task 2019-08-30T11:42:01.415Z] 11:42:01 INFO - 08-30 12:29:29.715 F/MOZ_Assert( 2865): Assertion failure: mForceShutDown || LifecycleStateRef() < LIFECYCLE_WAITING_FOR_MAIN_THREAD_CLEANUP, at /builds/worker/workspace/build/src/dom/media/MediaStreamGraph.cpp:1690

Asserts are not reported in opt builds so I'm gonna assume this is the opt version of bug 1577755. Apparently MOZ_CRASH reasons are not propagating to the logs either.

If all streams and all ports have been destroyed, there's no guarantee that the
graph is still alive. By forbidding AppendMessage calls after this point, we can
catch bugs with the offending callsite still being in the stack.

Blocks: 1577722

With this assert, I managed to catch an offender: https://treeherder.mozilla.org/#/jobs?repo=try&revision=4ff288afc77808b9c348159e1a40cf768d9df8cd

[task 2019-08-30T20:09:04.411Z] 20:09:04     INFO - Thread 0 (crashed)
[task 2019-08-30T20:09:04.411Z] 20:09:04     INFO -  0  XUL!mozilla::MediaStreamGraphImpl::AppendMessage(mozilla::UniquePtr<mozilla::ControlMessage, mozilla::DefaultDelete<mozilla::ControlMessage> >) [MediaStreamGraph.cpp:4ff288afc77808b9c348159e1a40cf768d9df8cd : 1804 + 0x11]
[task 2019-08-30T20:09:04.411Z] 20:09:04     INFO -     rax = 0x0000000115c69b37   rdx = 0x0000000000000002
[task 2019-08-30T20:09:04.411Z] 20:09:04     INFO -     rcx = 0x000000010b912e30   rbx = 0x0000000128ef4d00
[task 2019-08-30T20:09:04.411Z] 20:09:04     INFO -     rsi = 0x00007ffee46da038   rdi = 0x0000000128ebc400
[task 2019-08-30T20:09:04.411Z] 20:09:04     INFO -     rbp = 0x00007ffee46da020   rsp = 0x00007ffee46d9ff0
[task 2019-08-30T20:09:04.411Z] 20:09:04     INFO -      r8 = 0x000000010ba00148    r9 = 0x0000000000001a6b
[task 2019-08-30T20:09:04.411Z] 20:09:04     INFO -     r10 = 0x0000000000000000   r11 = 0xffff8002325d7c6c
[task 2019-08-30T20:09:04.411Z] 20:09:04     INFO -     r12 = 0x0000000128ebc400   r13 = 0x00000000ffffffff
[task 2019-08-30T20:09:04.411Z] 20:09:04     INFO -     r14 = 0x00007ffee46da038   r15 = 0x0000000128ebc400
[task 2019-08-30T20:09:04.411Z] 20:09:04     INFO -     rip = 0x0000000112232684
[task 2019-08-30T20:09:04.412Z] 20:09:04     INFO -     Found by: given as instruction pointer in context
[task 2019-08-30T20:09:04.412Z] 20:09:04     INFO -  1  XUL!mozilla::MediaStreamGraphImpl::CollectReports(nsIHandleReportCallback*, nsISupports*, bool) [MediaStreamGraph.cpp:4ff288afc77808b9c348159e1a40cf768d9df8cd : 3404 + 0x57]
[task 2019-08-30T20:09:04.412Z] 20:09:04     INFO -     rbp = 0x00007ffee46da070   rsp = 0x00007ffee46da030
[task 2019-08-30T20:09:04.412Z] 20:09:04     INFO -     rip = 0x000000011223d76a
[task 2019-08-30T20:09:04.412Z] 20:09:04     INFO -     Found by: previous frame's frame pointer
[task 2019-08-30T20:09:04.412Z] 20:09:04     INFO -  2  XUL!non-virtual thunk to mozilla::MediaStreamGraphImpl::CollectReports(nsIHandleReportCallback*, nsISupports*, bool) [MediaStreamGraph.cpp:4ff288afc77808b9c348159e1a40cf768d9df8cd : 0 + 0xf]
[task 2019-08-30T20:09:04.412Z] 20:09:04     INFO -     rbp = 0x00007ffee46da080   rsp = 0x00007ffee46da080
[task 2019-08-30T20:09:04.412Z] 20:09:04     INFO -     rip = 0x000000011223dacf
[task 2019-08-30T20:09:04.412Z] 20:09:04     INFO -     Found by: previous frame's frame pointer
[task 2019-08-30T20:09:04.412Z] 20:09:04     INFO -  3  XUL!mozilla::detail::RunnableFunction<nsMemoryReporterManager::DispatchReporter(nsIMemoryReporter*, bool, nsIHandleReportCallback*, nsISupports*, bool)::$_0>::Run() [nsThreadUtils.h:4ff288afc77808b9c348159e1a40cf768d9df8cd : 564 + 0x16]
[task 2019-08-30T20:09:04.412Z] 20:09:04     INFO -     rbp = 0x00007ffee46da0a0   rsp = 0x00007ffee46da090
[task 2019-08-30T20:09:04.412Z] 20:09:04     INFO -     rip = 0x000000010f6e6b9f
[task 2019-08-30T20:09:04.412Z] 20:09:04     INFO -     Found by: previous frame's frame pointer

As usual, not the one you'd expect.

Pushed by pehrsons@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/4aa6364cc6e8
Catch AppendMessage calls that could be too late. r=karlt
https://hg.mozilla.org/integration/autoland/rev/977ca44c928d
Exit MediaStreamGraphImpl::CollectReports early when there are no streams. r=padenot
Flags: needinfo?(apehrson)
Pushed by pehrsons@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/5f1b0d254f43
Catch AppendMessage calls that could be too late. r=karlt
https://hg.mozilla.org/integration/autoland/rev/51cdbae0ac64
Exit MediaStreamGraphImpl::CollectReports early when there are no streams. r=padenot
Status: ASSIGNED → RESOLVED
Closed: 3 months ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla71

Comment on attachment 9089852 [details]
Bug 1577537 - Exit MediaStreamGraphImpl::CollectReports early when there are no streams. r?padenot

Beta/Release Uplift Approval Request

  • User impact if declined: Unclear what impact this would have in release or beta -- I'd guess at worst a leak or a shutdownhang. But it can fail an assert in CI (and for users) in dev edition and nightly.
  • Is this code covered by automated tests?: Yes
  • Has the fix been verified in Nightly?: No
  • Needs manual test from QE?: No
  • If yes, steps to reproduce:
  • List of other uplifts needed: None
  • Risk to taking this patch: Low
  • Why is the change risky/not risky? (and alternatives if risky): Trivial
  • String changes made/needed:
Attachment #9089852 - Flags: approval-mozilla-beta?
Attachment #9089471 - Flags: approval-mozilla-beta?
Duplicate of this bug: 1577755
Duplicate of this bug: 1577722

Comment on attachment 9089852 [details]
Bug 1577537 - Exit MediaStreamGraphImpl::CollectReports early when there are no streams. r?padenot

Fix an assert that might also reflect shutdown hangs, let's try it in beta 4.

Attachment #9089852 - Flags: approval-mozilla-beta? → approval-mozilla-beta+
Attachment #9089471 - Flags: approval-mozilla-beta? → approval-mozilla-beta+
Regressions: 1586387
Duplicate of this bug: 1578247
Crash Signature: [@ mozilla::(anonymous namespace)::MediaStreamGraphStableStateRunnable::Run()] → [@ mozilla::(anonymous namespace)::MediaStreamGraphStableStateRunnable::Run()] [@ mozilla::MediaStreamGraphImpl::RunInStableState(bool)]
You need to log in before you can comment on or make changes to this bug.