search

nvaccess / nvda

NVDA, the free and open source Screen Reader for Microsoft Windows
Other
2.06k stars 625 forks source link

Sometimes pressing shift during SayAll stops it instead of just pausing it #10946

Open CyrilleB79 opened 4 years ago

CyrilleB79 commented 4 years ago

Steps to reproduce:

Steps for a stress test since this issue appears only sporadically:

Actual behavior:

After max 20-30 seconds pressing pausing and resuming quickly, SayAll does not resume anymore.

Expected behavior:

If SayAll is paused with shift key, it should always be able to be resumed.

Note

Elaborated this stress test since I can see that sometimes (but quite rarely), sayAll does not resume even at normal rate, with eSpeak and with IBMTTS.

System configuration

NVDA installed/portable/running from source:

Installed 2019.3, portable 2020.1beta1

NVDA version:

All

Windows version:

Windows 7 (both NVDA versions), Windows 10 (NVDA 2019.3 tested).

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

Any where SayAll works. E.g. Firefox 68.

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.

NVDA 2019.2.1: cannot reproduce this issue.

If addons are disabled, is your problem still occuring?

Yes

Did you try to run the COM registry fixing tool in NVDA menu / tools?

No

CyrilleB79 commented 4 years ago

Adding the log: LogSayAllDoesNotResume.txt

bhavyashah commented 4 years ago

I am unable to reproduce this issue on a webpage in Firefox 78.0.1 with NVDA 2020.2 Beta 2. I was erratically switching between pausing and resuming say all by pressing the left and right Shift keys; but everything kept working as expected in my brief test.

CyrilleB79 commented 4 years ago

I can still reproduce the issue with:

@bhavyashah do you confirm that you have tried with eSpeak, rate 100, rate boost on? Can you try on the same webpage than I? Thanks.

bhavyashah commented 4 years ago

I can now confirm this issue with the said webpage, browser, and NVDA version. I first had to disable the Sticky Keys (press Shift key 5 times) setting. Then, I went on the linked page, started a say all, and kept pressing and releasing the right Shift key multiple times each second. After 15 seconds or so, the say all ceased to resume. I tried this again and was able to reproduce the issue quicker than the first time. However, I think this issue persists even with lower speech rates (40% with Rate Boost) but just that it seems to take longer before the issue crops up. Also, while doing this testing, I also get the following error once or twice during each iteration of the exercise: ERROR - queueHandler.flushQueue (14:33:48.633) - MainThread (5304): Error in func nextLine from eventQueue Traceback (most recent call last): File "queueHandler.pyc", line 50, in flushQueue File "sayAllHandler.pyc", line 181, in nextLine AttributeError: 'NoneType' object has no attribute 'collapse' To be clear, this error is somewhat separate from say all stopping. This is because I get this error 5-10 seconds into the test, whereas Shift fails to resume the say all approximately 15 seconds into the test.

CyrilleB79 commented 4 years ago

On the contrary, it seems to me that the error cause sayAll not to resume properly.

Here is a slightly different STR procedure to prove this:

Additional note: The issue seems to occur (at least) in a piece of text containing many links. That's why the table of contents of NVDA user guide is a good place to reproduce this issue.

@feerrenrut may you have a look on this since we already have a clear way to reproduce this issue and since it is a regression introduced with speech refactor?

As noted by @bhavyashah, sticky key shortcut has to be disabled. Thanks! I had forgotten to indicate this since I always live with this shortcut disabled.

CyrilleB79 commented 3 years ago

Note that I have also reproduced this issue using SayAll with review cursor (gesture = NumpadPlus) in the Notepad edit area.

The error is the following (with following debug message also giving an indication):


Error running speech callback
Traceback (most recent call last):
  File "speech\manager.pyc", line 669, in _handleIndex
  File "speech\commands.pyc", line 326, in run
  File "sayAllHandler.pyc", line 155, in _onLineReached
  File "sayAllHandler.pyc", line 212, in lineReached
  File "sayAllHandler.pyc", line 181, in nextLine
AttributeError: 'NoneType' object has no attribute 'collapse'
DEBUG - sayAllHandler._TextReader.nextLine (22:18:51.516) - MainThread (34744):
no self.reader```

@feerrenrut is the log enough? Or should I check some debug log options in the Advanced setting panel?

CyrilleB79 commented 3 years ago

On last alpha the log seems to give more information:


Input: kb(desktop):NVDA+downArrow
IO - speech.speak (17:19:15.213) - MainThread (14988):
Speaking [CallbackCommand(name=say-all:lineReached), LangChangeCommand ('fr_FR'), '#inputCore.py\r\n', CallbackCommand(name=say-all:lineReached), '#A part of NonVisual Desktop Access (NVDA)\r\n', CallbackCommand(name=say-all:lineReached), '#This file is covered by the GNU General Public License.\r\n']
DEBUG - synthDrivers.oneCore.SynthDriver._processQueue (17:19:15.213) - MainThread (14988):
Begin processing speech
DEBUG - synthDrivers.oneCore.SynthDriver.cancel (17:19:17.142) - MainThread (14988):
Cancelling
DEBUG - synthDrivers.oneCore.SynthDriver._callback (17:19:17.142) - Dummy-4 (11196):
Done pushing audio
DEBUG - synthDrivers.oneCore.SynthDriver._processQueue (17:19:17.142) - Dummy-4 (11196):
Calling sync on audio player
DEBUG - nvwave.WavePlayer._isPreferredDeviceOpen (17:19:17.142) - MainThread (14988):
preferred device: WAVE_MAPPER current device name: WAVE_MAPPER (id: -1)
IO - speech.speak (17:19:17.142) - MainThread (14988):
Speaking [CallbackCommand(name=say-all:lineReached), LangChangeCommand ('fr_FR'), '#See the file COPYING for more details.\r\n']
DEBUG - synthDrivers.oneCore.SynthDriver._processQueue (17:19:17.142) - Dummy-4 (11196):
Calling idle on audio player
DEBUG - nvwave.WavePlayer._isPreferredDeviceOpen (17:19:17.142) - Dummy-4 (11196):
preferred device: WAVE_MAPPER current device name: WAVE_MAPPER (id: -1)
DEBUG - synthDrivers.oneCore.SynthDriver._processQueue (17:19:17.142) - Dummy-4 (11196):
Begin processing speech
DEBUG - nvwave.WavePlayer._isPreferredDeviceOpen (17:19:17.142) - MainThread (14988):
preferred device: WAVE_MAPPER current device name: WAVE_MAPPER (id: -1)
DEBUG - nvwave.WavePlayer.open (17:19:17.142) - MainThread (14988):
Calling winmm.waveOutOpen. outputDeviceName: WAVE_MAPPER outputDeviceID: -1
DEBUG - nvwave.WavePlayer._isPreferredDeviceOpen (17:19:17.153) - MainThread (14988):
preferred device: WAVE_MAPPER current device name: WAVE_MAPPER (id: -1)
DEBUG - nvwave.WavePlayer._close (17:19:17.153) - MainThread (14988):
Calling winmm.waveOutClose
ERROR - speech.manager.SpeechManager._handleIndex (17:19:17.142) - MainThread (14988):
Error running speech callback
Traceback (most recent call last):
  File "speech\manager.py", line 669, in _handleIndex
    callbackCommand.run()
  File "speech\commands.py", line 326, in run
    return self._callback(*args,**kwargs)
  File "sayAllHandler.py", line 164, in _onLineReached
    self.lineReached(obj, bookmark, state)
  File "sayAllHandler.py", line 221, in lineReached
    self.nextLine()
  File "sayAllHandler.py", line 190, in nextLine
    self.reader.collapse(end=True)
AttributeError: 'NoneType' object has no attribute 'collapse'
DEBUG - sayAllHandler._TextReader.nextLine (17:19:17.193) - MainThread (14988):
no self.reader
DEBUG - nvwave.WavePlayer._isPreferredDeviceOpen (17:19:17.559) - nvwave.playWaveFile(error.wav) (5892):
preferred device: WAVE_MAPPER current device name: WAVE_MAPPER (id: -1)```

I have only pressed NVDA+downArrow and then quickly many times the shift key until the error sound is heard. But strangely the audio device (WavePlayer) is closed. I do not have knowledge about PRs ##11531 and #11024. But I seem to understand that the audio device should not be closed at all now. Let me know if I am wrong.

Adriani90 commented 3 years ago

cc: @jcsteh, @michaelDCurran

CyrilleB79 commented 3 years ago

@michaelDCurran since you have just worked on #11651, you may be able to see the root cause of this issue in case it is linked? I had tried to investigate but I do not have a clear idea of the speech framework.

Or if you or someone else has any advice where I should dig in, I may try to investigate again.

Also would it be useful to provide a new log with some extra debug channels activated?

feerrenrut commented 3 years ago

But strangely the audio device (WavePlayer) is closed.

This is misleading. When an error sound is played, a new nvWave instance is created to play the audio file. This results in an open and close of the audio device. It would be really good if this logging only happened with nvWave logging category enabled, it would also be good if it differentiated itself from the normal nvWave logging.

feerrenrut commented 3 years ago

One thing to note about the above log is the timestamps, the order of the log entries does not match the timestamps, the error log entry happened at the same moment as the call to open wave out.

CyrilleB79 commented 3 years ago

But strangely the audio device (WavePlayer) is closed.

This is misleading. When an error sound is played, a new nvWave instance is created to play the audio file. This results in an open and close of the audio device.

OK. Thanks for the explanation. So all is normal here.

It would be really good if this logging only happened with nvWave logging category enabled,

Yes, it does now. If I am not mistaken the log I had provided was done before the integration of ##11582.

it would also be good if it differentiated itself from the normal nvWave logging.

CyrilleB79 commented 3 years ago

One thing to note about the above log is the timestamps, the order of the log entries does not match the timestamps, the error log entry happened at the same moment as the call to open wave out.

I had not realized this. I do not know however what it implies.

feerrenrut commented 3 years ago

I do not know however what it implies.

The cause is likely due to the messages originating from different threads, not a concern. But its worth knowing about because it is tempting to assume the order of the messages in the log reflects the order of execution. In this particular case it is hard to determine that this message was due to the error sound without noticing the time stamps.

CyrilleB79 commented 3 years ago

Here are some more investigation on this issue (on last alpha):

First of all, doing more carefully these tests, I have been able to see that the real issue is that at a moment, pressing shift key while reading does not pause immediately the synthesis. Instead, an error sound is heard and the speech synth continues to speak until the end of the current short chunk. Once reading this chunk is finished, sayAll is completely stopped and pressing shift again does not allow to restart sayAll.

I will modify the title of this issue accordingly.

I have been able to see that _TextReader.stop function was called whereas I only press shift key and the we are not at all at the end of the text to be read. The call stack of the stop function is the following:

stop in nvda\source\sayAllHandler.py line 29
cancelSpeech in nvda\source\speech\__init__.py line 138
speak in nvda\source\speech\__init__.py line 740
speakWithoutPauses in nvda\source\speech\__init__.py line 2459
nextLine in nvda\source\sayAllHandler.py line 185
flushQueue in nvda\source\queueHandler.py line 55
pumpAll in nvda\source\queueHandler.py line 88
run in nvda\source\core.py line 538
Notify in nvda\source\gui\__init__.py line 1062
MainLoop in nvda\include\wxPython\wx\core.py line 2134
main in nvda\source\core.py line 568
<module> in source\nvda.pyw line 247

Note that the line number in sayAllHandler.py may not be exact due to log points and other debug code added by me.

What seems strange to me is the following statements in speech\__init__.py\speak

    if isPaused:
        cancelSpeech()

Why should speech be cancelled upon pause? @feerrenrut (for your work on speech refactor), @michaelDCurran (since you were the one who wrote these lines... in 2007) or anyone else, any clarification would help. Thanks!

feerrenrut commented 3 years ago

Thanks for the investigation @CyrilleB79. We have some unit tests that can imitate say-all. It would be great if we could replicate this in a unit test.

In order to stop the synth from speaking, we have to call cancel. SayAllHandler should maintain the current position / reading state I believe.

Instead, an error sound is heard and the speech synth continues to speak until the end of the current short chunk.

Please paste the error text from the log into a comment, ideally the stack at this moment too (you may need to add stack_info=True to the log call)

CyrilleB79 commented 3 years ago

@feerrenrut, I am not sure to understand what you are expecting.

Please find below the issue reproduced on this page with eSpeak rate 100, rate boost on. I have:

  1. started SayAll pressing NVDA+DownArrow
  2. pressed shift one time to pause speech
  3. pressed two times shift quickly to resume and pause speech again
  4. executed step 3. about 5-10 times When pressing the last shift, the error tone was heard and the speech did not pause until the end of the chunk.
  5. Pressed NVDA+F1 to get this log.
IO - external:inputCore.executeGesture (23:01:42.719) - winInputHook (24000):
Input: kb(desktop):NVDA+downArrow
IO - external:speech.speak (23:01:42.735) - MainThread (19864):
Speaking [CallbackCommand(name=say-all:lineReached), 'visité', 'lien', 'Homepage', CallbackCommand(name=say-all:lineReached)]
IO - external:speech.speak (23:01:42.751) - MainThread (19864):
Speaking ['Global', 'navigation région', 'visité', 'lien', 'Pull requests you created', CallbackCommand(name=say-all:lineReached)]
IO - external:speech.speak (23:01:42.751) - MainThread (19864):
Speaking ['visité', 'lien', 'Issues you created', CallbackCommand(name=say-all:lineReached)]
IO - external:speech.speak (23:01:42.760) - MainThread (19864):
Speaking ['lien', 'Marketplace ', CallbackCommand(name=say-all:lineReached)]
IO - external:speech.speak (23:01:42.760) - MainThread (19864):
Speaking ['visité', 'lien', 'Explore ', CallbackCommand(name=say-all:lineReached)]
IO - external:speech.speak (23:01:42.787) - MainThread (19864):
Speaking ['lien', 'You have no unread notifications', CallbackCommand(name=say-all:lineReached)]
IO - external:speech.speak (23:01:42.787) - MainThread (19864):
Speaking ['cliquable', 'bouton', 'réduit', 'sous-Menu', 'Create new…', CallbackCommand(name=say-all:lineReached)]
IO - external:speech.speak (23:01:42.806) - MainThread (19864):
Speaking ['cliquable', 'bouton', 'réduit', 'sous-Menu', 'View profile and more', CallbackCommand(name=say-all:lineReached)]
IO - external:speech.speak (23:01:42.811) - MainThread (19864):
Speaking ['principale région', 'titre', 'niveau 1', 'visité', 'lien', 'nvaccess', CallbackCommand(name=say-all:lineReached)]
IO - external:speech.speak (23:01:42.826) - MainThread (19864):
Speaking ['titre', 'niveau 1', '/', CallbackCommand(name=say-all:lineReached)]
IO - external:speech.speak (23:01:42.826) - MainThread (19864):
Speaking ['titre', 'niveau 1', 'visité', 'lien', 'nvda']
IO - external:speech.speak (23:01:53.747) - MainThread (19864):
Speaking [CallbackCommand(name=say-all:lineReached)]
IO - external:speech.speak (23:01:53.757) - MainThread (19864):
Speaking ['liste', 'de 4 éléments', 'bouton', 'réduit', ' Sponsor ', CallbackCommand(name=say-all:lineReached)]
IO - external:speech.speak (23:01:53.766) - MainThread (19864):
Speaking ['cliquable', 'bouton', 'réduit', 'sous-Menu', 'Notifications settings', CallbackCommand(name=say-all:lineReached)]
IO - external:speech.speak (23:01:53.771) - MainThread (19864):
Speaking ['lien', '142 users are watching this repository', CallbackCommand(name=say-all:lineReached)]
IO - external:speech.speak (23:01:53.777) - MainThread (19864):
Speaking ['bouton', 'Unstar this repository', CallbackCommand(name=say-all:lineReached)]
IO - external:speech.speak (23:01:53.782) - MainThread (19864):
Speaking ['lien', '1047 users starred this repository', CallbackCommand(name=say-all:lineReached)]
IO - external:speech.speak (23:01:53.787) - MainThread (19864):
Speaking ['bouton', 'Fork your own copy of nvaccess/nvda to your account', CallbackCommand(name=say-all:lineReached)]
IO - external:speech.speak (23:01:53.787) - MainThread (19864):
Speaking ['lien', '398 users forked this repository', CallbackCommand(name=say-all:lineReached), 'hors de liste']
IO - external:speech.speak (23:01:53.817) - MainThread (19864):
Speaking ['Repository', 'navigation région', 'liste', 'de 9 éléments', 'visité', 'lien', 'Code', CallbackCommand(name=say-all:lineReached)]
IO - external:speech.speak (23:01:53.827) - MainThread (19864):
Speaking ['visité', 'lien', 'page courante', 'Issues', CallbackCommand(name=say-all:lineReached)]
ERROR - external:queueHandler.flushQueue (23:01:53.827) - MainThread (19864):
Error in func _TextReader.nextLine
Traceback (most recent call last):
  File "queueHandler.py", line 55, in flushQueue
    func(*args,**kwargs)
  File "sayAllHandler.py", line 190, in nextLine
    self.reader.collapse(end=True)
AttributeError: 'NoneType' object has no attribute 'collapse'
IO - external:inputCore.executeGesture (23:01:55.663) - winInputHook (24000):
Input: kb(desktop):NVDA+f1

Let me know if this log is enough or if I should log something else. I may add additional log points in the code if required.

CyrilleB79 commented 3 years ago

As a follow-up, I have just tested last alpha (Version : source-master-c4de394) containing the recent rework on SayAll. But the issue is still present. As before, the occurence of this issue is very rare with eSpeak and a bit more frequent but still rare (1/20 - 1/50) with IBMTTS.

Also to clarify regarding the initial description of #12397, the issue may occur at first press but the probability of occurrence is low. So STR indicate to press shift many times to raise the probability of occurrence of the issue.

Adriani90 commented 1 month ago

I can reproduce this reliably with eSpeak while reading the table of contents in the NVDA user guide, WASAPI enabled, no add-ons in use, with NVDA 2024.3 Beta and Firefox 127.

Following is written to the log:

IO - inputCore.InputManager.executeGesture (23:27:59.389) - winInputHook (12176):
Input: kb(laptop):NVDA+a
IO - speech.speech.speak (23:27:59.394) - MainThread (14812):
Speaking [CallbackCommand(name=say-all:lineReached), 'Link', 'NVDA alpha-32650,405f9bfa Benutzerhandbuch', CallbackCommand(name=say-all:lineReached), 'Link', '1. ']
IO - speech.speech.speak (23:28:02.014) - MainThread (14812):
Speaking ['Einleitung', CallbackCommand(name=say-all:lineReached), 'Link', '1.1. ']
IO - speech.speech.speak (23:28:02.684) - MainThread (14812):
Speaking ['Allgemeine Features', CallbackCommand(name=say-all:lineReached)]
IO - speech.speech.speak (23:28:02.684) - MainThread (14812):
Speaking ['Link', '1.2. ']
IO - speech.speech.speak (23:28:03.849) - MainThread (14812):
Speaking ['System-Voraussetzungen', CallbackCommand(name=say-all:lineReached)]
IO - speech.speech.speak (23:28:03.849) - MainThread (14812):
Speaking ['Link', '1.3. ']
ERROR - speech.manager.SpeechManager._handleIndex (23:28:03.849) - MainThread (14812):
Error running speech callback
Traceback (most recent call last):
  File "speech\manager.pyc", line 686, in _handleIndex
  File "speech\commands.pyc", line 401, in run
  File "speech\sayAll.pyc", line 280, in _onLineReached
  File "speech\sayAll.pyc", line 329, in lineReached
  File "speech\sayAll.pyc", line 304, in nextLine
  File "speech\sayAll.pyc", line 241, in collapseLineImpl
AttributeError: 'NoneType' object has no attribute 'collapse'
DEBUG - speech.sayAll._TextReader.nextLine (23:28:04.424) - MainThread (14812):
no self.reader

and the speech is cancelled.

cc: @LeonarddeR any idea on this?