Skip to content
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.

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

First item not read when opening context submenu #12624

Closed
CyrilleB79 opened this issue Jul 8, 2021 · 19 comments · Fixed by #12720 or #12709
Closed

First item not read when opening context submenu #12624

CyrilleB79 opened this issue Jul 8, 2021 · 19 comments · Fixed by #12720 or #12709
Assignees

Comments

@CyrilleB79
Copy link
Collaborator

CyrilleB79 commented Jul 8, 2021

This issue gives a STR in Outlook French.
The issue is not specific to French but it's just the language of my Office/Windows.
Update: This issue occurs also in sub-menus in other applications; Thunderbird has been confirmed.

Steps to reproduce:

  1. Go in Outlook's message list and select a message
  2. Press the application key to open the context menu
  3. Press down arrow many times until you reach an item which has a submenu (you will hear "collapsed")
  4. Press right arrow to open the submenu
  5. Go to advanced options and set 'Attempt to cancel speech for expired focus events' option to 'No'
  6. Re-execute steps 1. to 4.

Actual behavior:

At step 4. you can hear:
'expanded' (interrupted), 'list', 'menu'

The log is the following when pressing right arrow:

IO - inputCore.executeGesture (17:07:55.077) - winInputHook (10864):
Input: kb(desktop):rightArrow
IO - speech.speech.speak (17:07:55.167) - MainThread (13900):
Speaking ['expanded']
IO - speech.speech.speak (17:07:55.307) - MainThread (13900):
Speaking ['list', CancellableSpeech (still valid)]
IO - speech.speech.speak (17:07:55.327) - MainThread (13900):
Speaking ['Boîte de réception', 'not selected', CancellableSpeech (still valid)]
IO - speech.speech.speak (17:07:55.337) - MainThread (13900):
Speaking ['menu', CancellableSpeech (still valid)]

We can see in the log that 'Boîte de réception' and 'not selected' are spoken but they are actually not heard at all.

At step 6. you can hear:
'expanded' (interrupted), 'list', 'Boîte de réception', 'not selected', 'menu'
Note: 'Boîte de réception' stands for 'Inbox' in French and was the first item of the submenu.

The log is the following when pressing right arrow:

IO - inputCore.executeGesture (17:18:47.738) - winInputHook (10864):
Input: kb(desktop):rightArrow
IO - speech.speech.speak (17:18:47.827) - MainThread (13900):
Speaking ['expanded']
IO - speech.speech.speak (17:18:47.960) - MainThread (13900):
Speaking ['list']
IO - speech.speech.speak (17:18:47.977) - MainThread (13900):
Speaking ['Boîte de réception', 'not selected']
IO - speech.speech.speak (17:18:47.997) - MainThread (13900):
Speaking ['menu']

Expected behavior:

The first menu item's name ('Boîte de réception') should be reported when the menu is opened, whatever the setting of the option 'Attempt to cancel speech for expired events'.

Note

  • This may be considered regression of NVDA 2021.1 since the advanced option was not enabled by default in 23020.4
  • I imagine such a minor bug will not stop the release in any case.
  • I think this issue is not specific to Outlook. I have read messages describing the same issue in submenus of Thunderbird. I have not verified it by myself however.

System configuration

NVDA installed/portable/running from source:

Installed

NVDA version:

NVDA 2021.1rc2

Windows version:

Windows 10 1809 (64-bit) build 17763.1935

Name and version of other software in use when reproducing the issue:

Other information about your system:

Other questions

Does the issue still occur after restarting your computer?

Yes

Have you tried any other versions of NVDA? If so, please report their behaviors.

2020.4 with default config: issue not present.
But 2020.4 with cancellable speech activated: issue present.

If add-ons are disabled, is your problem still occurring?

Yes

Does the issue still occur after you run the COM Registration Fixing Tool in NVDA's tools menu?

Yes

@CyrilleB79
Copy link
Collaborator Author

I have received the confirmation that the same issue occurs in Thunderbird menus: here is the thread for reference (French mailing-list).

@CyrilleB79 CyrilleB79 changed the title First item not read when opening context submenu in Outlook First item not read when opening context submenu Jul 8, 2021
@CyrilleB79
Copy link
Collaborator Author

Cc @feerrenrut as the author of #10885 and #11266.

@CyrilleB79 CyrilleB79 reopened this Jul 9, 2021
@feerrenrut feerrenrut added this to the 2021.2 milestone Jul 12, 2021
@seanbudd seanbudd self-assigned this Jul 29, 2021
@seanbudd
Copy link
Member

seanbudd commented Aug 3, 2021

Here is detailed speech manager logging of reproducing this on Thunderbird.

IO - inputCore.InputManager.executeGesture (11:58:00.175) - winInputHook (5720):
Input: kb(desktop):rightArrow
DEBUG - speech.manager.SpeechManager.cancel (11:58:00.209) - MainThread (2924):
SpeechManager- Cancel
DEBUG - speech.manager.SpeechManager._onSynthDoneSpeaking (11:58:00.219) - Dummy-6 (4816):
SpeechManager- synthDoneSpeaking synth:<synthDrivers.oneCore.SynthDriver object at 0x04A8C9F0>
DEBUG - eventHandler.doPreGainFocus (11:58:00.241) - MainThread (2924):
SpeechManager- executeEvent: Removing cancelled speech commands.
DEBUG - speech.manager.SpeechManager.removeCancelledSpeechCommands (11:58:00.241) - MainThread (2924):
SpeechManager- removeCancelledSpeechCommands
DEBUG - speech.manager.SpeechManager._getMostRecentlyCancelledUtterance (11:58:00.241) - MainThread (2924):
SpeechManager- Length of _cancelCommandsForUtteranceBeingSpokenBySynth: 0 Length of _indexesSpeaking: 0 
DEBUG - speech.manager.SpeechManager._doRemoveCancelledSpeechCommands (11:58:00.241) - MainThread (2924):
SpeechManager- Last index: None
IO - speech.speech.speak (11:58:00.244) - MainThread (2924):
Speaking [LangChangeCommand ('en_US'), 'Inline', 'I', '1 of 2', CancellableSpeech (still valid, devInfo< isCanceledCache: False, isValidCallback: True, isValidCallbackDevInfo: isLast: True, previouslyHad: True, isAncestorOfCurrentFocus: False, is foreground obj False >)]
DEBUG - speech.manager.SpeechManager.speak (11:58:00.244) - MainThread (2924):
SpeechManager- speak (priority <SpeechPriority.NORMAL: 0>): [LangChangeCommand ('en_US'), 'Inline  ', 'I  ', '1 of 2  ', CancellableSpeech (still valid, devInfo< isCanceledCache: False, isValidCallback: True, isValidCallbackDevInfo: isLast: True, previouslyHad: True, isAncestorOfCurrentFocus: False, is foreground obj False >)]
DEBUG - speech.manager.SpeechManager._queueSpeechSequence (11:58:00.244) - MainThread (2924):
SpeechManager- Out Seq: [[LangChangeCommand ('en_US'), 'Inline  ', 'I  ', '1 of 2  ', CancellableSpeech (still valid, devInfo< isCanceledCache: False, isValidCallback: True, isValidCallbackDevInfo: isLast: True, previouslyHad: True, isAncestorOfCurrentFocus: False, is foreground obj False >), IndexCommand(105)], [EndUtteranceCommand()]]
DEBUG - speech.manager.SpeechManager._queueSpeechSequence (11:58:00.244) - MainThread (2924):
SpeechManager- Current priority: 0, queLen: 0
DEBUG - speech.manager.SpeechManager._getMostRecentlyCancelledUtterance (11:58:00.244) - MainThread (2924):
SpeechManager- Length of _cancelCommandsForUtteranceBeingSpokenBySynth: 0 Length of _indexesSpeaking: 0 
DEBUG - speech.manager.SpeechManager._doRemoveCancelledSpeechCommands (11:58:00.244) - MainThread (2924):
SpeechManager- Last index: None
DEBUG - speech.manager.SpeechManager.speak (11:58:00.244) - MainThread (2924):
SpeechManager- Will interrupt: False Will push: True | _indexesSpeaking: [] | _curPriQueue valid: False | _shouldPushWhenDoneSpeaking: False | _cancelledLastSpeechWithSynth False
DEBUG - speech.manager.SpeechManager.speak (11:58:00.245) - MainThread (2924):
SpeechManager- Pushing next speech
DEBUG - speech.manager.SpeechManager._pushNextSpeech (11:58:00.245) - MainThread (2924):
SpeechManager- pushNextSpeech - doneSpeaking: True
DEBUG - speech.manager.SpeechManager._checkForCancellations (11:58:00.245) - MainThread (2924):
SpeechManager- Speaking utterance with cancellable item, index: 105
DEBUG - speech.manager.SpeechManager._pushNextSpeech (11:58:00.245) - MainThread (2924):
SpeechManager- Synth Gets: [LangChangeCommand ('en_US'), 'Inline  ', 'I  ', '1 of 2  ', IndexCommand(105)]
DEBUG - speech.manager.SpeechManager._handleDoneSpeaking (11:58:00.245) - MainThread (2924):
SpeechManager- Synth done speaking, should push: False
DEBUG - eventHandler.doPreGainFocus (11:58:00.246) - MainThread (2924):
SpeechManager- executeEvent: Removing cancelled speech commands.
DEBUG - speech.manager.SpeechManager.removeCancelledSpeechCommands (11:58:00.247) - MainThread (2924):
SpeechManager- removeCancelledSpeechCommands
DEBUG - speech.manager.SpeechManager._getMostRecentlyCancelledUtterance (11:58:00.247) - MainThread (2924):
SpeechManager- Length of _cancelCommandsForUtteranceBeingSpokenBySynth: 1 Length of _indexesSpeaking: 1 
DEBUG - speech.manager.SpeechManager._doRemoveCancelledSpeechCommands (11:58:00.247) - MainThread (2924):
SpeechManager- Last index: 105
DEBUG - speech.manager.SpeechManager._doRemoveCancelledSpeechCommands (11:58:00.247) - MainThread (2924):
SpeechManager- Cancel and push speech
DEBUG - speech.manager.SpeechManager._removeCompletedFromQueue (11:58:00.247) - MainThread (2924):
SpeechManager- Removing: [LangChangeCommand ('en_US'), 'Inline  ', 'I  ', '1 of 2  ', CancellableSpeech (cancelled, devInfo< isCanceledCache: True, isValidCallback: False, isValidCallbackDevInfo: isLast: False, previouslyHad: True, isAncestorOfCurrentFocus: False, is foreground obj False >), IndexCommand(105)]
DEBUG - speech.manager.SpeechManager._removeCompletedFromQueue (11:58:00.247) - MainThread (2924):
SpeechManager- Item is in _cancelCommandsForUtteranceBeingSpokenBySynth: True
DEBUG - speech.manager.SpeechManager._pushNextSpeech (11:58:00.247) - MainThread (2924):
SpeechManager- pushNextSpeech - doneSpeaking: True
DEBUG - speech.manager.SpeechManager._pushNextSpeech (11:58:00.247) - MainThread (2924):
SpeechManager- No more speech
IO - speech.speech.speak (11:58:00.250) - MainThread (2924):
Speaking [LangChangeCommand ('en_US'), 'Forward As', 'menu', CancellableSpeech (still valid, devInfo< isCanceledCache: False, isValidCallback: True, isValidCallbackDevInfo: isLast: True, previouslyHad: True, isAncestorOfCurrentFocus: False, is foreground obj False >)]
DEBUG - speech.manager.SpeechManager.speak (11:58:00.250) - MainThread (2924):
SpeechManager- speak (priority <SpeechPriority.NORMAL: 0>): [LangChangeCommand ('en_US'), 'Forward As  ', 'menu  ', CancellableSpeech (still valid, devInfo< isCanceledCache: False, isValidCallback: True, isValidCallbackDevInfo: isLast: True, previouslyHad: True, isAncestorOfCurrentFocus: False, is foreground obj False >)]
DEBUG - speech.manager.SpeechManager._queueSpeechSequence (11:58:00.250) - MainThread (2924):
SpeechManager- Out Seq: [[LangChangeCommand ('en_US'), 'Forward As  ', 'menu  ', CancellableSpeech (still valid, devInfo< isCanceledCache: False, isValidCallback: True, isValidCallbackDevInfo: isLast: True, previouslyHad: True, isAncestorOfCurrentFocus: False, is foreground obj False >), IndexCommand(106)], [EndUtteranceCommand()]]
DEBUG - speech.manager.SpeechManager._queueSpeechSequence (11:58:00.251) - MainThread (2924):
SpeechManager- Current priority: 0, queLen: 0
DEBUG - speech.manager.SpeechManager._queueSpeechSequence (11:58:00.251) - MainThread (2924):
SpeechManager- current queue: []
DEBUG - speech.manager.SpeechManager._getMostRecentlyCancelledUtterance (11:58:00.251) - MainThread (2924):
SpeechManager- Length of _cancelCommandsForUtteranceBeingSpokenBySynth: 0 Length of _indexesSpeaking: 0 
DEBUG - speech.manager.SpeechManager._doRemoveCancelledSpeechCommands (11:58:00.251) - MainThread (2924):
SpeechManager- Last index: None
DEBUG - speech.manager.SpeechManager.speak (11:58:00.251) - MainThread (2924):
SpeechManager- Will interrupt: False Will push: True | _indexesSpeaking: [] | _curPriQueue valid: False | _shouldPushWhenDoneSpeaking: False | _cancelledLastSpeechWithSynth True
DEBUG - speech.manager.SpeechManager.speak (11:58:00.251) - MainThread (2924):
SpeechManager- Pushing next speech
DEBUG - speech.manager.SpeechManager._pushNextSpeech (11:58:00.251) - MainThread (2924):
SpeechManager- pushNextSpeech - doneSpeaking: True
DEBUG - speech.manager.SpeechManager._onSynthDoneSpeaking (11:58:00.251) - Dummy-6 (4816):
SpeechManager- synthDoneSpeaking synth:<synthDrivers.oneCore.SynthDriver object at 0x04A8C9F0>
DEBUG - speech.manager.SpeechManager._checkForCancellations (11:58:00.251) - MainThread (2924):
SpeechManager- Speaking utterance with cancellable item, index: 106
DEBUG - speech.manager.SpeechManager._pushNextSpeech (11:58:00.252) - MainThread (2924):
SpeechManager- Synth Gets: [LangChangeCommand ('en_US'), 'Forward As  ', 'menu  ', IndexCommand(106)]
DEBUG - speech.manager.SpeechManager._handleDoneSpeaking (11:58:00.252) - MainThread (2924):
SpeechManager- Synth done speaking, should push: False
DEBUG - speech.manager.SpeechManager._onSynthIndexReached (11:58:01.520) - Dummy-7 (17620):
SpeechManager- synthReachedIndex: 106, synth: <synthDrivers.oneCore.SynthDriver object at 0x04A8C9F0>
DEBUG - speech.manager.SpeechManager._handleIndex (11:58:01.542) - MainThread (2924):
SpeechManager- Handle index: 106
DEBUG - speech.manager.SpeechManager._removeCompletedFromQueue (11:58:01.543) - MainThread (2924):
SpeechManager- Removing: [LangChangeCommand ('en_US'), 'Forward As  ', 'menu  ', CancellableSpeech (still valid, devInfo< isCanceledCache: False, isValidCallback: True, isValidCallbackDevInfo: isLast: True, previouslyHad: True, isAncestorOfCurrentFocus: False, is foreground obj False >), IndexCommand(106)]
DEBUG - speech.manager.SpeechManager._removeCompletedFromQueue (11:58:01.543) - MainThread (2924):
SpeechManager- Item is in _cancelCommandsForUtteranceBeingSpokenBySynth: True
DEBUG - speech.manager.SpeechManager._getMostRecentlyCancelledUtterance (11:58:01.543) - MainThread (2924):
SpeechManager- Length of _cancelCommandsForUtteranceBeingSpokenBySynth: 0 Length of _indexesSpeaking: 0 
DEBUG - speech.manager.SpeechManager._doRemoveCancelledSpeechCommands (11:58:01.543) - MainThread (2924):
SpeechManager- Last index: None
DEBUG - speech.manager.SpeechManager._pushNextSpeech (11:58:01.543) - MainThread (2924):
SpeechManager- pushNextSpeech - doneSpeaking: False
DEBUG - speech.manager.SpeechManager._pushNextSpeech (11:58:01.544) - MainThread (2924):
SpeechManager- No more speech
DEBUG - speech.manager.SpeechManager._onSynthDoneSpeaking (11:58:01.729) - Dummy-7 (17620):
SpeechManager- synthDoneSpeaking synth:<synthDrivers.oneCore.SynthDriver object at 0x04A8C9F0>
DEBUG - speech.manager.SpeechManager._handleDoneSpeaking (11:58:01.748) - MainThread (2924):
SpeechManager- Synth done speaking, should push: False
DEBUG - speech.manager.SpeechManager.cancel (11:58:04.960) - MainThread (2924):
SpeechManager- Cancel

@seanbudd
Copy link
Member

seanbudd commented Aug 4, 2021

Here is a detailed log of the MSAA events

Input: kb(desktop):rightArrow
DEBUG - IAccessibleHandler.internalWinEventHandler.winEventCallback (11:50:32.735) - MainThread (15540):
Hook received winEvent: EVENT_OBJECT_SHOW, window 329374 (MozillaWindowClass), objectID OBJID_CLIENT, childID -106, process 10860 (thunderbird), thread 6676
DEBUG - IAccessibleHandler.internalWinEventHandler.winEventCallback (11:50:32.735) - MainThread (15540):
Adding winEvent to limiter: EVENT_OBJECT_SHOW, window 329374 (MozillaWindowClass), objectID OBJID_CLIENT, childID -106, process 10860 (thunderbird), thread 6676
DEBUG - IAccessibleHandler.internalWinEventHandler.winEventCallback (11:50:32.737) - MainThread (15540):
Hook received winEvent: EVENT_OBJECT_SHOW, window 329374 (MozillaWindowClass), objectID OBJID_CLIENT, childID -107, process 10860 (thunderbird), thread 6676
DEBUG - IAccessibleHandler.internalWinEventHandler.winEventCallback (11:50:32.737) - MainThread (15540):
Adding winEvent to limiter: EVENT_OBJECT_SHOW, window 329374 (MozillaWindowClass), objectID OBJID_CLIENT, childID -107, process 10860 (thunderbird), thread 6676
DEBUG - IAccessibleHandler.internalWinEventHandler.winEventCallback (11:50:32.738) - MainThread (15540):
Hook received winEvent: EVENT_OBJECT_FOCUS, window 329374 (MozillaWindowClass), objectID OBJID_CLIENT, childID -106, process 10860 (thunderbird), thread 6676
DEBUG - IAccessibleHandler.internalWinEventHandler.winEventCallback (11:50:32.738) - MainThread (15540):
Adding winEvent to limiter: EVENT_OBJECT_FOCUS, window 329374 (MozillaWindowClass), objectID OBJID_CLIENT, childID -106, process 10860 (thunderbird), thread 6676
DEBUG - IAccessibleHandler.orderedWinEventLimiter.OrderedWinEventLimiter.flushEvents (11:50:32.739) - MainThread (15540):
Emitting winEvent EVENT_OBJECT_SHOW, window 329374 (MozillaWindowClass), objectID OBJID_CLIENT, childID -106, process 10860 (thunderbird), thread 6676
DEBUG - IAccessibleHandler.orderedWinEventLimiter.OrderedWinEventLimiter.flushEvents (11:50:32.739) - MainThread (15540):
Emitting winEvent EVENT_OBJECT_SHOW, window 329374 (MozillaWindowClass), objectID OBJID_CLIENT, childID -107, process 10860 (thunderbird), thread 6676
DEBUG - IAccessibleHandler.orderedWinEventLimiter.OrderedWinEventLimiter.flushEvents (11:50:32.740) - MainThread (15540):
Emitting winEvent EVENT_OBJECT_FOCUS, window 329374 (MozillaWindowClass), objectID OBJID_CLIENT, childID -106, process 10860 (thunderbird), thread 6676
DEBUG - IAccessibleHandler.processFocusWinEvent (11:50:32.740) - MainThread (15540):
Processing focus winEvent: window 329374 (MozillaWindowClass), objectID OBJID_CLIENT, childID -106, process 10860 (thunderbird), force False
DEBUG - IAccessibleHandler.winEventToNVDAEvent (11:50:32.740) - MainThread (15540):
Creating NVDA event from winEvent: EVENT_OBJECT_FOCUS, window 329374 (MozillaWindowClass), objectID OBJID_CLIENT, childID -106, process 10860 (thunderbird), use cache False
DEBUG - IAccessibleHandler.winEventToNVDAEvent (11:50:32.741) - MainThread (15540):
winEvent mapped to NVDA event: gainFocus
DEBUG - IAccessibleHandler.internalWinEventHandler.winEventCallback (11:50:32.750) - MainThread (15540):
Hook received winEvent: EVENT_OBJECT_LOCATIONCHANGE, window 329268 (MozillaDropShadowWindowClass), objectID OBJID_WINDOW, childID 0, process 10860 (thunderbird), thread 6676
DEBUG - IAccessibleHandler.internalWinEventHandler.winEventCallback (11:50:32.750) - MainThread (15540):
locationChange for something other than the caret. Dropping winEvent EVENT_OBJECT_LOCATIONCHANGE, window 329268 (MozillaDropShadowWindowClass), objectID OBJID_WINDOW, childID 0, process 10860 (thunderbird), thread 6676
DEBUG - IAccessibleHandler.internalWinEventHandler.winEventCallback (11:50:32.750) - MainThread (15540):
Hook received winEvent: EVENT_OBJECT_SHOW, window 329268 (MozillaDropShadowWindowClass), objectID OBJID_WINDOW, childID 0, process 10860 (thunderbird), thread 6676
DEBUG - IAccessibleHandler.internalWinEventHandler.winEventCallback (11:50:32.750) - MainThread (15540):
Changing OBJID_WINDOW to OBJID_CLIENT for winEvent: EVENT_OBJECT_SHOW, window 329268 (MozillaDropShadowWindowClass), objectID OBJID_CLIENT, childID 0, process 10860 (thunderbird), thread 6676
DEBUG - IAccessibleHandler.internalWinEventHandler.winEventCallback (11:50:32.750) - MainThread (15540):
Adding winEvent to limiter: EVENT_OBJECT_SHOW, window 329268 (MozillaDropShadowWindowClass), objectID OBJID_CLIENT, childID 0, process 10860 (thunderbird), thread 6676
DEBUG - IAccessibleHandler.internalWinEventHandler.winEventCallback (11:50:32.750) - MainThread (15540):
Hook received winEvent: EVENT_OBJECT_LOCATIONCHANGE, window 1115156 (SysShadow), objectID OBJID_WINDOW, childID 0, process 10860 (thunderbird), thread 6676
DEBUG - IAccessibleHandler.internalWinEventHandler.winEventCallback (11:50:32.750) - MainThread (15540):
locationChange for something other than the caret. Dropping winEvent EVENT_OBJECT_LOCATIONCHANGE, window 1115156 (SysShadow), objectID OBJID_WINDOW, childID 0, process 10860 (thunderbird), thread 6676
DEBUG - IAccessibleHandler.internalWinEventHandler.winEventCallback (11:50:32.750) - MainThread (15540):
Hook received winEvent: EVENT_OBJECT_SHOW, window 1115156 (SysShadow), objectID OBJID_WINDOW, childID 0, process 10860 (thunderbird), thread 6676
DEBUG - IAccessibleHandler.internalWinEventHandler.winEventCallback (11:50:32.751) - MainThread (15540):
Changing OBJID_WINDOW to OBJID_CLIENT for winEvent: EVENT_OBJECT_SHOW, window 1115156 (SysShadow), objectID OBJID_CLIENT, childID 0, process 10860 (thunderbird), thread 6676
DEBUG - IAccessibleHandler.internalWinEventHandler.winEventCallback (11:50:32.751) - MainThread (15540):
Adding winEvent to limiter: EVENT_OBJECT_SHOW, window 1115156 (SysShadow), objectID OBJID_CLIENT, childID 0, process 10860 (thunderbird), thread 6676
DEBUG - IAccessibleHandler.internalWinEventHandler.winEventCallback (11:50:32.751) - MainThread (15540):
Hook received winEvent: EVENT_SYSTEM_MENUPOPUPSTART, window 329268 (MozillaDropShadowWindowClass), objectID OBJID_CLIENT, childID -108, process 10860 (thunderbird), thread 6676
DEBUG - IAccessibleHandler.internalWinEventHandler.winEventCallback (11:50:32.751) - MainThread (15540):
Adding winEvent to limiter: EVENT_SYSTEM_MENUPOPUPSTART, window 329268 (MozillaDropShadowWindowClass), objectID OBJID_CLIENT, childID -108, process 10860 (thunderbird), thread 6676
DEBUG - IAccessibleHandler.winEventToNVDAEvent (11:50:32.753) - MainThread (15540):
Successfully created NVDA event gainFocus for <NVDAObjects.Dynamic_MenuItemMozillaIAccessible object at 0x083E7ED0> from winEvent EVENT_OBJECT_FOCUS, window 329374 (MozillaWindowClass), objectID OBJID_CLIENT, childID -106, process 10860 (thunderbird)
DEBUG - IAccessibleHandler.internalWinEventHandler.winEventCallback (11:50:32.771) - MainThread (15540):
Hook received winEvent: EVENT_OBJECT_NAMECHANGE, window 65926 (DynamicContent1), objectID OBJID_WINDOW, childID 0, process 15636 (explorer), thread 4416
DEBUG - IAccessibleHandler.internalWinEventHandler.winEventCallback (11:50:32.771) - MainThread (15540):
Changing OBJID_WINDOW to OBJID_CLIENT for winEvent: EVENT_OBJECT_NAMECHANGE, window 65926 (DynamicContent1), objectID OBJID_CLIENT, childID 0, process 15636 (explorer), thread 4416
DEBUG - IAccessibleHandler.internalWinEventHandler.winEventCallback (11:50:32.771) - MainThread (15540):
Adding winEvent to limiter: EVENT_OBJECT_NAMECHANGE, window 65926 (DynamicContent1), objectID OBJID_CLIENT, childID 0, process 15636 (explorer), thread 4416
IO - speech.speech.speak (11:50:32.779) - MainThread (15540):
Speaking [LangChangeCommand ('en_US'), 'Inline', 'I', '1 of 2', CancellableSpeech (still valid)]
DEBUG - IAccessibleHandler.orderedWinEventLimiter.OrderedWinEventLimiter.flushEvents (11:50:32.780) - MainThread (15540):
Emitting winEvent EVENT_OBJECT_SHOW, window 329268 (MozillaDropShadowWindowClass), objectID OBJID_CLIENT, childID 0, process 10860 (thunderbird), thread 6676
DEBUG - IAccessibleHandler.orderedWinEventLimiter.OrderedWinEventLimiter.flushEvents (11:50:32.781) - MainThread (15540):
Emitting winEvent EVENT_OBJECT_SHOW, window 1115156 (SysShadow), objectID OBJID_CLIENT, childID 0, process 10860 (thunderbird), thread 6676
DEBUG - IAccessibleHandler.orderedWinEventLimiter.OrderedWinEventLimiter.flushEvents (11:50:32.781) - MainThread (15540):
Emitting winEvent EVENT_SYSTEM_MENUPOPUPSTART, window 329268 (MozillaDropShadowWindowClass), objectID OBJID_CLIENT, childID -108, process 10860 (thunderbird), thread 6676
DEBUG - IAccessibleHandler.orderedWinEventLimiter.OrderedWinEventLimiter.flushEvents (11:50:32.781) - MainThread (15540):
Emitting winEvent EVENT_OBJECT_NAMECHANGE, window 65926 (DynamicContent1), objectID OBJID_CLIENT, childID 0, process 15636 (explorer), thread 4416
DEBUG - IAccessibleHandler.processGenericWinEvent (11:50:32.781) - MainThread (15540):
Processing generic winEvent: EVENT_OBJECT_NAMECHANGE, window 65926 (DynamicContent1), objectID OBJID_CLIENT, childID 0, process 15636 (explorer)
DEBUG - IAccessibleHandler.winEventToNVDAEvent (11:50:32.781) - MainThread (15540):
Creating NVDA event from winEvent: EVENT_OBJECT_NAMECHANGE, window 65926 (DynamicContent1), objectID OBJID_CLIENT, childID 0, process 15636 (explorer), use cache True
DEBUG - IAccessibleHandler.winEventToNVDAEvent (11:50:32.781) - MainThread (15540):
winEvent mapped to NVDA event: nameChange
DEBUG - IAccessibleHandler.winEventToNVDAEvent (11:50:32.783) - MainThread (15540):
Successfully created NVDA event nameChange for <NVDAObjects.IAccessible.Button object at 0x083E7B10> from winEvent EVENT_OBJECT_NAMECHANGE, window 65926 (DynamicContent1), objectID OBJID_CLIENT, childID 0, process 15636 (explorer)
DEBUG - IAccessibleHandler.processMenuStartWinEvent (11:50:32.783) - MainThread (15540):
Processing menuStart winEvent: window 329268 (MozillaDropShadowWindowClass), objectID OBJID_CLIENT, childID -108, process 10860 (thunderbird), validFocus False
DEBUG - IAccessibleHandler.winEventToNVDAEvent (11:50:32.783) - MainThread (15540):
Creating NVDA event from winEvent: EVENT_SYSTEM_MENUPOPUPSTART, window 329268 (MozillaDropShadowWindowClass), objectID OBJID_CLIENT, childID -108, process 10860 (thunderbird), use cache True
DEBUG - IAccessibleHandler.winEventToNVDAEvent (11:50:32.783) - MainThread (15540):
winEvent mapped to NVDA event: menuStart
DEBUG - IAccessibleHandler.winEventToNVDAEvent (11:50:32.787) - MainThread (15540):
Fetched existing NVDAObject <NVDAObjects.IAccessible.mozilla.Mozilla object at 0x08527870> from liveNVDAObjectTable for winEvent window 329268 (MozillaDropShadowWindowClass), objectID OBJID_CLIENT, childID -108, process 10860 (thunderbird)
DEBUG - IAccessibleHandler.winEventToNVDAEvent (11:50:32.788) - MainThread (15540):
Successfully created NVDA event menuStart for <NVDAObjects.IAccessible.mozilla.Mozilla object at 0x08527870> from winEvent EVENT_SYSTEM_MENUPOPUPSTART, window 329268 (MozillaDropShadowWindowClass), objectID OBJID_CLIENT, childID -108, process 10860 (thunderbird)
IO - speech.speech.speak (11:50:32.794) - MainThread (15540):
Speaking [LangChangeCommand ('en_US'), 'Forward As', 'menu', CancellableSpeech (still valid)]

@seanbudd
Copy link
Member

seanbudd commented Aug 4, 2021

Technical summary of "First item not read when opening context submenu" issue:

NVDA receives 2 events when activating the submenu, one for the menu, and one for the menu item.
If the menu item is processed first, the submenu event will cancel the speech of the menu item.

The submenu event is processed by processMenuStartWinEvent, in source\IAccessibleHandler\__init__.py. validFocus = True when the submenu event is processed first, and False when it processed second.

Due to incorrectly assuming the validFocus = False, the following check in processMenuStartWinEvent fails

if validFocus:
      if (
	      isinstance(lastFocus, NVDAObjects.IAccessible.IAccessible)
	      and lastFocus.IAccessibleRole in (oleacc.ROLE_SYSTEM_MENUPOPUP, oleacc.ROLE_SYSTEM_MENUITEM)
      ):
              lastFocus = eventHandler.lastQueuedFocusObject
	      # Focus has already been set to a menu or menu item, so we don't need to handle the menuStart.
	      return

If the check is replaced by the following, the menu item is spoken properly (but the submenu activation is no longer announced).

lastFocus = eventHandler.lastQueuedFocusObject
if validFocus or isinstance(lastFocus, NVDAObjects.IAccessible.MenuItem):
      if (
	      isinstance(lastFocus, NVDAObjects.IAccessible.IAccessible)
	      and lastFocus.IAccessibleRole in (oleacc.ROLE_SYSTEM_MENUPOPUP, oleacc.ROLE_SYSTEM_MENUITEM)
      ):
	      # Focus has already been set to a menu or menu item, so we don't need to handle the menuStart.
	      return

@seanbudd
Copy link
Member

seanbudd commented Aug 4, 2021

I could not reproduce this with Outlook Version 2107 (Microsoft® Outlook® for Microsoft 365 MSO (16.0.14228.20200) 64-bit). But I could reproduce this with Thunderbird 78.12. What version of Outlook were you using @CyrilleB79?

seanbudd added a commit that referenced this issue Aug 7, 2021
Link to issue number:
Fixes #12624

Summary of the issue:
When opening a submenu in certain applications (like Thunderbird 78.12),
NVDA can process a menu start event after the first item in the menu is focused.
The menu start event causes a focus event on the menu, taking NVDA's focus from the menu item.
Additionally, the "menu" parent of the submenu item is not keyboard focusable, and is separate from
the menu item which triggered the submenu.
The object tree in this case (menu item > submenu (not keyboard focusable) > submenu item).
The focus event order after activating the menu item's sub menu is (submenu item, submenu).

Description of how this pull request fixes the issue:
Before cancelling speech, check that the focus is now on the parent menu.

Testing strategy:
Manual testing (note that this does not always occur and is hard to consistently reproduce):

Enable debug logging
With a Thunderbird 78.12 context menu (activate one on an email, for example)
navigate to a menu item with a submenu.
Activate it.
Examine the logs for an event (submenu item, submenu) - eg the speech is announced in this order in the logs, as are the events if event debugging is enabled.
On this PR: Confirm that this case has extensive logging when it occurs. When this event occurs confirm that the menu item is spoken, followed by the submenu. If you want to hear a beep on this event, change the logging to an error beep.
On 2021.1: Confirm that only menu item is spoken, as the seubmenu item is cancelled.
Known issues with pull request:
This may be an overzealous check. Speech in similar contexts that should be cancelled may continue to be spoken.
As such, debug logs are added to make handling new cases easier until the root problem of event processing is addressed.
@CyrilleB79
Copy link
Collaborator Author

Unfortunately, this issue is not resolved.

I have just been able to test again with NVDA 2021.2beta1 on my work computer where I had had this issue. Unfortunately, the issue remains the same.
Here is the log: nvda2.log
The Outlook version on this computer is Outlook 2016 version 16.0.5182.1000. It is not the latest one but I am stuck to this one on this computer being a work computer.
I cannot repro
duce this issue either on my home computer which runs a more up-to-date version of Outlook 2016.

It seems that I am not able to re-open this issue myself. @seanbudd, could you do it for me? Thanks.

@seanbudd
Copy link
Member

Thanks @CyrilleB79 for providing detailed logs with the developer object information. In order to fix this specific case, it would be good to know the parent item of the menu item as well. Would you be able to provide a debug log after following these amended steps using object navigation:

  1. Go in Outlook's message list and select a message
  2. Press the application key to open the context menu
  3. Press down arrow many times until you reach an item which has a submenu (you will hear "collapsed")
  4. Press right arrow to open the submenu
  5. Press the key for "Move to focus object". NVDA+numpadMinus (desktop) / NVDA+backspace (laptop)
  6. Press NVDA+F1 to log that information.
  7. Press the key for "Move to containing object". NVDA+numpad8 (desktop) / NVDA+shift+upArrow (laptop)
  8. Press NVDA+F1 to log that information.

@CyrilleB79
Copy link
Collaborator Author

Hello
Here is the log
logOutlookMenuNavigation.txt

I have added the following steps to yours:
6.1 Press escape to close the log viewer.
6.2 Repeat steps 2 to 5 since the context menu has been closed when the log viewer has been opened.
and:
9. Close log viewer with Escape
10. Repeat steps 2 to 5 since the context menu has closed again du to log viewer.
11. With object navigation put the navigator object on the first sub-menu item.
12. Open the log viewer with NVDA+F1.

Since I have realized that the main menu has kept the focus instead of the first sub-menu item, I have added steps 9 to 12 to provide you the first sub-menu item properties.

Hope this helps!

@seanbudd
Copy link
Member

@CyrilleB79 - thanks for following (and fixing!) the steps - this was just what was needed!

I have another fix prepared on #12786 - can you test this build and see if the problem is resolved?

@CyrilleB79
Copy link
Collaborator Author

Unfortunately, the issue is still present in this new build (tested the snapshot build and from source).
More details in the PR in #12786 (comment).

@seanbudd
Copy link
Member

seanbudd commented Sep 3, 2021

We are not prioritising this work for upcoming releases. This is considering this is an old version of Outlook, fixed in newer versions of Outlook, there is a work around, and the fix would need to be specifically applied to that version of Outlook. We would accept a PR that fixes this, as long as the fix is safely applied to this specific control pattern and Outlook version.

@CyrilleB79
Copy link
Collaborator Author

Unfortunately for me, my company stucks with this version of Outlook.

But I understand that NVAccess does not prioritize this issue for the following reasonsvalid :

  • MS has fixed the issue in newer versions of Outlook and the upgrade is free
  • There is a work-around which consists in disabling speech cancellation for Outlook.

Just a question @seanbudd :
Since you have already worked on this topic, wich path would you recommend to explore for someone wanting to fix this issue?
Thanks.

@seanbudd
Copy link
Member

seanbudd commented Sep 5, 2021

I think the investigation performed in #12786 (comment), should inform how to classify the control pattern. I would use a similar strategy as #12786, with your notes into consideration. Specifically:

The submenu items are instances of AutoCompleteListItem but they have actually nothing to do with auto-complete list. I do not think however that it has any consequence. But maybe it's a bit risky to have a check on this class in case Outlook's chooseNVDAObjectOverlayClasses is refined in the future.

I would update outlook.chooseNVDAObjectOverlayClasses to ensure a new object is set instead of AutoCompleteListItem. This new object should only be set for this specific Outlook version, and should only occur for this particular problematic case. This can be informed by the analysis you performed in #12786 (comment) and with the log in #12624 (comment).

Or we can look at fixing this by ensuring these events are always processed in the correct order to begin with. Not much investigation has been performed in addressing this.

@seanbudd seanbudd removed this from the 2021.3 milestone Sep 8, 2021
@Adriani90
Copy link
Collaborator

Testing with Outlook 2016 Build (16.0.5257.1000) MSO (16.0.5366.1000) 32-Bit
and NVDA 2022.3.1, this issue occurs now even regardless of the cancelable speech being on or off. NVDA just doesn't report the focused sub menu item at all when opening the submenu with right arrow.

Is this solved just in Outlook 365? Or also in Outlook 2016? Note that this build is an update from November 2022, so it is not a very old version.
In which version of Outlook does this work correctly?

@Adriani90
Copy link
Collaborator

I think I found an issue here that might be causing this. I am using laptop keyboard layout for your reference. When opening the submenu with right arrow and pressing nvda+shift+down arrow and nvda+shift+up arrow, it seems Outlook opens a menu as child element of the parent element which is also a menu. However, NVDA should ignore the child menu role for the menu in the simplified mode of object presentation. Then NVDA would probably report the list which actually contains the elements of the sub menu. The question is, where does Outlook redirect the focus visually when opening the sub menu? Is this the first child element in the list? Then NVDA should report the first item, and not the parent object. In this case, NVDA should actually even ignore the list role which is defined as the parent object of the sub menu items.

Maybe this can be solved in the object handler of NVDA by deciding what to be ignored in the simplified mode of object presentation.
Otherwise in the Outlook app module.

@Adriani90
Copy link
Collaborator

Tested in Outlook 365, the issue is not reproducible. So it seems related to Outlook 2016.

@CyrilleB79
Copy link
Collaborator Author

The issue still occurs in Outlook 2016 version '16.0.5257.1000' that I have on my company's computer. But it does not on my home's computer that run an Office 2016 with a higher release number.

@Adriani90
Copy link
Collaborator

Ok, then I am closing this since it seems it is fixed by Microsoft in a newer Office 2016 update.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment