Fix SAPI5 Audio Ducking Crash on Slow startup

[seanbudd]

Link to issue number:

Fixes #13694

Summary of the issue:

• NVDA start up is slow.
• Speech is announced during start up to warn the user that start up is slow.
• If using SAPI5 and audioducking is enabled, SAPI5 will try to duck the audio using wx callbacks
• The wxWidgets App has not beeing initialized, so the callback fails and NVDA crashes.

Description of how this pull request fixes the issue:

Throw a known exception if NVDA is not ready when callLater is called.
If this exception occurs when audio ducking, force audio ducking to unduck immediately instead of delay

Testing strategy:

Manual testing:

Using NVDA 2022.1rc1 with audio ducking enabled and SAPI5.

• emulate a slow start up and reproduce the crash.

Using a try build from this PR with audio ducking enabled and SAPI5.

• emulate a slow start up
• Note that the warning message that announces that NVDA start up is slow doesn't duck audio
• Note that NVDA starts successfully
• Confirm that audio ducking works as expected once NVDA has started
• Note the following log

WARNING - mathPres.initialize (12:46:35.192) - MainThread (6344):
MathPlayer 4 not available
DEBUGWARNING - core.main (12:46:40.207) - MainThread (6344):
Slow starting core (6.88 sec)
IO - speech.speech.speak (12:46:40.207) - MainThread (6344):
Speaking [LangChangeCommand ('en_US'), 'Loading NVDA. Please wait...']
DEBUGWARNING - characterProcessing._getSpeechSymbolsForLocale (12:46:40.208) - MainThread (6344):
No CLDR data for locale en_US
DEBUGWARNING - synthDrivers.sapi5.SynthDriver.speak (12:46:40.344) - MainThread (6344):
Unsupported speech command: LangChangeCommand ('en_US')
DEBUGWARNING - audioDucking._unensureDucked (12:46:40.349) - MainThread (6344):
wx App not initialized, cannot delay audio un-duck
INFO - core.main (12:46:40.349) - MainThread (6344):
Using wx version 4.1.1 msw (phoenix) wxWidgets 3.1.5 with six version 1.16.0

Known issues with pull request:

None

Change log entries:

Fixes an unreleased regression

Code Review Checklist:

• Pull Request description:
  • description is up to date
  • change log entries
• Testing:
  • Unit tests
  • System (end to end) tests
  • Manual testing
• API is compatible with existing add-ons.
• Documentation:
  • User Documentation
  • Developer / Technical Documentation
  • Context sensitive help for GUI changes
• UX of all users considered:
  • Speech
  • Braille
  • Low Vision
  • Different web browsers
  • Localization in other languages / culture than English
    e

[feerrenrut]

Perhaps this should happen in / also in core.callLater? Here it is a bit removed from the core problem, which might be fine for a quick work-around for this issue / release, but longer term this could happen in other scenarios.

Perhaps as a follow up we should ensure that all usages of wx.Calllater are converted to go via `core.callLater

[seanbudd]

What would be the suggested behaviour when we cannot continue in core.callLater? Log an exception?

I support those 2 pieces of work for 2022.2

[feerrenrut]

Yes, I think log then raise an exception to notify the caller. We'd convert all internal usages of wx.CallLater to use core.callLater and handle the exception. Then later we can consider an implementation that can work without wx.

[seanbudd]

I'd avoid raising an exception: wx raising an exception here is causing the crash.
I think this is because the exception is raised before our exception handling is initialized.
Raising an exception here will not be an improvement of behaviour.

[seanbudd]

I've created a PR here to start on this: #13701

I'd like to get this into rc as a priority first

[lukaszgo1]

Using a try build from this PR with audio ducking enabled and SAPI5.

* emulate a slow start up.

* Note that the warning message that announces that NVDA start up is slow doesn't duck audio

* Note that NVDA starts successfully

* Confirm that audio ducking works as expected once NVDA has started

My testing does not confirm this. If the message about startup being slow is announced during startup audio ducking remains non functional afterwards. Looking at the code audioDucking.isAudioDuckingSupported is executed only once and for the next invocations the result cached in _isAudioDuckingSupported is returned. As a result if during the first call WX app is not yet ready the cache is set to False and then False is always returned. Could you please retest this scenario? If this is confirmed perhaps audioDucking.isAudioDuckingSupported should be modified not to cache the results as it is no longer constant during NVDA's lifetime.

[seanbudd]

@lukaszgo1 - a simpler and safer approach (that still allow the un-duck to happen) is being used instead now

[feerrenrut]

Generally looks good. But I'm not familiar enough with the expectations of the audioDucking system. I see reference counting going on, and there is _ensureDucked and _unensureDucked, private methods that look like they ought to be paired. Exiting _unensureDucked without doing the task seems like it could lead to an imbalanced reference count.

You'll need to verify the logic here.
I notice that callLater is only required if delay is True, perhaps it would be better to do it immediately if delay is impossible.

[feerrenrut]

Sorry, I misread this. I see now that on exception the unducking continues, just without a delay.