From a9ad03b03be34e11873c857176ddaede933d9443 Mon Sep 17 00:00:00 2001 From: Michael Curran Date: Tue, 25 Aug 2020 10:23:26 +1000 Subject: [PATCH 01/10] Add significant optional debug logging for MSAA events. --- source/IAccessibleHandler/__init__.py | 105 ++++++++++++++++++ .../internalWinEventHandler.py | 38 ++++++- .../orderedWinEventLimiter.py | 13 ++- source/config/configSpec.py | 1 + source/gui/settingsDialogs.py | 1 + 5 files changed, 155 insertions(+), 3 deletions(-) diff --git a/source/IAccessibleHandler/__init__.py b/source/IAccessibleHandler/__init__.py index 7aef9891220..ca3850a605f 100644 --- a/source/IAccessibleHandler/__init__.py +++ b/source/IAccessibleHandler/__init__.py @@ -99,6 +99,57 @@ 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): + """ + Formats the given winEvent parameters into a printable string. + window, objectID and childID are mandetory, + but eventID is optional. + """ + windowClassName = winUser.getClassName(window) + objectIDName = getObjectIDName(objectID) + if eventID is not None: + eventName = getWinEventName(eventID) + return f"{eventName} for window {window} ({windowClassName}), objectID {objectIDName} and childID {childID}" + else: + return f"window {window} ({windowClassName}), objectID {objectIDName} and childID {childID}" + + +def isMSAADebugLoggingEnabled(): + """ 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 @@ -522,27 +573,45 @@ 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("Dropping winEvent for invalid window") 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") return None # We do not support MSAA object proxied from native UIA if UIAHandler.handler and UIAHandler.handler.isUIAWindow(window): + if isMSAADebugLoggingEnabled(): + log.debug("Dropping winEvent for native UIA window") 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("Fetched existing NVDAObject for winEvent from liveNVDAObjectTable") # 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") 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 @@ -569,6 +638,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 @@ -577,15 +650,21 @@ 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("Directing winEvent to focus object") NVDAEvent = (NVDAEvent[0], focus) eventHandler.queueEvent(*NVDAEvent) return True @@ -605,6 +684,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, @@ -693,6 +777,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) @@ -724,6 +812,10 @@ 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(): return False @@ -758,6 +850,10 @@ def processForegroundWinEvent(window, objectID, childID): 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: @@ -771,6 +867,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: @@ -796,6 +896,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 ( diff --git a/source/IAccessibleHandler/internalWinEventHandler.py b/source/IAccessibleHandler/internalWinEventHandler.py index 6167cba249e..42f3e074fcb 100644 --- a/source/IAccessibleHandler/internalWinEventHandler.py +++ b/source/IAccessibleHandler/internalWinEventHandler.py @@ -13,6 +13,9 @@ import core import winUser +from . import getWinEventLogInfo +from . import isMSAADebugLoggingEnabled + from comInterfaces.IAccessible2Lib import ( IA2_EVENT_TEXT_CARET_MOVED, @@ -69,6 +72,10 @@ # C901: winEventCallback is too complex def winEventCallback(handle, eventID, window, objectID, childID, threadID, timestamp): # noqa: C901 + if isMSAADebugLoggingEnabled(): + log.debug( + f"Hook received winEvent: {getWinEventLogInfo(window, objectID, childID, eventID)}" + ) try: # Ignore all object IDs from alert onwards (sound, nativeom etc) as we don't support them if objectID <= winUser.OBJID_ALERT: @@ -82,6 +89,8 @@ def winEventCallback(handle, eventID, window, objectID, childID, threadID, times # Change window objIDs to client objIDs for better reporting of objects if (objectID == 0) and (childID == 0): objectID = winUser.OBJID_CLIENT + if isMSAADebugLoggingEnabled(): + log.debug("Changing OBJID_WINDOW to OBJID_CLIENT") # Ignore events with invalid window handles isWindow = winUser.isWindow(window) if window else 0 if window == 0 or ( @@ -92,8 +101,12 @@ def winEventCallback(handle, eventID, window, objectID, childID, threadID, times winUser.EVENT_SYSTEM_MENUPOPUPEND, ) ): + if isMSAADebugLoggingEnabled(): + log.debug("Redirecting winEvent to desktop window") window = winUser.getDesktopWindow() elif not isWindow: + if isMSAADebugLoggingEnabled(): + log.debug("Dropping winEvent for invalid window") return windowClassName = winUser.getClassName(window) @@ -114,14 +127,20 @@ def winEventCallback(handle, eventID, window, objectID, childID, threadID, times global _deferUntilForegroundWindow, _foregroundDefers _deferUntilForegroundWindow = window _foregroundDefers = 0 + if isMSAADebugLoggingEnabled(): + log.debug("Recording foreground winEvent defer") 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)}" + ) if winEventLimiter.addEvent(eventID, window, objectID, childID, threadID): core.requestPump() - except: # noqa: E722 Bare except + except Exception: log.error("winEventCallback", exc_info=True) @@ -162,18 +181,33 @@ def _shouldGetEvents(): if _deferUntilForegroundWindow: # #3831: Sometimes, a foreground event is fired, # but GetForegroundWindow() takes a short while to return this new foreground. + curForegroundWindow = winUser.getForegroundWindow() + curForegroundClassName = winUser.getClassName(curForegroundWindow) + futureForegroundClassName = winUser.getClassName(_deferUntilForegroundWindow) if ( _foregroundDefers < MAX_FOREGROUND_DEFERS - and winUser.getForegroundWindow() != _deferUntilForegroundWindow + and curForegroundWindow != _deferUntilForegroundWindow ): # Wait a core cycle before handling events to give the foreground window time to update. core.requestPump() _foregroundDefers += 1 + if isMSAADebugLoggingEnabled(): + log.debugWarning( + f"Foreground still {curForegroundWindow} ({curForegroundClassName}). " + f"Deferring until foreground is {_deferUntilForegroundWindow} ({futureForegroundClassName}), " + f"defer count {_foregroundDefers}" + ) return False else: # Either the foreground window is now correct # or we've already had the maximum number of defers. # (Sometimes, foreground events are fired even when the foreground hasn't actually changed.) + if curForegroundWindow != _deferUntilForegroundWindow: + log.debugWarning( + "Foreground took too long to change. " + f"Foreground still {curForegroundWindow} ({curForegroundClassName}). " + f"Should be {_deferUntilForegroundWindow} ({futureForegroundClassName})" + ) _deferUntilForegroundWindow = None return True diff --git a/source/IAccessibleHandler/orderedWinEventLimiter.py b/source/IAccessibleHandler/orderedWinEventLimiter.py index 65203e73430..060aeda2ab4 100644 --- a/source/IAccessibleHandler/orderedWinEventLimiter.py +++ b/source/IAccessibleHandler/orderedWinEventLimiter.py @@ -2,6 +2,9 @@ import itertools import winUser +from logHandler import log +from . import isMSAADebugLoggingEnabled, getWinEventLogInfo + MAX_WINEVENTS_PER_THREAD = 10 @@ -89,10 +92,13 @@ def flushEvents(self): threadCounters = {} for k, v in sorted(g.items(), key=lambda item: item[1], reverse=True): threadCount = threadCounters.get(k[-1], 0) + threadCounters[k[-1]] = threadCount + 1 if threadCount > MAX_WINEVENTS_PER_THREAD: + if isMSAADebugLoggingEnabled(): + if threadCount == (MAX_WINEVENTS_PER_THREAD + 1): + log.debug(f"winEvent limit for thread {k[-1]} hit for this core cycle") continue heapq.heappush(self._eventHeap, (v,) + k) - threadCounters[k[-1]] = threadCount + 1 f = self._focusEventCache self._focusEventCache = {} for k, v in sorted(f.items(), key=lambda item: item[1])[0 - self.maxFocusItems:]: @@ -102,5 +108,10 @@ def flushEvents(self): r = [] for count in range(len(e)): event = heapq.heappop(e)[1:-1] + if isMSAADebugLoggingEnabled(): + eventID, window, objectID, childID = event + log.debug( + f"Emitting winEvent {getWinEventLogInfo(window, objectID, childID, eventID)}" + ) r.append(event) return r diff --git a/source/config/configSpec.py b/source/config/configSpec.py index a170574c675..131d78a60bf 100644 --- a/source/config/configSpec.py +++ b/source/config/configSpec.py @@ -235,6 +235,7 @@ [debugLog] hwIo = boolean(default=false) + MSAA = boolean(default=false) UIA = boolean(default=false) audioDucking = boolean(default=false) gui = boolean(default=false) diff --git a/source/gui/settingsDialogs.py b/source/gui/settingsDialogs.py index 941bbc73ba8..024c5640afc 100644 --- a/source/gui/settingsDialogs.py +++ b/source/gui/settingsDialogs.py @@ -2447,6 +2447,7 @@ def __init__(self, parent): self.logCategories=[ "hwIo", + "MSAA", "UIA", "audioDucking", "gui", From b92e417730b1aa4e17a7bf99cd5371f47f89aaa2 Mon Sep 17 00:00:00 2001 From: Michael Curran Date: Wed, 26 Aug 2020 11:11:10 +1000 Subject: [PATCH 02/10] Fix typo Co-authored-by: Leonard de Ruijter --- source/IAccessibleHandler/__init__.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/source/IAccessibleHandler/__init__.py b/source/IAccessibleHandler/__init__.py index ca3850a605f..1ad3890fc4d 100644 --- a/source/IAccessibleHandler/__init__.py +++ b/source/IAccessibleHandler/__init__.py @@ -134,7 +134,7 @@ def getObjectIDName(objectID): def getWinEventLogInfo(window, objectID, childID, eventID=None): """ Formats the given winEvent parameters into a printable string. - window, objectID and childID are mandetory, + window, objectID and childID are mandatory, but eventID is optional. """ windowClassName = winUser.getClassName(window) From 8457b71cf705479b902ba25f0c5ba6b5a281a944 Mon Sep 17 00:00:00 2001 From: Michael Curran Date: Wed, 26 Aug 2020 11:18:32 +1000 Subject: [PATCH 03/10] Include winEvent params in log message. Co-authored-by: Leonard de Ruijter --- source/IAccessibleHandler/__init__.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/source/IAccessibleHandler/__init__.py b/source/IAccessibleHandler/__init__.py index 1ad3890fc4d..4458da401de 100644 --- a/source/IAccessibleHandler/__init__.py +++ b/source/IAccessibleHandler/__init__.py @@ -611,7 +611,7 @@ def winEventToNVDAEvent(eventID, window, objectID, childID, useCache=True): # 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") + log.debug(f"Could not instantiate an NVDAObject for winEvent: {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 From 7958539c918ecc745c225dc8f664cbd0452be6dd Mon Sep 17 00:00:00 2001 From: Michael Curran Date: Wed, 26 Aug 2020 11:20:58 +1000 Subject: [PATCH 04/10] Include winEvent params in log message. Co-authored-by: Leonard de Ruijter --- source/IAccessibleHandler/__init__.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/source/IAccessibleHandler/__init__.py b/source/IAccessibleHandler/__init__.py index 4458da401de..b5b294e0dd3 100644 --- a/source/IAccessibleHandler/__init__.py +++ b/source/IAccessibleHandler/__init__.py @@ -604,7 +604,7 @@ def winEventToNVDAEvent(eventID, window, objectID, childID, useCache=True): # 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("Fetched existing NVDAObject for winEvent from liveNVDAObjectTable") + log.debug(f"Fetched existing NVDAObject for winEvent from liveNVDAObjectTable: {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) From 13f6514ee1c0cb40f7ea28f3a4aa0febe994975d Mon Sep 17 00:00:00 2001 From: Michael Curran Date: Wed, 26 Aug 2020 11:24:29 +1000 Subject: [PATCH 05/10] Include window handle and windowClass name in log message about native UIA window. Co-authored-by: Leonard de Ruijter --- source/IAccessibleHandler/__init__.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/source/IAccessibleHandler/__init__.py b/source/IAccessibleHandler/__init__.py index b5b294e0dd3..2290e2556ba 100644 --- a/source/IAccessibleHandler/__init__.py +++ b/source/IAccessibleHandler/__init__.py @@ -597,7 +597,7 @@ def winEventToNVDAEvent(eventID, window, objectID, childID, useCache=True): # We do not support MSAA object proxied from native UIA if UIAHandler.handler and UIAHandler.handler.isUIAWindow(window): if isMSAADebugLoggingEnabled(): - log.debug("Dropping winEvent for native UIA window") + log.debug(f"Dropping winEvent for native UIA window {window} ({winUser.getClassName(window)})") return None obj = None if useCache: From 95552babe54e87491e07eeb05c1d74e868ca8244 Mon Sep 17 00:00:00 2001 From: Michael Curran Date: Wed, 26 Aug 2020 12:47:45 +1000 Subject: [PATCH 06/10] Fix linting issues. --- source/IAccessibleHandler/__init__.py | 10 ++++++++-- 1 file changed, 8 insertions(+), 2 deletions(-) diff --git a/source/IAccessibleHandler/__init__.py b/source/IAccessibleHandler/__init__.py index 2290e2556ba..e160ad79d94 100644 --- a/source/IAccessibleHandler/__init__.py +++ b/source/IAccessibleHandler/__init__.py @@ -604,14 +604,20 @@ def winEventToNVDAEvent(eventID, window, objectID, childID, useCache=True): # 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 for winEvent from liveNVDAObjectTable: {getWinEventLogInfo(window, objectID, childID)}") + log.debug( + "Fetched existing NVDAObject for winEvent from liveNVDAObjectTable: " + f"{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(f"Could not instantiate an NVDAObject for winEvent: {getWinEventLogInfo(window, objectID, childID, eventID)}") + 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 From 8117303721edfa750ed5ffd5c3897b987918ed6a Mon Sep 17 00:00:00 2001 From: Michael Curran Date: Tue, 1 Sep 2020 10:48:43 +1000 Subject: [PATCH 07/10] * Included winEvent info to several more log calls. * 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. --- source/IAccessibleHandler/__init__.py | 33 ++++++++++++------- .../internalWinEventHandler.py | 16 +++++---- .../orderedWinEventLimiter.py | 8 ++--- 3 files changed, 36 insertions(+), 21 deletions(-) diff --git a/source/IAccessibleHandler/__init__.py b/source/IAccessibleHandler/__init__.py index e160ad79d94..8f79e49000f 100644 --- a/source/IAccessibleHandler/__init__.py +++ b/source/IAccessibleHandler/__init__.py @@ -131,20 +131,30 @@ def getObjectIDName(objectID): return name -def getWinEventLogInfo(window, objectID, childID, eventID=None): +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 is optional. + but eventID and threadID are optional. """ - windowClassName = winUser.getClassName(window) + 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) - return f"{eventName} for window {window} ({windowClassName}), objectID {objectIDName} and childID {childID}" - else: - return f"window {window} ({windowClassName}), objectID {objectIDName} and childID {childID}" - + messageList.append(f"{eventName}") + messageList.append( + f"window {window} ({windowClassName}), objectID {objectIDName}, childID {childID}, " + f"from process {processID} ({processName})" + ) + if threadID is not None: + messageList.append(f"thread {threadID}") + return ", ".join(messageList) def isMSAADebugLoggingEnabled(): """ Whether the user has configured NVDA to log extra information about MSAA events. """ @@ -395,10 +405,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 diff --git a/source/IAccessibleHandler/internalWinEventHandler.py b/source/IAccessibleHandler/internalWinEventHandler.py index 42f3e074fcb..498c112434c 100644 --- a/source/IAccessibleHandler/internalWinEventHandler.py +++ b/source/IAccessibleHandler/internalWinEventHandler.py @@ -74,7 +74,7 @@ def winEventCallback(handle, eventID, window, objectID, childID, threadID, timestamp): # noqa: C901 if isMSAADebugLoggingEnabled(): log.debug( - f"Hook received winEvent: {getWinEventLogInfo(window, objectID, childID, eventID)}" + f"Hook received winEvent: {getWinEventLogInfo(window, objectID, childID, eventID, threadID)}" ) try: # Ignore all object IDs from alert onwards (sound, nativeom etc) as we don't support them @@ -90,7 +90,7 @@ def winEventCallback(handle, eventID, window, objectID, childID, threadID, times if (objectID == 0) and (childID == 0): objectID = winUser.OBJID_CLIENT if isMSAADebugLoggingEnabled(): - log.debug("Changing OBJID_WINDOW to OBJID_CLIENT") + log.debug(f"Changing OBJID_WINDOW to OBJID_CLIENT for winEvent: {getWinEventLogInfo(window, objectID, childID, eventID, threadID)}") # Ignore events with invalid window handles isWindow = winUser.isWindow(window) if window else 0 if window == 0 or ( @@ -102,11 +102,11 @@ def winEventCallback(handle, eventID, window, objectID, childID, threadID, times ) ): if isMSAADebugLoggingEnabled(): - log.debug("Redirecting winEvent to desktop window") + log.debug(f"Changing NULL or invalid window to desktop window for winEvent: {getWinEventLogInfo(window, objectID, childID, eventID, threadID)}") window = winUser.getDesktopWindow() elif not isWindow: if isMSAADebugLoggingEnabled(): - log.debug("Dropping winEvent for invalid window") + log.debug(f"Invalid window. Dropping winEvent: {getWinEventLogInfo(window, objectID, childID, eventID, threadID)}") return windowClassName = winUser.getClassName(window) @@ -117,10 +117,14 @@ def winEventCallback(handle, eventID, window, objectID, childID, threadID, times # Modern IME candidate list windows fire menu events which confuse us # and can't be used properly in conjunction with input composition support. if windowClassName == "Microsoft.IME.UIManager.CandidateWindow.Host" and eventID in MENU_EVENTIDS: + if isMSAADebugLoggingEnabled(): + log.debug(f"Dropping menu event for IME window. WinEvent: {getWinEventLogInfo(window, objectID, childID, eventID, threadID)}") return if eventID == winUser.EVENT_SYSTEM_FOREGROUND: # We never want to see foreground events for the Program Manager or Shell (task bar) if windowClassName in ("Progman", "Shell_TrayWnd"): + if isMSAADebugLoggingEnabled(): + log.debug(f"Progman or shell_trayWnd window. Dropping winEvent: {getWinEventLogInfo(window, objectID, childID, eventID, threadID)}") return # #3831: Event handling can be deferred if Windows takes a while to change the foreground window. # See pumpAll for details. @@ -128,7 +132,7 @@ def winEventCallback(handle, eventID, window, objectID, childID, threadID, times _deferUntilForegroundWindow = window _foregroundDefers = 0 if isMSAADebugLoggingEnabled(): - log.debug("Recording foreground winEvent defer") + log.debug(f"Recording foreground defer for WinEvent: {getWinEventLogInfo(window, objectID, childID, eventID, threadID)}") 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 @@ -136,7 +140,7 @@ def winEventCallback(handle, eventID, window, objectID, childID, threadID, times return if isMSAADebugLoggingEnabled(): log.debug( - f"Adding winEvent to limitor: {getWinEventLogInfo(window, objectID, childID, eventID)}" + f"Adding winEvent to limiter: {getWinEventLogInfo(window, objectID, childID, eventID, threadID)}" ) if winEventLimiter.addEvent(eventID, window, objectID, childID, threadID): core.requestPump() diff --git a/source/IAccessibleHandler/orderedWinEventLimiter.py b/source/IAccessibleHandler/orderedWinEventLimiter.py index 060aeda2ab4..0666dbc33f6 100644 --- a/source/IAccessibleHandler/orderedWinEventLimiter.py +++ b/source/IAccessibleHandler/orderedWinEventLimiter.py @@ -107,11 +107,11 @@ def flushEvents(self): self._eventHeap = [] r = [] for count in range(len(e)): - event = heapq.heappop(e)[1:-1] + event = heapq.heappop(e)[1:] if isMSAADebugLoggingEnabled(): - eventID, window, objectID, childID = event + eventID, window, objectID, childID, threadID = event log.debug( - f"Emitting winEvent {getWinEventLogInfo(window, objectID, childID, eventID)}" + f"Emitting winEvent {getWinEventLogInfo(window, objectID, childID, eventID, threadID)}" ) - r.append(event) + r.append(event[:-1]) return r From e3ffb3b0e85c62861c3ddcf7484eddd8e9fa346d Mon Sep 17 00:00:00 2001 From: Michael Curran Date: Tue, 1 Sep 2020 12:45:09 +1000 Subject: [PATCH 08/10] Added yet more MSAA debug log messages. --- source/IAccessibleHandler/__init__.py | 74 +++++++++++++++++-- .../internalWinEventHandler.py | 40 ++++++++-- 2 files changed, 101 insertions(+), 13 deletions(-) diff --git a/source/IAccessibleHandler/__init__.py b/source/IAccessibleHandler/__init__.py index 8f79e49000f..583482b1d49 100644 --- a/source/IAccessibleHandler/__init__.py +++ b/source/IAccessibleHandler/__init__.py @@ -150,12 +150,13 @@ def getWinEventLogInfo(window, objectID, childID, eventID=None, threadID=None): messageList.append(f"{eventName}") messageList.append( f"window {window} ({windowClassName}), objectID {objectIDName}, childID {childID}, " - f"from process {processID} ({processName})" + f"process {processID} ({processName})" ) if threadID is not None: messageList.append(f"thread {threadID}") return ", ".join(messageList) + def isMSAADebugLoggingEnabled(): """ Whether the user has configured NVDA to log extra information about MSAA events. """ return config.conf["debugLog"]["MSAA"] @@ -598,17 +599,23 @@ def winEventToNVDAEvent(eventID, window, objectID, childID, useCache=True): # Ignore any events with invalid window handles if not window or not winUser.isWindow(window): if isMSAADebugLoggingEnabled(): - log.debug("Dropping winEvent for invalid window") + 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): if isMSAADebugLoggingEnabled(): - log.debug("Dropping winEvent for ghosted hung window") + 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"Dropping winEvent for native UIA window {window} ({winUser.getClassName(window)})") + log.debug( + f"Native UIA window. Dropping winEvent {getWinEventLogInfo(window, objectID, childID, eventID)}" + ) return None obj = None if useCache: @@ -616,8 +623,8 @@ def winEventToNVDAEvent(eventID, window, objectID, childID, useCache=True): obj = liveNVDAObjectTable.get((window, objectID, childID), None) if isMSAADebugLoggingEnabled() and obj: log.debug( - "Fetched existing NVDAObject for winEvent from liveNVDAObjectTable: " - f"{getWinEventLogInfo(window, objectID, childID)}" + 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: @@ -637,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} " + f"from winEvent {getWinEventLogInfo(window, objectID, childID, eventID)}" + ) return (NVDAEventName, obj) @@ -681,7 +693,9 @@ def processGenericWinEvent(eventID, window, objectID, childID): return if NVDAEvent[1] == focus: if isMSAADebugLoggingEnabled(): - log.debug("Directing winEvent to focus object") + log.debug( + f"Directing winEvent to focus object {focus}. WinEvent {getWinEventLogInfo(window, objectID, childID)}" + ) NVDAEvent = (NVDAEvent[0], focus) eventHandler.queueEvent(*NVDAEvent) return True @@ -715,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]) @@ -725,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 @@ -767,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 @@ -835,6 +862,11 @@ def processForegroundWinEvent(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 @@ -843,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 ( @@ -851,16 +888,31 @@ 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 @@ -944,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()) @@ -954,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) diff --git a/source/IAccessibleHandler/internalWinEventHandler.py b/source/IAccessibleHandler/internalWinEventHandler.py index 498c112434c..95168700b39 100644 --- a/source/IAccessibleHandler/internalWinEventHandler.py +++ b/source/IAccessibleHandler/internalWinEventHandler.py @@ -79,9 +79,19 @@ def winEventCallback(handle, eventID, window, objectID, childID, threadID, times try: # Ignore all object IDs from alert onwards (sound, nativeom etc) as we don't support them if objectID <= winUser.OBJID_ALERT: + if isMSAADebugLoggingEnabled(): + log.debug( + f"objectID not supported. " + f"Dropping winEvent {getWinEventLogInfo(window, objectID, childID, eventID, threadID)}" + ) return # Ignore all locationChange events except ones for the caret if eventID == winUser.EVENT_OBJECT_LOCATIONCHANGE and objectID != winUser.OBJID_CARET: + if isMSAADebugLoggingEnabled(): + log.debug( + f"locationChange for something other than the caret. " + f"Dropping winEvent {getWinEventLogInfo(window, objectID, childID, eventID, threadID)}" + ) return if eventID == winUser.EVENT_OBJECT_DESTROY: _processDestroyWinEvent(window, objectID, childID) @@ -90,7 +100,10 @@ def winEventCallback(handle, eventID, window, objectID, childID, threadID, times if (objectID == 0) and (childID == 0): objectID = winUser.OBJID_CLIENT if isMSAADebugLoggingEnabled(): - log.debug(f"Changing OBJID_WINDOW to OBJID_CLIENT for winEvent: {getWinEventLogInfo(window, objectID, childID, eventID, threadID)}") + log.debug( + f"Changing OBJID_WINDOW to OBJID_CLIENT " + f"for winEvent: {getWinEventLogInfo(window, objectID, childID, eventID, threadID)}" + ) # Ignore events with invalid window handles isWindow = winUser.isWindow(window) if window else 0 if window == 0 or ( @@ -102,11 +115,17 @@ def winEventCallback(handle, eventID, window, objectID, childID, threadID, times ) ): if isMSAADebugLoggingEnabled(): - log.debug(f"Changing NULL or invalid window to desktop window for winEvent: {getWinEventLogInfo(window, objectID, childID, eventID, threadID)}") + log.debug( + f"Changing NULL or invalid window to desktop window " + f"for winEvent: {getWinEventLogInfo(window, objectID, childID, eventID, threadID)}" + ) window = winUser.getDesktopWindow() elif not isWindow: if isMSAADebugLoggingEnabled(): - log.debug(f"Invalid window. Dropping winEvent: {getWinEventLogInfo(window, objectID, childID, eventID, threadID)}") + log.debug( + f"Invalid window. " + f"Dropping winEvent: {getWinEventLogInfo(window, objectID, childID, eventID, threadID)}" + ) return windowClassName = winUser.getClassName(window) @@ -118,13 +137,19 @@ def winEventCallback(handle, eventID, window, objectID, childID, threadID, times # and can't be used properly in conjunction with input composition support. if windowClassName == "Microsoft.IME.UIManager.CandidateWindow.Host" and eventID in MENU_EVENTIDS: if isMSAADebugLoggingEnabled(): - log.debug(f"Dropping menu event for IME window. WinEvent: {getWinEventLogInfo(window, objectID, childID, eventID, threadID)}") + log.debug( + f"Dropping menu event for IME window. " + f"WinEvent: {getWinEventLogInfo(window, objectID, childID, eventID, threadID)}" + ) return if eventID == winUser.EVENT_SYSTEM_FOREGROUND: # We never want to see foreground events for the Program Manager or Shell (task bar) if windowClassName in ("Progman", "Shell_TrayWnd"): if isMSAADebugLoggingEnabled(): - log.debug(f"Progman or shell_trayWnd window. Dropping winEvent: {getWinEventLogInfo(window, objectID, childID, eventID, threadID)}") + log.debug( + f"Progman or shell_trayWnd window. " + f"Dropping winEvent: {getWinEventLogInfo(window, objectID, childID, eventID, threadID)}" + ) return # #3831: Event handling can be deferred if Windows takes a while to change the foreground window. # See pumpAll for details. @@ -132,7 +157,10 @@ def winEventCallback(handle, eventID, window, objectID, childID, threadID, times _deferUntilForegroundWindow = window _foregroundDefers = 0 if isMSAADebugLoggingEnabled(): - log.debug(f"Recording foreground defer for WinEvent: {getWinEventLogInfo(window, objectID, childID, eventID, threadID)}") + log.debug( + f"Recording foreground defer " + f"for WinEvent: {getWinEventLogInfo(window, objectID, childID, eventID, threadID)}" + ) 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 From 70e83cb978a5c1f83950a06c489d8a6538c6be8b Mon Sep 17 00:00:00 2001 From: Michael Curran Date: Wed, 2 Sep 2020 08:58:36 +1000 Subject: [PATCH 09/10] Fix typo --- source/IAccessibleHandler/__init__.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/source/IAccessibleHandler/__init__.py b/source/IAccessibleHandler/__init__.py index 583482b1d49..65a8f98f9c4 100644 --- a/source/IAccessibleHandler/__init__.py +++ b/source/IAccessibleHandler/__init__.py @@ -646,7 +646,7 @@ def winEventToNVDAEvent(eventID, window, objectID, childID, useCache=True): obj = SDMChild if isMSAADebugLoggingEnabled(): log.debug( - f"Successfully created NvDA event {NVDAEventName} for {obj} " + f"Successfully created NVDA event {NVDAEventName} for {obj} " f"from winEvent {getWinEventLogInfo(window, objectID, childID, eventID)}" ) return (NVDAEventName, obj) From 8f1825dc3f4600d62ad602eeae583132628c87cc Mon Sep 17 00:00:00 2001 From: Michael Curran Date: Wed, 2 Sep 2020 09:01:07 +1000 Subject: [PATCH 10/10] Update what's new --- user_docs/en/changes.t2t | 1 + 1 file changed, 1 insertion(+) diff --git a/user_docs/en/changes.t2t b/user_docs/en/changes.t2t index e659e5659c5..ff4809bf01c 100644 --- a/user_docs/en/changes.t2t +++ b/user_docs/en/changes.t2t @@ -61,6 +61,7 @@ What's New in NVDA - NVDA-specific objects that are found by Python's cyclic garbage collector are now logged when being deleted by the collector to aide in removing reference cycles from NVDA. (#11499) - The majority of NVDA's classes are tracked including NVDAObjects, appModules, GlobalPlugins, SynthDrivers, and TreeInterceptors. - A class that needs to be tracked should inherit from garbageHandler.TrackedObject. +- Significant debug logging for MSAA events can be now enabled in NVDA's Advanced settings. (#11521) = 2020.2 =