prevent Chrome losing focus during systests by seanbudd · Pull Request #12293 · nvaccess/nvda

seanbudd · 2021-04-15T02:21:55Z

Link to issue number:

None

Summary of the issue:

Our system tests randomly fail due to chrome not having focus, and so NVDA does not read the expected speech. Sometimes this is due to a Docker popup asking for feedback such as this one .

Description of how this pull request fixes the issue:

Log when the event postNvdaStartup fires
sleep for 2s before launching chrome

Testing strategy:

Run many builds to ensure system tests don't fail.

Known issues with pull request:

Docker popups may still block the build
2s of sleep might not be long enough (we have confidence that 10s is)
Lint checking randomly blocks builds due to a failed merge (likely due to a rare GitHub issue)

Change log entry:

None

Code Review Checklist:

feerrenrut · 2021-04-20T01:01:10Z

The build artifacts for the build linked in the description will expire, and become unavailable in 6 months (soon this will change to 3 months I believe). So I'll attach the relevant files here:
dockerPopup-systemTestResults.zip
dockerPopup-fullBuildlog.txt

Co-authored-by: Reef Turner <feerrenrut@users.noreply.github.com>

feerrenrut · 2021-04-20T01:57:01Z

+			if self._popup_stole_focus():
+				return self.wait_for_specific_speech(speech, afterIndex, maxWaitSeconds)


I actually don't think I saw any tests where this window being created mid system test was likely. Certainly there were situations where the popup had focus, but I doubt it was due to the popup being created mid test. Instead I suspect it was a result of NVDA "restoring focus" over the top of chrome due to a race condition during startup. I expect that the popup is first created much earlier, during the build.

Perhaps a comment in here (or the function) to say that this is to collect data on whether this is happening. And may be removed if we determine that it is not. An alternative approach may be to have an "allow list" of windows / processes that are allowed to gain focus after the test is started, anything else is a failure with the process name reported.

This test where we sleep for 10s failed due to a docker popup: https://ci.appveyor.com/project/NVAccess/nvda/builds/38672328/artifacts.

@michaelDCurran also noted that we probably shouldn't be killing processes that developers may be running when running system tests locally. I'm going to remove this code in favour of the quick sleep fix and we can follow up to address the Docker issue later.

AppVeyorBot · 2021-04-20T02:04:24Z

System test failure
Build (for testing PR)

See test results for failed build of commit 959892a3d4

seanbudd · 2021-04-20T05:13:10Z

System test failure

Build (for testing PR)

See test results for failed build of commit 959892a3d4

well it seems like this fix does not work - should we return to sleeping before launching chrome?

AppVeyorBot · 2021-04-20T05:56:24Z

PR introduces Flake8 errors
Build (for testing PR)

See test results for failed build of commit 56f6f10d89

feerrenrut · 2021-04-20T06:59:49Z

System test failure
Build (for testing PR)
See test results for failed build of commit 959892a

well it seems like this fix does not work - should we return to sleeping before launching chrome?

That build failure had the following log, from the screen shot I could confirm that the taskbar had focus.

DEBUG - core._doPostNvdaStartupAction (02:03:06.704) - MainThread (4720):
Notify of postNvdaStartup action
IO - speech.speak (02:03:06.704) - MainThread (4720):
Speaking [LangChangeCommand ('en'), 'Taskbar', CancellableSpeech (still valid)]
DEBUGWARNING - IAccessibleHandler.internalWinEventHandler._shouldGetEvents (02:03:08.007) - MainThread (4720):
Foreground took too long to change. Foreground still 131098 (Shell_TrayWnd). Should be 328256 (Chrome_WidgetWin_1)
DEBUG - external:globalPlugins.speechSpyGlobalPlugin.NVDASpyLib.dump_speech_to_log (02:03:12.546) - RF Test Spy Thread (2444):
dump_speech_to_log.
DEBUGWARNING - displayModel.DisplayModelTextInfo._get__storyFieldsAndRects (02:03:12.546) - RF Test Spy Thread (2444):
AppModule does not have a binding handle
INFO - external:globalPlugins.speechSpyGlobalPlugin.NVDASpyLib._devInfoToLog (02:03:12.546) - RF Test Spy Thread (2444):
Developer info for navigator object:
name: 'Taskbar'
role: ROLE_PANE
roleText: None
states: STATE_FOCUSABLE, STATE_FOCUSED
isFocusable: True
hasFocus: True
Python object: <NVDAObjects.IAccessible.Taskbar object at 0x06C32178>
Python class mro: (<class 'NVDAObjects.IAccessible.Taskbar'>, <class 'NVDAObjects.IAccessible.IAccessible'>, <class 'NVDAObjects.window.Window'>, <class 'NVDAObjects.NVDAObject'>, <class 'documentBase.TextContainerObject'>, <class 'baseObject.ScriptableObject'>, <class 'baseObject.AutoPropertyObject'>, <class 'garbageHandler.TrackedObject'>, <class 'object'>)
description: None
location: RectLTWH(left=0, top=728, width=1024, height=40)
value: None
appModule: <'explorer' (appName 'explorer', process ID 4376) at address 5200178>
appModule.productName: 'Microsoft® Windows® Operating System'
appModule.productVersion: '10.0.17763.1'
TextInfo: <class 'NVDAObjects.NVDAObjectTextInfo'>
windowHandle: 131098
windowClassName: 'Shell_TrayWnd'
windowControlID: 0
windowStyle: -1778384896
extendedWindowStyle: 136
windowThreadID: 4500
windowText: ''
displayText: ''
IAccessibleObject: <POINTER(IAccessible) ptr=0x39c02d8 at 69ce4f0>
IAccessibleChildID: 0
IAccessible event parameters: windowHandle=131098, objectID=-4, childID=0
IAccessible accName: 'Taskbar'
IAccessible accRole: ROLE_SYSTEM_CLIENT
IAccessible accState: STATE_SYSTEM_FOCUSED, STATE_SYSTEM_FOCUSABLE, STATE_SYSTEM_VALID (1048580)
IAccessible accDescription: None
IAccessible accValue: None
DEBUG - external:globalPlugins.speechSpyGlobalPlugin.NVDASpyLib.dump_speech_to_log (02:03:12.546) - RF Test Spy Thread (2444):
All speech:
[[''], [LangChangeCommand ('en'), 'Taskbar  ', IndexCommand(1)]]

feerrenrut · 2021-04-21T08:20:46Z

It's a shame to lose the logging for the startup task.

feerrenrut · 2021-04-21T08:56:58Z

My mistake, I looked at the "changes since last review"

As discussed in #12293, our systems fail randomly. Usually this is due to another window stealing focus, such as the taskbar or Docker. As system tests are run locally, we shouldn't be killing these processes. Description of how this pull request fixes the issue: Use windows API to make the chrome window gain focus Adds logging that lists the foreground window and open windows if chrome doesn't gain focus Removes extra sleep time after starting NVDA

seanbudd added 3 commits April 15, 2021 12:21

attempt to avoid NVDA losing focus during systests

677a188

fix lint

27cff53

only call get last speech once

a231d62

seanbudd marked this pull request as ready for review April 15, 2021 07:02

seanbudd requested review from feerrenrut and michaelDCurran April 15, 2021 07:02

seanbudd changed the title ~~attempt to avoid NVDA losing focus during systests~~ prevent NVDA losing focus during systests Apr 15, 2021

seanbudd self-assigned this Apr 15, 2021

seanbudd changed the title ~~prevent NVDA losing focus during systests~~ prevent chrome losing focus during systests Apr 15, 2021

seanbudd changed the title ~~prevent chrome losing focus during systests~~ prevent Chrome losing focus during systests Apr 15, 2021

seanbudd added this to the 2021.1 milestone Apr 20, 2021

feerrenrut reviewed Apr 20, 2021

View reviewed changes

Comment thread source/core.py Outdated

log before firing postNvdaStartup notify event

9f4a8ac

Co-authored-by: Reef Turner <feerrenrut@users.noreply.github.com>

feerrenrut reviewed Apr 20, 2021

View reviewed changes

Merge branch 'master' into fix-systests-2

737cdb1

seanbudd added 2 commits April 21, 2021 09:57

add 2s sleep to system tests

9c7d9c2

Merge branch 'master' into fix-systests-2

557cc70

seanbudd requested a review from a team as a code owner April 21, 2021 00:14

revert killing docker

f19e481

michaelDCurran approved these changes Apr 21, 2021

View reviewed changes

seanbudd merged commit 0703066 into master Apr 21, 2021

seanbudd deleted the fix-systests-2 branch April 21, 2021 01:01

seanbudd mentioned this pull request Apr 27, 2021

Increase sleep to 5s after starting NVDA in chromeTests #12343

Merged

7 tasks

seanbudd mentioned this pull request Apr 29, 2021

Focus chrome after starting in system tests #12352

Merged

7 tasks

Navigation Menu

Uh oh!

Uh oh!

prevent Chrome losing focus during systests - #12293

prevent Chrome losing focus during systests#12293
seanbudd merged 8 commits into
masterfrom
fix-systests-2

seanbudd commented Apr 15, 2021 •

edited

Loading

Uh oh!

feerrenrut commented Apr 20, 2021 •

edited

Loading

Uh oh!

Uh oh!

feerrenrut Apr 20, 2021

Uh oh!

seanbudd Apr 21, 2021 •

edited

Loading

Uh oh!

AppVeyorBot commented Apr 20, 2021

Uh oh!

seanbudd commented Apr 20, 2021

Uh oh!

AppVeyorBot commented Apr 20, 2021

Uh oh!

feerrenrut commented Apr 20, 2021

Uh oh!

feerrenrut commented Apr 21, 2021

Uh oh!

feerrenrut commented Apr 21, 2021

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

		if self._popup_stole_focus():
		return self.wait_for_specific_speech(speech, afterIndex, maxWaitSeconds)

Uh oh!

Uh oh!

Conversation

seanbudd commented Apr 15, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Link to issue number:

Summary of the issue:

Description of how this pull request fixes the issue:

Testing strategy:

Known issues with pull request:

Change log entry:

Code Review Checklist:

Uh oh!

feerrenrut commented Apr 20, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Uh oh!

feerrenrut Apr 20, 2021

Choose a reason for hiding this comment

Uh oh!

seanbudd Apr 21, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

AppVeyorBot commented Apr 20, 2021

Uh oh!

seanbudd commented Apr 20, 2021

Uh oh!

AppVeyorBot commented Apr 20, 2021

Uh oh!

feerrenrut commented Apr 20, 2021

Uh oh!

feerrenrut commented Apr 21, 2021

Uh oh!

feerrenrut commented Apr 21, 2021

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

seanbudd commented Apr 15, 2021 •

edited

Loading

feerrenrut commented Apr 20, 2021 •

edited

Loading

seanbudd Apr 21, 2021 •

edited

Loading