Add significant optional debug logging for MSAA events

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 mandatory,
+	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,51 @@ 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(f"Dropping winEvent for native UIA window {window} ({winUser.getClassName(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: "
+				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(
+				"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
@@ -569,6 +644,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 +656,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 +690,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 +783,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 +818,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 +856,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 +873,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 +902,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 (

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
 

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

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)

source/gui/settingsDialogs.py

@@ -2447,6 +2447,7 @@ def __init__(self, parent):
 
 		self.logCategories=[
 			"hwIo",
+			"MSAA",
 			"UIA",
 			"audioDucking",
 			"gui",