-
-
Notifications
You must be signed in to change notification settings - Fork 631
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
Conversation
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
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?
# Ignore any events with invalid window handles | ||
if not window or not winUser.isWindow(window): | ||
if isMSAADebugLoggingEnabled(): | ||
log.debug("Dropping winEvent for invalid window") |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
log.debug("Dropping winEvent for invalid window") | |
log.debug(f"Dropping winEvent for invalid window {window}") |
There was a problem hiding this comment.
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.
In the changelog entry, swap the word order:
|
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: 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>
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>
ee06e26
to
13f6514
Compare
See test results for failed build of commit 77d1f7bab7 |
@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. |
@LeonarddeR or @feerrenrut is there any feedback you still need me to address here? |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
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)}" |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
limitOr should be limitEr
f"Adding winEvent to limitor: {getWinEventLogInfo(window, objectID, childID, eventID)}" | |
f"Adding winEvent to limiter: {getWinEventLogInfo(window, objectID, childID, eventID)}" | |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
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") |
There was a problem hiding this comment.
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") |
There was a problem hiding this comment.
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})" | ||
) |
There was a problem hiding this comment.
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.
See test results for failed build of commit 825960d132 |
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 LoggingIt 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:
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.
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.
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.
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:
There are many reasons why a winEvent may be deliberately dropped along the way.
Or perhaps, the winEvent was for a window that supported UI automation natively:
DEBUG - IAccessibleHandler.processGenericWinEvent (10:54:56.458) - MainThread (32): |
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 controlsThe Windows 10 Objects global plugin also has ability to track UIA events for controls and log info about them, executed via
Thanks. |
@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. |
@@ -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} " |
There was a problem hiding this comment.
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
…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>
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 variousprocess*WinEvent
functions. This logging must be turned on with the MSAA debug log checkbox in NVDA's advanced settings.When
winEvent
params are logged, theeventID
andobjectID
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: