1881609 - Firefox WebRTC breaks audio system-wide on macOS

Status: NEW

(Core :: WebRTC, defect)

Description

[Sam Johnson]

I've been experiencing this issue for quite some time on Nightly; I will try to get a mozregression to help narrow things down.

STR:

1. Connect AirPods to your Mac and use them as the default output and input device. I am currently using AirPods (3rd generation) and a 2019 16" MacBook Pro (Intel) running macOS 14.3.1.
2. Start playing some audio outside of Firefox so that you can identify when system-wide audio breaks. I used Spotify for this test, but it affects any app (and system sounds).
3. Visit https://webrtc.github.io/test-pages/src/single-audio/ and grant it permission to your microphone.
4. At this point you should hear yourself, plus the audio playing from step 2.
5. Reload the test page, then close the tab before you hear yourself again.
6. At this point system-wide audio is completely broken--sometimes it is silent, other times all audio is played at comically slow speed.

Comment 1

[Jan-Ivar Bruaroey [:jib] (needinfo? me)]

Hi Sam thanks for reporting. I'm on 14.0. with 3rd gen AirPods and cannot repro, so a range from mozregression would be great!

FWIW I played an mp3 file from Finder, and the music volume jumps up after a tiny pause in step 3. Step 5 I assume is timing sensitive but I think I closed it fast enough. In step 6 the volume returns to the earlier (lower) level for me after a second tiny pause, but the music keeps playing at the right speed.

Comment 2

[Sam Johnson]

Hi @jib! Were you testing with an Intel or Apple silicon machine? I've tried to reproduce on several machines here, and I've only had success on the Intel machines.

Unfortunately, I'm having a hard time getting the microphone to work with builds from mozregression. Are there any tips you're aware of for that?

Comment 3

[Andreas Pehrson [:pehrsons]]

Hi Sam, thanks for the report.

This is probably regressed by bug 1670633. You could try manually the nightlies from around then. Barring any timezone issues I think it first appeared in the late 2023-11-24 nightly.

To help debug this, could you on a machine where it reproduces, in a new session, capture a profile, please? These steps:

• Go to about:logging, select the WebRTC preset, click Start Logging
• Open a new tab and reproduce the bug there.
• On about:logging again, click Stop Logging.
• A new tab will open with the Firefox Profiler, in the upper right corner click the button to upload the profile. Include hidden threads, please.

I'll also try to reproduce on my end. Thanks!

Comment 4

[Andreas Pehrson [:pehrsons]]

I could reproduce complete silence after the reloading in step 5 with 2nd gen airpods on macOS 14.3.1, but only for a while. Closing the tab extended the time it took for audio in the other app to come back. S3 because it didn't seem like a permanently bad state. Maybe it is in your case though, but at least we then know it doesn't affect every macOS 14 user with a bluetooth device.

FWIW on macOS 12.7.2 it behaves better as the closing of the page using the mic doesn't immediately cause a bluetooth profile switch (that period when the audio from the other app is silent). This meant a reload where we end up using the mic again does not affect the audio in the other app at all.

I'd say generally that this is an Apple bug, so if you have a moment, please report it there. Perhaps we can improve or work around it in Firefox though, let's start with bug 1880244.

Comment 5

[BugBot [:suhaib / :marco/ :calixte]]

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

Comment 6

[Sam Johnson]

Hi Andreas! I can confirm that it looks like bug 1670633 was the regressor--build 20231124214933 (the first build with bug 1670633) is the first build where I can reproduce the issue. I was not able to reproduce the issue on build 20231124092418 which doesn't have the patches from bug 1670633.

Here is the profile: https://share.firefox.dev/3uJHlRs

Thanks!

Comment 7

[Donal Meehan [:dmeehan]]

:phersons Fx126 is now in Beta, Bug 1880244 landed in time for Fx126.
Do you plan on tracking anything else here, or should Bug 1880244 have fixed this?

Comment 8

[Andreas Pehrson [:pehrsons]]

Sam, could you give latest nightly or beta a spin to see if you can reproduce?
Things have shifted in more than one way, but importantly what was triggered in your step 5 should now be triggered 10 seconds after we close the last stream that was using the microphone. I.e. to achieve the same symptoms you'd need different steps. If you can find something common I can take a look again, but note I have had a hard time reproducing your original report as well as finding any issues with latest nightly.

I will say I have occasionally gotten macOS into a weird state, and there are definitely macOS bugs here. If easy enough to hit we may attempt a mitigation, but otherwise what we can do is a bit limited.

Comment 9

[Sam Johnson]

Hi Andreas! Unfortunately the issue continues to reproduce readily for me in the latest Nightly. I am running into this issue from a real-world application using the Twilio Voice SDK that is much more straightforward at reproducing than the test case I was able to come up with for this bug, but unfortunately I am not able to grant access to the application. The reproduction in the application happens after ending a voice call (per your comment, it does now take 10 seconds after the call ends before system audio cuts out).

I have been working around this by running sudo killall coreaudiod in Terminal. Unfortunately, this then breaks audio in Firefox completely until I restart Firefox. Other apps seem to recover from this more gracefully.

Comment 10

[Andreas Pehrson [:pehrsons]]

Would you mind capturing logs into a profile per comment 3 while reproducing with the real-world application? I'd want all audio related threads (and some are not obviously audio related so I'd prefer defaulting to all) but you could upload the profile without URLs and main threads for instance.

Safari and Facetime both use the same VoiceProcessingIO audio unit as we use now. Safari never disposes of it, which is what seems to trigger your issue with Firefox. How Facetime manages the lifetime of the audio unit I am not sure.

When system-wide audio is in a broken state, does switching audio format for the airpods output device in the "Audio MIDI Setup" app affect anything? Does switching system default output device in System Settings -> Sound affect anything?

I'll try to reproduce the inability to recover from a killed coreaudiod.

Comment 11

[Andreas Pehrson [:pehrsons]]

I do note some reports online specific to macos 14, https://www.reddit.com/r/MacOS/comments/173pkf3/i_am_going_crazy_mac_is_unusable_when_bluetooth/, https://www.reddit.com/r/applehelp/comments/182zxvt/macos_monterey_sonoma_bluetooth_headphone_audio/ that could be related to your issue. If so, observing and playing with the format in Audio MIDI Setup per comment 10 should reveal it.

It could also be interesting to look at system logs (like sudo log show --debug --last 10m) of a reproduction and subsequent exit of Firefox to restore things to normal, but they'd have to come with a correlation between log timestamps and user actions to be useful.

Comment 12

[Sam Johnson]

Here is a new profile with the reproduction: https://share.firefox.dev/4d6jVXV

I also captured system logs using the command you provided during the same time period as the profile. I do see lots of coreaudio logging so hopefully it is helpful. I can provide this, but I'm not sure if it contains any private information-- is there a way I can provide that privately?

Thanks for the tip re Audio MIDI Setup. Indeed, changing the audio format of the AirPods output device returns everything to normal!

Comment 13

[Andreas Pehrson [:pehrsons]]

Feel free to email the logs or a link to the logs to me, apehrson at mozilla.com.
When you fix this with Audio MIDI Setup what formats are you changing between?

Comment 14

[Andreas Pehrson [:pehrsons]]

Also, do you recall what actions you took and what symptoms you observed during the recording of that profile? Somewhat time correlated ideally.

I see us opening a 256-frame-latency@48kHz output-only stream first, then we switch to a 24kHz duplex (input+output, 24kHz because the input reports having only 24kHz, which is because of bluetooth) stream that sets up a voice processing audio unit and then gets destroyed right away. I'd have maybe expected it to be used for a bit?
Regardless, I see also right away another 256-frame-latency@24kHz (we don't translate the latency, and the device is now in handsfree profile, so only 24k) output-only stream get created. We cache the voice processing audio unit for a bit, 10 seconds, after being stopped because it is expensive to create and destroy. During the time the voice processing unit is alive, the second output stream runs on 512 frame callbacks (after upsampling to 48kHz), and after the voice processing unit has been destroyed, it runs on 128 frame callbacks. I'm not sure what happened there, or what rate it is now running at -- Possibly it has swapped format from 24kHz to 48kHz but 256@24 is 512 and not 128 @48..

Do you recall at what point during the capturing of this profile did all system output go silent?

Let's try to verify if your issue is related to the buffer size / latency: On about:config could you add a number pref media.cubeb_latency_mtg_frames and set it to 512 or 1024, then test again?
FWIW we are reading out the device's supported buffer sizes but perhaps it is specific to the current audio format, or something.

Comment 15

[Sam Johnson]

(In reply to Andreas Pehrson [:pehrsons] from comment #13)

When you fix this with Audio MIDI Setup what formats are you changing between?

In Audio MIDI Setup, I have two choices: "24 kHz 1 ch 32-bit Float", and "48 kHz 2 ch 32-bit Float". When audio is silent, it is set to the 48 kHz option. To fix it, I switch to the 24 kHz option and then immediately switch back to the 48 kHz option, which causes audio to resume as expected.

(In reply to Andreas Pehrson [:pehrsons] from comment #14)

Also, do you recall what actions you took and what symptoms you observed during the recording of that profile? Somewhat time correlated ideally.
I see us opening a 256-frame-latency@48kHz output-only stream first, then we switch to a 24kHz duplex (input+output, 24kHz because the input reports having only 24kHz, which is because of bluetooth) stream that sets up a voice processing audio unit and then gets destroyed right away. I'd have maybe expected it to be used for a bit?

At the beginning of the profile, the app is initialized. As part of this, there is some logic like so used to grab the list of input devices:

navigator.mediaDevices.getUserMedia({audio:true}).then((stream) => {
  try {
    // do stuff to retrieve input device list
  } finally {
    stream.getTracks().forEach((track) => track.stop());
  }
});

This sometimes causes the issue on its own, and is what the STR originally posted attempted to emulate (the tracks starting and stopping basically immediately).

After the app is initialized, a voice call was received and answered. After a few seconds, the voice call is ended, I believe this was about 13 seconds into the profile. About 10 seconds after this point, the system audio stopped and did not resume.

Let's try to verify if your issue is related to the buffer size / latency: On about:config could you add a number pref media.cubeb_latency_mtg_frames and set it to 512 or 1024, then test again?

Unfortunately I was able to reproduce the issue with this set to both 512 and 1024.

I should add an interesting side effect of the silent audio that I have not yet mentioned--when in this state, Firefox will not play videos, such as from YouTube. Either they play in very-slow-motion (<1fps) or do not play at all.

Comment 16

[Andreas Pehrson [:pehrsons]]

Thank you Sam. I see some error in the log like

2024-04-22 18:10:08.666327-0500 0xf7b4f9   Default     0x0                  73321  0    firefox: (AudioDSP) [com.apple.coreaudio:auvp]         AUVPAggregate.cpp:4919  Current output device tap stream physical format =  1 ch,  24000 Hz, Float32
2024-04-22 18:10:08.667508-0500 0xf7b4f9   Default     0x0                  73321  0    firefox: (AudioDSP) [com.apple.coreaudio:auvp]         AUVPAggregate.cpp:4956  Found max number of channels output device tap stream physical format =  2 ch,  48000 Hz, Float32, interleaved
2024-04-22 18:10:08.667513-0500 0xf7b4f9   Default     0x0                  73321  0    firefox: (AudioDSP) [com.apple.coreaudio:auvp]         AUVPAggregate.cpp:4957  Setting output device tap stream physical format =  2 ch,  48000 Hz, Float32, interleaved
2024-04-22 18:10:08.667929-0500 0x1003089  Default     0x0                  11896  0    coreaudiod: (BTAudioHALPlugin) [com.apple.bluetooth:BTAudio] [ 73321 ] Request for physical format change 24000.000000 -> 48000.000000 format change supported 1
2024-04-22 18:10:08.667931-0500 0x1003089  Default     0x0                  11896  0    coreaudiod: (BTAudioHALPlugin) [com.apple.bluetooth:BTAudio] BTUnifiedAudioDevice: Format Fixed  Requested for unsupported sample rate 48000.000000 [ Supported 24000.000000]
2024-04-22 18:10:08.667943-0500 0x1003089  Default     0x0                  11896  0    coreaudiod: (CoreAudio)         HALS_UCPlugIn.cpp:1160   HALS_UCPlugIn::ObjectSetPropertyData: failed:  [<private>/<private>/0], Error: 1852797029 (<private>)
2024-04-22 18:10:08.667993-0500 0xf7b4f9   Default     0x0                  73321  0    firefox: (CoreAudio)      HALC_ProxyObject.cpp:1364   HALC_ProxyObject::SetPropertyData ('<private>', '<private>', 0, Unk): got an error from the server, 0x6E6F7065
2024-04-22 18:10:08.667995-0500 0xf7b4f9   Error       0x0                  73321  0    firefox: (CoreAudio)       HALC_ShellObject.mm:564    HALC_ShellObject::SetPropertyData: call to the proxy failed, Error: 1852797029 (<private>)
2024-04-22 18:10:08.667998-0500 0xf7b4f9   Default     0x0                  73321  0    firefox: (CoreAudio)             HALPlugIn.cpp:329    HALPlugIn::ObjectSetPropertyData: got an error from the plug-in routine [<private>/<private>/0], Error: 1852797029 (<private>)
2024-04-22 18:10:08.668023-0500 0xf7b4f9   Error       0x0                  73321  0    firefox: (AudioDSP) [com.apple.coreaudio:auvp]         AUVPAggregate.cpp:4961  Failed to set output device tap stream physical format =  2 ch,  48000 Hz, Float32, interleaved, err=1852797029
2024-04-22 18:10:08.668197-0500 0xf7b4f9   Default     0x0                  73321  0    firefox: (AudioDSP) [com.apple.coreaudio:auvp]         AUVPAggregate.cpp:1323  ID=60/ scope=0 / element=0 / err=-10879

but it seems to correlate to setting up the duplex (input+output) stream so probably irrelevant.

Looking beyond the point where we've switched to an output-only stream again, some things of interest seem to be:

2024-04-22 18:10:24.290703-0500 0x10033f5  Default     0x0                  11896  0    coreaudiod: (CoreAudio)        HALS_IOEngine2.cpp:2043   HALS_IOEngine2::StartIO: starting IO on device <private>
2024-04-22 18:10:24.290713-0500 0x10033f5  Default     0x0                  11896  0    coreaudiod: (BTAudioHALPlugin) [com.apple.bluetooth:BTAudio] BTUnifiedAudioDevice: StartIO activeIO:0 [32] delegate to current Device  F8:4D:<redacted>-tacl
2024-04-22 18:10:24.290717-0500 0x10033f5  Default     0x0                  11896  0    coreaudiod: (BTAudioHALPlugin) [com.apple.bluetooth:BTAudio] Smart Route Manager StartIO:  <private> Device ID 0:
2024-04-22 18:10:24.290718-0500 0x10033f5  Default     0x0                  11896  0    coreaudiod: (BTAudioHALPlugin) [com.apple.bluetooth:BTAudio] updateSession Create Session
2024-04-22 18:10:24.290720-0500 0x10033f5  Default     0x0                  11896  0    coreaudiod: (BTAudioHALPlugin) [com.apple.bluetooth:BTAudio] Initialize Bluetooth Audio Smart Route Session in Route Manager <private>
2024-04-22 18:10:24.290721-0500 0x10033f5  Default     0x0                  11896  0    coreaudiod: (BTAudioHALPlugin) [com.apple.bluetooth:BTAudio] updateSession startIO <private> isStart 1 isInput Output SInput false, SOutput true
2024-04-22 18:10:24.290730-0500 0x10033f5  Default     0x0                  11896  0    coreaudiod: (BTAudioHALPlugin) [com.apple.bluetooth:BTAudio] Starting IO on profile tacl, 0 to F8:4D:<redacted>-tacl mAudioObjectID: 33 Wait IO Start 1
2024-04-22 18:10:24.290746-0500 0x10033f5  Default     0x0                  11896  0    coreaudiod: (BTAudioHALPlugin) [com.apple.bluetooth:BTAudio] XPC START MESSAGE SENT, Shared Memory output 0x0x0 of size 27392. Shared Memory Input 0x0x0 of size 0
2024-04-22 18:10:24.290761-0500 0x10033f5  Error       0x0                  11896  0    coreaudiod: (BTAudioHALPlugin) [com.apple.bluetooth:BTAudio] #Error BTAudioXpcConnection::SendStartMsg null values[0]
2024-04-22 18:10:24.290762-0500 0x10033f5  Error       0x0                  11896  0    coreaudiod: (BTAudioHALPlugin) [com.apple.bluetooth:BTAudio] #Error BTAudioXpcConnection::SendStartMsg null values[1]

though things appear to continue as normal after this. After a while I see some pairs of StartIO and StopIO on first Firefox then Spotify, then these two lines repeat every 50ms or so until the end of the log:

2024-04-22 18:10:25.504453-0500 0xb55de5   Default     0x0                  11896  0    coreaudiod: (CoreAudio) [com.apple.coreaudio:AMCP] 197947                 HALS_IOClock.cpp:183   HALS_IORawClock::Update: Re-anchoring IO timeline. Sample time is not consecutive. Ring buffer size: 16384.000000, sample diff: 2560.000000
2024-04-22 18:10:25.504675-0500 0xb55de5   Error       0x0                  11896  0    coreaudiod: (CoreAudio) [com.apple.coreaudio:AMCP] 197947               HALS_IOEngine2.cpp:4006  Detected possible coloring mixer glitch on F8-4D-<redacted>:output: buffer time: 49748  actual time: 47188  safety violation: -1540  with 2 running contexts

I'd recommend reproducing this again, then filing with Apple through Feedback Assistant on CoreAudio, making sure to add a sysdiagnose (in Feedback Assistant add one under attachments, it gets captured automatically).

All this is from platform libraries. The main input we have here is buffer size and sample rate, but I don't see errors related to those. Marking stalled.

Comment 17

[Andreas Pehrson [:pehrsons]]

Since this is an internal Apple thing, and we also saw something internal to the VPIO unit getting affected in bug 1895787, would you mind checking if you're still affected in latest Nightly? Chances are low, I guess, but why not check.

Also, you could probably avoid this issue by turning off the voice pref for input streams, by setting the media.getusermedia.microphone.prefer_voice_stream_with_processing.enabled pref to false.
OTOH then you'll be exposed to the original issue reported in bug 1670633, but it seems to happen mainly with usb devices.