Add significant optional debug logging for MSAA events by michaelDCurran · Pull Request #11521 · nvaccess/nvda

michaelDCurran · 2020-08-25T01:54:36Z

Link to issue number:

None.

Summary of the issue:

There is not much logging for the receiving and processing of MSAA winEvents in NVDA. It is currently hard to debug issues around missing MSAA events and or creating IAccessible objects from events.

Description of how this pull request fixes the issue:

Ads a significant amount of debug and debugWarning messages to the log in the winEvent hook, the limiter, and the various process*WinEvent functions. This logging must be turned on with the MSAA debug log checkbox in NVDA's advanced settings.
When winEvent params are logged, the eventID and objectID constant names are resolved, as well as the window class name for the window handle.

Testing performed:

Ran NVDA with and without this logging turned on.

Known issues with pull request:

None.

Change log entry:

Changes for developers:

Significant debug logging for MSAA events can be now enabled in NVDA's Advanced settings.

LeonarddeR

I think overall this looks good, but may be it is good to ensure that most logging items log the event info as well, as I suggested in several comments. Or will it always be clear what the source event is from the order of log entries?

LeonarddeR · 2020-08-25T05:58:45Z

 	# Ignore any events with invalid window handles
 	if not window or not winUser.isWindow(window):
+		if isMSAADebugLoggingEnabled():
+			log.debug("Dropping winEvent for invalid window")


Suggested change

log.debug("Dropping winEvent for invalid window")

log.debug(f"Dropping winEvent for invalid window {window}")

I think @LeonarddeR's suggestion here is worth adding.

codeofdusk · 2020-08-25T07:19:00Z

In the changelog entry, swap the word order:

Significant debug logging for IAccessible events can now be enabled in NVDA's Advanced settings.

feerrenrut · 2020-08-25T14:20:04Z

One thing that might make the conditional logging for this a little less repetitive is to install a new log handler, for an example see:
log._speechManagerDebug in source/speech/manager.py:88

One problem with this approach is that it introduces a hidden dependency for other files wishing to use this. Perhaps these special logging categories should be added / installed by logHandler.

Co-authored-by: Leonard de Ruijter <leonardder@users.noreply.github.com>

…e UIA window. Co-authored-by: Leonard de Ruijter <leonardder@users.noreply.github.com>

AppVeyorBot · 2020-08-26T01:36:18Z

Build (for testing PR)
PR introduces Flake8 errors

See test results for failed build of commit 77d1f7bab7

michaelDCurran · 2020-08-26T02:55:01Z

@feerrenrut I think I'd prefer to leave this as explicit if-checks as there is code that may be costly if run, even if the string itself was not printed to the log.

michaelDCurran · 2020-08-31T06:28:13Z

@LeonarddeR or @feerrenrut is there any feedback you still need me to address here?

LeonarddeR

Apart from one typo, this looks ok

LeonarddeR · 2020-08-31T13:06:29Z

 			return
+		if isMSAADebugLoggingEnabled():
+			log.debug(
+				f"Adding winEvent to limitor: {getWinEventLogInfo(window, objectID, childID, eventID)}"


limitOr should be limitEr

Suggested change

f"Adding winEvent to limitor: {getWinEventLogInfo(window, objectID, childID, eventID)}"

f"Adding winEvent to limiter: {getWinEventLogInfo(window, objectID, childID, eventID)}"

feerrenrut

It would be good if some notes were added about this to highlight the setting and messages to look for in certain use-cases. Perhaps to the developer documentation?

feerrenrut · 2020-08-31T15:26:23Z

 	# Ignore any events with invalid window handles
 	if not window or not winUser.isWindow(window):
+		if isMSAADebugLoggingEnabled():
+			log.debug("Dropping winEvent for invalid window")


I think @LeonarddeR's suggestion here is worth adding.

feerrenrut · 2020-08-31T15:27:05Z

 	# Make sure this window does not have a ghost window if possible
 	if NVDAObjects.window.GhostWindowFromHungWindow and NVDAObjects.window.GhostWindowFromHungWindow(window):
+		if isMSAADebugLoggingEnabled():
+			log.debug("Dropping winEvent for ghosted hung window")


Might be worth adding which window this message is for?

feerrenrut · 2020-08-31T15:33:22Z

+			if curForegroundWindow != _deferUntilForegroundWindow:
+				log.debugWarning(
+					"Foreground took too long to change. "
+					f"Foreground still {curForegroundWindow} ({curForegroundClassName}). "
+					f"Should be {_deferUntilForegroundWindow} ({futureForegroundClassName})"
+				)


Note, this isn't protected by isMSAADebugLoggingEnabled, however I think that is appropriate for this message.

* Added several more log calls. * Improved log call for error in AccessibleObjectFromEvent and put it behind isMSAADebugLoggingEnabled. * Fixed typo. * Included threadID, processID and process name in winEvent log info where possible.

AppVeyorBot · 2020-09-01T00:59:43Z

PR introduces Flake8 errors
Build (for testing PR)

See test results for failed build of commit 825960d132

michaelDCurran · 2020-09-01T02:18:51Z

I'd prefer to get this implementation merged before spending any time on possible dev docs, as this code could become out of date rather quickly, and this logging has already proved extremely useful in the last little while.

At very least though, I will put here a quick explanation. Someone else is welcome to try and incorporate this into the dev guide before I get around to it:

MSAA Logging

It may be useful to see just how NVDA receives and processes events for Microsoft Active Accessibility (MSAA), in order to understand why a particular focus event is being ignored, or why NVDA is extra slow etc.

You can turn on logging of MSAA winEvents by setting NVDA's log level to debug, and also turnning on the MSAA checkbox in the debug logging section of NVDA's Advanced settings panel.

With this logging switched on, you will now see particular messages logged such as the following:

DEBUG - IAccessibleHandler.internalWinEventHandler.winEventCallback (10:54:56.442) - MainThread (32):
Hook received winEvent: EVENT_OBJECT_FOCUS, window 1443880 (Button), objectID OBJID_CLIENT, childID 0, from process 5512 (explorer), thread 21136

This is the point where NVDA first receives the winEvent directly from Windows. No processing or filtering has happened at all yet. This log message shows that the app in question has actually fired the winEvent.

DEBUG - IAccessibleHandler.internalWinEventHandler.winEventCallback (10:54:56.442) - MainThread (32):
Adding winEvent to limiter: EVENT_OBJECT_FOCUS, window 1443880 (Button), objectID OBJID_CLIENT, childID 0, from process 5512 (explorer), thread 21136

Here NvDA is adding the winEvent to its winEventLimiter, to ensure that we do not get flooded with winEvents. The limiter tries to filter out duplicate winEvents, and also limits the number of events for a thread, per NVDA core cycle.
It is possible that a winEvent will be dropped before this point, due to the window being invalid, or perhaps it is a locationChange event for an object other than the caret (which we have no use for). If a winEvent is dropped before this point, another specific message will be logged.

DEBUG - IAccessibleHandler.orderedWinEventLimiter.OrderedWinEventLimiter.flushEvents (10:54:56.458) - MainThread (32):
Emitting winEvent EVENT_OBJECT_FOCUS, window 1443880 (Button), objectID OBJID_CLIENT, childID 0, from process 5512 (explorer), thread 21136

Here the winEvent is coming out of the limiter on the next NvDA core cycle, and will be processed via one or more specific winEvent handling functions, and either dropped or queued as an NVDA event.
For example, the following messages show that the focus winEvent is being handled by processFocusWinEvent, and in in tern converted from a winEvent to an NVDA event:

DEBUG - IAccessibleHandler.processFocusWinEvent (12:10:25.854) - MainThread (3636):
Processing focus winEvent: window 395144 (Button), objectID OBJID_CLIENT, childID 0, process 5512 (explorer), force False
DEBUG - IAccessibleHandler.winEventToNVDAEvent (12:10:25.854) - MainThread (3636):
Creating NVDA event from winEvent: EVENT_OBJECT_FOCUS, window 395144 (Button), objectID OBJID_CLIENT, childID 0, process 5512 (explorer), use cache False
DEBUG - IAccessibleHandler.winEventToNVDAEvent (12:10:25.854) - MainThread (3636):
winEvent mapped to NVDA event: gainFocus
DEBUG - IAccessibleHandler.winEventToNVDAEvent (12:10:25.854) - MainThread (3636):
Successfully created NvDA event gainFocus for <NVDAObjects.IAccessible.Button object at 0x04C78330> from winEvent EVENT_OBJECT_FOCUS, window 395144 (Button), objectID OBJID_CLIENT, childID 0, process 5512 (explorer)

Sometimes a winEvent is for an NvDAObject that is already being tracked by NVDA, such as the current focus. In this case, the winEvent will be redirected straight to the existing NVDAObject, rather than creating a new one with AccessibleObjectFromEvent etc:

DEBUG - IAccessibleHandler.winEventToNVDAEvent (12:13:33.703) - MainThread (19248):
Fetched existing NVDAObject <NVDAObjects.IAccessible.Button object at 0x08053310> from liveNVDAObjectTable for winEvent window 5636926 (Button), objectID OBJID_CLIENT, childID 0, process 5512 (explorer)

There are many reasons why a winEvent may be deliberately dropped along the way.
One might be that the limiter detected too many events for a particular thread during an NVDA core cycle. If so you will see this message:

DEBUG - IAccessibleHandler.orderedWinEventLimiter.OrderedWinEventLimiter.flushEvents (12:16:24.886) - MainThread (19248):
winEvent limit for thread 17008 hit for this core cycle

Or perhaps, the winEvent was for a window that supported UI automation natively:

DEBUG - IAccessibleHandler.winEventToNVDAEvent (12:17:44.604) - MainThread (19248):
Native UIA window. Dropping winEvent EVENT_OBJECT_STATECHANGE, window 854612 (DirectUIHWND), objectID 100794482, childID 0, process 5512 (explorer)

DEBUG - IAccessibleHandler.processGenericWinEvent (10:54:56.458) - MainThread (32):
Directing winEvent to focus object

josephsl · 2020-09-01T02:30:05Z

Hi,

I guess it can go under "events" section where we describe list of common events. Due to the nature of this PR, I think a section on debugging API level events might be useful, which would then be linked from the events section.

Below is what Windows 10 App Essentials add-on internals document says about UIA event tracking, which I think would be a good starting point:

Tracking UIA events for controls

The Windows 10 Objects global plugin also has ability to track UIA events for controls and log info about them, executed via uiaDebugLogging function that takes an object and the event name. This function records the following if NVDA is started with debug logging enabled or told to monitor specific events and/or events from specific apps:

What the object actually is.
Object name.
Name of the event being logged.
App where the control can be found (specifically, the app module).
Automation Id if possible.
UIA class name.
For controller for event, the list of objects the given control depends on.
For tooltip open event, the GUI framework that powers the element.
For item status event, new item status text.
For state change event, current element status.

Thanks.

michaelDCurran · 2020-09-01T02:57:19Z

@feerrenrut I think I have now addressed everything except for adding to the dev guide, but see my comment above. I have also added yet more log calls. Plus, as we quickly spoke about last week, I have now included the process name in the winEvent log info.

feerrenrut · 2020-09-01T13:53:14Z

 			obj = SDMChild
+	if isMSAADebugLoggingEnabled():
+		log.debug(
+			f"Successfully created NvDA event {NVDAEventName} for {obj} "


Minor: lower case v in NVDA

…isfy Linter and decrease likelihood of circular imports (#12367) Summary of the issue: Linter complains about various imports in IAccessibleHandler not being at the top of file. In the current situation moving them to the top causes errors about imports from not fully initialized module. Description of how this pull request fixes the issue: At first I thought this can be solved by not importing NVDAObjects.IAccessible in the api module which is unused there anyway. Unfortunately removing this import just delayed the error but NVDA still was unable to start. Therefore I've moved parts of IAccessibleHandler which are imported by various other files in this package to two new files: types.py contains typing information for IAccessibleHandler utils.py contains various utility functions mostly introduced in #11521 Co-authored-by: buddsean <sean@nvaccess.org>

Add significant optional debug logging for MSAA events.

a9ad03b

michaelDCurran requested a review from feerrenrut August 25, 2020 01:54

LeonarddeR reviewed Aug 25, 2020

View reviewed changes

michaelDCurran and others added 4 commits August 26, 2020 11:11

Fix typo

b92e417

Co-authored-by: Leonard de Ruijter <leonardder@users.noreply.github.com>

Include winEvent params in log message.

8457b71

Co-authored-by: Leonard de Ruijter <leonardder@users.noreply.github.com>

Include winEvent params in log message.

7958539

Co-authored-by: Leonard de Ruijter <leonardder@users.noreply.github.com>

Include window handle and windowClass name in log message about nativ…

13f6514

…e UIA window. Co-authored-by: Leonard de Ruijter <leonardder@users.noreply.github.com>

michaelDCurran force-pushed the MSAALogging branch from ee06e26 to 13f6514 Compare August 26, 2020 01:27

Fix linting issues.

95552ba

LeonarddeR previously approved these changes Aug 31, 2020

View reviewed changes

feerrenrut suggested changes Aug 31, 2020

View reviewed changes

* Included winEvent info to several more log calls.

8117303

* Added several more log calls. * Improved log call for error in AccessibleObjectFromEvent and put it behind isMSAADebugLoggingEnabled. * Fixed typo. * Included threadID, processID and process name in winEvent log info where possible.

michaelDCurran dismissed LeonarddeR’s stale review via 8117303 September 1, 2020 00:50

Added yet more MSAA debug log messages.

e3ffb3b

feerrenrut previously approved these changes Sep 1, 2020

View reviewed changes

Fix typo

70e83cb

michaelDCurran dismissed feerrenrut’s stale review via 70e83cb September 1, 2020 22:58

Update what's new

8f1825d

michaelDCurran merged commit f4cb084 into master Sep 1, 2020

michaelDCurran deleted the MSAALogging branch September 1, 2020 23:12

nvaccessAuto added this to the 2020.3 milestone Sep 1, 2020

This was referenced Sep 3, 2020

Rely on IA2 caret events for Chrome and Firefox editors #11545

Closed

NVDA Laggs a lot in Visual Studio Code editor while typing and reading the code #11533

Closed

lukaszgo1 mentioned this pull request May 5, 2021

Move some helper functions from main IAccessibleHandler module to satisfy Linter and decrease likelihood of circular imports #12367

Merged

7 tasks

	log.debug("Dropping winEvent for invalid window")
	log.debug(f"Dropping winEvent for invalid window {window}")

	f"Adding winEvent to limitor: {getWinEventLogInfo(window, objectID, childID, eventID)}"
	f"Adding winEvent to limiter: {getWinEventLogInfo(window, objectID, childID, eventID)}"

Uh oh!

Conversation

michaelDCurran commented Aug 25, 2020 • edited by feerrenrut 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 performed:

Known issues with pull request:

Change log entry:

Uh oh!

LeonarddeR left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

LeonarddeR Aug 25, 2020

Choose a reason for hiding this comment

Uh oh!

feerrenrut Aug 31, 2020

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

codeofdusk commented Aug 25, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

feerrenrut commented Aug 25, 2020

Uh oh!

AppVeyorBot commented Aug 26, 2020

Uh oh!

michaelDCurran commented Aug 26, 2020

Uh oh!

michaelDCurran commented Aug 31, 2020

Uh oh!

LeonarddeR left a comment

Choose a reason for hiding this comment

Uh oh!

LeonarddeR Aug 31, 2020

Choose a reason for hiding this comment

Uh oh!

feerrenrut left a comment

Choose a reason for hiding this comment

Uh oh!

feerrenrut Aug 31, 2020

Choose a reason for hiding this comment

Uh oh!

feerrenrut Aug 31, 2020

Choose a reason for hiding this comment

Uh oh!

feerrenrut Aug 31, 2020

Choose a reason for hiding this comment

Uh oh!

AppVeyorBot commented Sep 1, 2020

Uh oh!

michaelDCurran commented Sep 1, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

MSAA Logging

Uh oh!

josephsl commented Sep 1, 2020

Tracking UIA events for controls

Uh oh!

michaelDCurran commented Sep 1, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

feerrenrut Sep 1, 2020

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

7 participants

michaelDCurran commented Aug 25, 2020 •

edited by feerrenrut

Loading

codeofdusk commented Aug 25, 2020 •

edited

Loading

michaelDCurran commented Sep 1, 2020 •

edited

Loading

michaelDCurran commented Sep 1, 2020 •

edited

Loading