Skip to content

Commit 825960d

Browse files
michaelDCurranmichaelDCurran
authored
Merge 8117303 into 9a4074b 
2 parents 9a4074b + 8117303 commit 825960d

5 files changed

Lines changed: 182 additions & 9 deletions

File tree

‎source/IAccessibleHandler/__init__.py‎

Lines changed: 126 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -99,6 +99,67 @@
9999
IA2_ROLE_FOOTER,
100100
IA2_ROLE_MARK,
101101
)
102+
import config
103+
104+
105+
_winEventNameCache = {}
106+
107+
108+
def getWinEventName(eventID):
109+
""" Looks up the name of an EVENT_* winEvent constant. """
110+
global _winEventNameCache
111+
if not _winEventNameCache:
112+
_winEventNameCache = {y: x for x, y in vars(winUser).items() if x.startswith('EVENT_')}
113+
_winEventNameCache.update({y: x for x, y in vars(IA2).items() if x.startswith('IA2_EVENT_')})
114+
name = _winEventNameCache.get(eventID)
115+
if not name:
116+
name = "unknown event ({eventID})"
117+
return name
118+
119+
120+
_objectIDNameCache = {}
121+
122+
123+
def getObjectIDName(objectID):
124+
""" Looks up the name of an OBJID_* winEvent constant. """
125+
global _objectIDNameCache
126+
if not _objectIDNameCache:
127+
_objectIDNameCache = {y: x for x, y in vars(winUser).items() if x.startswith('OBJID_')}
128+
name = _objectIDNameCache.get(objectID)
129+
if not name:
130+
name = str(objectID)
131+
return name
132+
133+
134+
def getWinEventLogInfo(window, objectID, childID, eventID=None, threadID=None):
135+
"""
136+
Formats the given winEvent parameters into a printable string.
137+
window, objectID and childID are mandatory,
138+
but eventID and threadID are optional.
139+
"""
140+
windowClassName = winUser.getClassName(window) or "unknown"
141+
objectIDName = getObjectIDName(objectID)
142+
processID = winUser.getWindowThreadProcessID(window)[0]
143+
if processID:
144+
processName = appModuleHandler.getAppModuleFromProcessID(processID).appName
145+
else:
146+
processName = "unknown application"
147+
messageList = []
148+
if eventID is not None:
149+
eventName = getWinEventName(eventID)
150+
messageList.append(f"{eventName}")
151+
messageList.append(
152+
f"window {window} ({windowClassName}), objectID {objectIDName}, childID {childID}, "
153+
f"from process {processID} ({processName})"
154+
)
155+
if threadID is not None:
156+
messageList.append(f"thread {threadID}")
157+
return ", ".join(messageList)
158+
159+
def isMSAADebugLoggingEnabled():
160+
""" Whether the user has configured NVDA to log extra information about MSAA events. """
161+
return config.conf["debugLog"]["MSAA"]
162+
102163

103164
from . import internalWinEventHandler
104165
# Imported for backwards compat
@@ -344,10 +405,11 @@ def accessibleObjectFromEvent(window, objectID, childID):
344405
try:
345406
pacc, childID = oleacc.AccessibleObjectFromEvent(window, objectID, childID)
346407
except Exception as e:
347-
log.debug(
348-
f"oleacc.AccessibleObjectFromEvent with"
349-
f" window {window}, objectID {objectID} and childID {childID}: {e}"
350-
)
408+
if isMSAADebugLoggingEnabled():
409+
log.debugWarning(
410+
f"oleacc.AccessibleObjectFromEvent failed with {e}."
411+
f" WinEvent: {getWinEventLogInfo(window, objectID, childID)}"
412+
)
351413
return None
352414
return normalizeIAccessible(pacc, childID), childID
353415

@@ -522,27 +584,51 @@ def winEventToNVDAEvent(eventID, window, objectID, childID, useCache=True):
522584
@returns: the NVDA event name and the NVDAObject the event is for
523585
@rtype: tuple of string and L{NVDAObjects.IAccessible.IAccessible}
524586
"""
587+
if isMSAADebugLoggingEnabled():
588+
log.debug(
589+
f"Creating NVDA event from winEvent: {getWinEventLogInfo(window, objectID, childID, eventID)}, "
590+
f"use cache {useCache}"
591+
)
525592
NVDAEventName = winEventIDsToNVDAEventNames.get(eventID, None)
526593
if not NVDAEventName:
594+
log.debugWarning(f"No NVDA event name for {getWinEventName(eventID)}")
527595
return None
596+
if isMSAADebugLoggingEnabled():
597+
log.debug(f"winEvent mapped to NVDA event: {NVDAEventName}")
528598
# Ignore any events with invalid window handles
529599
if not window or not winUser.isWindow(window):
600+
if isMSAADebugLoggingEnabled():
601+
log.debug("Dropping winEvent for invalid window")
530602
return None
531603
# Make sure this window does not have a ghost window if possible
532604
if NVDAObjects.window.GhostWindowFromHungWindow and NVDAObjects.window.GhostWindowFromHungWindow(window):
605+
if isMSAADebugLoggingEnabled():
606+
log.debug("Dropping winEvent for ghosted hung window")
533607
return None
534608
# We do not support MSAA object proxied from native UIA
535609
if UIAHandler.handler and UIAHandler.handler.isUIAWindow(window):
610+
if isMSAADebugLoggingEnabled():
611+
log.debug(f"Dropping winEvent for native UIA window {window} ({winUser.getClassName(window)})")
536612
return None
537613
obj = None
538614
if useCache:
539615
# See if we already know an object by this win event info
540616
obj = liveNVDAObjectTable.get((window, objectID, childID), None)
617+
if isMSAADebugLoggingEnabled() and obj:
618+
log.debug(
619+
"Fetched existing NVDAObject for winEvent from liveNVDAObjectTable: "
620+
f"{getWinEventLogInfo(window, objectID, childID)}"
621+
)
541622
# If we don't yet have the object, then actually instanciate it.
542623
if not obj:
543624
obj = NVDAObjects.IAccessible.getNVDAObjectFromEvent(window, objectID, childID)
544625
# At this point if we don't have an object then we can't do any more
545626
if not obj:
627+
if isMSAADebugLoggingEnabled():
628+
log.debug(
629+
"Could not instantiate an NVDAObject for winEvent: "
630+
f"{getWinEventLogInfo(window, objectID, childID, eventID)}"
631+
)
546632
return None
547633
# SDM MSAA objects sometimes don't contain enough information to be useful Sometimes there is a real
548634
# window that does, so try to get the SDMChild property on the NVDAObject, and if successull use that as
@@ -569,6 +655,10 @@ def processGenericWinEvent(eventID, window, objectID, childID):
569655
@returns: True if the event was processed, False otherwise.
570656
@rtype: boolean
571657
"""
658+
if isMSAADebugLoggingEnabled():
659+
log.debug(
660+
f"Processing generic winEvent: {getWinEventLogInfo(window, objectID, childID, eventID)}"
661+
)
572662
# Notify appModuleHandler of this new window
573663
appModuleHandler.update(winUser.getWindowThreadProcessID(window)[0])
574664
# Handle particular events for the special MSAA caret object just as if they were for the focus object
@@ -577,15 +667,21 @@ def processGenericWinEvent(eventID, window, objectID, childID):
577667
winUser.EVENT_OBJECT_LOCATIONCHANGE,
578668
winUser.EVENT_OBJECT_SHOW
579669
):
670+
if isMSAADebugLoggingEnabled():
671+
log.debug("handling winEvent as caret event on focus")
580672
NVDAEvent = ("caret", focus)
581673
else:
582674
NVDAEvent = winEventToNVDAEvent(eventID, window, objectID, childID)
583675
if not NVDAEvent:
584676
return False
585677
if NVDAEvent[0] == "nameChange" and objectID == winUser.OBJID_CURSOR:
678+
if isMSAADebugLoggingEnabled():
679+
log.debug("Handling winEvent as mouse shape change")
586680
mouseHandler.updateMouseShape(NVDAEvent[1].name)
587681
return
588682
if NVDAEvent[1] == focus:
683+
if isMSAADebugLoggingEnabled():
684+
log.debug("Directing winEvent to focus object")
589685
NVDAEvent = (NVDAEvent[0], focus)
590686
eventHandler.queueEvent(*NVDAEvent)
591687
return True
@@ -605,6 +701,11 @@ def processFocusWinEvent(window, objectID, childID, force=False):
605701
@returns: True if the focus is valid and was handled, False otherwise.
606702
@rtype: boolean
607703
"""
704+
if isMSAADebugLoggingEnabled():
705+
log.debug(
706+
f"Processing focus winEvent: {getWinEventLogInfo(window, objectID, childID)}, "
707+
f"force {force}"
708+
)
608709
windowClassName = winUser.getClassName(window)
609710
# Generally, we must ignore focus on child windows of SDM windows as we only want the SDM MSAA events.
610711
# However, we don't want to ignore focus if the child ID isn't 0,
@@ -693,6 +794,10 @@ def event_gainFocus(self):
693794

694795

695796
def processDesktopSwitchWinEvent(window, objectID, childID):
797+
if isMSAADebugLoggingEnabled():
798+
log.debug(
799+
f"Processing desktopSwitch winEvent: {getWinEventLogInfo(window, objectID, childID)}"
800+
)
696801
hDesk = windll.user32.OpenInputDesktop(0, False, 0)
697802
if hDesk != 0:
698803
windll.user32.CloseDesktop(hDesk)
@@ -724,6 +829,10 @@ def processForegroundWinEvent(window, objectID, childID):
724829
@returns: True if the foreground was processed, False otherwise.
725830
@rtype: boolean
726831
"""
832+
if isMSAADebugLoggingEnabled():
833+
log.debug(
834+
f"Processing foreground winEvent: {getWinEventLogInfo(window, objectID, childID)}"
835+
)
727836
# Ignore foreground events on windows that aren't the current foreground window
728837
if window != winUser.getForegroundWindow():
729838
return False
@@ -758,6 +867,10 @@ def processForegroundWinEvent(window, objectID, childID):
758867

759868

760869
def processShowWinEvent(window, objectID, childID):
870+
if isMSAADebugLoggingEnabled():
871+
log.debug(
872+
f"Processing show winEvent: {getWinEventLogInfo(window, objectID, childID)}"
873+
)
761874
# eventHandler.shouldAcceptEvent only accepts show events for a few specific cases.
762875
# Narrow this further to only accept events for clients or custom objects.
763876
if objectID == winUser.OBJID_CLIENT or objectID > 0:
@@ -771,6 +884,10 @@ def processDestroyWinEvent(window, objectID, childID):
771884
This removes the object associated with the event parameters from L{liveNVDAObjectTable} if
772885
such an object exists.
773886
"""
887+
if isMSAADebugLoggingEnabled():
888+
log.debug(
889+
f"Processing destroy winEvent: {getWinEventLogInfo(window, objectID, childID)}"
890+
)
774891
try:
775892
del liveNVDAObjectTable[(window, objectID, childID)]
776893
except KeyError:
@@ -796,6 +913,11 @@ def processMenuStartWinEvent(eventID, window, objectID, childID, validFocus):
796913
"""Process a menuStart win event.
797914
@postcondition: Focus will be directed to the menu if appropriate.
798915
"""
916+
if isMSAADebugLoggingEnabled():
917+
log.debug(
918+
f"Processing menuStart winEvent: {getWinEventLogInfo(window, objectID, childID)}, "
919+
f"validFocus {validFocus}"
920+
)
799921
if validFocus:
800922
lastFocus = eventHandler.lastQueuedFocusObject
801923
if (

‎source/IAccessibleHandler/internalWinEventHandler.py‎

Lines changed: 40 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -13,6 +13,9 @@
1313

1414
import core
1515
import winUser
16+
from . import getWinEventLogInfo
17+
from . import isMSAADebugLoggingEnabled
18+
1619

1720
from comInterfaces.IAccessible2Lib import (
1821
IA2_EVENT_TEXT_CARET_MOVED,
@@ -69,6 +72,10 @@
6972

7073
# C901: winEventCallback is too complex
7174
def winEventCallback(handle, eventID, window, objectID, childID, threadID, timestamp): # noqa: C901
75+
if isMSAADebugLoggingEnabled():
76+
log.debug(
77+
f"Hook received winEvent: {getWinEventLogInfo(window, objectID, childID, eventID, threadID)}"
78+
)
7279
try:
7380
# Ignore all object IDs from alert onwards (sound, nativeom etc) as we don't support them
7481
if objectID <= winUser.OBJID_ALERT:
@@ -82,6 +89,8 @@ def winEventCallback(handle, eventID, window, objectID, childID, threadID, times
8289
# Change window objIDs to client objIDs for better reporting of objects
8390
if (objectID == 0) and (childID == 0):
8491
objectID = winUser.OBJID_CLIENT
92+
if isMSAADebugLoggingEnabled():
93+
log.debug(f"Changing OBJID_WINDOW to OBJID_CLIENT for winEvent: {getWinEventLogInfo(window, objectID, childID, eventID, threadID)}")
8594
# Ignore events with invalid window handles
8695
isWindow = winUser.isWindow(window) if window else 0
8796
if window == 0 or (
@@ -92,8 +101,12 @@ def winEventCallback(handle, eventID, window, objectID, childID, threadID, times
92101
winUser.EVENT_SYSTEM_MENUPOPUPEND,
93102
)
94103
):
104+
if isMSAADebugLoggingEnabled():
105+
log.debug(f"Changing NULL or invalid window to desktop window for winEvent: {getWinEventLogInfo(window, objectID, childID, eventID, threadID)}")
95106
window = winUser.getDesktopWindow()
96107
elif not isWindow:
108+
if isMSAADebugLoggingEnabled():
109+
log.debug(f"Invalid window. Dropping winEvent: {getWinEventLogInfo(window, objectID, childID, eventID, threadID)}")
97110
return
98111

99112
windowClassName = winUser.getClassName(window)
@@ -104,24 +117,34 @@ def winEventCallback(handle, eventID, window, objectID, childID, threadID, times
104117
# Modern IME candidate list windows fire menu events which confuse us
105118
# and can't be used properly in conjunction with input composition support.
106119
if windowClassName == "Microsoft.IME.UIManager.CandidateWindow.Host" and eventID in MENU_EVENTIDS:
120+
if isMSAADebugLoggingEnabled():
121+
log.debug(f"Dropping menu event for IME window. WinEvent: {getWinEventLogInfo(window, objectID, childID, eventID, threadID)}")
107122
return
108123
if eventID == winUser.EVENT_SYSTEM_FOREGROUND:
109124
# We never want to see foreground events for the Program Manager or Shell (task bar)
110125
if windowClassName in ("Progman", "Shell_TrayWnd"):
126+
if isMSAADebugLoggingEnabled():
127+
log.debug(f"Progman or shell_trayWnd window. Dropping winEvent: {getWinEventLogInfo(window, objectID, childID, eventID, threadID)}")
111128
return
112129
# #3831: Event handling can be deferred if Windows takes a while to change the foreground window.
113130
# See pumpAll for details.
114131
global _deferUntilForegroundWindow, _foregroundDefers
115132
_deferUntilForegroundWindow = window
116133
_foregroundDefers = 0
134+
if isMSAADebugLoggingEnabled():
135+
log.debug(f"Recording foreground defer for WinEvent: {getWinEventLogInfo(window, objectID, childID, eventID, threadID)}")
117136
if windowClassName == "MSNHiddenWindowClass":
118137
# HACK: Events get fired by this window in Windows Live Messenger 2009 when it starts. If we send a
119138
# WM_NULL to this window at this point (which happens in accessibleObjectFromEvent), Messenger will
120139
# silently exit (#677). Therefore, completely ignore these events, which is useless to us anyway.
121140
return
141+
if isMSAADebugLoggingEnabled():
142+
log.debug(
143+
f"Adding winEvent to limiter: {getWinEventLogInfo(window, objectID, childID, eventID, threadID)}"
144+
)
122145
if winEventLimiter.addEvent(eventID, window, objectID, childID, threadID):
123146
core.requestPump()
124-
except: # noqa: E722 Bare except
147+
except Exception:
125148
log.error("winEventCallback", exc_info=True)
126149

127150

@@ -162,18 +185,33 @@ def _shouldGetEvents():
162185
if _deferUntilForegroundWindow:
163186
# #3831: Sometimes, a foreground event is fired,
164187
# but GetForegroundWindow() takes a short while to return this new foreground.
188+
curForegroundWindow = winUser.getForegroundWindow()
189+
curForegroundClassName = winUser.getClassName(curForegroundWindow)
190+
futureForegroundClassName = winUser.getClassName(_deferUntilForegroundWindow)
165191
if (
166192
_foregroundDefers < MAX_FOREGROUND_DEFERS
167-
and winUser.getForegroundWindow() != _deferUntilForegroundWindow
193+
and curForegroundWindow != _deferUntilForegroundWindow
168194
):
169195
# Wait a core cycle before handling events to give the foreground window time to update.
170196
core.requestPump()
171197
_foregroundDefers += 1
198+
if isMSAADebugLoggingEnabled():
199+
log.debugWarning(
200+
f"Foreground still {curForegroundWindow} ({curForegroundClassName}). "
201+
f"Deferring until foreground is {_deferUntilForegroundWindow} ({futureForegroundClassName}), "
202+
f"defer count {_foregroundDefers}"
203+
)
172204
return False
173205
else:
174206
# Either the foreground window is now correct
175207
# or we've already had the maximum number of defers.
176208
# (Sometimes, foreground events are fired even when the foreground hasn't actually changed.)
209+
if curForegroundWindow != _deferUntilForegroundWindow:
210+
log.debugWarning(
211+
"Foreground took too long to change. "
212+
f"Foreground still {curForegroundWindow} ({curForegroundClassName}). "
213+
f"Should be {_deferUntilForegroundWindow} ({futureForegroundClassName})"
214+
)
177215
_deferUntilForegroundWindow = None
178216
return True
179217

‎source/IAccessibleHandler/orderedWinEventLimiter.py‎

Lines changed: 14 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -2,6 +2,9 @@
22
import itertools
33

44
import winUser
5+
from logHandler import log
6+
from . import isMSAADebugLoggingEnabled, getWinEventLogInfo
7+
58

69
MAX_WINEVENTS_PER_THREAD = 10
710

@@ -89,10 +92,13 @@ def flushEvents(self):
8992
threadCounters = {}
9093
for k, v in sorted(g.items(), key=lambda item: item[1], reverse=True):
9194
threadCount = threadCounters.get(k[-1], 0)
95+
threadCounters[k[-1]] = threadCount + 1
9296
if threadCount > MAX_WINEVENTS_PER_THREAD:
97+
if isMSAADebugLoggingEnabled():
98+
if threadCount == (MAX_WINEVENTS_PER_THREAD + 1):
99+
log.debug(f"winEvent limit for thread {k[-1]} hit for this core cycle")
93100
continue
94101
heapq.heappush(self._eventHeap, (v,) + k)
95-
threadCounters[k[-1]] = threadCount + 1
96102
f = self._focusEventCache
97103
self._focusEventCache = {}
98104
for k, v in sorted(f.items(), key=lambda item: item[1])[0 - self.maxFocusItems:]:
@@ -101,6 +107,11 @@ def flushEvents(self):
101107
self._eventHeap = []
102108
r = []
103109
for count in range(len(e)):
104-
event = heapq.heappop(e)[1:-1]
105-
r.append(event)
110+
event = heapq.heappop(e)[1:]
111+
if isMSAADebugLoggingEnabled():
112+
eventID, window, objectID, childID, threadID = event
113+
log.debug(
114+
f"Emitting winEvent {getWinEventLogInfo(window, objectID, childID, eventID, threadID)}"
115+
)
116+
r.append(event[:-1])
106117
return r

‎source/config/configSpec.py‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -235,6 +235,7 @@
235235
236236
[debugLog]
237237
hwIo = boolean(default=false)
238+
MSAA = boolean(default=false)
238239
UIA = boolean(default=false)
239240
audioDucking = boolean(default=false)
240241
gui = boolean(default=false)

0 commit comments

Comments
 (0)