Skip to content

Commit 77d1f7b

Browse files
michaelDCurranmichaelDCurran
authored
Merge 13f6514 into 9a4074b 
2 parents 9a4074b + 13f6514 commit 77d1f7b

5 files changed

Lines changed: 155 additions & 3 deletions

File tree

‎source/IAccessibleHandler/__init__.py‎

Lines changed: 105 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -99,6 +99,57 @@
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):
135+
"""
136+
Formats the given winEvent parameters into a printable string.
137+
window, objectID and childID are mandatory,
138+
but eventID is optional.
139+
"""
140+
windowClassName = winUser.getClassName(window)
141+
objectIDName = getObjectIDName(objectID)
142+
if eventID is not None:
143+
eventName = getWinEventName(eventID)
144+
return f"{eventName} for window {window} ({windowClassName}), objectID {objectIDName} and childID {childID}"
145+
else:
146+
return f"window {window} ({windowClassName}), objectID {objectIDName} and childID {childID}"
147+
148+
149+
def isMSAADebugLoggingEnabled():
150+
""" Whether the user has configured NVDA to log extra information about MSAA events. """
151+
return config.conf["debugLog"]["MSAA"]
152+
102153

103154
from . import internalWinEventHandler
104155
# Imported for backwards compat
@@ -522,27 +573,45 @@ def winEventToNVDAEvent(eventID, window, objectID, childID, useCache=True):
522573
@returns: the NVDA event name and the NVDAObject the event is for
523574
@rtype: tuple of string and L{NVDAObjects.IAccessible.IAccessible}
524575
"""
576+
if isMSAADebugLoggingEnabled():
577+
log.debug(
578+
f"Creating NVDA event from winEvent: {getWinEventLogInfo(window, objectID, childID, eventID)}, "
579+
f"use cache {useCache}"
580+
)
525581
NVDAEventName = winEventIDsToNVDAEventNames.get(eventID, None)
526582
if not NVDAEventName:
583+
log.debugWarning(f"No NVDA event name for {getWinEventName(eventID)}")
527584
return None
585+
if isMSAADebugLoggingEnabled():
586+
log.debug(f"winEvent mapped to NVDA event: {NVDAEventName}")
528587
# Ignore any events with invalid window handles
529588
if not window or not winUser.isWindow(window):
589+
if isMSAADebugLoggingEnabled():
590+
log.debug("Dropping winEvent for invalid window")
530591
return None
531592
# Make sure this window does not have a ghost window if possible
532593
if NVDAObjects.window.GhostWindowFromHungWindow and NVDAObjects.window.GhostWindowFromHungWindow(window):
594+
if isMSAADebugLoggingEnabled():
595+
log.debug("Dropping winEvent for ghosted hung window")
533596
return None
534597
# We do not support MSAA object proxied from native UIA
535598
if UIAHandler.handler and UIAHandler.handler.isUIAWindow(window):
599+
if isMSAADebugLoggingEnabled():
600+
log.debug(f"Dropping winEvent for native UIA window {window} ({winUser.getClassName(window)})")
536601
return None
537602
obj = None
538603
if useCache:
539604
# See if we already know an object by this win event info
540605
obj = liveNVDAObjectTable.get((window, objectID, childID), None)
606+
if isMSAADebugLoggingEnabled() and obj:
607+
log.debug(f"Fetched existing NVDAObject for winEvent from liveNVDAObjectTable: {getWinEventLogInfo(window, objectID, childID)}")
541608
# If we don't yet have the object, then actually instanciate it.
542609
if not obj:
543610
obj = NVDAObjects.IAccessible.getNVDAObjectFromEvent(window, objectID, childID)
544611
# At this point if we don't have an object then we can't do any more
545612
if not obj:
613+
if isMSAADebugLoggingEnabled():
614+
log.debug(f"Could not instantiate an NVDAObject for winEvent: {getWinEventLogInfo(window, objectID, childID, eventID)}")
546615
return None
547616
# SDM MSAA objects sometimes don't contain enough information to be useful Sometimes there is a real
548617
# 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):
569638
@returns: True if the event was processed, False otherwise.
570639
@rtype: boolean
571640
"""
641+
if isMSAADebugLoggingEnabled():
642+
log.debug(
643+
f"Processing generic winEvent: {getWinEventLogInfo(window, objectID, childID, eventID)}"
644+
)
572645
# Notify appModuleHandler of this new window
573646
appModuleHandler.update(winUser.getWindowThreadProcessID(window)[0])
574647
# 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):
577650
winUser.EVENT_OBJECT_LOCATIONCHANGE,
578651
winUser.EVENT_OBJECT_SHOW
579652
):
653+
if isMSAADebugLoggingEnabled():
654+
log.debug("handling winEvent as caret event on focus")
580655
NVDAEvent = ("caret", focus)
581656
else:
582657
NVDAEvent = winEventToNVDAEvent(eventID, window, objectID, childID)
583658
if not NVDAEvent:
584659
return False
585660
if NVDAEvent[0] == "nameChange" and objectID == winUser.OBJID_CURSOR:
661+
if isMSAADebugLoggingEnabled():
662+
log.debug("Handling winEvent as mouse shape change")
586663
mouseHandler.updateMouseShape(NVDAEvent[1].name)
587664
return
588665
if NVDAEvent[1] == focus:
666+
if isMSAADebugLoggingEnabled():
667+
log.debug("Directing winEvent to focus object")
589668
NVDAEvent = (NVDAEvent[0], focus)
590669
eventHandler.queueEvent(*NVDAEvent)
591670
return True
@@ -605,6 +684,11 @@ def processFocusWinEvent(window, objectID, childID, force=False):
605684
@returns: True if the focus is valid and was handled, False otherwise.
606685
@rtype: boolean
607686
"""
687+
if isMSAADebugLoggingEnabled():
688+
log.debug(
689+
f"Processing focus winEvent: {getWinEventLogInfo(window, objectID, childID)}, "
690+
f"force {force}"
691+
)
608692
windowClassName = winUser.getClassName(window)
609693
# Generally, we must ignore focus on child windows of SDM windows as we only want the SDM MSAA events.
610694
# However, we don't want to ignore focus if the child ID isn't 0,
@@ -693,6 +777,10 @@ def event_gainFocus(self):
693777

694778

695779
def processDesktopSwitchWinEvent(window, objectID, childID):
780+
if isMSAADebugLoggingEnabled():
781+
log.debug(
782+
f"Processing desktopSwitch winEvent: {getWinEventLogInfo(window, objectID, childID)}"
783+
)
696784
hDesk = windll.user32.OpenInputDesktop(0, False, 0)
697785
if hDesk != 0:
698786
windll.user32.CloseDesktop(hDesk)
@@ -724,6 +812,10 @@ def processForegroundWinEvent(window, objectID, childID):
724812
@returns: True if the foreground was processed, False otherwise.
725813
@rtype: boolean
726814
"""
815+
if isMSAADebugLoggingEnabled():
816+
log.debug(
817+
f"Processing foreground winEvent: {getWinEventLogInfo(window, objectID, childID)}"
818+
)
727819
# Ignore foreground events on windows that aren't the current foreground window
728820
if window != winUser.getForegroundWindow():
729821
return False
@@ -758,6 +850,10 @@ def processForegroundWinEvent(window, objectID, childID):
758850

759851

760852
def processShowWinEvent(window, objectID, childID):
853+
if isMSAADebugLoggingEnabled():
854+
log.debug(
855+
f"Processing show winEvent: {getWinEventLogInfo(window, objectID, childID)}"
856+
)
761857
# eventHandler.shouldAcceptEvent only accepts show events for a few specific cases.
762858
# Narrow this further to only accept events for clients or custom objects.
763859
if objectID == winUser.OBJID_CLIENT or objectID > 0:
@@ -771,6 +867,10 @@ def processDestroyWinEvent(window, objectID, childID):
771867
This removes the object associated with the event parameters from L{liveNVDAObjectTable} if
772868
such an object exists.
773869
"""
870+
if isMSAADebugLoggingEnabled():
871+
log.debug(
872+
f"Processing destroy winEvent: {getWinEventLogInfo(window, objectID, childID)}"
873+
)
774874
try:
775875
del liveNVDAObjectTable[(window, objectID, childID)]
776876
except KeyError:
@@ -796,6 +896,11 @@ def processMenuStartWinEvent(eventID, window, objectID, childID, validFocus):
796896
"""Process a menuStart win event.
797897
@postcondition: Focus will be directed to the menu if appropriate.
798898
"""
899+
if isMSAADebugLoggingEnabled():
900+
log.debug(
901+
f"Processing menuStart winEvent: {getWinEventLogInfo(window, objectID, childID)}, "
902+
f"validFocus {validFocus}"
903+
)
799904
if validFocus:
800905
lastFocus = eventHandler.lastQueuedFocusObject
801906
if (

‎source/IAccessibleHandler/internalWinEventHandler.py‎

Lines changed: 36 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)}"
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("Changing OBJID_WINDOW to OBJID_CLIENT")
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("Redirecting winEvent to desktop window")
95106
window = winUser.getDesktopWindow()
96107
elif not isWindow:
108+
if isMSAADebugLoggingEnabled():
109+
log.debug("Dropping winEvent for invalid window")
97110
return
98111

99112
windowClassName = winUser.getClassName(window)
@@ -114,14 +127,20 @@ def winEventCallback(handle, eventID, window, objectID, childID, threadID, times
114127
global _deferUntilForegroundWindow, _foregroundDefers
115128
_deferUntilForegroundWindow = window
116129
_foregroundDefers = 0
130+
if isMSAADebugLoggingEnabled():
131+
log.debug("Recording foreground winEvent defer")
117132
if windowClassName == "MSNHiddenWindowClass":
118133
# HACK: Events get fired by this window in Windows Live Messenger 2009 when it starts. If we send a
119134
# WM_NULL to this window at this point (which happens in accessibleObjectFromEvent), Messenger will
120135
# silently exit (#677). Therefore, completely ignore these events, which is useless to us anyway.
121136
return
137+
if isMSAADebugLoggingEnabled():
138+
log.debug(
139+
f"Adding winEvent to limitor: {getWinEventLogInfo(window, objectID, childID, eventID)}"
140+
)
122141
if winEventLimiter.addEvent(eventID, window, objectID, childID, threadID):
123142
core.requestPump()
124-
except: # noqa: E722 Bare except
143+
except Exception:
125144
log.error("winEventCallback", exc_info=True)
126145

127146

@@ -162,18 +181,33 @@ def _shouldGetEvents():
162181
if _deferUntilForegroundWindow:
163182
# #3831: Sometimes, a foreground event is fired,
164183
# but GetForegroundWindow() takes a short while to return this new foreground.
184+
curForegroundWindow = winUser.getForegroundWindow()
185+
curForegroundClassName = winUser.getClassName(curForegroundWindow)
186+
futureForegroundClassName = winUser.getClassName(_deferUntilForegroundWindow)
165187
if (
166188
_foregroundDefers < MAX_FOREGROUND_DEFERS
167-
and winUser.getForegroundWindow() != _deferUntilForegroundWindow
189+
and curForegroundWindow != _deferUntilForegroundWindow
168190
):
169191
# Wait a core cycle before handling events to give the foreground window time to update.
170192
core.requestPump()
171193
_foregroundDefers += 1
194+
if isMSAADebugLoggingEnabled():
195+
log.debugWarning(
196+
f"Foreground still {curForegroundWindow} ({curForegroundClassName}). "
197+
f"Deferring until foreground is {_deferUntilForegroundWindow} ({futureForegroundClassName}), "
198+
f"defer count {_foregroundDefers}"
199+
)
172200
return False
173201
else:
174202
# Either the foreground window is now correct
175203
# or we've already had the maximum number of defers.
176204
# (Sometimes, foreground events are fired even when the foreground hasn't actually changed.)
205+
if curForegroundWindow != _deferUntilForegroundWindow:
206+
log.debugWarning(
207+
"Foreground took too long to change. "
208+
f"Foreground still {curForegroundWindow} ({curForegroundClassName}). "
209+
f"Should be {_deferUntilForegroundWindow} ({futureForegroundClassName})"
210+
)
177211
_deferUntilForegroundWindow = None
178212
return True
179213

‎source/IAccessibleHandler/orderedWinEventLimiter.py‎

Lines changed: 12 additions & 1 deletion
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:]:
@@ -102,5 +108,10 @@ def flushEvents(self):
102108
r = []
103109
for count in range(len(e)):
104110
event = heapq.heappop(e)[1:-1]
111+
if isMSAADebugLoggingEnabled():
112+
eventID, window, objectID, childID = event
113+
log.debug(
114+
f"Emitting winEvent {getWinEventLogInfo(window, objectID, childID, eventID)}"
115+
)
105116
r.append(event)
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)

‎source/gui/settingsDialogs.py‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -2447,6 +2447,7 @@ def __init__(self, parent):
24472447

24482448
self.logCategories=[
24492449
"hwIo",
2450+
"MSAA",
24502451
"UIA",
24512452
"audioDucking",
24522453
"gui",

0 commit comments

Comments
 (0)