Invalid add-on store cache in latest alphas, whole cache dumpped to log

[XLTechie]

Steps to reproduce:

Run one of the last few alphas, since merger of #15071.

Actual behavior:

An error sound plays on startup. "Invalid add-on store cache" is reported in the log, and the whole cache is dumped to the log in JSON form.
Additionally, an invalid hash is reported:

Traceback (most recent call last):
  File "_addonStore\dataManager.pyc", line 164, in _getCachedAddonData
KeyError: 'cacheHash'

Expected behavior:

No error, no cache dump, no invalid hash.

NVDA logs, crash dumps and other attachments:

nvda-badcachehash.txt

System configuration

NVDA installed/portable/running from source:

Installed

NVDA version:

alpha-28628,67ecd257

Windows version:

10

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

N/A

Other information about your system:

Other questions

Does the issue still occur after restarting your computer?

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

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?

N/A

[XLTechie]

CC @nvdaes

[nvdaes]

Hi Luke, I think this is expected and should be resolved when add-ons are cached and the json files are saved again.
Have you tried restarting NVDA and opening the store to fetch last and compatible add-ons?

[XLTechie]

@nvdaes yes, it still does this on every startup, even after the store has been loaded and exited. Regardless, how can dumping the entire add-on cache JSON to the log, followed by a KeyError, be expected behavior? I have not looked into why the hash is not a valid key, but if this is expected then the cache should not be dumped to the log--it takes up a lot of log space. Perhaps this entire exception should be silently suppressed, or replaced with a reasonable log message? This seems like very unusual expected behavior.

[nvdaes]

Have checked that your json files can be modified? I cannot reproduce this after fetching add-ons.
About storing the cache in the log, I think that @seanbudd suggested to do it and I support this in case it makes easy to debug some kind of error

[XLTechie]

I confirm that no JSON files are read-only, I have checked all their attributes individually. I do note that the cache date shown in the logged JSON--6/19/2023--is the same as the date shown in Explorer for the _cachedLatestAddons.json file. Maybe this file is not being rewritten for some reason? I could just delete this file and NVDA will recreate it, but I would rather see the cause of the error be fixed in code. My guess, and it's only a guess, is that the cache on disk is being checked for validity before it is updated, and if it fails it is not updated. I think if it fails it should be updated immediately.

[nvdaes]

My guess, and it's only a guess, is that the cache on disk is being checked for
validity before it is updated, and if it fails it is not updated.
I think if it fails it should be updated immediately.

In my case, in a portable version of an old alpha (which had a cacheDate key) has been updated. I think that Sean will provide more details about this.

[seanbudd]

I believe this issue would solve itself if you opened the add-on store and view available add-ons - can you confirm?

[seanbudd]

I think we should just delete invalid cache files - I've opened #15111 to do this

[XLTechie]

@seanbudd no. @nvdaes already suggested the same, and it does not. Next restart, same problem.

[XLTechie]

@seanbudd I even went into the store, accessed available add-ons, downloaded an update that was listed as available, and restarted. The keyError still happens, the whole cache is still dumpped to log, and the date at the start of the JSON is still 2023-06-19.