Regression: Unable to update add-ons containing dynamic link libraries.

[cary-rowen]

Steps to reproduce:

1. Install this add-on: https://github.com/cary-rowen/AudioControl/releases/download/v1.8.1/AudioControl-1.8.1.nvda-addon
2. After the add-on has been installed and restarted, try installing it again to simulate the update process.

Actual behavior:

You will get an error:Failed to install add-on from D:\audioControl-1.8.1.nvda-addon
Error log snippet:

ERROR - gui.addonGui.installAddon (09:25:32.966) - MainThread (3700):
Error installing  addon bundle from D:\audioManager-1.0.0.nvda-addon
Traceback (most recent call last):
  File "addonHandler\__init__.pyc", line 464, in completeRemove
PermissionError: [WinError 5] 拒绝访问。: 'C:\\Users\\cary\\AppData\\Roaming\\nvda\\addons\\audioManager' -> 'C:\\Users\\cary\\AppData\\Roaming\\nvda\\addons\\tmpbzig4yv2.delete'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "gui\addonGui.pyc", line 553, in installAddon
  File "addonHandler\__init__.pyc", line 438, in requestRemove
  File "addonHandler\__init__.pyc", line 466, in completeRemove
RuntimeError: Cannot rename add-on path for deletion

Restarting NVDA gives the following error:

ERROR - addonHandler.Addon.completeInstall (09:34:02.103) - MainThread (808):
Failed to complete addon installation for audioControl
Traceback (most recent call last):
  File "addonHandler\__init__.pyc", line 429, in completeInstall
FileExistsError: [WinError 183] 当文件已存在时，无法创建该文件。: 'C:\\Users\\cary\\AppData\\Roaming\\nvda\\addons\\audioControl.pendingInstall' -> 'C:\\Users\\cary\\AppData\\Roaming\\nvda\\addons\\audioControl'
DEBUG - addonHandler._getAvailableAddonsFromPath (09:34:02.264) - MainThread (808):
Found add-on audioControl - 1.8.1. Requires API: (2022, 4, 0). Last-tested API: (2023, 1, 0)
DEBUG - addonHandler._getAvailableAddonsFromPath (09:34:02.264) - MainThread (808):
Loading add-on from C:\Users\cary\AppData\Roaming\nvda\addons\audioControl.pendingInstall
DEBUG - addonHandler.Addon.__init__ (09:34:02.264) - MainThread (808):
Using manifest translation from C:\Users\cary\AppData\Roaming\nvda\addons\audioControl.pendingInstall\locale\zh_CN\manifest.ini

Expected behavior:

The add-on is installed without popping up an error dialog, although the old add-on directory cannot be deleted immediately because it contains occupied files(DLL files).
After the next restart of NVDA, the old add-on directory is deleted and the add-on is updated.
This is the behavior of NVDA-2023.1

NVDA logs, crash dumps and other attachments:

Logs have been provided above.

System configuration

NVDA installed/portable/running from source:

installed and portable

NVDA version:

alpha-28387

Windows version:

Windows 10 22H2 (AMD64) build 19045.2965

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

None

Other information about your system:

None

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-2023.1 cannot reproduce.

If NVDA 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

[cary-rowen]

cc @seanbudd
I'm guessing this is a regression introduced by #13985.

[nvdaes]

I can confirm this with your provided add-on, but not with piper Neural Voices. I get an error with a sound, but when NVDA is restarted in the seccond installation, then the add-on is installed, and I've checked that it contains at least a .dll file.

[cary-rowen]

If it's because I'm using ctypes wrong then I'd love to know the correct way to do it.
But judging by NVDA performance, this is indeed a regression.

[nvdaes]

If it's because I'm using ctypes wrong then I'd love to know the correct way to do it.

Sorry Cary, I didn't tested properly. The behavior with audioControl and Piper add-on is the same: seems that they can be reinstalled but when previously they are disabled. I don't know if this regression is caused for the store or due to anything else related to the usage of files when trying to remove them.

[cary-rowen]

I suspect this is caused by the store, I also tried looking for the problem in the code.

[mzanm]

Have you tried unloading the DLL you're using in the Terminate method of the global plugin? It seems to be blocked from deleting it because of the DLL being open in NVDA.

[cary-rowen]

Hi @mzanm
But I think the point of the problem is that the same code works fine on NVDA2023.1. I think NVDA 2023.1 handles this properly.
Also, I don't think the DLL needs an explicit release.
Thanks

[seanbudd]

Can you upload a full log file or send it info@nvaccess.org. Please reproduce this issue and provide a full log file of the behaviour. Ensure your log level is set to debug in general preferences.

Can you also do the same for 2023.1, we haven't significantly changed the add-on bundle installation process.
A suspect cause is that add-ons are now started when they are pending removal

[cary-rowen]

Hi @seanbudd

Can you also do the same for 2023.1, we haven't significantly changed the add-on bundle installation process.

NVDA-2023.1 cannot reproduce the issue, add-ons can be updated successfully.

With audioControl installed, reinstalling the add-on to simulate the process of updating the add-on, NVDA throws an error: Here is the full log during the process.
1.txt
Try restarting NVDA manually, the log after restarting is as follows:
2.txt

[cary-rowen]

I have a new discovery: Add-ons can be updated normally using Add-onUpdater.

[seanbudd]

Thanks, with the full log file this code snippet contains more context

DEBUG - addonHandler.Addon.loadModule (09:38:12.553) - gui.ExecAndPump(<function installAddonBundle at 0x0372D4B0>) (2552):
Importing module installTasks from plugin Addon ('audioControl', running=False)
DEBUG - addonHandler.Addon.loadModule (09:38:12.558) - MainThread (3780):
Importing module installTasks from plugin Addon ('audioControl', running=False)
IO - tones.beep (09:38:12.558) - MainThread (3780):
Beep at pitch 1760, for 40 ms, left volume 50, right volume 50
ERROR - gui.addonGui.installAddon (09:38:12.558) - MainThread (3780):
Error installing  addon bundle from D:\MyData\心音音乐工作室\nvda 中文站 - NVDACN\NVDA-Addons\New\audioControl-1.8.1.nvda-addon
Traceback (most recent call last):
  File "addonHandler\__init__.pyc", line 464, in completeRemove
PermissionError: [WinError 5] 拒绝访问。: 'C:\\Users\\cary\\AppData\\Roaming\\nvda\\addons\\audioControl' -> 'C:\\Users\\cary\\AppData\\Roaming\\nvda\\addons\\tmpe0a8_rse.delete'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "gui\addonGui.pyc", line 553, in installAddon
  File "addonHandler\__init__.pyc", line 438, in requestRemove
  File "addonHandler\__init__.pyc", line 466, in completeRemove
RuntimeError: Cannot rename add-on path for deletion
IO - speech.speech.speak (09:38:12.633) - MainThread (3780):
Speaking [LangChangeCommand ('zh_CN'), 'Error', 'dialog', 'Failed to install add-on from D:\\MyData\\心音音乐工作室\\nvda 中文站 - NVDACN\\NVDA-Addons\\New\\audioControl-1.8.1.nvda-addon', CancellableSpeech (still valid)]
IO - speech.speech.speak (09:38:12.633) - MainThread (3780):
Speaking [LangChangeCommand ('zh_CN'), 'OK', 'button', CancellableSpeech (still valid)

[LeonarddeR]

I'm pretty sure I know what's causing this. It can become pretty clear if you compare the implementations of isPendingInstall

Old implementation:

	def isPendingInstall(self):
		return self.path.endswith(ADDON_PENDINGINSTALL_SUFFIX)

New implemenation:

	def isPendingInstall(self) -> bool:
		return Path(self.pendingInstallPath).exists()

The old implementation checks whether the addon has the pending install fsuffix in its path. Then, when calling requestRemove, completeRemove is run when isPendingInstall is True. This ensures that the uninstall behavior runs instantly when calling requestRemove for add-ons that are installed but directly removed thereafter.
Now the new implementation checks whether there is a pending suffix add-on available without actually checking whether the instance is the pending install itself. Therefore, isPendingInstall will return True for the not pending instance as well. This means that isPendingInstall is True erroneously and completeRemove is executed for a running add-on.

[cary-rowen]

Hi @seanbudd
With @LeonarddeR's analysis, the problem becomes clearer. Will you provide a PR to fix this?
Thanks

[paulber19]

Hi. I confirm that this regression still exists in the latest alpha version of NVDA: NVDA version alpha-28542.8accbfa7 This error also occurs when installing other add-ons like "Monitor resource", "sound splitter", "volume adjustment" and "NVDAExtensionGlobalPlugin. Here is an example with "Monitor resource": DEBUG - addonHandler.Addon.loadModule (15:42:15.791) - MainThread (5372): Importing module installTasks from plugin Addon ('resourceMonitor', running=False) ERROR - addonHandler.Addon.completeRemove (15:42:16.786) - MainThread (5372): Error removing addon directory F:\documents\Paulo\temp\nvda alpha Noémie\userConfig\addons\resourceMonitor, deferring until next NVDA restartwhen All the add-ons mentioned use the same "psutil" library and load it when they start. If this library is not loaded, there is no error. The difference between NVDA 2023.1 (or earlier) and these latest NVDA alpha versions is when the add-on folder is deleted. With 2023, this deletion was done when restarting NVDA. With the alpha, the deletion is done immediately upon installing the add-on before restarting NVDA, ie with an add-on running. If NVDA is not restarted, NVDA continues to work with an add-on that no longer has a folder. Which, by the way, can cause problems if not all of its modules have been loaded before deletion. This is behavior that I do not find normal. If the deletion of the add-on folder must be done at this time, it seems necessary to ask the add-on to end before this deletion. I think this issue needs to be addressed rather in P1 to be resolved before the release of NVDA 2023.2. Sorry this is an automatic translation. Best regards. Paul. Le 19/06/2023 08:41, Leonard de Ruijter a écrit :

…

I'm pretty sure I know what's causing this. It can become pretty clear if you compare the implementations of |isPendingInstall| Old implementation: | def isPendingInstall(self): return self.path.endswith(ADDON_PENDINGINSTALL_SUFFIX) | New implemenation: | def isPendingInstall(self) -> bool: return Path(self.pendingInstallPath).exists() | The old implementation checks whether the addon has the pending install fsuffix in its path. Then, when calling requestRemove, completeRemove is run when isPendingInstall is True. This ensures that the uninstall behavior runs instantly when calling requestRemove for add-ons that are installed but directly removed thereafter. Now the new implementation checks whether there is a pending suffix add-on available without actually checking whether the instance is the pending install itself. Therefore, isPendingInstall will return True for the not pending instance as well. This means that isPendingInstall is True erroneously and completeRemove is executed for a running add-on. — Reply to this email directly, view it on GitHub <#14991 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ADZLFFCZ5QRFIQVHEHQOSD3XL7YCZANCNFSM6AAAAAAZAAFC64>. You are receiving this because you are subscribed to this thread.Message ID: ***@***.***>

[seanbudd]

Could folks please test this try-build:

https://ci.appveyor.com/api/buildjobs/mnwso9c3vy5rgx0e/artifacts/output%2Fnvda_snapshot_try-fix-14991-28658%2C2cba2382.exe

Let me know if there are any issues installing, removing or updating add-ons.
The manual test plan may be useful: https://github.com/nvaccess/nvda/blob/master/tests/manual/addonStore.md#installing-add-ons

[nvdaes]

Following steps to reproduce described by @cary-rowen , it works fine now.

[cary-rowen]

Hi @seanbudd, I confirm that the build you provided above works fine.