Potential freeze when WASAPI is enabled

[cary-rowen]

cc @jcsteh It would be great if you could look into it.
alpha-29899 appears to have included #15754. This PR failed to fix this.

I created a demo add-on that reproduces the issue. It is derived from some functions in real projects.

Steps to reproduce:

Reproduce the following steps using 2023.3 or the latest Alpha version, as these versions have WASAPI enabled by default.

1. Download and install the demo.
2. Restart NVDA and press:
   • nvda+ctrl+l
   • nvda+ctrl+h

Actual behavior:

You will notice that NVDA is temporarily lagging.
You'll also notice the following in the log.

DEBUG - watchdog._waitUntilNormalCoreAliveTimeout (13:06:04.105) - watchdog (14208):
Recovered from potential freeze after 3.002258599999891 seconds.
DEBUG - watchdog._waitUntilNormalCoreAliveTimeout (13:06:04.435) - watchdog (14208):
Potential freeze, waiting up to 10 seconds.

Expected behavior:

NVDA should not potentially freeze.

NVDA logs, crash dumps and other attachments:

System configuration

NVDA installed/portable/running from source:

Installed

NVDA version:

2023.3 and 2024.1alpha-29899,cb356535

Windows version:

Windows 10 22H2 (AMD64) build 19045.3448

Name and version of other software in use when reproducing the issue:

None

Other information about your system:

None

Other questions

Does the issue still occur after restarting your computer?

Yes

Have you tried any other versions of NVDA? If so, please report their behaviors.

This cannot be reproduced if WASAPI is disabled or tested under 2023.2 (without WASAPI enabled).

If NVDA add-ons are disabled, is your problem still occurring?

No, the problem needs to be reproduced using a add-on, I can't find any other way to reproduce it.

Does the issue still occur after you run the COM Registration Fixing Tool in NVDA's tools menu?

Yes

[jcsteh]

I created a demo add-on that reproduces the issue.

Thanks.

It is derived from some functions in real projects.

To help with the understanding of user impact, can you explain how this impacts NVDA users or users of your add-ons? What doesn't work and/or what aren't you able to implement as a result of this?

[jcsteh]

From a brief look at your add-on, it looks like you might be playing multiple sounds in quick succession. Obviously, this shouldn't freeze, but can I ask what you are trying to achieve here? Even if this worked, there's no way you would be able to hear both sounds properly; the first would always be cut off by the second.

[jcsteh]

I am aware of a bug where playing multiple sounds in quick succession will block on the first sound. You can reproduce that easily with this Python console snippet:

import nvwave; nvwave.playWaveFile("waves/start.wav"); nvwave.playWaveFile("waves/start.wav")

I guess there is a race condition between the audio starting to play in the background thread and being stopped from the main thread. Either it doesn't handle an immediate play then stop, or the WASAPI code has slightly different timing such that the stop call is hitting before the first chunk of audio is fed. The WinMM code had a lot more locks, which caused a bunch of performance and other problems, but it's possible they did slow some calls down enough that this kind of thing was less likely.

[cary-rowen]

Hi @jcsteh,

From a brief look at your add-on, it looks like you might be playing multiple sounds in quick succession. Obviously, this shouldn't freeze, but can I ask what you are trying to achieve here? Even if this worked, there's no way you would be able to hear both sounds properly; the first would always be cut off by the second.

Frankly, this is problematic code, as you said, it won't be of much use, and I just happened to find it because of this bug in NVDA.

[Adriani90]

One remark, I think at least from security reasons NVDA should try to find a way to work around this freeze. I am thinkin of the example where someone could try to introduce intentionally malicious behavior with such code.

[Brian1Gaff]

This was one of the reasons why the 3D sound effects add on or custom sounds etc, has been disabled as if two sounds were played it tended to lock up the machine with lots of wave player errors. Strangely, this also seems to happen in Web Formatter which I've also disabled. This seems to be a bottleneck in windows from at least win 7 with nvda. Brian

…

-- ***@***.*** Sent via blueyonder.(Virgin media) Please address personal E-mail to:- ***@***.***, putting 'Brian Gaff' in the display name field. ----- Original Message ----- From: Rowen To: nvaccess/nvda Cc: Subscribed Sent: Wednesday, November 08, 2023 7:57 AM Subject: Re: [nvaccess/nvda] Potential freeze when WASAPI is enabled (Issue #15757) Hi @jcsteh, From a brief look at your add-on, it looks like you might be playing multiple sounds in quick succession. Obviously, this shouldn't freeze, but can I ask what you are trying to achieve here? Even if this worked, there's no way you would be able to hear both sounds properly; the first would always be cut off by the second. Frankly, this is problematic code, as you said, it won't be of much use, and I just happened to find it because of this bug in NVDA. — Reply to this email directly, view it on GitHub, or unsubscribe. You are receiving this because you are subscribed to this thread.Message ID: ***@***.***>

[Brian1Gaff]

I assume you mean by intentionally crashing the software into a circular watchdog or garbage error, though I've seen this, I don't think its intentional, its more to do with more than one add on assuming nobody else is using the routines its using and these are a problem to find, looking through the logs and seeing what line and in which add on the problem seems to start from. Brian

…

-- ***@***.*** Sent via blueyonder.(Virgin media) Please address personal E-mail to:- ***@***.***, putting 'Brian Gaff' in the display name field. ----- Original Message ----- From: Adriani90 To: nvaccess/nvda Cc: Subscribed Sent: Wednesday, November 08, 2023 8:28 AM Subject: Re: [nvaccess/nvda] Potential freeze when WASAPI is enabled (Issue #15757) One remark, I think at least from security reasons NVDA should try to find a way to work around this freeze. I am thinkin of the example where someone could try to introduce intentionally malicious behavior. — Reply to this email directly, view it on GitHub, or unsubscribe. You are receiving this because you are subscribed to this thread.Message ID: ***@***.***>

[jcsteh]

NVDA should try to find a way to work around this freeze.

Of course, which is why this issue remains open.

I am thinkin of the example where someone could try to introduce intentionally malicious behavior with such code.

There are far more malicious things people can do far more easily with the Python console and unreviewed add-ons. This is not to suggest it shouldn't be fixed, just that if someone has managed to get this code onto a user's system, they already have far bigger problems.

This was one of the reasons why the 3D sound effects add on or custom sounds etc, has been disabled as if two sounds were played it tended to lock up the machine with lots of wave player errors.

That should have been fixed in #15681.

[jcsteh]

There are two race conditions here:

1. feed() might be called on the background thread after stop() is called in the main thread. We can fix this with a simple boolean flag in playWaveFile stored on the fileWavePlayer. Unfortunately, it turns out that this race is pretty rare.
2. Even with 1) fixed, it seems that stop() can be called on the main thread in between the time that feed() is called in Python and the time that the C++ WasapiPlayer::feed function starts running. The obvious way to fix this is to use a lock, except we can't do this in Python because WasapiPlayer::feed might block if the data is too big to fit the buffer. That means a C++ lock, but the question is where to put it without impacting performance.

The C++ feed code does see that stop was called, but it assumes (normally correctly) that this was just an extra stop call after feed last returned. It doesn't realise (and has no way of knowing) that there might be a delay between the time feed is called in Python and the time that feed runs in C++.