Open Bug 1721731 Opened 3 months ago Updated 1 month ago

Intermittent dom/media/test/test_streams_element_capture_mediatrack.html | application crashed [@ mozilla::detail::RunnableFunction<mozilla::SourceVideoTrackListener::NotifyOutput(mozilla::MediaTrackGraph*, long)::$_8>::Run()]

Categories

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

defect

Tracking

()

REOPENED
94 Branch
Tracking Status
firefox94 --- affected

People

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

Details

(4 keywords, Whiteboard: [stockwell unknown])

Crash Data

Attachments

(1 file)

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


[task 2021-07-21T20:14:12.071Z] 20:14:12     INFO -  TEST-PASS | dom/media/test/test_streams_element_capture_mediatrack.html | [finished bipbop-lateaudio.mp4-62 t=5.286] Length of array should match number of running tests
[task 2021-07-21T20:14:12.071Z] 20:14:12     INFO -  TEST-PASS | dom/media/test/test_streams_element_capture_mediatrack.html | [started opus-mapping2.mp4-64 t=5.289] Length of array should match number of running tests
[task 2021-07-21T20:14:32.292Z] 20:14:32     INFO -  wait for org.mozilla.geckoview.test complete; top activity=com.android.launcher3
[task 2021-07-21T20:14:32.292Z] 20:14:32     INFO -  runtestsremote.py | Application ran for: 0:10:22.033844
[task 2021-07-21T20:14:32.399Z] 20:14:32     INFO -  mozcrash Copy/paste: /builds/worker/fetches/minidump_stackwalk/minidump_stackwalk /tmp/tmpwv65kyaq/4ae38824-10ea-1567-0bda-ba087abfb81f.dmp /builds/worker/workspace/build/symbols
[task 2021-07-21T20:14:36.084Z] 20:14:36     INFO -  mozcrash Saved minidump as /builds/worker/workspace/build/blobber_upload_dir/4ae38824-10ea-1567-0bda-ba087abfb81f.dmp
[task 2021-07-21T20:14:36.085Z] 20:14:36     INFO -  mozcrash Saved app info as /builds/worker/workspace/build/blobber_upload_dir/4ae38824-10ea-1567-0bda-ba087abfb81f.extra
[task 2021-07-21T20:14:36.092Z] 20:14:36  WARNING -  PROCESS-CRASH | dom/media/test/test_streams_element_capture_mediatrack.html | application crashed [@ mozilla::detail::RunnableFunction<mozilla::SourceVideoTrackListener::NotifyOutput(mozilla::MediaTrackGraph*, long)::$_8>::Run()]
[task 2021-07-21T20:14:36.092Z] 20:14:36     INFO -  Mozilla crash reason: MOZ_ASSERT(mAudioEnded)
[task 2021-07-21T20:14:36.092Z] 20:14:36     INFO -  Crash dump filename: /tmp/tmpwv65kyaq/4ae38824-10ea-1567-0bda-ba087abfb81f.dmp
[task 2021-07-21T20:14:36.093Z] 20:14:36     INFO -  Operating system: Android
[task 2021-07-21T20:14:36.093Z] 20:14:36     INFO -                    0.0.0 Linux 3.10.0+ #260 SMP PREEMPT Fri May 19 12:48:14 PDT 2017 x86_64
[task 2021-07-21T20:14:36.093Z] 20:14:36     INFO -  CPU: amd64
[task 2021-07-21T20:14:36.093Z] 20:14:36     INFO -       family 6 model 6 stepping 3
[task 2021-07-21T20:14:36.093Z] 20:14:36     INFO -       4 CPUs
[task 2021-07-21T20:14:36.093Z] 20:14:36     INFO -  GPU: UNKNOWN
[task 2021-07-21T20:14:36.093Z] 20:14:36     INFO -  Crash reason:  SIGSEGV /SEGV_MAPERR
[task 2021-07-21T20:14:36.093Z] 20:14:36     INFO -  Crash address: 0x0
[task 2021-07-21T20:14:36.094Z] 20:14:36     INFO -  Process uptime: not available
[task 2021-07-21T20:14:36.094Z] 20:14:36     INFO -  Thread 41 (crashed) 0  libxul.so!mozilla::DecodedStreamGraphListener::NotifyOutput(mozilla::MediaSegment::Type, long) [DecodedStream.cpp:9d2cc3a9622d834ec8551ace34a254e7da0c683a : 160 + 0x29]
[task 2021-07-21T20:14:36.094Z] 20:14:36     INFO -      rax = 0x000070406a56462e   rdx = 0x0000000000000004
[task 2021-07-21T20:14:36.094Z] 20:14:36     INFO -      rcx = 0x0000704085ffbc20   rbx = 0x0000704054afc040
[task 2021-07-21T20:14:36.094Z] 20:14:36     INFO -      rsi = 0x000070405d078c50   rdi = 0x000000000000001b
[task 2021-07-21T20:14:36.095Z] 20:14:36     INFO -      rbp = 0x000070405d079da0   rsp = 0x000070405d079d70
[task 2021-07-21T20:14:36.095Z] 20:14:36     INFO -       r8 = 0x000000000000ffff    r9 = 0x0000000000000000
[task 2021-07-21T20:14:36.095Z] 20:14:36     INFO -      r10 = 0x00007040885d73d0   r11 = 0x0000000000000246
[task 2021-07-21T20:14:36.095Z] 20:14:36     INFO -      r12 = 0x000070405420d1b8   r13 = 0x000070405d079de8
[task 2021-07-21T20:14:36.095Z] 20:14:36     INFO -      r14 = 0x0000000000003200   r15 = 0x0000000000000001
[task 2021-07-21T20:14:36.095Z] 20:14:36     INFO -      rip = 0x00007040655b8276
[task 2021-07-21T20:14:36.096Z] 20:14:36     INFO -      Found by: given as instruction pointer in context
[task 2021-07-21T20:14:36.096Z] 20:14:36     INFO -   1  libxul.so!mozilla::detail::RunnableFunction<mozilla::SourceVideoTrackListener::NotifyOutput(mozilla::MediaTrackGraph*, long)::$_8>::Run() [nsThreadUtils.h:9d2cc3a9622d834ec8551ace34a254e7da0c683a : 532 + 0x21]
[task 2021-07-21T20:14:36.096Z] 20:14:36     INFO -      rbp = 0x000070405d079dc0   rsp = 0x000070405d079db0
[task 2021-07-21T20:14:36.096Z] 20:14:36     INFO -      rip = 0x00007040655b8057
[task 2021-07-21T20:14:36.096Z] 20:14:36     INFO -      Found by: previous frame's frame pointer
[task 2021-07-21T20:14:36.097Z] 20:14:36     INFO -   2  libxul.so!mozilla::TaskQueue::Runner::Run() [TaskQueue.cpp:9d2cc3a9622d834ec8551ace34a254e7da0c683a : 208 + 0x11]
[task 2021-07-21T20:14:36.097Z] 20:14:36     INFO -      rbp = 0x000070405d079e70   rsp = 0x000070405d079dd0
[task 2021-07-21T20:14:36.097Z] 20:14:36     INFO -      rip = 0x00007040633acca9
[task 2021-07-21T20:14:36.097Z] 20:14:36     INFO -      Found by: previous frame's frame pointer
[task 2021-07-21T20:14:36.097Z] 20:14:36     INFO -   3  libxul.so!nsThreadPool::Run() [nsThreadPool.cpp:9d2cc3a9622d834ec8551ace34a254e7da0c683a : 303 + 0x11]
[task 2021-07-21T20:14:36.097Z] 20:14:36     INFO -      rbp = 0x000070405d079f90   rsp = 0x000070405d079e80
[task 2021-07-21T20:14:36.098Z] 20:14:36     INFO -      rip = 0x00007040633bc1d3
[task 2021-07-21T20:14:36.098Z] 20:14:36     INFO -      Found by: previous frame's frame pointer
[task 2021-07-21T20:14:36.098Z] 20:14:36     INFO -   4  libxul.so!nsThread::ProcessNextEvent(bool, bool*) [nsThread.cpp:9d2cc3a9622d834ec8551ace34a254e7da0c683a : 1142 + 0x11]
[task 2021-07-21T20:14:36.098Z] 20:14:36     INFO -      rbp = 0x000070405d07a0c0   rsp = 0x000070405d079fa0
[task 2021-07-21T20:14:36.098Z] 20:14:36     INFO -      rip = 0x00007040633b6722
[task 2021-07-21T20:14:36.098Z] 20:14:36     INFO -      Found by: previous frame's frame pointer
[task 2021-07-21T20:14:36.099Z] 20:14:36     INFO -   5  libxul.so!NS_ProcessNextEvent(nsIThread*, bool) [nsThreadUtils.cpp:9d2cc3a9622d834ec8551ace34a254e7da0c683a : 466 + 0x10]
[task 2021-07-21T20:14:36.099Z] 20:14:36     INFO -      rbp = 0x000070405d07a100   rsp = 0x000070405d07a0d0
[task 2021-07-21T20:14:36.099Z] 20:14:36     INFO -      rip = 0x00007040633baba1
[task 2021-07-21T20:14:36.099Z] 20:14:36     INFO -      Found by: previous frame's frame pointer
[task 2021-07-21T20:14:36.099Z] 20:14:36     INFO -   6  libxul.so!mozilla::ipc::MessagePumpForNonMainThreads::Run(base::MessagePump::Delegate*) [MessagePump.cpp:9d2cc3a9622d834ec8551ace34a254e7da0c683a : 300 + 0xa]
[task 2021-07-21T20:14:36.099Z] 20:14:36     INFO -      rbp = 0x000070405d07a150   rsp = 0x000070405d07a110
[task 2021-07-21T20:14:36.099Z] 20:14:36     INFO -      rip = 0x00007040639b0412
[task 2021-07-21T20:14:36.100Z] 20:14:36     INFO -      Found by: previous frame's frame pointer
[task 2021-07-21T20:14:36.100Z] 20:14:36     INFO -   7  libxul.so!MessageLoop::RunInternal() [message_loop.cc:9d2cc3a9622d834ec8551ace34a254e7da0c683a : 331 + 0x17]
[task 2021-07-21T20:14:36.100Z] 20:14:36     INFO -      rbp = 0x000070405d07a190   rsp = 0x000070405d07a160
[task 2021-07-21T20:14:36.100Z] 20:14:36     INFO -      rip = 0x00007040639515de
[task 2021-07-21T20:14:36.100Z] 20:14:36     INFO -      Found by: previous frame's frame pointer
[task 2021-07-21T20:14:36.100Z] 20:14:36     INFO -   8  libxul.so!MessageLoop::Run() [message_loop.cc:9d2cc3a9622d834ec8551ace34a254e7da0c683a : 306 + 0x8]
[task 2021-07-21T20:14:36.100Z] 20:14:36     INFO -      rbp = 0x000070405d07a1d0   rsp = 0x000070405d07a1a0
[task 2021-07-21T20:14:36.101Z] 20:14:36     INFO -      rip = 0x0000704063951547
[task 2021-07-21T20:14:36.101Z] 20:14:36     INFO -      Found by: previous frame's frame pointer
[task 2021-07-21T20:14:36.101Z] 20:14:36     INFO -   9  libxul.so!nsThread::ThreadFunc(void*) [nsThread.cpp:9d2cc3a9622d834ec8551ace34a254e7da0c683a : 390 + 0x8]
[task 2021-07-21T20:14:36.101Z] 20:14:36     INFO -      rbp = 0x000070405d07a3a0   rsp = 0x000070405d07a1e0
[task 2021-07-21T20:14:36.101Z] 20:14:36     INFO -      rip = 0x00007040633b4102
[task 2021-07-21T20:14:36.101Z] 20:14:36     INFO -      Found by: previous frame's frame pointer
[task 2021-07-21T20:14:36.101Z] 20:14:36     INFO -  10  libnss3.so!_pt_root [ptthread.c:9d2cc3a9622d834ec8551ace34a254e7da0c683a : 201 + 0xa]
[task 2021-07-21T20:14:36.102Z] 20:14:36     INFO -      rbp = 0x000070405d07a3e0   rsp = 0x000070405d07a3b0
[task 2021-07-21T20:14:36.102Z] 20:14:36     INFO -      rip = 0x000070406d6ff5dd
[task 2021-07-21T20:14:36.102Z] 20:14:36     INFO -      Found by: previous frame's frame pointer
[task 2021-07-21T20:14:36.102Z] 20:14:36     INFO -  11  libnss3.so!pt_recvfrom_cont [ptio.c:9d2cc3a9622d834ec8551ace34a254e7da0c683a : 996 + 0x2f]
[task 2021-07-21T20:14:36.102Z] 20:14:36     INFO -      rbp = 0x000070405d07a3e0   rsp = 0x000070405d07a3d0
[task 2021-07-21T20:14:36.102Z] 20:14:36     INFO -      rip = 0x000070406d6ff492
[task 2021-07-21T20:14:36.102Z] 20:14:36     INFO -      Found by: stack scanning
[task 2021-07-21T20:14:36.102Z] 20:14:36     INFO -  12  libc.so + 0x89772
[task 2021-07-21T20:14:36.103Z] 20:14:36     INFO -      rsp = 0x000070405d07a3f0   rip = 0x0000704088639772
[task 2021-07-21T20:14:36.103Z] 20:14:36     INFO -      Found by: stack scanning
[task 2021-07-21T20:14:36.103Z] 20:14:36     INFO -  13  libnss3.so!pt_recvfrom_cont [ptio.c:9d2cc3a9622d834ec8551ace34a254e7da0c683a : 996 + 0x2f]
[task 2021-07-21T20:14:36.103Z] 20:14:36     INFO -      rsp = 0x000070405d07a428   rip = 0x000070406d6ff492
[task 2021-07-21T20:14:36.103Z] 20:14:36     INFO -      Found by: stack scanning
[task 2021-07-21T20:14:36.104Z] 20:14:36     INFO -  14  libc.so + 0x299ec
[task 2021-07-21T20:14:36.104Z] 20:14:36     INFO -      rsp = 0x000070405d07a440   rip = 0x00007040885d99ec
[task 2021-07-21T20:14:36.104Z] 20:14:36     INFO -      Found by: stack scanning
[task 2021-07-21T20:14:36.104Z] 20:14:36     INFO -  15  libc.so + 0x896c0
[task 2021-07-21T20:14:36.104Z] 20:14:36     INFO -      rsp = 0x000070405d07a448   rip = 0x00007040886396c0
[task 2021-07-21T20:14:36.104Z] 20:14:36     INFO -      Found by: stack scanning
[task 2021-07-21T20:14:36.104Z] 20:14:36     INFO -  16  libc.so + 0x1ca66
[task 2021-07-21T20:14:36.104Z] 20:14:36     INFO -      rsp = 0x000070405d07a450   rip = 0x00007040885cca66
[task 2021-07-21T20:14:36.105Z] 20:14:36     INFO -      Found by: stack scanning
[task 2021-07-21T20:14:36.105Z] 20:14:36     INFO -  17  libnss3.so!pt_recvfrom_cont [ptio.c:9d2cc3a9622d834ec8551ace34a254e7da0c683a : 996 + 0x2f]
[task 2021-07-21T20:14:36.105Z] 20:14:36     INFO -      rsp = 0x000070405d07a4b8   rip = 0x000070406d6ff492
[task 2021-07-21T20:14:36.105Z] 20:14:36     INFO -      Found by: stack scanning
Component: Audio/Video: Playback → Audio/Video: MediaStreamGraph

There have been 37 total failures in the last 7 days (recent failure log).
Affected platforms are:

  • android-em-7-0-x86_64-qr debug
  • android-em-7-0-x86_64-lite-qr debug

Paul, could you please assign this to someone who can take a look?

Flags: needinfo?(padenot)
Whiteboard: [stockwell needswork]

Alastor, this is in your new code for HTMLMediaElement playback with the graph, can you have a look?

Flags: needinfo?(padenot) → needinfo?(alwu)

It seems a racy issue which happens between the graph thread and the decoder thread (MDSM), but I am not sure the reason yet. The failure caused by the assertion is here and the mAudioEnded would only be modified on the decoder thread (if we have an audio track)

When video notifies its output, the video track listener would check another attribute, which can only be accessed and modified on the graph thread (or the main thread if the graph thread is dead), in order to know if audio ends or not. If the audio has been ended, it would dispatch a NotifyOutput() to the decoder thread to let video track to drive the clock.

However, if audio has been ended, that means we should already notify the listener on the graph thread, which should trigger setting mAudioEnded first on the decoder thread.

I will go to enable debug log on the try server and see if I can get more information about how this failure happens.

Assignee: nobody → alwu
Flags: needinfo?(alwu)

Unfortunately, although I can reproduce once this issue on the try server, but on Android the moz log seems not showing. Per the analyisis on the comment10, I don't have a good explanation for that assertion faliure based on the current information I had. As this only happens on Android debug, I will go to disable it on that platform.

Pushed by alwu@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/780bbc9a2c16
disable 'test_streams_element_capture_mediatrack.html' on Android debug. r=padenot
Status: NEW → RESOLVED
Closed: 1 month ago
Resolution: --- → FIXED
Target Milestone: --- → 94 Branch
Status: RESOLVED → REOPENED
Keywords: leave-open
Resolution: FIXED → ---
You need to log in before you can comment on or make changes to this bug.