Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Code actions can be requested on document that is not yet opened #83338

Closed
mjbvz opened this issue Oct 26, 2019 · 12 comments
Closed

Code actions can be requested on document that is not yet opened #83338

mjbvz opened this issue Oct 26, 2019 · 12 comments
Assignees
Labels
bug Issue identified by VS Code Team member as probable bug verified Verification succeeded
Milestone

Comments

@mjbvz
Copy link
Contributor

mjbvz commented Oct 26, 2019

Issue Type: Bug

Repo

  1. Create a ts file a.ts with the content const i = error
  2. rename the file to b.ts
  3. Rename it back to a.ts
  4. Then back to b.ts

Bug
See unexpected resource printed in the dev tools console

The root cause seems to be that we end up requesting code actions for b.ts before it that file is properly reopened. I added logs in onDidAddTextDocument and provideCodeActions. Here's what they show:

Screen Shot 2019-10-25 at 5 26 44 PM

Noticed how in the last few frames actions are requested for b.ts before the open for b.ts is fired

VS Code version: Code - OSS Dev 1.40.0 (Commit unknown, Date unknown)
OS version: Darwin x64 18.7.0

System Info
Item Value
CPUs Intel(R) Core(TM) i7-4770HQ CPU @ 2.20GHz (8 x 2200)
GPU Status 2d_canvas: enabled
flash_3d: enabled
flash_stage3d: enabled
flash_stage3d_baseline: enabled
gpu_compositing: enabled
metal: disabled_off
multiple_raster_threads: enabled_on
oop_rasterization: disabled_off
protected_video_decode: unavailable_off
rasterization: enabled
skia_renderer: disabled_off
surface_control: disabled_off
surface_synchronization: enabled_on
video_decode: enabled
viz_display_compositor: enabled_on
viz_hit_test_surface_layer: disabled_off
webgl: enabled
webgl2: enabled
Load (avg) 3, 3, 3
Memory (System) 16.00GB (1.23GB free)
Process Argv .
Screen Reader no
VM 25%
@mjbvz mjbvz self-assigned this Oct 26, 2019
@mjbvz mjbvz added the bug Issue identified by VS Code Team member as probable bug label Oct 26, 2019
@mjbvz
Copy link
Contributor Author

mjbvz commented Oct 26, 2019

I've starting debugged this and it looks like onDidAddTextDocument is never fired for the last rename. I added a logpoint in ModelService.createModel and here's what I see happening:

Screen Shot 2019-10-25 at 5 47 23 PM

Starting with a file a.ts:

  1. On the rename of a.ts to b.ts, createModel is invoked for b.ts
  2. On the rename of b.ts back to a.ts, createModel is invoked for a.ts
  3. On the rename of a.ts to b.ts again, createModel is not invoked

@alexandrudima or @bpasero: Do you know why this may be happenig? Is it expected?

@bpasero
Copy link
Member

bpasero commented Oct 26, 2019

I cannot reproduce this, I get 3 createModel calls properly:

image

@mjbvz
Copy link
Contributor Author

mjbvz commented Oct 29, 2019

@bpasero I can confirm this does not happen for plain text files. Can you test using a TS file containing a quick fix. I just tested this using the oss build (no extensions) in an empty workspace and can still repo this in a TS file using my original repo steps:

Screen Shot 2019-10-28 at 8 04 56 PM

@mjbvz mjbvz added this to the November 2019 milestone Oct 29, 2019
@bpasero
Copy link
Member

bpasero commented Oct 29, 2019

Can you test using a TS file containing a quick fix.

How?

@alexdima
Copy link
Member

@bpasero I think the workbench is acting a bit funny around renaming, but I am not sure if it is necessarily a bug... On the second rename the workbench no longer disposes the old model, but it decides to keep it around, even if the file is deleted on disk... which is a bit bizarre.

I have disabled git to reduce noise with text models.


Here is how things look like for an extension:

@mjbvz Here is how it looks from an extension point of view

I have done the following diff to TS in extension.ts:
image

And in features/quickFix.ts:
image

Rename a.ts to b.ts.:

  • onDidCloseTextDocument: file:///c%3A/Alex/src/working_dir/a.ts
  • documents:
  • onDidOpenTextDocument: file:///c%3A/Alex/src/working_dir/b.ts
  • documents: file:///c%3A/Alex/src/working_dir/b.ts
  • TypeScriptQuickFixProvider.provideCodeActions for file:///c%3A/Alex/src/working_dir/b.ts

Rename b.ts to a.ts. Note how b.ts is not closed:

  • onDidOpenTextDocument: file:///c%3A/Alex/src/working_dir/a.ts
  • documents: file:///c%3A/Alex/src/working_dir/b.ts file:///c%3A/Alex/src/working_dir/a.ts
  • TypeScriptQuickFixProvider.provideCodeActions for file:///c%3A/Alex/src/working_dir/a.ts

Rename a.ts to b.ts. Note how no open/close text document events are emitted, since b.ts was not closed so it is still open:

  • Unexpected resource file:///c%3A/Alex/src/working_dir/b.ts
  • TypeScriptQuickFixProvider.provideCodeActions for file:///c%3A/Alex/src/working_dir/b.ts

Here is how things look like in our IModelService:

I have added logging in two places in src/vs/editor/common/services/modelServiceImpl.ts

image

image

Open workbench with a.ts:

  • createModel file:///c%3A/Alex/src/working_dir/a.ts
  • ==> models alive: file:///c%3A/Alex/src/working_dir/a.ts

Rename a.ts to b.ts. Note how a.ts is disposed and b.ts is created:

  • destroyModel file:///c%3A/Alex/src/working_dir/a.ts
  • ==> models alive:
  • createModel file:///c%3A/Alex/src/working_dir/b.ts
  • ==> models alive: file:///c%3A/Alex/src/working_dir/b.ts

Rename b.ts to a.ts. Note how now the workbench decides to keep b.ts around and not dispose it.

  • createModel file:///c%3A/Alex/src/working_dir/a.ts
  • ==> models alive: file:///c%3A/Alex/src/working_dir/b.ts,file:///c%3A/Alex/src/working_dir/a.ts

Rename b.ts to a.ts. Note how no events are generated because b.ts was around, but the following exception appears from TS:

  • [Extension Host] Unexpected resource file:///c%3A/Alex/src/working_dir/b.ts

@bpasero
Copy link
Member

bpasero commented Oct 29, 2019

@bpasero I think the workbench is acting a bit funny around renaming

I am not convinced. This must be something else. We have a very simple ref-counting model of text editor models. The editor will try to dispose the model when it gets closed, but if someone else managed to get hold of the model (via ITextModelResolverService), the model will not be disposed until the last reference is freed.

This smells like the extension host asking for a reference to the model (for the quick fix?) and then holding onto the model for a while (@jrieken might know) and only then dispose it.

I think the issue here is that the extension host is not disposing the reference at the time it is not needed anymore, but only after a delay.

@bpasero
Copy link
Member

bpasero commented Oct 29, 2019

PS: the reason why I think another party is involved is that I still cannot reproduce this when simply having an empty file a.ts. Just give that a try.

createModel: file:///Users/bpasero/Desktop/modeldispose/a.ts
models alive: file:///Users/bpasero/Desktop/modeldispose/a.ts
destroyModel: file:///Users/bpasero/Desktop/modeldispose/a.ts
models alive: 
createModel: file:///Users/bpasero/Desktop/modeldispose/b.ts
models alive: file:///Users/bpasero/Desktop/modeldispose/b.ts
destroyModel: file:///Users/bpasero/Desktop/modeldispose/b.ts
models alive: 
createModel: file:///Users/bpasero/Desktop/modeldispose/a.ts
models alive: file:///Users/bpasero/Desktop/modeldispose/a.ts

@alexdima
Copy link
Member

👍 Yeah, I'm pretty sure the fact that we see code actions (which must be disposed!!) has something to do with it... So the ball moves to @jrieken to investigate who is doing model references which prevent the model from getting disposed.

@jrieken
Copy link
Member

jrieken commented Oct 29, 2019

This smells like the extension host asking for a reference to the model (for the quick fix?) and then holding onto the model for a while (@jrieken might know) and only then dispose it.

The extension host is only doing that when an extension calls openTextDocument, for all language features, like quick fix, suggestion etc it is not doing that - the assumption (and assertion) is that the a document has been opened before running any language feature.

@mjbvz where is that assertion you see failing? It is not this, right? Is this inside tsserver and how is that being updated?

@jrieken
Copy link
Member

jrieken commented Oct 29, 2019

Screenshot 2019-10-29 at 15 49 44

So, looks like TS itself is calling openTextDocument when a rename happens. That would explain why the model isn't disposed immediately (references created on behalf of extensions are auto disposed after a short while).

Tho, I don't know where tsserver is missing the document. The extension host has it, otherwise the call to the code action provider wouldn't event happen (see my previous comment).

@alexdima
Copy link
Member

Perhaps tsserver is listening to file change events from the disk and on the disk the file is deleted ?

@mjbvz
Copy link
Contributor Author

mjbvz commented Oct 29, 2019

Thank you for looking into this. I now have a better understanding of what is going on.

I think the root cause is that the lifetime of a TextDocument does not have to match the lifetime of a user document in the editor. The JS/TS extension only cares about TextDocuments that users see in the editor. If an extension holds on to a TextDocument that the user then deletes it (or renames it), we generally don't want to keep synchronizing the old document with the tsserver.

Here is the sequence of events:

  1. Starting with a file a.ts

    • TS extension creates a synchronized buffer for a.ts. This buffer is automatically synchronized with tsserver by the extension
  2. Rename a.ts to b.ts

    • First we see onDidCloseTextDocument fired with a.ts. This causes the js/ts extension to close the synchronized buffer for a.ts.
    • Then we see openTextDocument fired for b.ts. This creates a synced buffer for b.ts
    • Then we hit the updatePaths rename logic in flushRenames. This calls openTextDocument on a.ts (which also should be a noop I believe since the document is already open?) It also again tries to close the synchronized buffer for a.ts (which is a noop since we already closed it).
  3. Rename b.ts to a.ts

    • There is no onDidCloseTextDocument for b.ts (This likely means someone is holding on to a reference to b.ts)
    • Then we see onDidOpenTextDocument fired with a.ts. This causes the js/ts extension to create a new synchronized buffer for a.ts
    • Then we hit the updatePaths rename logic in flushRenames. This closes the buffer for b.ts (however the TextDocument for b.ts is still live)
  4. Rename a.ts back to b.ts

    • No events are triggered this time. This means that a TextDocument for b.ts already exists so no onDidOpenTextDocument is not fired, and that someone is holding on the the TextDocument for a.ts so onDidCloseTextDocument is not fired either.
    • Now the code action provider is fired on b.ts. It tries to ensure that tsserver has a synchronized buffer for b.ts, however it does not so we log this error.
    • A little while later, flushRenames kicks in and explicitly opens a buffer for b.ts, which is why you only see the error once.

I'm going to look into who is holding on to these text documents that prevents the open and close events from firing. I'm also going to see if our TypeScript code can be more robust and check the list of TextDocuments before complaining that no syncrhonized buffer exists.

@mjbvz mjbvz modified the milestones: November 2019, October 2019 Oct 29, 2019
@mjbvz mjbvz closed this as completed in c80fb1b Oct 29, 2019
@jrieken jrieken added the verified Verification succeeded label Oct 31, 2019
@vscodebot vscodebot bot locked and limited conversation to collaborators Dec 16, 2019
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
bug Issue identified by VS Code Team member as probable bug verified Verification succeeded
Projects
None yet
Development

No branches or pull requests

5 participants
@bpasero @jrieken @alexdima @mjbvz and others