System Test Failure: Speech did not finish before timeout - symbolPronunciationTests

[feerrenrut]

Link to build:

https://ci.appveyor.com/project/NVAccess/nvda/builds/45323366/tests

System test logs:

pr14343-27110 commit 5958643d-symbolsTestFailures-systemTestResults.zip

Failures:

• Robot.symbolPronunciationTests.symbolInSpeechUI
  • Error message: Speech did not finish before timeout
• Robot.symbolPronunciationTests.delayedCharacterDescriptions
  • Error message: Speech did not finish before timeout
• Robot.symbolPronunciationTests.moveByCharacter
  • Error message: Speech did not finish before timeout
• Robot.symbolPronunciationTests.selectionByWord
  • Error message: Speech did not finish before timeout
• Robot.symbolPronunciationTests.selectionByCharacter
  • Error message: Speech did not finish before timeout
• Robot.symbolPronunciationTests.selectionByLine
  • Error message: Speech did not finish before timeout
• Robot.symbolPronunciationTests.moveByLine
  • Error message: Speech did not finish before timeout
• Robot.symbolPronunciationTests.moveByWord
  • Error message: Speech did not finish before timeout

Investigation:

• Given all the errors are the same, just investigate the first failure. Used the RobotFramework Log to determine the first to run: Robot.symbolPronunciationTests.symbolInSpeechUI

• The screenshot shows the notepad window in the foreground with a single 't' character, behind notepad is chrome on the 'welcome' screen.

• The robot framework log ends with:

  14:44:04.906    INFO    Foreground window title: test (253622053) - Notepad 
  14:44:04.907    INFO    wait_for_speech_to_finish   
  14:44:04.909    INFO    get_next_speech_index   
  14:44:04.911    INFO    emulateKeyPress ('home',)   
  14:44:05.218    INFO    wait_for_speech_to_finish {'speechStartedIndex': 6} 
  14:44:10.339    FAIL    Speech did not finish before timeout    
  14:44:10.339    DEBUG   Traceback (most recent call last):
  File "C:\Users\appveyor\AppData\Local\Temp\1\nvdaProfile\scratchpad\globalPlugins\speechSpyGlobalPlugin\__init__.py", line 475, in wait_for_speech_to_finish
  errorMessage=errorMessage,
  File "C:\Users\appveyor\AppData\Local\Temp\1\nvdaProfile\scratchpad\globalPlugins\speechSpyGlobalPlugin\blockUntilConditionMet.py", line 77, in _blockUntilConditionMet
  raise AssertionError(errorMessage)

• Looking at the NVDA log confirms there was no speech after pressing the "home" key.

• The RF log shows that the speechStartedIndex is used. From the NVDA log it is clear that the failure is because speech didn't start (and so therefore could not finish):

  DEBUG - external:globalPlugins.speechSpyGlobalPlugin.NVDASpyLib._hasSpeechFinished (06:44:10.035) - RF Test Spy Thread (4732):
  started: False (speechStartedIndex: 6, nextIndex: 6) elapsedSinceLastSpeech: 11.725686500000002

• The NVDA log also shows that the task switcher was used to make notepad the foreground window.

• There was a freeze when showing the task switcher, however it had recovered (at 06:43:58.720 after 1 second), before the home key was pressed.

• After refocusing the notepad window (with enter on the task switcher), there is a foreground took too long to change debugwarning:

  DEBUGWARNING - IAccessibleHandler.internalWinEventHandler._shouldGetEvents (06:43:59.553) - MainThread (1000):
  Foreground took too long to change. Foreground still 1245770 (Notepad). Should be 65818 (ForegroundStaging)

• After the home key was pressed, NVDA processed the input and the core went to sleep.

Note: Pressing 'home' should always result in speech, in this case it does not, cause unknown.

[seanbudd]

Possibly duplicated in https://github.com/nvaccess/nvda/issues/14353#issuecomment-1356921578