Skip to content

System tests foreground fixes#14054

Closed
feerrenrut wants to merge 37 commits intomasterfrom
systemTests-foregroundFixes
Closed

System tests foreground fixes#14054
feerrenrut wants to merge 37 commits intomasterfrom
systemTests-foregroundFixes

Conversation

@feerrenrut
Copy link
Copy Markdown
Contributor

@feerrenrut feerrenrut commented Aug 23, 2022 •
edited
Loading

Link to issue number:

Related to #13983
Follow on from #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:

  • 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.

@feerrenrut feerrenrut mentioned this pull request Aug 23, 2022
Merged
6 tasks
@feerrenrut feerrenrut marked this pull request as ready for review August 24, 2022 03:04
@feerrenrut feerrenrut requested a review from a team as a code owner August 24, 2022 03:04
@feerrenrut feerrenrut requested review from seanbudd and removed request for a team August 24, 2022 03:04
seanbudd
seanbudd reviewed Aug 24, 2022
View reviewed changes
@seanbudd seanbudd changed the title systemTest foreground fixes System tests foreground fixes Aug 24, 2022
@feerrenrut feerrenrut marked this pull request as draft August 25, 2022 02:32
@feerrenrut feerrenrut changed the base branch from beta to master August 25, 2022 06:59
@feerrenrut feerrenrut marked this pull request as ready for review August 25, 2022 07:34
@feerrenrut feerrenrut requested a review from seanbudd August 25, 2022 08:24
lukaszgo1
lukaszgo1 reviewed Aug 25, 2022
View reviewed changes
seanbudd
seanbudd approved these changes Aug 26, 2022
View reviewed changes
seanbudd
seanbudd reviewed Aug 29, 2022
View reviewed changes
@AppVeyorBot
Copy link
Copy Markdown

AppVeyorBot commented Aug 29, 2022

See test results for failed build of commit 6d05096a6c

@feerrenrut
Copy link
Copy Markdown
Contributor Author

feerrenrut commented Aug 29, 2022

The test failed due to a popup "Restore pages? Chrome didn't shutdown correctly."
Robot symbolPronunciationTests-tableHeaderSymbols-failedTest

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
Copy link
Copy Markdown

AppVeyorBot commented Aug 29, 2022

See test results for failed build of commit f30e7bd108

@feerrenrut
Copy link
Copy Markdown
Contributor Author

feerrenrut commented Aug 30, 2022

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
Copy link
Copy Markdown

AppVeyorBot commented Aug 31, 2022

See test results for failed build of commit a399f46ae7

@seanbudd seanbudd marked this pull request as draft September 5, 2022 05:31
@AppVeyorBot
Copy link
Copy Markdown

AppVeyorBot commented Sep 5, 2022

See test results for failed build of commit 1892cd58a9

@AppVeyorBot
Copy link
Copy Markdown

AppVeyorBot commented Sep 6, 2022

See test results for failed build of commit 0e1983ccbf

feerrenrut added a commit that referenced this pull request Sep 6, 2022
@feerrenrut
Control high verbosity nvda logging during system tests with appveyor…
119c4da 
… environment var (PR #14055)

Related to PR #14054

Summary :
When tests are failing in an unusual way, it may be helpful to be able to review verbose debug logging for interaction with MSAA or UIA.

For developers:
VERBOSE_SYSTEM_TEST_LOGGING can be set (to "true") via Appveyor settings to enable high verbosity NVDA logging.

Development approach:
When the environment variable VERBOSE_SYSTEM_TEST_LOGGING is set on appveyor, the system tests are started with an extra parameter (verboseDebugLogging='True') which enables the advanced logging categories in NVDA.
@feerrenrut
Increase time required for speech has finished
2b89a84 
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.
@feerrenrut
Ensure to speech has started when waiting for the address bar speech
998f0e0
@feerrenrut
Use highligher during tests
3acceeb 
Seeing focus / nav / browsemode during tests can help some
developers with debugging issues with the tests.
@feerrenrut
Fix docs presentation
48699ba
@feerrenrut
Change config after preparing chrome tests
168f4c0 
Some config can affect the way the test samples are prepared,
E.G. moving focus / review to the start location.
@feerrenrut
Track start and exit of notepad
e97e92e 
Prior approach was flowed, the 'start.exe' process was being tracked
instead. The 'start.exe' process exited immediatly after starting notepad.
Now it waits until the process is complete.
Additionally the notepad RF lib has access to the Windows HWND allowing
for checking if the window is in the foreground.
@feerrenrut feerrenrut force-pushed the systemTests-foregroundFixes branch from 04531a5 to 34361ba Compare September 14, 2022 04:54
@michaelDCurran michaelDCurran mentioned this pull request Oct 11, 2022
Merged
6 tasks
This was referenced Oct 17, 2022
Merged
Merged
Merged
Merged
Closed
Merged
Merged
This was referenced Oct 25, 2022
Merged
Closed
Merged
feerrenrut added a commit that referenced this pull request Oct 26, 2022
@feerrenrut
Disable 'Starts from desktop shortcut' system test (PR #14294)
f606c89 
The test 'Starts from desktop shortcut' relies on NVDA to be running to
send the hotkey. This interferes with the logic of the test.

The test intermittently fails, see: #14054
Disable test until this can be addressed.
Issue #14293 has been opened to resolve this and re-enable the test.
@feerrenrut feerrenrut mentioned this pull request Oct 27, 2022
Merged
6 tasks
@feerrenrut
Copy link
Copy Markdown
Contributor Author

feerrenrut commented Nov 9, 2022

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

@feerrenrut feerrenrut closed this Nov 9, 2022
seanbudd pushed a commit that referenced this pull request Dec 19, 2022
@feerrenrut
Use highligher during tests (#14261)
c3cdcee 
Splitting up PR #14054

Summary of the issue:
When a system test fails a screenshot is captured.
However, this does not make it clear where the focus/ nav / virtual cursor is positioned.

Description of user facing changes
None

Description of development approach
Seeing focus / nav / virtual cursor during tests can help some developers with debugging issues with the tests.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

@seanbudd seanbudd seanbudd approved these changes

+1 more reviewer

@lukaszgo1 lukaszgo1 lukaszgo1 left review comments

Reviewers whose approvals may not affect merge requirements

Assignees

No one assigned

Labels

component/system-testing

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

4 participants

@feerrenrut @AppVeyorBot @seanbudd @lukaszgo1