If NvDA is restarted during a braille display auto detection, the new NVDA instance may be very unstable

[michaelDCurran]

Steps to reproduce:

• Pair a Bluetooth serial braille display to the machine. E.g. An Orbit Reader 40.
• Ensure the braille display is off / not in range of Bluetooth.
• Ensure NvDA's braille display selection is set to 'Automatic'.
• Restart NvDA. Note for the best chance of reproducing this, Quit NvDA by pressing NVDA+q and then enter, and then quickly start NVDA from the Run dialog or a terminal.

Actual behavior:

When the new NvDA instance starts:

• alt tabbing reports nothing.
• NVDA seems to occasionally freeze for up to 10 seconds at a time.
• NVDA cannot provide virtual buffers and or other features that rely on process injection.

Expected behavior:

The new instance of NvDA should function normally.

NVDA logs, crash dumps and other attachments:

In nvda.log, with debugging, after the normal final line "NvDA Exit", we see the following:

DEBUG - hwIo.base.Serial.__init__ (16:42:40.778) - ThreadPoolExecutor-0_0 (12472):
Open failed: could not open port 'COM13': OSError(22, 'The semaphore timeout period has expired.', None, 121)
DEBUGWARNING - brailleDisplayDrivers.baum.BrailleDisplayDriver.__init__ (16:42:40.778) - ThreadPoolExecutor-0_0 (12472):
Traceback (most recent call last):
  File "brailleDisplayDrivers\baum.py", line 172, in __init__
    self._dev = hwIo.Serial(
                ^^^^^^^^^^^^
  File "hwIo\base.py", line 253, in __init__
    self._ser = serial.Serial(*args, **kwargs)
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\mick\programming\git\nvda\.venv\Lib\site-packages\serial\serialwin32.py", line 33, in __init__
    super(Serial, self).__init__(*args, **kwargs)
  File "C:\Users\mick\programming\git\nvda\.venv\Lib\site-packages\serial\serialutil.py", line 244, in __init__
    self.open()
  File "C:\Users\mick\programming\git\nvda\.venv\Lib\site-packages\serial\serialwin32.py", line 64, in open
    raise SerialException("could not open port {!r}: {!r}".format(self.portstr, ctypes.WinError()))
serial.serialutil.SerialException: could not open port 'COM13': OSError(22, 'The semaphore timeout period has expired.', None, 121)
DEBUGWARNING - braille.BrailleHandler.setDisplayByName (16:42:40.788) - ThreadPoolExecutor-0_0 (12472):
Couldn't initialize display driver 'baum'
Traceback (most recent call last):
  File "braille.py", line 2482, in setDisplayByName
    self._setDisplay(newDisplayClass, isFallback=isFallback, detected=detected)
  File "braille.py", line 2552, in _setDisplay
    newDisplay = self._switchDisplay(oldDisplay, newDisplayClass, **kwargs)
                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "braille.py", line 2522, in _switchDisplay
    extensionPoints.callWithSupportedKwargs(newDisplay.__init__, **kwargs)
  File "extensionPoints\util.py", line 216, in callWithSupportedKwargs
    return func(*boundArguments.args, **boundArguments.kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "brailleDisplayDrivers\baum.py", line 218, in __init__
    raise RuntimeError("No Baum display found")
RuntimeError: No Baum display found
DEBUG - autoSettingsUtils.autoSettings.AutoSettings._registerConfigSaveAction (16:42:40.788) - ThreadPoolExecutor-0_0 (12472):
registering pre_configSave action: <class 'brailleDisplayDrivers.noBraille.BrailleDisplayDriver'>
DEBUG - autoSettingsUtils.autoSettings.AutoSettings._loadSpecificSettings (16:42:40.794) - ThreadPoolExecutor-0_0 (12472):
loading braille noBraille
INFO - braille.BrailleHandler._setDisplay (16:42:40.794) - ThreadPoolExecutor-0_0 (12472):
Loaded braille display driver 'noBraille', current display has 0 cells.

Technical findings

It is best if all background threads in NVDA are daemon threads, so that we can guarantee that they will be killed off if running when NVDA's main thread dies.
However, NVDA's braille display detector (that runs _bgScan) is implemented as a ThreadPoolExecutor. ThreadPoolExecutor starts non-daemon worker threads which are never joined before NVDA exits. Thus if NVDA is in the middle of a bluetooth scan when exiting, this thread may hold the NVDA process around until it is done.
In the case where a bluetooth serial device is out of range / off, this can cause Windows to block on CreateFile for 5 seconds while it tries to open the COM port. The only way this can be interrupted is to kill the thread currently blocked on the call, and or kill the entire process.

Because this thread is not joined and or killed before NvDA exits, NVDA releases its mutex, which allows a new instance of NvDA to start while the old process is still blocked on the bluetooth scan. In theory this should be okay - everything else in NVDA has been correctly finalized. However, it causes some significant issues in nvdaHelper which are very hard to work around.

@jcsteh also came up with steps to reproduce this without requiring Braille display auto detection:

1.Open the Python console.
2.Paste this code:
import atexit, time, winsound
def e():
	time.sleep(10)
	winsound.PlaySound("waves/browseMode.wav", 0)

atexit.register(e)
3. Exit NVDA.
4. Before 10 seconds elapses, start NVDA again from the Run dialog. Note that using the restart option from the Exit dialog sometimes results in the old NVDA getting killed off, perhaps because the old NVDA is still cleaning up the mutex and GUI when the new one starts. If this happens, the browse mode sound won't play 10 seconds after you run the Python code.

The first issue is that there can be a deadlock in the UI thread of a process if a new nvdahelperRemote is injected while the old nvdahelperRemote is terminating. Specifically, the winEvent callback which starts the new inproc manager thread if needed, blocks on the inproc manager thread for up to 10 seconds as it initializes all subsystems. However, when we terminate IAccessible2 support in the old inproc manager thread, in order to correctly unregister IAccessible2 from the UI thread, we post a window message to the UI thread and wait for it to be handled (for up to 10 seconds). But, in this case, the UI thread is currently waiting on the new inproc manager thread to initialize, which is itself waiting on the inproc manager thread mutex.
This bug is pretty easy to fix really, We should just not wait in the UI thread on the inproc manager thread to initialize. True we may miss a focus/foreground event going to the inproc manager thread callbacks, but that is not as bad as deadlocking.

The second issue is that our current RPC implementation for nvdaController / nvdaControllerInternal does not support being replaced by a new instance of NvDA while the old NvDA process is still alive, even if the old NVDA process correctly terminated nvdaHelperLocal / RPC support. this is due to the fact that we use rpcUseProtSeqEp to tell RPC to listen on a particular known ncalrpc endpoint, but there is no function available to unbind from this endpoint, even if we do correctly unregister all our individual RPC interfaces. We could instead use functions like rpcEpRegister and register nvdaControllerInternal with a unique UUID, or we could continue to use rpcUseProcSeqEp but use a unique string. But either way, we'd need a way to communicate this new UUID or string to the in-process code beforehand. Lots of possibilities here, but would involve some significant rewriting of our injection code.

Possible solution

At an absolute minimum, just before releasing our mutex in nvda.pyw, we should log and join any remaining non-daemon thread.
This will ensure we continue to hold the mutex while any possible braille auto detect bluetooth scan completes, and or any other non-daemon background thread (such as in a bad add-on) completes.
It is possible that the new instance of NVDA will eventually kill off the old process before the background thread completes, but at least it will either complete or be killed off, rather than the process staying around after the mutex is released.

Further to this, we could rewrite the bgScan thread to be a daemon thread. This may have the added advantage that Python can kill off this thread at exit, therefore speed up NVDA exit when auto detecting.

Another alternative we considered but I don't think is appropriate now is to simply set wait=True on ThreadPoolExecutor.shutdown when terminating the detector. this is bad as although NvDA will wait, it has not yet terminated a lot of other subsystems, and will most likely be killed off by the new instance.

Thoughts on all this @jcsteh and @LeonarddeR ?

[LeonarddeR]

Thanks for this outline Mick

ThreadPoolExecutor starts non-daemon worker threads...

I was like, they really should have been daemon threads, pretty sure I checked that when implementing. It turns out that the ThreadPoolExecutor threads indeed really were daemon threads when we started using the Executor. This was changed in Python 3.9, so I think this is likely to be a NVDA 2024.1 regression. See python/cpython@b61b818.

At an absolute minimum, just before releasing our mutex in nvda.pyw, we should log and join any remaining non-daemon thread. This will ensure we continue to hold the mutex while any possible braille auto detect bluetooth scan completes, and or any other non-daemon background thread (such as in a bad add-on) completes. It is possible that the new instance of NVDA will eventually kill off the old process before the background thread completes, but at least it will either complete or be killed off, rather than the process staying around after the mutex is released.

Makes sense to me.

Further to this, we could rewrite the bgScan thread to be a daemon thread. This may have the added advantage that Python can kill off this thread at exit, therefore speed up NVDA exit when auto detecting.

Before using the ThreadPoolExecutor, we used a daemon thread with APCs, but that had its own challenges (it is not possible to cancel APCs as soon as they have been queued). Now the ThreadPoolExecutor decided to no longer create daemon threads, it might be better to run a single thread with a simple loop that watches a queue, indeed. So basically, we need to rewrite a very basic ThreadPoolExecutor.
That said, given ThreadPoolExecutor could possibly be used by add-ons (I recall @bramd used it) and there could indeed be other add-ons that have something that sticks around, I think I'd just ensure that the mutex stays around until all the non daemon-threads are processed (either joined/killed) and leave bdDetect as is.

Another alternative we considered but I don't think is appropriate now is to simply set wait=True on ThreadPoolExecutor.shutdown when terminating the detector.

We should at least add cancel_futures=True, though I'm pretty sure we only use one future at the time and that's already canceled by stopBgScan.

Thoughts on all this @jcsteh and @LeonarddeR ?

Given the underlying issue with bdDetect here is that CreateFile hangs, I wonder whether we could make that cancellable. That would definitely improve detection speed when Bluetooth is on and the system tries to poll devices over and over again. You would say that two seconds (instead of five) should be more than enough to determine whether a device is responding.

[jcsteh]

It turns out that the ThreadPoolExecutor threads indeed really were daemon threads when we started using the Executor.

That's true, but in Python 3.8 at least, there was an atexit handler that joined the threads until they finished. So they were effectively non-daemon as far as NVDA is concerned and we would have ended up with the same bug. I actually thought that was happening here and that was part of the initial analysis I discussed with Mick, but i neglected to realise that I was reading Python 3.8 code and that it might have changed in 3.9. At any rate, the net result is the same.

Given the underlying issue with bdDetect here is that CreateFile hangs, I wonder whether we could make that cancellable.

I've never found a way to do that. Windows has overlapped IO, of course, but CreateFile has to return a handle to the file and you can't get a handle until the file is open. This Stack Overflow question seems to agree and provides more detail. Even if we could, I think it would be pretty challenging because we'd need to somehow apply that to all drivers, ideally without changing their code (because of third party drivers).

Perhaps separately from the issue at hand (but related), I think we should consider one or more of the following:

1. Verify that Windows releases mutexes on process exit. If it does, allow Windows to do it rather than doing it ourselves. That's ugly, but it at least means an appropriate error will be logged when we fail to acquire the mutex.
   • That said, there's a weird "Prior NVDA exited without releasing mutex, taking ownership." log message in nvda.pyw that makes me wonder whether we discovered that Windows doesn't in fact release mutexes on process termination.
2. Have watchdog or similar terminate the process if it doesn't exit within 5 seconds.
3. Have NVDA startup be more aggressive about killing old NVDA instances beyond just searching for the window. I'm not quite sure how we'd do this search; process name is tricky because of source copies. However, the reality of the situation is that having two NVDA instances running at once is clearly very unsafe, and because of how nasty this is and how important a screen reader is to a blind user, we should try to avoid failing like this at any cost.

[XLTechie]

3. Have NVDA startup be more aggressive about killing old NVDA instances beyond just searching for the window. I'm not quite sure how we'd do this search; process name is tricky because of source copies.

Just spitballing here, but if this were a problem in a Linux environment (where I have more experience at process management), I would: 1. Have each process, as its first act, record its PID and name in a PID file of some kind. Alternate, use the most central thread for process reporting and recording. 2. If it's the master process: on start, have it hard kill any PIDs with matching names that remain in the file that aren't part of this run, and remove them once their confirmed dead. Obviously, the PID file/database/whatever would need to use the best locking scheme available, with a rather short timeout for voiding stuck locks. I don't claim a full understanding of all the variables here, so apologies if this is an irrelevant suggestion.

[jcsteh]

Yeah, pid files is where my brain went too, but as I understand it, that's not really something that is done on Windows. I don't really know why. I think even Unix might be moving away from it to some extent with the rise of things like systemd.

Even a pid file doesn't really solve the generic pythonw.exe problem though. You could check the command line arguments (assuming that's possible), but if we're going to do that, we may as well just skip the pid file and do that in the first place.

[XLTechie]

@jcsteh

You could check the command line arguments (assuming that's possible), but if we're going to do that, we may as well just skip the pid file and do that in the first place.

True. So why not do that?

Call every subprocess with manditory first argument "--nvdaParentID=PID", where PID is the actual PID of the main process.

Then, on startup, do something (maybe a little more elegant than, but) similar to this:

import psutil
import globalVars

for p in psutil.process_iter():
	try:
		cLine = p.cmdline()
		if (
			("nvda" in cLine[0] or "python" in cLine[0])  # I would use checks against known possible executable names instead
			and cLine[1].startswith("--nvdaParentID=")
and not cLine[1].endswith(f"={globalVars.appPid}")
		):
			# Kill kill kill!
	except psutil.AccessDenied:
		pass

[XLTechie]

@jcsteh as to Unix/Linux moving away from PID files with the rise of SystemD: I'm not really seeing any evidence of that. SysD does manage processes in a slightly more Windowsish way, but behind the scenes there are still a rather huge number of PID files being used, if /run and /var/run on my Ubuntu 22.4 machines are any indication. Not that this is particularly relevant to why Windows doesn't use them much, upon which I have little idea, unless it is that the Windows service runners that manage most services, just handle process management internally, and expect to be the only ones ever needing to terminate a process.

But I think my above comment may be a lower overhead proposal than PID files anyway, so feel free to hide this comment once you read it.

[jcsteh]

We need to kill the NVDA process itself. It doesn't have a parent process id. There might not necessarily be any subprocesses left. We can scan for nvda.exe and pythonw.exe, but pythonw.exe is ambiguous and even nvda.exe could theoretically be ambiguous. I guess we can live with nvda.exe. For pythonw.exe, we can scan for nvda.pyw. But it still feels risky to my paranoid soul, especially since we're killing these things.

I guess a pid file would at least help to lower the number of false positives, but it doesn't entirely bring it down to 0. There's a very slight chance that someone could start NVDA, force terminate it, start some other thing called nvda.exe which happens to end up with the same pid, and then start NVDA. That new NVDA would then go and kill the unrelated nvda.exe. Yes, this is ridiculously paranoid.

My understanding is that the ideal intent with systemd is that services are managed entirely by systemd. Rather than daemonising themselves, they don't detach; they let systemd handle that. There isn't a need for pid files in this case because systemd knows the pids. Maybe systemd internally creates pid files, I'm not sure. And of course, not every service follows this ideal (according to systemd) pattern, so systemd does support legacy daemons. But as you say, this is getting way off-topic.

[LeonarddeR]

Since #16934, aren't we pretty sure now that the mutex stays behind until NVDA is completely shut down?
I wouldn't care about pythonw.exe indeed.

even nvda.exe could theoretically be ambiguous.

May be we can get the fileinfo for running executables that conflict with ours and compare things like the company as provided in the digital signature? That way we are sure that we aren't killing executables that don't belong to NV Access.

[jcsteh]

Since #16934, aren't we pretty sure now that the mutex stays behind until NVDA is completely shut down?

Yes, and that does address this particular instance. However, I'm concerned about this same pattern happening again, and given how serious the consequences are, I think we should code defensively here, rather than waiting for the next instance to break people badly. To give you some context, I discussed this with Mick because I was seeing it fairly regularly, and sometimes, the only way I could recover was to log out completely.

I wouldn't care about pythonw.exe indeed.

That does make testing this in source copies impossible, which is unfortunate. I guess it's not so bad to require a binary build to test this, though.

May be we can get the fileinfo for running executables that conflict with ours and compare things like the company as provided in the digital signature? That way we are sure that we aren't killing executables that don't belong to NV Access.

That's a fair point, though it does preclude testing without a signature.

[XLTechie]

Would a stub runner be possible?
That is, nvda.exe could start, and immediately check the commandline. If it wasn't given an option, e.g. "--runGroupID" with some kind of GUID (above I used a PID, but the point is that it should be run-unique), it will:

1. Start itself again as an independent process, with the original commandline, but passing in a --nvdaRunID.
2. Exit before initiating the GUI, letting the newly spawned process continue as the "NVDA of record".

At that point, the central process would know the same GUID as any subprocess it spawns.

It could safely kill any correctly named process on the system with a --nvdaRunID that did not match its own, using some variant of the code in my prior comment.
It would lose shell redirects (FDs), but I'm not sure we care.

[LeonarddeR]

I wouldn't care about pythonw.exe indeed.

That does make testing this in source copies impossible, which is unfortunate.

Can we solve this by checking whether there is another executable with the same path running? so ckill another pythonw.exe when it is exactly the same pythonw as the new instance? Since pythonw.exe is started from a venv, it shouldn't interfere with other pythonw.exe instances.

I discussed this with Mick because I was seeing it fairly regularly, and sometimes, the only way I could recover was to log out completely.

That's still pretty serious indeed. Should we reopen this issue or continue in a new one?