Skip to content

Add significant optional debug logging for MSAA events #11521

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.

Sign up for GitHub

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

Merged
michaelDCurran merged 10 commits into from
Sep 1, 2020
Merged

Add significant optional debug logging for MSAA events #11521

Show file tree
Hide file tree
Changes from 8 commits
Commits
Show all changes
10 commits
Select commit Hold shift + click to select a range
a9ad03b
Add significant optional debug logging for MSAA events.
michaelDCurran Aug 25, 2020
b92e417
Fix typo
michaelDCurran Aug 26, 2020
8457b71
Include winEvent params in log message.
michaelDCurran Aug 26, 2020
7958539
Include winEvent params in log message.
michaelDCurran Aug 26, 2020
13f6514
Include window handle and windowClass name in log message about nativ…
michaelDCurran Aug 26, 2020
95552ba
Fix linting issues.
michaelDCurran Aug 26, 2020
8117303
* Included winEvent info to several more log calls.
michaelDCurran Sep 1, 2020
e3ffb3b
Added yet more MSAA debug log messages.
michaelDCurran Sep 1, 2020
70e83cb
Fix typo
michaelDCurran Sep 1, 2020
8f1825d
Update what's new
michaelDCurran Sep 1, 2020
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
190 changes: 186 additions & 4 deletions source/IAccessibleHandler/__init__.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -99,6 +99,68 @@
IA2_ROLE_FOOTER,
IA2_ROLE_MARK,
)
import config


_winEventNameCache = {}


def getWinEventName(eventID):
""" Looks up the name of an EVENT_* winEvent constant. """
global _winEventNameCache
if not _winEventNameCache:
_winEventNameCache = {y: x for x, y in vars(winUser).items() if x.startswith('EVENT_')}
_winEventNameCache.update({y: x for x, y in vars(IA2).items() if x.startswith('IA2_EVENT_')})
name = _winEventNameCache.get(eventID)
if not name:
name = "unknown event ({eventID})"
return name


_objectIDNameCache = {}


def getObjectIDName(objectID):
""" Looks up the name of an OBJID_* winEvent constant. """
global _objectIDNameCache
if not _objectIDNameCache:
_objectIDNameCache = {y: x for x, y in vars(winUser).items() if x.startswith('OBJID_')}
name = _objectIDNameCache.get(objectID)
if not name:
name = str(objectID)
return name


def getWinEventLogInfo(window, objectID, childID, eventID=None, threadID=None):
"""
Formats the given winEvent parameters into a printable string.
window, objectID and childID are mandatory,
but eventID and threadID are optional.
"""
windowClassName = winUser.getClassName(window) or "unknown"
objectIDName = getObjectIDName(objectID)
processID = winUser.getWindowThreadProcessID(window)[0]
if processID:
processName = appModuleHandler.getAppModuleFromProcessID(processID).appName
else:
processName = "unknown application"
messageList = []
if eventID is not None:
eventName = getWinEventName(eventID)
messageList.append(f"{eventName}")
messageList.append(
f"window {window} ({windowClassName}), objectID {objectIDName}, childID {childID}, "
f"process {processID} ({processName})"
)
if threadID is not None:
messageList.append(f"thread {threadID}")
return ", ".join(messageList)


def isMSAADebugLoggingEnabled():
Comment thread
feerrenrut marked this conversation as resolved.
""" Whether the user has configured NVDA to log extra information about MSAA events. """
return config.conf["debugLog"]["MSAA"]


from . import internalWinEventHandler
# Imported for backwards compat
Expand Down Expand Up @@ -344,10 +406,11 @@ def accessibleObjectFromEvent(window, objectID, childID):
try:
pacc, childID = oleacc.AccessibleObjectFromEvent(window, objectID, childID)
except Exception as e:
log.debug(
f"oleacc.AccessibleObjectFromEvent with"
f" window {window}, objectID {objectID} and childID {childID}: {e}"
)
if isMSAADebugLoggingEnabled():
log.debugWarning(
f"oleacc.AccessibleObjectFromEvent failed with {e}."
f" WinEvent: {getWinEventLogInfo(window, objectID, childID)}"
)
return None
return normalizeIAccessible(pacc, childID), childID

Expand Down Expand Up @@ -522,27 +585,57 @@ def winEventToNVDAEvent(eventID, window, objectID, childID, useCache=True):
@returns: the NVDA event name and the NVDAObject the event is for
@rtype: tuple of string and L{NVDAObjects.IAccessible.IAccessible}
"""
if isMSAADebugLoggingEnabled():
log.debug(
f"Creating NVDA event from winEvent: {getWinEventLogInfo(window, objectID, childID, eventID)}, "
f"use cache {useCache}"
)
NVDAEventName = winEventIDsToNVDAEventNames.get(eventID, None)
if not NVDAEventName:
log.debugWarning(f"No NVDA event name for {getWinEventName(eventID)}")
return None
if isMSAADebugLoggingEnabled():
log.debug(f"winEvent mapped to NVDA event: {NVDAEventName}")
# Ignore any events with invalid window handles
if not window or not winUser.isWindow(window):
if isMSAADebugLoggingEnabled():
log.debug(
f"Invalid window. Dropping winEvent {getWinEventLogInfo(window, objectID, childID, eventID)}"
)
return None
# Make sure this window does not have a ghost window if possible
if NVDAObjects.window.GhostWindowFromHungWindow and NVDAObjects.window.GhostWindowFromHungWindow(window):
Comment thread
feerrenrut marked this conversation as resolved.
if isMSAADebugLoggingEnabled():
log.debug(
f"Ghosted hung window. Dropping winEvent {getWinEventLogInfo(window, objectID, childID, eventID)}"
)
return None
# We do not support MSAA object proxied from native UIA
if UIAHandler.handler and UIAHandler.handler.isUIAWindow(window):
if isMSAADebugLoggingEnabled():
log.debug(
f"Native UIA window. Dropping winEvent {getWinEventLogInfo(window, objectID, childID, eventID)}"
)
return None
obj = None
if useCache:
# See if we already know an object by this win event info
obj = liveNVDAObjectTable.get((window, objectID, childID), None)
if isMSAADebugLoggingEnabled() and obj:
log.debug(
f"Fetched existing NVDAObject {obj} from liveNVDAObjectTable"
f" for winEvent {getWinEventLogInfo(window, objectID, childID)}"
)
# If we don't yet have the object, then actually instanciate it.
if not obj:
obj = NVDAObjects.IAccessible.getNVDAObjectFromEvent(window, objectID, childID)
# At this point if we don't have an object then we can't do any more
if not obj:
if isMSAADebugLoggingEnabled():
log.debug(
"Could not instantiate an NVDAObject for winEvent: "
f"{getWinEventLogInfo(window, objectID, childID, eventID)}"
)
return None
# SDM MSAA objects sometimes don't contain enough information to be useful Sometimes there is a real
# window that does, so try to get the SDMChild property on the NVDAObject, and if successull use that as
Expand All @@ -551,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} "

@feerrenrut feerrenrut Sep 1, 2020

Copy link
Copy Markdown
Contributor

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

f"from winEvent {getWinEventLogInfo(window, objectID, childID, eventID)}"
)
return (NVDAEventName, obj)


Expand All @@ -569,6 +667,10 @@ def processGenericWinEvent(eventID, window, objectID, childID):
@returns: True if the event was processed, False otherwise.
@rtype: boolean
"""
if isMSAADebugLoggingEnabled():
log.debug(
f"Processing generic winEvent: {getWinEventLogInfo(window, objectID, childID, eventID)}"
)
# Notify appModuleHandler of this new window
appModuleHandler.update(winUser.getWindowThreadProcessID(window)[0])
# Handle particular events for the special MSAA caret object just as if they were for the focus object
Expand All @@ -577,15 +679,23 @@ def processGenericWinEvent(eventID, window, objectID, childID):
winUser.EVENT_OBJECT_LOCATIONCHANGE,
winUser.EVENT_OBJECT_SHOW
):
if isMSAADebugLoggingEnabled():
log.debug("handling winEvent as caret event on focus")
NVDAEvent = ("caret", focus)
else:
NVDAEvent = winEventToNVDAEvent(eventID, window, objectID, childID)
if not NVDAEvent:
return False
if NVDAEvent[0] == "nameChange" and objectID == winUser.OBJID_CURSOR:
if isMSAADebugLoggingEnabled():
log.debug("Handling winEvent as mouse shape change")
mouseHandler.updateMouseShape(NVDAEvent[1].name)
return
if NVDAEvent[1] == focus:
if isMSAADebugLoggingEnabled():
log.debug(
f"Directing winEvent to focus object {focus}. WinEvent {getWinEventLogInfo(window, objectID, childID)}"
)
NVDAEvent = (NVDAEvent[0], focus)
eventHandler.queueEvent(*NVDAEvent)
return True
Expand All @@ -605,6 +715,11 @@ def processFocusWinEvent(window, objectID, childID, force=False):
@returns: True if the focus is valid and was handled, False otherwise.
@rtype: boolean
"""
if isMSAADebugLoggingEnabled():
log.debug(
f"Processing focus winEvent: {getWinEventLogInfo(window, objectID, childID)}, "
f"force {force}"
)
windowClassName = winUser.getClassName(window)
# Generally, we must ignore focus on child windows of SDM windows as we only want the SDM MSAA events.
# However, we don't want to ignore focus if the child ID isn't 0,
Expand All @@ -614,6 +729,11 @@ def processFocusWinEvent(window, objectID, childID, force=False):
and not windowClassName.startswith('bosa_sdm')
and winUser.getClassName(winUser.getAncestor(window, winUser.GA_PARENT)).startswith('bosa_sdm')
):
if isMSAADebugLoggingEnabled():
log.debug(
f"Focus event for child window of MS Office SDM window. "
f"Dropping winEvent {getWinEventLogInfo(window, objectID, childID)}, "
)
return False
# Notify appModuleHandler of this new foreground window
appModuleHandler.update(winUser.getWindowThreadProcessID(window)[0])
Expand All @@ -624,6 +744,10 @@ def processFocusWinEvent(window, objectID, childID, force=False):
and JABHandler.isRunning
and JABHandler.isJavaWindow(window)
):
if isMSAADebugLoggingEnabled():
log.debug(
f"Redirecting focus to Java window. WinEvent {getWinEventLogInfo(window, objectID, childID)}"
)
JABHandler.event_enterJavaWindow(window)
return True
# Convert the win event to an NVDA event
Expand Down Expand Up @@ -666,8 +790,12 @@ def processFocusNVDAEvent(obj, force=False):
if not force and isinstance(obj, NVDAObjects.IAccessible.IAccessible):
focus = eventHandler.lastQueuedFocusObject
if isinstance(focus, NVDAObjects.IAccessible.IAccessible) and focus.isDuplicateIAccessibleEvent(obj):
if isMSAADebugLoggingEnabled():
log.debug(f"Dropping duplicate IAccessible focus event for {obj}")
return True
if not obj.shouldAllowIAccessibleFocusEvent:
if isMSAADebugLoggingEnabled():
log.debug(f"IAccessible focus event not allowed by {obj}")
return False
eventHandler.queueEvent('gainFocus', obj)
return True
Expand All @@ -693,6 +821,10 @@ def event_gainFocus(self):


def processDesktopSwitchWinEvent(window, objectID, childID):
if isMSAADebugLoggingEnabled():
log.debug(
f"Processing desktopSwitch winEvent: {getWinEventLogInfo(window, objectID, childID)}"
)
hDesk = windll.user32.OpenInputDesktop(0, False, 0)
if hDesk != 0:
windll.user32.CloseDesktop(hDesk)
Expand Down Expand Up @@ -724,8 +856,17 @@ def processForegroundWinEvent(window, objectID, childID):
@returns: True if the foreground was processed, False otherwise.
@rtype: boolean
"""
if isMSAADebugLoggingEnabled():
log.debug(
f"Processing foreground winEvent: {getWinEventLogInfo(window, objectID, childID)}"
)
# Ignore foreground events on windows that aren't the current foreground window
if window != winUser.getForegroundWindow():
if isMSAADebugLoggingEnabled():
log.debug(
f"Dropping foreground winEvent as it does not match GetForegroundWindow. "
f"WinEvent {getWinEventLogInfo(window, objectID, childID)}"
)
return False
# If there is a pending gainFocus, it will handle the foreground object.
oldFocus = eventHandler.lastQueuedFocusObject
Expand All @@ -734,6 +875,11 @@ def processForegroundWinEvent(window, objectID, childID):
isinstance(oldFocus, NVDAObjects.window.Window)
and winUser.isDescendantWindow(window, oldFocus.windowHandle)
):
if isMSAADebugLoggingEnabled():
log.debug(
f"Dropping foreground winEvent as focus is already on a descendant. "
f"WinEvent {getWinEventLogInfo(window, objectID, childID)}"
)
return False
# If the existing focus has the same win event params as these, then ignore this event
if (
Expand All @@ -742,22 +888,41 @@ def processForegroundWinEvent(window, objectID, childID):
and objectID == oldFocus.event_objectID
and childID == oldFocus.event_childID
):
if isMSAADebugLoggingEnabled():
log.debug(
f"Dropping foreground winEvent as it is duplicate to existing focus. "
f"WinEvent {getWinEventLogInfo(window, objectID, childID)}"
)
return False
# Notify appModuleHandler of this new foreground window
appModuleHandler.update(winUser.getWindowThreadProcessID(window)[0])
# If Java access bridge is running, and this is a java window, then pass it to java and forget about it
if JABHandler.isRunning and JABHandler.isJavaWindow(window):
JABHandler.event_enterJavaWindow(window)
if isMSAADebugLoggingEnabled():
log.debug(
f"Redirecting foreground winEvent to Java window. "
f"WinEvent {getWinEventLogInfo(window, objectID, childID)}"
)
return True
# Convert the win event to an NVDA event
NVDAEvent = winEventToNVDAEvent(winUser.EVENT_SYSTEM_FOREGROUND, window, objectID, childID, useCache=False)
if not NVDAEvent:
if isMSAADebugLoggingEnabled():
log.debug(
f"Could not convert foreground winEvent to an NVDA event. "
f"WinEvent {getWinEventLogInfo(window, objectID, childID)}"
)
return False
eventHandler.queueEvent(*NVDAEvent)
return True


def processShowWinEvent(window, objectID, childID):
if isMSAADebugLoggingEnabled():
log.debug(
f"Processing show winEvent: {getWinEventLogInfo(window, objectID, childID)}"
)
# eventHandler.shouldAcceptEvent only accepts show events for a few specific cases.
# Narrow this further to only accept events for clients or custom objects.
if objectID == winUser.OBJID_CLIENT or objectID > 0:
Expand All @@ -771,6 +936,10 @@ def processDestroyWinEvent(window, objectID, childID):
This removes the object associated with the event parameters from L{liveNVDAObjectTable} if
such an object exists.
"""
if isMSAADebugLoggingEnabled():
log.debug(
f"Processing destroy winEvent: {getWinEventLogInfo(window, objectID, childID)}"
)
try:
del liveNVDAObjectTable[(window, objectID, childID)]
except KeyError:
Expand All @@ -796,6 +965,11 @@ def processMenuStartWinEvent(eventID, window, objectID, childID, validFocus):
"""Process a menuStart win event.
@postcondition: Focus will be directed to the menu if appropriate.
"""
if isMSAADebugLoggingEnabled():
log.debug(
f"Processing menuStart winEvent: {getWinEventLogInfo(window, objectID, childID)}, "
f"validFocus {validFocus}"
)
if validFocus:
lastFocus = eventHandler.lastQueuedFocusObject
if (
Expand All @@ -822,6 +996,10 @@ def processFakeFocusWinEvent(eventID, window, objectID, childID):
# find the focus and fake it.
# However, it is possible that the focus event has simply been delayed, so wait a bit and only do it if
# the focus hasn't changed yet.
if isMSAADebugLoggingEnabled():
log.debug(
f"Processing fake focus winEvent {getWinEventLogInfo(window, objectID, childID)}"
)
core.callLater(50, _fakeFocus, api.getFocusObject())


Expand All @@ -832,6 +1010,10 @@ def _fakeFocus(oldFocus):
focus = api.getDesktopObject().objectWithFocus()
if not focus:
return
if isMSAADebugLoggingEnabled():
log.debug(
f"Faking focus on {focus}"
)
processFocusNVDAEvent(focus)


Expand Down
Loading