Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add significant optional debug logging for MSAA events #11521

Merged
merged 10 commits into from Sep 1, 2020

Conversation

michaelDCurran
Copy link
Member

@michaelDCurran michaelDCurran commented Aug 25, 2020

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.

@michaelDCurran michaelDCurran requested a review from feerrenrut Aug 25, 2020
Copy link
Collaborator

@leonardder leonardder left a comment

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?

source/IAccessibleHandler/__init__.py Outdated Show resolved Hide resolved
source/IAccessibleHandler/__init__.py Show resolved Hide resolved
# Ignore any events with invalid window handles
if not window or not winUser.isWindow(window):
if isMSAADebugLoggingEnabled():
log.debug("Dropping winEvent for invalid window")
Copy link
Collaborator

@leonardder leonardder Aug 25, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Member

@feerrenrut feerrenrut Aug 31, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

source/IAccessibleHandler/__init__.py Show resolved Hide resolved
source/IAccessibleHandler/__init__.py Outdated Show resolved Hide resolved
source/IAccessibleHandler/__init__.py Outdated Show resolved Hide resolved
source/IAccessibleHandler/__init__.py Outdated Show resolved Hide resolved
@codeofdusk
Copy link
Contributor

codeofdusk commented Aug 25, 2020

In the changelog entry, swap the word order:

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

@feerrenrut
Copy link
Member

feerrenrut commented Aug 25, 2020

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.

michaelDCurran and others added 4 commits Aug 26, 2020
Co-authored-by: Leonard de Ruijter <leonardder@users.noreply.github.com>
Co-authored-by: Leonard de Ruijter <leonardder@users.noreply.github.com>
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
Copy link

AppVeyorBot commented Aug 26, 2020

See test results for failed build of commit 77d1f7bab7

@michaelDCurran
Copy link
Member Author

michaelDCurran commented Aug 26, 2020

@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
Copy link
Member Author

michaelDCurran commented Aug 31, 2020

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

leonardder
leonardder previously approved these changes Aug 31, 2020
Copy link
Collaborator

@leonardder leonardder left a comment

Apart from one typo, this looks ok

if windowClassName == "MSNHiddenWindowClass":
# HACK: Events get fired by this window in Windows Live Messenger 2009 when it starts. If we send a
# WM_NULL to this window at this point (which happens in accessibleObjectFromEvent), Messenger will
# silently exit (#677). Therefore, completely ignore these events, which is useless to us anyway.
return
if isMSAADebugLoggingEnabled():
log.debug(
f"Adding winEvent to limitor: {getWinEventLogInfo(window, objectID, childID, eventID)}"
Copy link
Collaborator

@leonardder leonardder Aug 31, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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)}"

Copy link
Member

@feerrenrut feerrenrut left a comment

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?

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

@feerrenrut feerrenrut Aug 31, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

return None
# 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")
Copy link
Member

@feerrenrut feerrenrut Aug 31, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Might be worth adding which window this message is for?

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

@feerrenrut feerrenrut Aug 31, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

AppVeyorBot commented Sep 1, 2020

See test results for failed build of commit 825960d132

@michaelDCurran
Copy link
Member Author

michaelDCurran commented Sep 1, 2020

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

josephsl commented Sep 1, 2020

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
Copy link
Member Author

michaelDCurran commented Sep 1, 2020

@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
feerrenrut previously approved these changes Sep 1, 2020
@@ -626,6 +644,11 @@ def winEventToNVDAEvent(eventID, window, objectID, childID, useCache=True):
SDMChild = getattr(obj, 'SDMChild', None)
if SDMChild:
obj = SDMChild
if isMSAADebugLoggingEnabled():
log.debug(
f"Successfully created NvDA event {NVDAEventName} for {obj} "
Copy link
Member

@feerrenrut feerrenrut Sep 1, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Minor: lower case v in NVDA

@michaelDCurran michaelDCurran merged commit f4cb084 into master Sep 1, 2020
1 check passed
@michaelDCurran michaelDCurran deleted the MSAALogging branch Sep 1, 2020
@nvaccessAuto nvaccessAuto added this to the 2020.3 milestone Sep 1, 2020
seanbudd added a commit that referenced this pull request May 12, 2021
…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>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

7 participants