1859796 - mStateComputedTime spuriously becomes lower than oldProcessedTime when capturing ALSA input with pipewire-alsa

Status: UNCONFIRMED

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

Description

[prathamIN]

Attachment: 1ec532ec-167f-aa5e-f672-275d34c1172a.dmp

User Agent: Mozilla/5.0 (X11; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/118.0

Steps to reproduce:

1. Open about:config, set media.cubeb.backend to alsa
2. Quit Firefox
3. Have pipewire-alsa configured to be the default (Have /usr/share/alsa/alsa.conf.d/99-pipewire-default.conf symlinked/copied to /etc/alsa/conf.d)
4. Restart pipewire (Increases likelihood of the bug occuring, very hard to get it to occur)
5. Restart Firefox
6. Open any conferencing site (eg. https://demo.dyte.io)
7. Allow microphone access
8. If no crash occurs immediately, repeat steps 5-7

Actual results:

Tab Crashed

From minidump-stackwalk <...>.dmp --use-local-debuginfo, it is evident that the "crash" occured due to request for too big of an allocation (due to unsigned integer underflow)

Thread 38 GraphRunner (crashed)
 0  libxul.so!nsDebugImpl::Create(nsID const&, void**) [nsDebugImpl.cpp : 628 + 0x1]
     rax = 0x000055b5a5f80580    rdx = 0x00007ffa0dcaff8d
     rcx = 0x0000000000000004    rbx = 0x0000000000000004
     rsi = 0x0000000000000004    rdi = 0x00000003fffff000
     rbp = 0x00007ff978063148    rsp = 0x00007ffa08758340
      r8 = 0x0000000000000004     r9 = 0x00007ff978063120
     r10 = 0x0000000000a3608a    r11 = 0x00007ff9780086a8
     r12 = 0x0000000000001000    r13 = 0x0000000000000001
     r14 = 0x00000000fffffc00    r15 = 0x000000000000ac44
     rip = 0x00007ffa0deb8eaa
    Found by: given as instruction pointer in context
 1  0xffffebff
     rbx = 0x00007ffa08758350    rbp = 0x00007ff978063148
     rsp = 0x00007ffa08758360    r12 = 0x0000000000001000
     r13 = 0x0000000000000001    r14 = 0x00000000fffffc00
     r15 = 0x000000000000ac44    rip = 0x00000000ffffec00
    Found by: call frame info
 2  libxul.so!bool nsTArray_Impl<mozilla::MediaTrack*, nsTArrayInfallibleAllocator>::RemoveElement<mozilla::MediaTrack*, nsDefaultComparator<mozilla::MediaTrack*, mozilla::MediaTrack*> >(mozilla::MediaTrack* const&, nsDefaultComparator<mozilla::MediaTrack*, mozilla::MediaTrack*> const&) [nsTArray.h : 1969]
    Found by: inlining
 3  libxul.so!bool nsTArray_Impl<mozilla::MediaTrack*, nsTArrayInfallibleAllocator>::RemoveElement<mozilla::MediaTrack*>(mozilla::MediaTrack* const&) [nsTArray.h : 1981]
    Found by: inlining
 4  libxul.so!mozilla::MediaTrack::DecrementSuspendCount() [MediaTrackGraph.cpp : 2143]
    Found by: inlining
 5  libxul.so!mozilla::MediaTrack::DecrementSuspendCount() [clone .cold] [MediaTrackGraph.cpp : 2131 + 0x111]
     rsp = 0x00007ffa08758390    rip = 0x00007ffa0ffda679
    Found by: stack scanning
 6  libxul.so!operator new(unsigned long) [cxxalloc.h : 33]
    Found by: inlining
 7  libxul.so!mozilla::MozPromise<nsTString<char>, nsresult, false>::ThenValueBase::Dispatch(mozilla::MozPromise<nsTString<char>, nsresult, false>*) [MozPromise.h : 545 + 0x4]
     rbx = 0x0000000000000004    rbp = 0x0000000000000001
     rsp = 0x00007ffa087583c0    r12 = 0x00007ff978063120
     r13 = 0x0000000000000001    rip = 0x00007ffa0fff90bc
    Found by: call frame info
 8  libxul.so + 0x2ae1d9d
     rbx = 0x00007ffa13f72020    rbp = 0x00007ffa0dc4a196
     rsp = 0x00007ffa08758410    r12 = 0x0000000000000000
     r13 = 0x00007ffa0df76c6a    r14 = 0x000055b5a8e7e510
     rip = 0x00007ffa0df76d9e
    Found by: call frame info
 9  libxul.so!nsThread::ProcessNextEvent(bool, bool*) [nsThread.cpp : 1228 + 0x1]
     rbp = 0x00007ffa0dc4a196    rsp = 0x00007ffa08758430
     rip = 0x00007ffa0df8854d
    Found by: stack scanning
10  0x9960bc9c77218aff
     rbx = 0x000055b5a9430e00    rbp = 0x000055b5a8e7e510
     rsp = 0x00007ffa08758510    r12 = 0x00000000ffffffff
     r13 = 0x00000000014ec6bd    r14 = 0x00007ffa00000000
     r15 = 0x0000000000001fa1    rip = 0x9960bc9c77218b00
    Found by: call frame info
11  libxul.so!nsTArray_Impl<RefPtr<mozilla::MozPromise<CopyableTArray<bool>, RefPtr<mozilla::MediaMgrError>, true>::Private>, nsTArrayInfallibleAllocator>::Clear() [nsTArray.h : 1947]
    Found by: inlining
12  libxul.so!mozilla::MozPromise<CopyableTArray<bool>, RefPtr<mozilla::MediaMgrError>, true>::DispatchAll() [MozPromise.h : 1164 + 0x1]
     rsp = 0x00007ffa08758550    rip = 0x00007ffa0fff9a66
    Found by: stack scanning
13  0x7ff97806311f
     rbx = 0x00007ffa08758830    rbp = 0x00007ffa13f72020
     rsp = 0x00007ffa08758558    r12 = 0x00007ffa08758580
     r13 = 0x0000000000001fa1    r14 = 0x00007ffa0fff9a66
     rip = 0x00007ff978063120
    Found by: call frame info
14  firefox!mozilla::detail::MutexImpl::unlock() [clone .cold] [Mutex_posix.cpp : 119 + 0x4]
     rbp = 0x00007ffa13f72020    rsp = 0x00007ffa08758640
     rip = 0x000055b5a5f47ee6
    Found by: stack scanning

Expected results:

Tab Shouldn't crash

Comment 1

[prathamIN]

A log with MOZ_LOG=GraphDriver:5,HTMLMediaElement:5,RTCRtpSender:5,VideoEngine:5,RTCDMTFSender:5,CamerasParent:5,PeerConnectionImpl:5,signaling:5,WebAudioAPI:5,MediaEncoder:5,MediaChild:5,ForwardedInputTrack:5,sdp:5,HTMLMediaElementEvents:5,GetUserMedia:5,VP8TrackEncoder:5,CamerasChild:5,MediaPipeline:5,MediaStream:5,TabShare:5,RTCRtpReceiver:5,VideoFrameConverter:5,ShmemPool:5,MediaTrackGraph:5,webrtc_trace:5,WebrtcTCPSocket:5,MediaManager:5,DriftCompensator:5,ForwardInputTrack:5,cubeb:5,TrackEncoder:5,jsep:5,MediaParent:5,RTCRtpTransceiver:5,MediaRecorder:5,Muxer:5,MediaStreamTrack:5,mtransport:5 is attached here (filename is just MOZ_LOG)

Note that I've added one line of logging here (https://github.com/mozilla/gecko-dev/blob/c3c92500ef8ffab4fa53d4b2d5c5e2b49025e89b/dom/media/MediaTrackGraph.cpp#L1577) that logs the passed values of aState and other parameters, eg. the function call that underflows logs the following line

VALS mProcessedTime 8320, mStateComputedTime 7680 (aState 7680)

This explains the underflow that happens here: https://github.com/mozilla/gecko-dev/blob/c3c92500ef8ffab4fa53d4b2d5c5e2b49025e89b/dom/media/MediaTrackGraph.cpp#L1485

mStateComputedTime - oldProcessedTime underflows to a huge value, which the mixer tries to allocate and fill here: https://github.com/mozilla/gecko-dev/blob/c3c92500ef8ffab4fa53d4b2d5c5e2b49025e89b/dom/media/AudioMixer.h#L117 which obviously causes the Infaliable Allocator to reject the allocation and kill the process

Comment 2

[prathamIN]

Attachment: MOZ_LOG

Comment 3

[prathamIN]

Seems like an issue with "shutting down" cubeb -- In all the crash logs, one pattern is common:

...
[Child 21331: AudioIPC Client Callback]: V/MediaTrackGraph 55b54c784040: interval[6014; 6425] state[6528; 7040] (frames: 471) (durationMS: 10) (duration ticks: 512)
[Child 21331: AudioIPC Client Callback]: V/MediaTrackGraph 55b54c784040: interval[6425; 6917] state[7040; 7552] (frames: 470) (durationMS: 10) (duration ticks: 512)
[Child 21331: AudioIPC Client Callback]: D/MediaTrackGraph Releasing audio driver off main thread.
[Child 21331: AudioIPC Client Callback]: D/MediaTrackGraph Starting new audio driver off main thread, to ensure it runs after previous shutdown.
[Child 21331: CubebOperation #1]: D/MediaTrackGraph 55b54c784040: AsyncCubebOperation::SHUTDOWN driver=7f3c080cb910
[Child 21331: MediaTrackGrph]: V/MediaTrackGraph 7f3c080645d0: interval[6917; 6921] state[7552; 8320]
[Child 21331: AudioIPC Client Callback]: V/MediaTrackGraph 55b54c784040: interval[6917; 7425] state[7552; 7680] (frames: 236) (durationMS: 5) (duration ticks: 128)

So one cubeb callback gets fired even after it's been requested to shut down, and that callback uses the "old" values (7552; 7680 rather than 8320; ..., which cause this bug. Does this make sense? If so, I can work on a fix for this

Comment 4

[prathamIN]

Yup, that was it:

void AudioCallbackDriver::Stop() {
  ...
  if (cubeb_stream_stop(mAudioStream) != CUBEB_OK) {
    NS_WARNING("Could not stop cubeb stream for MTG.");
  } else {
  ...
}

Logging the return value of cubeb_stream_stop here returns 0, but the callback (https://github.com/mozilla/gecko-dev/blob/e37662380b7b5507732a4f37a17da1a2f7802c04/dom/media/GraphDriver.cpp#L845) still gets executed, with the mAudioStreamState set to AudioCallbackDriver::AudioStreamState::Stopping, and ThreadRunning() returning false (just added a small printf("Is stopping: %d, Thread Running: %d\n", AudioCallbackDriver::AudioStreamState::Stopping == mAudioStreamState, ThreadRunning());)

So the issue is somewhere in the interaction of cubeb with pipewire-alsa, not really in firefox, since cubeb reports that the stream has successfully been stopped. Will investigate this on that side.

Comment 5

[Andreas Pehrson [:pehrsons]]

It's part of the API contract that data callbacks must not occur after cubeb_stream_stop has returned, so this is a bug in the alsa backend. Note that we don't actively maintain it, but contributions are always welcome.