Skip to content

Wait for speech adjustment#14284

Merged
feerrenrut merged 14 commits into
masterfrom
systest-waitForSpeech
Oct 26, 2022
Merged

Wait for speech adjustment#14284
feerrenrut merged 14 commits into
masterfrom
systest-waitForSpeech

Conversation

@feerrenrut

@feerrenrut feerrenrut commented Oct 24, 2022

Copy link
Copy Markdown
Contributor

Link to issue number:

Splitting up PR #14054

Summary of the issue:

  • Some calls to wait_for_speech_to_finish do not specify the speech index for speech started (which usually should be nextSpeechIndex).
  • Generally, it is more concise to use _NvdaLib.getSpeechAfterKey rather than spy.emulateKeyPress, wait_for_speech_to_finish and then get speech after index. getSpeechAfterKey handles this all internally.
  • The speech spy synth driver simply called notify for all index commands, and added the speech to an internal buffer, then called doneSpeaking. This doesn't allow the core to process its queue.

Description of user facing changes

None

Description of development approach

  • Check all usages of wait_for_speech_to_finish and emulateKeyPress to see if getSpeechAfterKey is more appropriate, or if nextSpeechIndex needs to be used.
  • The speech spy synth driver now processes speech in a worker thread. Between each utterance, the thread yields to allow core to process any queued callbacks.

Testing strategy:

System tests on alpha

Known issues with pull request:

This PR appears to increase the time for tests from 15 min to ~22 min.

Change log entries:

None

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
  • Security precautions taken.

Since Appveyor seems to be less performant than previously,
give NVDA more time to handle events and get all speech out.

This will increase the time system tests take.
System tests could be optimised to reduce usages of
wait_for_speech_to_finish.
In many cases, wait_for_specific_speech could be preferable.
Note the index of captured speech, to be used by system tests.
This is not to be conflated with the speech IndexCommands.
@feerrenrut feerrenrut marked this pull request as ready for review October 25, 2022 01:49
@feerrenrut feerrenrut requested a review from a team as a code owner October 25, 2022 01:49
@feerrenrut feerrenrut requested a review from seanbudd October 25, 2022 01:49
Comment thread tests/system/libraries/SystemTestSpy/blockUntilConditionMet.py Outdated
Comment thread tests/system/libraries/SystemTestSpy/blockUntilConditionMet.py Outdated
Comment thread tests/system/libraries/SystemTestSpy/speechSpyGlobalPlugin.py Outdated
Comment thread tests/system/libraries/SystemTestSpy/speechSpyGlobalPlugin.py Outdated
Comment thread tests/system/libraries/SystemTestSpy/speechSpyGlobalPlugin.py Outdated
Comment thread tests/system/libraries/SystemTestSpy/speechSpySynthDriver.py Outdated
Comment thread tests/system/libraries/SystemTestSpy/speechSpySynthDriver.py Outdated
Comment thread tests/system/libraries/SystemTestSpy/speechSpySynthDriver.py Outdated
Comment thread tests/system/libraries/SystemTestSpy/speechSpySynthDriver.py Outdated
Comment thread tests/system/libraries/SystemTestSpy/__init__.py Outdated
@AppVeyorBot

This comment was marked as outdated.

@feerrenrut

Copy link
Copy Markdown
Contributor Author

Last build test failure Quits from keyboard with welcome dialog open with error:

NVDA failed to exit in the specified timeout

The wait time may need to be extended, the test gave up waiting just before NVDA was finished exiting.

Analysis of the failure

Highlights from NVDA log (context included below):


DEBUG - core.triggerNVDAExit (08:01:27.836) - MainThread (7908):
_doShutdown has been queued
...
WARNING - stdout (08:01:28.333) - RF Test Spy Thread (6240):
Robot Framework remote server at 127.0.0.1:8270 stopped.
...
DEBUGWARNING - RPC process 1088 (chrome.exe) (08:01:30.611) - Dummy-4 (7884):
Thread 7756, build\x86_64\remote\ia2Support.cpp, IA2Support_inProcess_terminate, 191:
WaitForMultipleObjects returned 258
...
Terminating speech
DEBUG - external:synthDrivers.speechSpySynthDriver.SpeechSpySynthDriver.cancel (08:01:30.755) - MainThread (7908):
Cancelling
DEBUG - external:synthDrivers.speechSpySynthDriver.SpeechSpySynthDriver._processSpeech (08:01:31.024) - speech spy synth driver (8080):
Stopping
...

Note the WaitForMultipleObjects returned 258 which is WAIT_TIMEOUT 0x00000102L

Robot log, from after the quit dialog announcement is checked:


16:01:27.830	INFO	emulateKeyPress ('enter',) {'blockUntilProcessed': False}	
16:01:30.842	FAIL	NVDA failed to exit in the specified timeout	
16:01:30.842	DEBUG	Traceback (most recent call last):
  File "C:\projects\nvda\tests\system\robot\startupShutdownNVDA.py", line 117, in quits_from_keyboard
    errorMessage="NVDA failed to exit in the specified timeout"
  File "C:\projects\nvda\tests\system\libraries\SystemTestSpy\blockUntilConditionMet.py", line 71, in _blockUntilConditionMet
    raise AssertionError(errorMessage)

NVDA log, from after the quit dialog is announced.


DEBUG - external:globalPlugins.speechSpyGlobalPlugin.NVDASpyLib.emulateKeyPress (08:01:27.831) - RF Test Spy Thread (6240):
Sending gesture enter
IO - inputCore.InputManager.executeGesture (08:01:27.832) - RF Test Spy Thread (6240):
Input: kb(desktop):enter
DEBUG - core.triggerNVDAExit (08:01:27.836) - MainThread (7908):
_doShutdown has been queued
DEBUGWARNING - NVDAObjects.IAccessible.IAccessible._get_IAccessibleRole (08:01:27.847) - MainThread (7908):
accRole failed: (-2147024809, 'The parameter is incorrect.', (None, None, None, 0, None))
DEBUG - external:synthDrivers.speechSpySynthDriver.SpeechSpySynthDriver.cancel (08:01:27.849) - MainThread (7908):
Cancelling
DEBUG - core._terminate (08:01:27.849) - MainThread (7908):
Terminating updateCheck
DEBUG - core._terminate (08:01:27.850) - MainThread (7908):
Terminating watchdog
DEBUG - core._terminate (08:01:27.850) - MainThread (7908):
Terminating globalPluginHandler
DEBUG - external:globalPlugins.speechSpyGlobalPlugin.SystemTestSpyServer.terminate (08:01:27.851) - MainThread (7908):
Terminating the SystemTestSpyServer
DEBUG - braille.BrailleHandler._onBrailleViewerChangedState (08:01:27.852) - MainThread (7908):
Braille Viewer enabled: False
DEBUG - core._closeAllWindows (08:01:27.853) - MainThread (7908):
destroying system tray icon and menu
DEBUG - core._closeAllWindows (08:01:27.856) - MainThread (7908):
closing window  during exit process
DEBUG - core._closeAllWindows (08:01:27.857) - MainThread (7908):
closing window  during exit process
DEBUG - core._closeAllWindows (08:01:27.869) - MainThread (7908):
destroying main frame during exit process
WARNING - stdout (08:01:28.333) - RF Test Spy Thread (6240):
Robot Framework remote server at 127.0.0.1:8270 stopped.
DEBUGWARNING - RPC process 1088 (chrome.exe) (08:01:30.611) - Dummy-4 (7884):
Thread 7756, build\x86_64\remote\ia2Support.cpp, IA2Support_inProcess_terminate, 191:
WaitForMultipleObjects returned 258

IO - speech.speech.speak (08:01:30.710) - MainThread (7908):
Speaking [LangChangeCommand ('en'), 'NVDA Browser Test Case (1094127420) - Google Chrome', CancellableSpeech (still valid)]
DEBUG - external:synthDrivers.speechSpySynthDriver.SpeechSpySynthDriver.speak (08:01:30.712) - MainThread (7908):
Sequence: [LangChangeCommand ('en'), 'NVDA Browser Test Case (1094127420)   Google Chrome  ', IndexCommand(9)]
DEBUG - external:synthDrivers.speechSpySynthDriver.SpeechSpySynthDriver._processSpeechSequence (08:01:30.713) - speech spy synth driver (8080):
Sequence: [LangChangeCommand ('en'), 'NVDA Browser Test Case (1094127420)   Google Chrome  ', IndexCommand(9)]
DEBUG - external:synthDrivers.speechSpySynthDriver.SpeechSpySynthDriver._doIndexReached (08:01:30.713) - speech spy synth driver (8080):
Speech IndexCommand reached: 9, notifying synthDriverHandler
DEBUG - external:synthDrivers.speechSpySynthDriver.SpeechSpySynthDriver._doNotifySequenceProcessed (08:01:30.714) - speech spy synth driver (8080):
Before notify post_speech
DEBUG - external:globalPlugins.speechSpyGlobalPlugin.NVDASpyLib._onNvdaSpeech (08:01:30.715) - speech spy synth driver (8080):
Appending to speech spy at index 9
DEBUG - external:synthDrivers.speechSpySynthDriver.SpeechSpySynthDriver._doNotifySequenceProcessed (08:01:30.715) - speech spy synth driver (8080):
After post_speech notify
INFO - core.main (08:01:30.722) - MainThread (7908):
Exiting
DEBUG - core.triggerNVDAExit (08:01:30.722) - MainThread (7908):
NVDA has already been triggered to exit safely.
DEBUG - core._terminate (08:01:30.722) - MainThread (7908):
Terminating gui
DEBUG - autoSettingsUtils.autoSettings.AutoSettings._saveSpecificSettings (08:01:30.723) - MainThread (7908):
Saved settings for NVDAHighlighterSettings
DEBUG - autoSettingsUtils.autoSettings.AutoSettings._saveSpecificSettings (08:01:30.723) - MainThread (7908):
Saved settings for ScreenCurtainSettings
DEBUG - fileUtils.FaultTolerantFile (08:01:30.724) - MainThread (7908):
C:\Users\appveyor\AppData\Local\Temp\1\nvdaProfile\nvda.ini6u9231il.tmp
INFO - config.ConfigManager.save (08:01:30.731) - MainThread (7908):
Base configuration saved
DEBUG - core.main (08:01:30.731) - MainThread (7908):
calling lose focus on object with focus
DEBUG - external:synthDrivers.speechSpySynthDriver.SpeechSpySynthDriver.cancel (08:01:30.731) - MainThread (7908):
Cancelling
DEBUG - core._terminate (08:01:30.731) - MainThread (7908):
Terminating treeInterceptorHandler
DEBUG - treeInterceptorHandler.killTreeInterceptor (08:01:30.732) - MainThread (7908):
Killed treeInterceptor: 
DEBUG - core._terminate (08:01:30.733) - MainThread (7908):
Terminating IAccessible support
DEBUG - core._terminate (08:01:30.734) - MainThread (7908):
Terminating UIA support
DEBUG - core._terminate (08:01:30.744) - MainThread (7908):
Terminating Legacy winConsole support
DEBUG - core._terminate (08:01:30.744) - MainThread (7908):
Terminating Java Access Bridge support
DEBUG - core._terminate (08:01:30.747) - MainThread (7908):
Terminating app module handler
DEBUG - core._terminate (08:01:30.747) - MainThread (7908):
Terminating tones
DEBUG - core._terminate (08:01:30.747) - MainThread (7908):
Terminating NVDAHelper
DEBUG - core._terminate (08:01:30.752) - MainThread (7908):
Terminating touchHandler
DEBUG - core._terminate (08:01:30.752) - MainThread (7908):
Terminating keyboard handler
DEBUG - core._terminate (08:01:30.752) - MainThread (7908):
Terminating mouseHandler
DEBUG - core._terminate (08:01:30.753) - MainThread (7908):
Terminating inputCore
DEBUG - core._terminate (08:01:30.753) - MainThread (7908):
Terminating vision
DEBUG - core._terminate (08:01:30.754) - MainThread (7908):
Terminating brailleInput
DEBUG - core._terminate (08:01:30.754) - MainThread (7908):
Terminating braille
DEBUG - core._terminate (08:01:30.754) - MainThread (7908):
Terminating speech
DEBUG - external:synthDrivers.speechSpySynthDriver.SpeechSpySynthDriver.cancel (08:01:30.755) - MainThread (7908):
Cancelling
DEBUG - external:synthDrivers.speechSpySynthDriver.SpeechSpySynthDriver._processSpeech (08:01:31.024) - speech spy synth driver (8080):
Stopping
DEBUG - core._terminate (08:01:31.024) - MainThread (7908):
Terminating addonHandler
DEBUG - core._terminate (08:01:31.024) - MainThread (7908):
Terminating garbageHandler
WARNING - nvwave.WavePlayer.open (08:01:31.026) - MainThread (7908):
Unable to open WAVE_MAPPER device, there may be no audio devices.
DEBUG - winAPI.sessionTracking.unregister (08:01:31.026) - MainThread (7908):
Unregistered session tracking
DEBUG - core.main (08:01:31.027) - MainThread (7908):
core done
INFO - __main__ (08:01:31.057) - MainThread (7908):
NVDA exit

@feerrenrut feerrenrut merged commit 43525cd into master Oct 26, 2022
@feerrenrut feerrenrut deleted the systest-waitForSpeech branch October 26, 2022 08:15
@nvaccessAuto nvaccessAuto added this to the 2023.1 milestone Oct 26, 2022
seanbudd added a commit that referenced this pull request Dec 7, 2022
Summary of the issue:
Due to intermittent system test failures, #14284 increased the polling interval used in blockUntilConditionMet.
When writing unit tests for blockUntilConditionMet in #14301, a bug was picked up. This bug caused blockUntilConditionMet to spin for longer than expected and potentially caused system tests to fail.

This bug was fixed with a new implementation of blockUntilConditionMet.

Description of user facing changes
For devs, system tests should be faster (todo: estimate from build?)

Description of development approach
Lower default polling interval
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

4 participants