search

dechamps / FlexASIO

A flexible universal ASIO driver that uses the PortAudio sound I/O library. Supports WASAPI (shared and exclusive), KS, DirectSound and MME.
Other
1.29k stars 70 forks source link

Max8 hangs with FlexASIO 1.10a WASAPI #235

Closed aleksati closed 1 month ago

aleksati commented 1 month ago

Max8 (audio programming environment developed by Cycling 74') crashes when choosing FlexAsio v.1.10 and 1.10a. v.1.9 seems to still work just fine.

dechamps commented 1 month ago

Uh, that doesn't sound good. I'll see if I can reproduce on my end, but in the mean time, could you provide a log please so that I can take a look?

dechamps commented 1 month ago

I just gave it a try. I'm afraid I am unable to reproduce. The "Audio Tester" in Max 8.6.2 works just fine with FlexASIO 1.10a:

image

In order to proceed any further I will need to understand the differences between your setup and mine. A log would help with that.

aleksati commented 1 month ago

Hi again,

Yes, I have now reinstalled 1.10a and did some tests. I get the same issue as before, Max crashes whenever I choose FlexASIO as my driver. I am using a Lenovo machine with Windows 10. Attached is the log and a screenshot.

FlexASIO.log

Screenshot 2024-05-31 093818

dechamps commented 1 month ago

Okay, now that your log gave me your FlexASIO config, I am able to reproduce. (Just for reference it is a hang, not a crash.)

The log shows the stream starting, a single stream callback being fired, and then Max suddenly decides to stop the stream (it's unclear why):

2024-05-31T18:28:53.1199471+01:00 1172 8100 --- ENTERING CONTEXT: start() on 000000002F4D40E0
2024-05-31T18:28:53.1200255+01:00 1172 8100 Checking if the host supports time info
2024-05-31T18:28:53.1200973+01:00 1172 8100 Sending message: selector = 1 [kAsioSelectorSupported], value = 7, message = 0000000000000000, opt = 0000000000000000
2024-05-31T18:28:53.1201869+01:00 1172 8100 Result: 1
2024-05-31T18:28:53.1202585+01:00 1172 8100 Sending message: selector = 7 [kAsioSupportsTimeInfo], value = 0, message = 0000000000000000, opt = 0000000000000000
2024-05-31T18:28:53.1203453+01:00 1172 8100 Result: 1
2024-05-31T18:28:53.1204157+01:00 1172 8100 The host supports time info
2024-05-31T18:28:53.1204863+01:00 1172 8100 Starting high resolution timer
2024-05-31T18:28:53.1205564+01:00 1172 8100 Starting PortAudio stream 000000002F9008C0
2024-05-31T18:28:53.1305395+01:00 1172 8384 [PortAudio] WASAPI: thread[ priority-0xD class-0x20 ]
2024-05-31T18:28:53.1307280+01:00 1172 8384 --- ENTERING STREAM CALLBACK
2024-05-31T18:28:53.1307285+01:00 1172 8100 PortAudio stream started
2024-05-31T18:28:53.1309131+01:00 1172 8384 Updated sample position: timestamp 78149733000000, 0 samples
2024-05-31T18:28:53.1309856+01:00 1172 8100 --- EXITING CONTEXT: start() [OK]
2024-05-31T18:28:53.1310436+01:00 1172 8384 PortAudio stream callback with input 0000000000000000, output 0000000028629A50, 512 frames, time info (PortAudio stream callback time info with input buffer ADC time 0, current time 78149.8, output buffer DAC time 78149.8), flags 0
2024-05-31T18:28:53.1311938+01:00 1172 8384 Transferring output buffers from buffer index #1 to PortAudio
2024-05-31T18:28:53.1312689+01:00 1172 8384 --- EXITING STREAM CALLBACK (0 [paContinue])
2024-05-31T18:28:53.1313759+01:00 1172 8384 --- ENTERING STREAM CALLBACK
2024-05-31T18:28:53.1314664+01:00 1172 8384 Updated sample position: timestamp 78149733000000, 0 samples
2024-05-31T18:28:53.1315604+01:00 1172 8384 PortAudio stream callback with input 0000000000000000, output 0000000028629A50, 512 frames, time info (PortAudio stream callback time info with input buffer ADC time 0, current time 78149.8, output buffer DAC time 78149.8), flags 0
2024-05-31T18:28:53.1316704+01:00 1172 8384 Transferring input buffers from PortAudio to ASIO buffer index #0
2024-05-31T18:28:53.1317455+01:00 1172 8384 Firing ASIO bufferSwitchTimeInfo() callback with buffer index: 0, time info: (ASIO time with reserved 0 0 0 0, time info (ASIO time info with speed 0, system time 78149733000000, sample position 0, sample rate 48000 Hz, flags 7 [kSystemTimeValid, kSamplePositionValid, kSampleRateValid], reserved 0 0 0 0 0 0 0 0 0 0 0 0), time code (ASIO time code with speed 0, samples 0, flags 0, future 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0))
2024-05-31T18:28:53.1320933+01:00 1172 8384 bufferSwitchTimeInfo() complete, returned time info: none
2024-05-31T18:28:53.1321749+01:00 1172 8384 Waiting for the ASIO Host Application to signal OutputReady
2024-05-31T18:28:53.2116005+01:00 1172 8100 --- ENTERING CONTEXT: stop() on 000000002F4D40E0
2024-05-31T18:28:53.2117684+01:00 1172 8100 Stopping PortAudio stream 000000002F9008C0

The logs just ends there, which indicates that it's FlexASIO that's hanging in stop().

I pulled out the debugger and the relevant thread is stuck in this stack (note line numbers are relative to FlexASIO 1.10a):

 # Child-SP          RetAddr               Call Site
00 00000000`00bfb7f8 00007ff8`47d2ce89     ntdll!NtSignalAndWaitForSingleObject+0x14
01 00000000`00bfb800 00007ff8`0eca490f     KERNELBASE!SignalObjectAndWait+0xd9
02 00000000`00bfb8b0 00007ff8`0ec9d394     portaudio!StopStreamByUser+0x3f [C:\Users\etien\Documents\FlexASIO\src\portaudio\src\hostapi\wasapi\pa_win_wasapi.c @ 4520] 
03 00000000`00bfb8e0 00007ff8`0ec7df9c     portaudio!StopStream+0x14 [C:\Users\etien\Documents\FlexASIO\src\portaudio\src\hostapi\wasapi\pa_win_wasapi.c @ 4560] 
04 00000000`00bfb910 00007ff8`0fdfed83     portaudio!Pa_StopStream+0x4c [C:\Users\etien\Documents\FlexASIO\src\portaudio\src\common\pa_front.c @ 1483] 
05 00000000`00bfb950 00007ff8`0fdef6e3     FlexASIO!flexasio::StreamStopper::operator()+0x53 [C:\Users\etien\Documents\FlexASIO\src\flexasio\FlexASIO\portaudio.cpp @ 49] 
06 00000000`00bfbbb0 00007ff8`0fdefd0d     FlexASIO!std::unique_ptr<PaUtilStreamRepresentation,flexasio::StreamStopper>::~unique_ptr<PaUtilStreamRepresentation,flexasio::StreamStopper>+0x43 [C:\Program Files\Microsoft Visual Studio\2022\Community\VC\Tools\MSVC\14.40.33807\include\memory @ 3410] 
07 00000000`00bfbbf0 00007ff8`0fdf0cb8     FlexASIO!flexasio::FlexASIO::PreparedState::RunningState::~RunningState+0x1d
08 00000000`00bfbc20 00007ff8`0fe31aa0     FlexASIO!flexasio::FlexASIO::PreparedState::RunningState::`scalar deleting destructor'+0x18
09 00000000`00bfbc50 00007ff8`0fe0685f     FlexASIO!std::_Optional_destruct_base<flexasio::FlexASIO::PreparedState::RunningState,0>::reset+0x30 [C:\Program Files\Microsoft Visual Studio\2022\Community\VC\Tools\MSVC\14.40.33807\include\optional @ 132] 
0a 00000000`00bfbc90 00007ff8`0fe05c87     FlexASIO!flexasio::FlexASIO::PreparedState::Stop+0x5f [C:\Users\etien\Documents\FlexASIO\src\flexasio\FlexASIO\flexasio.cpp @ 929] 
0b 00000000`00bfbce0 00007ff8`0fde084d     FlexASIO!flexasio::FlexASIO::Stop+0x67 [C:\Users\etien\Documents\FlexASIO\src\flexasio\FlexASIO\flexasio.cpp @ 923] 
0c 00000000`00bfbd30 00007ff8`0fde1857     FlexASIO!`flexasio::`anonymous namespace'::CFlexASIO::EnterWithMethod<void (__cdecl flexasio::FlexASIO::*)(void)>'::`2'::<lambda_1>::operator()+0x3d [C:\Users\etien\Documents\FlexASIO\src\flexasio\FlexASIO\cflexasio.cpp @ 190] 
0d 00000000`00bfbd70 00007ff8`0fde6080     FlexASIO!`flexasio::`anonymous namespace'::CFlexASIO::EnterInitialized<`flexasio::`anonymous namespace'::CFlexASIO::EnterWithMethod<void (__cdecl flexasio::FlexASIO::*)(void)>'::`2'::<lambda_1> >'::`2'::<lambda_1>::operator()+0x1b7 [C:\Users\etien\Documents\FlexASIO\src\flexasio\FlexASIO\cflexasio.cpp @ 185] 
0e 00000000`00bfbee0 00007ff8`0fde96f8     FlexASIO!flexasio::`anonymous namespace'::CFlexASIO::Enter<`flexasio::`anonymous namespace'::CFlexASIO::EnterInitialized<`flexasio::`anonymous namespace'::CFlexASIO::EnterWithMethod<void (__cdecl flexasio::FlexASIO::*)(void)>'::`2'::<lambda_1> >'::`2'::<lambda_1> >+0x110 [C:\Users\etien\Documents\FlexASIO\src\flexasio\FlexASIO\cflexasio.cpp @ 156] 
0f 00000000`00bfc370 00007ff8`0fde9ffd     FlexASIO!flexasio::`anonymous namespace'::CFlexASIO::EnterInitialized<`flexasio::`anonymous namespace'::CFlexASIO::EnterWithMethod<void (__cdecl flexasio::FlexASIO::*)(void)>'::`2'::<lambda_1> >+0xa8 [C:\Users\etien\Documents\FlexASIO\src\flexasio\FlexASIO\cflexasio.cpp @ 187] 
10 00000000`00bfc420 00007ff8`0fdde96e     FlexASIO!flexasio::`anonymous namespace'::CFlexASIO::EnterWithMethod<void (__cdecl flexasio::FlexASIO::*)(void)>+0x9d [C:\Users\etien\Documents\FlexASIO\src\flexasio\FlexASIO\cflexasio.cpp @ 191] 
11 00000000`00bfc4b0 00000000`0de12b25     FlexASIO!flexasio::`anonymous namespace'::CFlexASIO::stop+0x4e [C:\Users\etien\Documents\FlexASIO\src\flexasio\FlexASIO\cflexasio.cpp @ 118] 
12 00000000`00bfc520 00000000`0de130b5     ad_asio+0x2b25
13 00000000`00bfc550 00000001`414fd150     ad_asio+0x30b5
14 00000000`00bfc590 00000001`414df316     Max!typedmess+0x5d0
…lots of Max frames…

Meanwhile, in the streaming thread:

 # Child-SP          RetAddr               Call Site
00 00000000`31b2df58 00007ff8`4a7791db     ntdll!NtWaitForAlertByThreadId+0x14
01 00000000`31b2df60 00007ff8`47cbeaa9     ntdll!RtlSleepConditionVariableSRW+0x13b
02 00000000`31b2dfe0 00007ff8`0f7a21f6     KERNELBASE!SleepConditionVariableSRW+0x29
03 00000000`31b2e020 00007ff8`0f7a21a3     MSVCP140D!Concurrency::details::stl_condition_variable_win7::wait_for+0x36 [D:\a\_work\1\s\src\vctools\crt\github\stl\src\primitives.hpp @ 28] 
04 00000000`31b2e060 00007ff8`0f7a24d4     MSVCP140D!Concurrency::details::stl_condition_variable_win7::wait+0x23 [D:\a\_work\1\s\src\vctools\crt\github\stl\src\primitives.hpp @ 22] 
05 00000000`31b2e090 00007ff8`0fe32f44     MSVCP140D!_Cnd_wait+0x44 [D:\a\_work\1\s\src\vctools\crt\github\stl\src\cond.cpp @ 65] 
06 00000000`31b2e0d0 00007ff8`0fe211f4     FlexASIO!std::condition_variable::wait+0x44 [C:\Program Files\Microsoft Visual Studio\2022\Community\VC\Tools\MSVC\14.40.33807\include\mutex @ 559] 
07 00000000`31b2e110 00007ff8`0fe07dee     FlexASIO!std::condition_variable::wait<`flexasio::FlexASIO::PreparedState::RunningState::StreamCallback'::`51'::<lambda_1> >+0x34 [C:\Program Files\Microsoft Visual Studio\2022\Community\VC\Tools\MSVC\14.40.33807\include\mutex @ 565] 
08 00000000`31b2e140 00007ff8`0fe0809c     FlexASIO!flexasio::FlexASIO::PreparedState::RunningState::StreamCallback+0xd5e [C:\Users\etien\Documents\FlexASIO\src\flexasio\FlexASIO\flexasio.cpp @ 1033] 
09 00000000`31b2f470 00007ff8`0ec8296d     FlexASIO!flexasio::FlexASIO::PreparedState::StreamCallback+0x14c [C:\Users\etien\Documents\FlexASIO\src\flexasio\FlexASIO\flexasio.cpp @ 940] 
0a 00000000`31b2f9d0 00007ff8`0ec8162b     portaudio!NonAdaptingProcess+0x6cd [C:\Users\etien\Documents\FlexASIO\src\portaudio\src\common\pa_process.c @ 879] 
0b 00000000`31b2fa70 00007ff8`0eca4d09     portaudio!PaUtil_EndBufferProcessing+0x54b [C:\Users\etien\Documents\FlexASIO\src\portaudio\src\common\pa_process.c @ 1591] 
0c 00000000`31b2fb30 00007ff8`0eca5331     portaudio!WaspiHostProcessingLoop+0x289 [C:\Users\etien\Documents\FlexASIO\src\portaudio\src\hostapi\wasapi\pa_win_wasapi.c @ 5041] 
0d 00000000`31b2fc00 00007ff8`0ec9a6c0     portaudio!ProcessOutputBuffer+0x231 [C:\Users\etien\Documents\FlexASIO\src\portaudio\src\hostapi\wasapi\pa_win_wasapi.c @ 5647] 
0e 00000000`31b2fc80 00007ff8`0ed3a2a5     portaudio!ProcThreadPoll+0x2c0 [C:\Users\etien\Documents\FlexASIO\src\portaudio\src\hostapi\wasapi\pa_win_wasapi.c @ 6167] 
0f 00000000`31b2fed0 00007ff8`4999257d     portaudio!thread_start<unsigned int (__cdecl*)(void *),1>+0xa5 [minkernel\crts\ucrt\src\appcrt\startup\thread.cpp @ 97] 
10 00000000`31b2ff30 00007ff8`4a76aa48     KERNEL32!BaseThreadInitThunk+0x1d
11 00000000`31b2ff60 00000000`00000000     ntdll!RtlUserThreadStart+0x28

So what's going on is PortAudio is trying to stop the stream, but it can't because FlexASIO is hanging forever in the stream callback.

And the line FlexASIO hangs in is:

https://github.com/dechamps/FlexASIO/blob/fc4f5793ff88c8ec607924582cc0afefee02d4c2/src/flexasio/FlexASIO/flexasio.cpp#L1033

So the reason why FlexASIO is hanging is because it's waiting for OutputReady(), which Max advertised support for:

2024-05-31T18:28:53.0270431+01:00 1172 8100 --- ENTERING CONTEXT: outputReady() on 000000002F4D40E0
2024-05-31T18:28:53.0273865+01:00 1172 8100 Host supports OutputReady
2024-05-31T18:28:53.0274717+01:00 1172 8100 --- EXITING CONTEXT: outputReady() [OK]

…but the call never arrives, and so FlexASIO hangs forever.

So, to summarize:

  1. Max advertises support for outputReady().
  2. Max calls start() on FlexASIO.
  3. FlexASIO fires the first stream callback.
  4. Max returns from bufferSwitch().
  5. Max calls stop().
    • It's not clear why Max decides to stop the stream almost immediately after it starts. Technically this is a perfectly valid call, though. (Later examination of working setups reveals Max opens another stream immediately afterwards, so this one-buffer stream may just be Max attempting to "probe" the driver or something.)
  6. FlexASIO hangs in the stream callback because Max never called outputReady() for the corresponding bufferSwitch() call.
  7. PortAudio waits for the stream callback to return to stop the stream, and therefore hangs too.
  8. End result: Max hangs forever in stop().

I was wondering why I couldn't reproduce this at first. It turns out it's only triggered if the WASAPI backend is used. The reason for this is because the DirectSound PortAudio code "helpfully" has a timeout in its stop code, thus hiding the problem!

And indeed a DirectSound log does hint at the issue, through the error being returned from stop() and the gap in timestamps:

2024-05-31T19:01:56.3076028+01:00 11216 9732 --- ENTERING CONTEXT: start() on 000000000F3BF2B0
2024-05-31T19:01:56.3076776+01:00 11216 9732 Checking if the host supports time info
2024-05-31T19:01:56.3077445+01:00 11216 9732 Sending message: selector = 1 [kAsioSelectorSupported], value = 7, message = 0000000000000000, opt = 0000000000000000
2024-05-31T19:01:56.3078332+01:00 11216 9732 Result: 1
2024-05-31T19:01:56.3079051+01:00 11216 9732 Sending message: selector = 7 [kAsioSupportsTimeInfo], value = 0, message = 0000000000000000, opt = 0000000000000000
2024-05-31T19:01:56.3079896+01:00 11216 9732 Result: 1
2024-05-31T19:01:56.3080585+01:00 11216 9732 The host supports time info
2024-05-31T19:01:56.3081259+01:00 11216 9732 Starting high resolution timer
2024-05-31T19:01:56.3082116+01:00 11216 9732 Starting PortAudio stream 000000000F3BC770
2024-05-31T19:01:56.3086731+01:00 11216 9732 [PortAudio] StartStream: DSW_StartInput returned = 0x0.
2024-05-31T19:01:56.3097321+01:00 11216 9732 [PortAudio] PaHost_ClearOutputBuffer: IDirectSoundBuffer_SetCurrentPosition returned = 0x0.
2024-05-31T19:01:56.3440529+01:00 11216 9732 [PortAudio] PaHost_StartOutput: IDirectSoundBuffer_Play returned = 0x0.
2024-05-31T19:01:56.3444724+01:00 11216 9732 PortAudio stream started
2024-05-31T19:01:56.3446482+01:00 11216 9732 --- EXITING CONTEXT: start() [OK]
2024-05-31T19:01:56.3910160+01:00 11216 6896 --- ENTERING STREAM CALLBACK
2024-05-31T19:01:56.3911943+01:00 11216 6896 Updated sample position: timestamp 80132987000000, 0 samples
2024-05-31T19:01:56.3912985+01:00 11216 6896 PortAudio stream callback with input 000000000E247440, output 000000000E2474E0, 512 frames, time info (PortAudio stream callback time info with input buffer ADC time 80133, current time 80133.1, output buffer DAC time 80133.1), flags 0
2024-05-31T19:01:56.3916239+01:00 11216 6896 Transferring output buffers from buffer index #1 to PortAudio
2024-05-31T19:01:56.3917118+01:00 11216 6896 --- EXITING STREAM CALLBACK (0 [paContinue])
2024-05-31T19:01:56.3933597+01:00 11216 6896 --- ENTERING STREAM CALLBACK
2024-05-31T19:01:56.3935401+01:00 11216 6896 Updated sample position: timestamp 80132990000000, 0 samples
2024-05-31T19:01:56.3937172+01:00 11216 6896 PortAudio stream callback with input 000000000E247440, output 000000000E2474E0, 512 frames, time info (PortAudio stream callback time info with input buffer ADC time 80133, current time 80133.1, output buffer DAC time 80133.1), flags 0
2024-05-31T19:01:56.3939447+01:00 11216 6896 Transferring input buffers from PortAudio to ASIO buffer index #0
2024-05-31T19:01:56.3940965+01:00 11216 6896 Firing ASIO bufferSwitchTimeInfo() callback with buffer index: 0, time info: (ASIO time with reserved 0 0 0 0, time info (ASIO time info with speed 0, system time 80132990000000, sample position 0, sample rate 44100 Hz, flags 7 [kSystemTimeValid, kSamplePositionValid, kSampleRateValid], reserved 0 0 0 0 0 0 0 0 0 0 0 0), time code (ASIO time code with speed 0, samples 0, flags 0, future 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0))
2024-05-31T19:01:56.3945199+01:00 11216 6896 bufferSwitchTimeInfo() complete, returned time info: none
2024-05-31T19:01:56.3946198+01:00 11216 6896 Waiting for the ASIO Host Application to signal OutputReady
2024-05-31T19:01:56.4250228+01:00 11216 9732 --- ENTERING CONTEXT: stop() on 000000000F3BF2B0
2024-05-31T19:01:56.4251890+01:00 11216 9732 Stopping PortAudio stream 000000000F3BC770
2024-05-31T19:01:59.6108119+01:00 11216 9732 Unable to stop PortAudio stream: Unanticipated host error
2024-05-31T19:01:59.6110250+01:00 11216 9732 Stopping high resolution timer
2024-05-31T19:01:59.6111107+01:00 11216 9732 --- EXITING CONTEXT: stop() [OK]

In this case the streaming thread just hangs around forever, but it doesn't prevent stop() from progressing.

I also noticed this does not affect FlexASIO 1.9, which surprised me at first, until I realized that in 1.9 this problem would have been hidden by #180.

So, in other words, fixing #180 made Max regress because we are now (correctly) waiting for OutputReady, but Max does not call it in this initial one-buffer stream.

Whether Max is actually at fault here is somewhat debatable. On one hand, Max gets a bufferSwitch callback but then never calls outputReady(), even though it advertised support for it. On the other hand, one could argue that it doesn't make sense for FlexASIO to keep waiting for outputReady after stop() is called.

So, to summarize: this bug is a very subtle regression in FlexASIO 1.10 that affects Max when the WASAPI backend is used.

@aleksati I will fix this regression in the next FlexASIO release. In the mean time, you can work around this issue by going back to FlexASIO 1.9, or by avoiding the WASAPI backend.

dechamps commented 1 month ago

(Note to myself regarding a potential fix: one tricky part of this is, if we unblock stop() before outputReady() is called, then it follows that we'll need to be careful about outputReady() calls racing against stop(), especially with regard to the presence of RunningState.)

dechamps commented 1 month ago

This is fixed in FlexASIO 1.10b.