Weird strong cache for require() at extension runtime

[ayqy]

Version: 1.40.0
Commit: 86405ea
Date: 2019-11-06T17:09:34.601Z
Electron: 6.1.2
Chrome: 76.0.3809.146
Node.js: 12.4.0
V8: 7.6.303.31-electron.0
OS: Darwin x64 19.0.0

Steps to Reproduce:

1. Build a simple extension to just read a json file (e.g. config.json) opened at workspace using require(fullFilePath), and print a specified filed (e.g. version);

2. Trigger reading via command, and get output value (e.g. 0.0.1)

3. Edit this json file, change to 0.1.1 and save

4. Trigger reading via command, and still get the ORIGINAL output value (e.g. 0.0.1)

Nothing changed after restart multi-times, and found these error message at DevTools several times:

[Extension Host] FAILED TO VERIFY CACHED DATA. Deleting 'xxx/Library/Application Support/Code/CachedData/30fc53c35cbe62069e550ea6decad6fb5f17cd4b/config-5d7f390c22fd0c6ed44ca9d6999661ec.code' now, but a RESTART IS REQUIRED
[Extension Host] FAILED to unlink: 'xxx/Library/Application Support/Code/CachedData/30fc53c35cbe62069e550ea6decad6fb5f17cd4b/config-5d7f390c22fd0c6ed44ca9d6999661ec.code' null

Does this issue occur when all extensions are disabled?: Yes

[jrieken]

Sounds more scary than it actually is - when loading a file into V8 we produce cached data so that subsequent starts are faster. When a file changed in-between loads (like the config.json-file) its cached data is rejected and these messages are printed. We should make them sound less scary as nothing real has changed

[ayqy]

@jrieken Dig a bit more deeply into this problem, it seems to match the stale cache by mistake, so we can not read the latest change via require().

And it is a serious problem for some extensions that needs to load project configuration files (such as webpack configurations), users may be crazy for these cache.

P.S. I workaround this by deleting module cache manually.

[jrieken]

P.S. I workaround this by deleting module cache manually.

The simplest workaround is to not use require but to use fs.readFileSync. VS Code creates cached data files (https://v8.dev/blog/code-caching) and we assume that source files don't change after having them loaded und unloading them might work.

[jrieken]

I have changed the way how messages are logged and that's all I can do here. The caching of module is a node-thing that you get when using require - either massage the cache or use readFileSync

[ayqy]

The simplest workaround is to not use require but to use fs.readFileSync.

It's impossible if I want to read .js files, e.g. webpack config (webpack.config.js) as you know.

IMO, it's not an unimportant log by mistake, and silent failure is the worst solution.

Think about this, whether we should patch a custom module loader using fs.readFileSync to avoid the bad cache? @jrieken

[jrieken]

It's impossible if I want to read .js files, e.g. webpack config (webpack.config.js) as you know.

So how exactly are you patching a JSON-file that has been bundled?

[ayqy]

So how exactly are you patching a JSON-file that has been bundled?

JSON file is a simple case to reproduce the problem only. As I mentioned above, it's a common scenario:

Build a simple extension to just require a .js file (e.g. webpack.config.js) opened at workspace.

Users may edit their .js files, but extension CAN NOT re-require the new content in time, even after they shut down their VS Code entirely and reopen. How scary it is!

Even though I workaround this by delete V8 cache manually, I don't think that's a reasonable solution at all, so file the issue for your help. But, if the warning changes to be silent failure, please rollback the codes and just ignore this problem directly, because it will make the thing worse.

[jrieken]

but extension CAN NOT re-require the new content in time, even after they shut down their VS Code entirely and reopen. How scary it is!

I don't know why you say that, because that's not how it's implemented and not how it works. We create cached data and save that, if the source file for that cached data has changed in the meantime it will be dropped. That fact that require caches is unrelated to all of that and when you say "...workaround this by delete V8 cache manually..." then I don't think that you delete the cached data files VS Code creates or do you?

[ayqy]

That fact that require caches is unrelated to all of that...

Actually it is. The problem gone after deleting require cache:

function requireUncached(module){
    delete require.cache[require.resolve(module)]
    return require(module)
}

And I respect the new cache mechanism, the key is it breaks these extensions now. Could you please follow the reproduce steps above and have a look at what happened, then from a extension's point of view to think about this ?

P.S.More clearly, requireUncached is not working if there are deep require()s, so we iterates V8's call map to delete the require cache tree as what decache module done.

[jrieken]

And I respect the new cache mechanism, the key is it breaks these extensions now.

Unsure what you mean - we use cached data since couple of years already, for extensions I believe it's two years, for the rest of VS Code since much longer. Also, it is unrelated to require and how that caches. Your uncache trick seems legit but I don't understand how this is related to v8-cached data and would believe that in plain node you have the same problem.

[ayqy]

believe that in plain node you have the same problem.

Exactly, we can not require new module content if there's require cache in Node.js. But what if I exit and start a new Node.js process, it should require fresh module file, right ?

However, at extension runtime:

extension CAN NOT re-require the new content in time, even after they shut down their VS Code entirely and reopen.

And it seems these cache introduced several month ago, the strong cache after shut down does not exist on v1.28.0 as far as I know.

[ayqy]

FYI. fef6ca7

[ayqy]

@jrieken Sadly, you are right. I can not workaround this problem by deleting module require cache.

Technically, can we provide a flag to disable this kind of cache for debug purpose (e.g. something like --disable-extensions) ?

Or a whitelist for 3rd extensions ? Think about that build-in extensions are more controllable and applicable for performance profit.

[jrieken]

That flag exists as --no-cached-data. As said, we don't expect JS sources to be changing after having the installed. For JSON files, fs.writeFile should be sufficient.

[mike-lischke]

I also see this problem, but with a different situation. In my ANTLR4 extension I use an JS file which contains code for predicates, used in parsing. For debugging and sentence generation this file must be changable at all times, without restarting vscode. For this I use code to delete the cached module and reload it, whenever a debug session or sentence generation starts.

The problem here is similar to what the OP reports: first I see no change, the predicates execute with the old code and after a few seconds the mentioned warnings appear in the console. After that the new code is used instead.

The main problem for me is however not the warnings

extension.js:156
FAILED TO VERIFY CACHED DATA. Deleting '/Users/mike/Library/Application Support/Code/CachedData/26076a4de974ead31f97692a0d32f90d735645c0/MySQLPrediction-bcd77ccd600476d43007f8b18f3c8c94.code' now, but a RESTART IS REQUIRED
loader.js:19
FAILED to unlink: '/Users/mike/Library/Application Support/Code/CachedData/26076a4de974ead31f97692a0d32f90d735645c0/MySQLPrediction-bcd77ccd600476d43007f8b18f3c8c94.code' null

but the fact that the code is refreshed with a delay, which can confuse the user seriously.

In this case I can neither use fs.readFileSync nor --no-cached-data.

[jrieken]

For debugging and sentence generation this file must be changable at all times, without restarting vscode.

Is this during the time in which you develop the extension or after having shipped the extension? In the former case --no-cached-data should work for you, right?

[mike-lischke]

Applies to both, during development and when shipped. I should add that when I talk about debugging, I mean my grammar debugging (with a custom debug adapter), which is also possible with the shipped extension.

[jrieken]

And those grammar files are inside the extension installation location or somewhere else?

[mike-lischke]

No, the action (predicate) files can be anywhere on a user's disk. Usually I expect them to be in the workspace.

[jrieken]

@mike-lischke That's unfortunate but I am not yet willing to give up fast code loading for extensions (which is why this happens). Would you be able to use the runInThisContext API instead of using require?

[mike-lischke]

Thanks for the suggestion, but how would I unload the code I run with this function, before loading the changed code? A module can much more easily be removed, module variables disappear etc. and module content is isolated. And I believe you can debug code loaded with require(), but I'm unsure and have to check this.

[jrieken]

I don't think that you can safely unload arbitrary code, esp not when loaded via require. How would the unloader know what listeners to dispose, what globals the code as set, what APIs with stateful side effects it has used etc (e.g that's the reason vscode needs to restart when uninstalling extensions).

Anyways, the VM-module might be able to help you. While it also cannot unload code it allows to load code into a new context, see https://nodejs.org/dist/latest-v12.x/docs/api/vm.html#vm_vm_runinnewcontext_code_sandbox_options, and when loading something again you can load it in yet another new context. That might be helpful for you