briankendall / proxy-audio-device

A virtual audio driver for macOS to sends all audio to another output
The Unlicense
514 stars 33 forks source link

Ring buffer desync assistance #43

Open za-creature opened 5 months ago

za-creature commented 5 months ago

First off, a big thank you @briankendall for this awesome piece of hackery. I've had this issue since about 2018 and it's surprising to me that digital volume control is still not supported natively by Apple. I've been using your code since I found out about it (was previously using another solution that stopped working sometime around Catalina iirc), mostly successfully.

Regarding #14 and #19, I've recently stumbled upon a setup that goes out of sync after <5 minutes instead of hours. Not sure what's causing it, but I'll refrain from making any system changes for at least a week or so to give you some time to answer. I can confirm this behavior with both latest version and an older one (1.0.5)

I cloned and built both driver and config app locally and I sort of know what I'm doing but I haven't worked all that much (read: at all) with HAL or other Mac specific driver code so I'd most likely need some support here.

I'm fairly flexible about how to go about this: we can set up a live session (including, if you want, granting you supervised access to my machine) or we can go back and forth via text here. I'm primarily interested in domain knowledge, such as how to quickly deploy builds from xcode into the running kernel, where to collect logs from, etc.

Let me know when you have some availability. If need be, we can exchange credentials here using a DH exchange (disclaimer: I wrote the above)

briankendall commented 5 months ago

There's not too much domain knowledge I can impart. The way I've been doing logging -- and mind you this is probably not the best way to do it -- is to open Console and filter it for the string "proxyaudiodevice". Debug builds of the HAL driver will print to the console (see any place in the code where DebugMsg is used) and I set up every log statement to include that bit of text so it's easy to filter for.

I've been using the following shell script to copy in new builds of the driver and reload CoreAudio each time I make a build:

#/bin/bash
rm -rf /Library/Audio/Plug-Ins/HAL/ProxyAudioDevice.driver
cp -rf ./DerivedData/proxyAudioDevice/Build/Products/Debug/ProxyAudioDevice.driver /Library/Audio/Plug-Ins/HAL
launchctl kickstart -k system/com.apple.audio.coreaudiod

Bear in mind I have Xcode configured to put the DerivedData directory in the root of my project folder, so modify that path to the build products as necessary.

If you can find out anything about why things keep going out of sync, that would be great! I've sunk hours into trying to figure out this issue and didn't make any progress. I feel like I'm missing something basic, but I myself don't have that much experience working with CoreAudio and HAL plug-ins (this project is literally the extent of it) so I easily could be doing something wrong that someone with more experience would be able to spot quickly.

Most of my investigation was in ProxyAudioDevice::outputDeviceIOProc() since that's where the desync happens. I put in tons of print statements to notify when the number of samples that are left in the ring buffer gets smaller than the previous cycle, and can just watch it slowly run out until audio stops working. I haven't been able to figure out what configurations are the trigger either.

Can you say more about what your configuration is that causes the sync issue to happen within five minutes?

I don't think I'll have any time for live sessions all that soon -- both my work and personal life keep me plenty busy right now. But I'll try to assist you however else I can and answer any questions.

za-creature commented 5 months ago

No worries, what you've provided so far is plenty to get me started

I'm currently running Ventura 13.6.4 on what you might call unsanctioned hardware but I've only started having this issue a few days ago when I reinstalled due to having to give up one m.2 slot in favor of a different radio chip.

It may or may not be the same issue that others have been experiencing, but it definitely feels like a desync issue because:

  1. audio always starts back up as soon as I either restart the daemon or swap the buffer size in the config app AND
  2. sometimes the silence only lasts for a few minutes and starts working again (I mostly use the volume up + volume down keys, and listen for the tick - mind you, you have to enable that in settings > sound in more recent OS versions)

Thanks for the install script and the Console suggestion - previously I was doing syslog | grep ProxyAudioDevice but your way feels better!

If it's any help, here's some mostly raw output from the past couple of days:

Jan 25 22:53:52 Wolfcastle Core Audio Driver (ProxyAudioDevice.driver)[268] <Warning>: ProxyAudio: setupTargetOutputDevice could not find output device
Jan 25 23:04:27 Wolfcastle Core Audio Driver (ProxyAudioDevice.driver)[268] <Warning>: ProxyAudio: failed to add listener for 'l?L?' 'g?C?' 0
Jan 25 23:04:27 Wolfcastle Core Audio Driver (ProxyAudioDevice.driver)[268] <Warning>: ProxyAudio: failed to add listener for 'n?T?' 'g?C?' 0
Jan 25 23:04:31 Wolfcastle Core Audio Driver (ProxyAudioDevice.driver)[268] <Warning>: ProxyAudio: failed to add listener for 'l?L?' 'g?C?' 0
Jan 25 23:04:31 Wolfcastle Core Audio Driver (ProxyAudioDevice.driver)[268] <Warning>: ProxyAudio: failed to add listener for 'n?T?' 'g?C?' 0
Jan 26 00:50:26 Wolfcastle Core Audio Driver (ProxyAudioDevice.driver)[268] <Warning>: ProxyAudio: error: failed to start device 81
Jan 26 11:46:05 Wolfcastle Core Audio Driver (ProxyAudioDevice.driver)[268] <Warning>: ProxyAudio: error: failed to start device 81
Jan 26 11:47:58 Wolfcastle Core Audio Driver (ProxyAudioDevice.driver)[268] <Warning>: ProxyAudio: failed to add listener for 'l?L?' 'g?C?' 0
Jan 26 11:47:58 Wolfcastle Core Audio Driver (ProxyAudioDevice.driver)[268] <Warning>: ProxyAudio: failed to add listener for 'n?T?' 'g?C?' 0
Jan 26 11:48:00 Wolfcastle Core Audio Driver (ProxyAudioDevice.driver)[268] <Warning>: ProxyAudio: failed to add listener for 'l?L?' 'g?C?' 0
Jan 26 11:48:00 Wolfcastle Core Audio Driver (ProxyAudioDevice.driver)[268] <Warning>: ProxyAudio: failed to add listener for 'n?T?' 'g?C?' 0
Jan 26 11:49:34 Wolfcastle Core Audio Driver (ProxyAudioDevice.driver)[268] <Warning>: ProxyAudio: error: failed to start device 81
Jan 26 11:52:02 Wolfcastle Core Audio Driver (ProxyAudioDevice.driver)[268] <Warning>: ProxyAudio: error: failed to start device 81
Jan 26 11:58:03 Wolfcastle Core Audio Driver (ProxyAudioDevice.driver)[268] <Warning>: ProxyAudio: error: failed to start device 81
Jan 26 11:58:24 Wolfcastle Core Audio Driver (ProxyAudioDevice.driver)[268] <Warning>: ProxyAudio: failed to add listener for 'l?L?' 'g?C?' 0
Jan 26 11:58:24 Wolfcastle Core Audio Driver (ProxyAudioDevice.driver)[268] <Warning>: ProxyAudio: failed to add listener for 'n?T?' 'g?C?' 0
Jan 26 11:58:26 Wolfcastle Core Audio Driver (ProxyAudioDevice.driver)[268] <Warning>: ProxyAudio: failed to add listener for 'l?L?' 'g?C?' 0
Jan 26 11:58:26 Wolfcastle Core Audio Driver (ProxyAudioDevice.driver)[268] <Warning>: ProxyAudio: failed to add listener for 'n?T?' 'g?C?' 0
Jan 26 12:02:36 Wolfcastle Core Audio Driver (ProxyAudioDevice.driver)[268] <Warning>: ProxyAudio: error: failed to start device 81
Jan 26 12:03:09 Wolfcastle Core Audio Driver (ProxyAudioDevice.driver)[268] <Warning>: ProxyAudio: error: failed to stop device 81
Jan 26 12:03:09 Wolfcastle Core Audio Driver (ProxyAudioDevice.driver)[268] <Warning>: ProxyAudio: setupTargetOutputDevice could not find output device
Jan 26 12:05:14 Wolfcastle Core Audio Driver (ProxyAudioDevice.driver)[8921] <Warning>: ProxyAudio: error: failed to start device 48
Jan 26 12:05:55 Wolfcastle Core Audio Driver (ProxyAudioDevice.driver)[8921] <Warning>: ProxyAudio: error: failed to stop device 48
...
Followed by a lot of failed to start 48 with the occasional stop
...
Followed by pairs of
Jan 27 13:55:35 Wolfcastle Core Audio Driver (ProxyAudioDevice.driver)[266] <Warning>: ProxyAudio: setupTargetOutputDevice could not find output device

with repeated
Jan 27 13:55:37 Wolfcastle Core Audio Driver (ProxyAudioDevice.driver)[266] <Warning>: ProxyAudio: error: failed to start device 81

I'll add some log calls of my own after I figure out your code layout and I'll keep you posted with what I find out!

Thanks again

za-creature commented 5 months ago

Quick update, as I haven't had time to go through the codebase:

Every time the device fails to start is immediately preceded by: 5763 HALC_ProxyIOContext.cpp:783 HALC_ProxyIOContext::_StartIO(): Client running as an adaptive unboosted daemon which does not seem present when the device successfully starts.

The error returned by AudioDeviceStart is kAudioHardwareIllegalOperationError.

My current guess (again, mostly blind) is that a race condition in the driver is causing a second instance to start up while the previous one is still registered, and HAL interprets this as some other sort of driver with different semantics. Eventually all instances are released and a new one is successfully started after some time, which brings audio back up.

I'll add some more log calls when I get some time, the above is mostly a "I did not forget about this" notice.