System tests foreground fixes

[feerrenrut]

Link to issue number:

Related to https://github.com/nvaccess/nvda/pull/13983 Follow on from https://github.com/nvaccess/nvda/pull/14004

Summary of the issue:

System tests continue to fail intermittently.

1. In particular, occasionally docker desktop pops up a net promoter score survey window before/early in the build. This docker desktop window opened in the foreground (meaning Appveyor build window no longer is in the foreground) and caused system tests that rely on a 3rd party window taking the foreground to fail.
2. Appveyor build systems seem to be getting slower. Several key moments in the tests are approaching the limit of how long NVDA will wait for speech to complete.
3. After an update, chrome takes a long time to be ready for NVDA to interact.
4. Some tests use the same sample, resulting in matching titles. This can lead to setup code unable to uniquely identify the tab/title of the test.
5. From RF logs, it can be hard to tell what the foreground window is.
6. Visually following review/focus can be difficult when monitoring the tests.
7. Some settings were modified before setting up chrome, which could affect the setup procedure (I.E. review not following focus).

Description of user facing changes

For developers, the system tests shouldn't fail intermittently.

Description of development approach

1. When the required process (chrome / notepad) doesn't have the foreground, the task switcher is used to give it the foreground.
2. Extend the time limit waiting for speech to complete.
3. Start chrome early in the build process, giving it time to complete any post update actions.
4. Append a time stamp to the test sample, this is included in the hash of the sample used in the title.
5. Added more logging to report the foreground window
6. Enable NVDA highlighter.
7. Ensure that settings are modified after chrome is setup.

Testing strategy:

• Tests run locally
• Tests run in a try-build
• PR build
• Due to the intermittent nature of the failures, many builds are required to be sure that the situation has improved. To prevent interfering with other work (by occupying the CI), this can be delivered and monitored on alpha.

Known issues with pull request:

None

Change log entries:

None

Code Review Checklist:

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

[AppVeyorBot]

• PASS: Translation comments check.
• PASS: Unit tests.
• PASS: Lint check.
• FAIL: System tests. See test results for more information.
• Build (for testing PR): https://ci.appveyor.com/api/buildjobs/v4eqsvlr58x2m85r/artifacts/output/nvda_snapshot_pr14054-26390,6d05096a.exe

See test results for failed build of commit 6d05096a6c

[feerrenrut]

The test failed due to a popup "Restore pages? Chrome didn't shutdown correctly."

One thing worth noting, none of the other tabs (test cases) are open. Perhaps chrome ran out of memory. To address this :

• I'll look for a way to disable the popup.
• I'll re-enable the code to close the tab, but only if the tab/window has focus.

[AppVeyorBot]

• PASS: Translation comments check.
• PASS: Unit tests.
• PASS: Lint check.
• FAIL: System tests. See test results for more information.
• Build (for testing PR): https://ci.appveyor.com/api/buildjobs/53q2bmqy83tqk9it/artifacts/output/nvda_snapshot_pr14054-26394,f30e7bd1.exe

See test results for failed build of commit f30e7bd108

[feerrenrut]

The last CI run had test failures:

I7562

From RF log. Last check while waiting for Chrome (total 3 seconds of waiting):

21:21:53.695 No windows found matching the pattern: re.compile('^NVDA Browser Test Case \\(1887919363\\)')

From NVDA log NVDA report Chrome opening the tab:

IO - speech.speech.speak (13:21:53.938) - MainThread (3456):
Speaking [LangChangeCommand ('en'), 'NVDA Browser Test Case (1887919363) - Google Chrome', CancellableSpeech (still valid)]

ARIA checkbox

From RF log. Trying to read title (NVDA+t), speech didn't finish within 5 seconds

From NVDA log, error with gesture NVDA+t. Second time it has been run.

IO - inputCore.InputManager.executeGesture (13:23:00.057) - RF Test Spy Thread (4228):
Input: kb(desktop):NVDA+t
ERROR - scriptHandler.executeScript (13:23:00.073) - MainThread (1088):
error executing script: <bound method GlobalCommands.script_title of <globalCommands.GlobalCommands object at 0x067BE990>> with gesture 'NVDA+t'
Traceback (most recent call last):
  File "scriptHandler.pyc", line 289, in executeScript
  File "globalCommands.pyc", line 2302, in script_title
AttributeError: 'NoneType' object has no attribute 'name'

This seems strange. Looking at the script_title method in GlobalCommands it seems like api.getForegroundObject() returned None.

Starts from desktop shortcut

RF log:

21:35:10.211	INFO	emulateKeyPress ('control+alt+n',)	
21:35:17.569	FAIL	Connection to remote server broken: [WinError 10061] No connection could be made because the target machine actively refused it	
21:35:17.569	DEBUG	Traceback (most recent call last):
  File "C:\projects\nvda\tests\system\robot\startupShutdownNVDA.py", line 124, in test_desktop_shortcut
    spy.emulateKeyPress("control+alt+n")
  File "C:\projects\nvda\tests\system\libraries\NvdaLib.py", line 256, in runKeyword
    return lib.run_keyword(keyword, args, kwargs)
  File "C:\projects\nvda\.venv\lib\site-packages\robot\libraries\Remote.py", line 106, in run_keyword
    result = RemoteResult(self._client.run_keyword(name, args, kwargs))
  File "C:\projects\nvda\.venv\lib\site-packages\robot\libraries\Remote.py", line 264, in run_keyword
    raise RuntimeError(message)

Note NVDA is already running, and is providing the connection to RF. NVDA is used to send a "control+alt+n" shortcut to start NVDA. Starting a new instance of NVDA will cause the currently running instance to exit. This will cause the server to disconnect. In the failed test image there is no indication that NVDA is running, when NVDA is running the highlighter should be visible.

NVDA log:

INFO - core.main (13:35:12.499) - MainThread (4652):
Exiting
DEBUG - core.triggerNVDAExit (13:35:12.499) - MainThread (4652):
_doShutdown has been queued

This indicates it was about 5 seconds from NVDA shutdown until the RF remote error.

Test SelByWord

Failed because there were multiple notepad windows open with the same title: From RF log:

	Too many windows to focus [Window(hwndVal=524936, title='test (1548220167) - Notepad'), Window(hwndVal=4653638, title='test (1548220167) - Notepad')]

It's unknown why one of the notepad windows didn't close at the end of test, the screenshot doesn't give any indication, the "old" notepad instance is obscured by the new one. The prior test (from RF log) indicates the notepad This can be fixed by ensuring every test gets a unique title

Several tests use this same sample/title, from test "Test MoveByWord"

KEYWORD WindowsLib . Log Foreground Window Title
21:38:36.555	INFO	Foreground window title: test (1548220167) - Notepad
...
KEYWORD NotepadLib . Exit Notepad
Start / End / Elapsed:	20220829 21:38:36.562 / 20220829 21:38:48.697 / 00:00:12.135
21:38:36.562	INFO	Is Start process still running (True expected): True	
21:38:36.562	INFO	Test case in foreground, trying to close	
21:38:36.562	INFO	emulateKeyPress ('alt+f4',)
21:38:38.594	INFO	Waiting for process to complete.	
21:38:48.697	INFO	Process did not complete in 10 seconds.	
21:38:48.697	INFO	Leaving process intact.	
21:38:48.697	INFO	Is Start process still running (False expected): True

This is the only instance of "leaving process intact" in the log. It may be helpful in these instances to get a screenshot when notepad can't exit, was there a "save dialog"?

[AppVeyorBot]

• PASS: Translation comments check.
• PASS: Unit tests.
• PASS: Lint check.
• FAIL: System tests. See test results for more information.
• Build (for testing PR): https://ci.appveyor.com/api/buildjobs/9ii59v27w699cxew/artifacts/output/nvda_snapshot_pr14054-26425,a399f46a.exe

See test results for failed build of commit a399f46ae7

[AppVeyorBot]

• PASS: Translation comments check.
• PASS: Unit tests.
• PASS: Lint check.
• FAIL: System tests. See test results for more information.
• Build (for testing PR): https://ci.appveyor.com/api/buildjobs/5xj9u4upkan8b0nh/artifacts/output/nvda_snapshot_pr14054-26461,1892cd58.exe

See test results for failed build of commit 1892cd58a9

[AppVeyorBot]

• PASS: Translation comments check.
• PASS: Unit tests.
• PASS: Lint check.
• FAIL: System tests. See test results for more information.
• Build (for testing PR): https://ci.appveyor.com/api/buildjobs/i5yutnlq0ujw7ov5/artifacts/output/nvda_snapshot_pr14054-26475,0e1983cc.exe

See test results for failed build of commit 0e1983ccbf

[feerrenrut]

This work has been split up, and entirely delivered via other PRs. Closing.