Stale diagnostic locations being returned with format on paste

[mjbvz]

TypeScript Version: 3.0.0-dev.20180706

Bug In VS Code, when using the format on paste setting, I've noticed that we sometimes end up displaying diagnostics at incorrect locations. Editing the file fixes this problem. I've tried tracking this down and believe that the TS server may be returning stale locations in this case.

Here's the sequence of events:

1. User pastes an some code that includes tabs onto an existing line.

   Here I've pasting a line: \t\tthis.fileConfigManager.ensureConfigurationForDocument(document, token);\n into code that looks like:

   class OrganizeImportsCommand implements Command {
       public async execute(file: string): Promise<boolean> {
           | PASTE HERE
   
           const args: Proto.OrganizeImportsRequestArgs = { };
                   ....
       }
   }

   This triggers a change against tsserver

   Info 5011 [21:46:36.187] request:
       {"seq":501,"type":"request","command":"change","arguments":{"insertString":"\t\tthis.fileConfigManager.ensureConfigurationForDocument(document, token);\n","file":"/Users/matb/projects/vscode/extensions/typescript-language-features/src/features/organizeImports.ts","line":29,"offset":3,"endLine":29,"endOffset":3}}
   Perf 5012 [21:46:36.187] 501::change: async elapsed time (in milliseconds) 0.1477

2. Back in vscode, we run format and send tsserver another change request after applying the edit. In this case the change remove the two extra tabs that were added from the paste

   Info 5013 [21:46:36.187] request:
       {"seq":502,"type":"request","command":"format","arguments":{"file":"/Users/matb/projects/vscode/extensions/typescript-language-features/src/features/organizeImports.ts","line":29,"offset":3,"endLine":30,"endOffset":1}}
   Perf 5014 [21:46:36.197] 502::format: elapsed time (in milliseconds) 10.5431
   Info 5015 [21:46:36.197] response:
       {"seq":0,"type":"response","command":"format","request_seq":502,"success":true,"body":[{"start":{"line":29,"offset":1},"end":{"line":29,"offset":5},"newText":"\t\t"}]}
   Info 5016 [21:46:36.207] request:
       {"seq":503,"type":"request","command":"change","arguments":{"insertString":"","file":"/Users/matb/projects/vscode/extensions/typescript-language-features/src/features/organizeImports.ts","line":29,"offset":3,"endLine":29,"endOffset":5}}
   Perf 5017 [21:46:36.207] 503::change: async elapsed time (in milliseconds) 0.1534

3. We then kick off a geterr request a little later.

   Info 5024 [21:46:36.508] request:
       {"seq":506,"type":"request","command":"geterr","arguments":{"delay":0,"files":["/users/matb/projects/vscode/extensions/typescript-language-features/src/features/organizeimports.ts"]}}
   Perf 5025 [21:46:36.508] 506::geterr: async elapsed time (in milliseconds) 0.3785
   Info 5026 [21:46:36.510] Starting updateGraphWorker: Project: /Users/matb/projects/vscode/extensions/typescript-language-features/tsconfig.json
   Info 5027 [21:46:36.510] Finishing updateGraphWorker: Project: /Users/matb/projects/vscode/extensions/typescript-language-features/tsconfig.json Version: 43 structureChanged: false Elapsed: 0ms
   Info 5028 [21:46:36.510] Starting updateGraphWorker: Project: /Users/matb/projects/vscode/extensions/typescript-language-features/tsconfig.json
   Info 5029 [21:46:36.510] Finishing updateGraphWorker: Project: /Users/matb/projects/vscode/extensions/typescript-language-features/tsconfig.json Version: 43 structureChanged: false Elapsed: 0ms
   Info 5030 [21:46:36.510] event:
       {"seq":0,"type":"event","event":"syntaxDiag","body":{"file":"/users/matb/projects/vscode/extensions/typescript-language-features/src/features/organizeimports.ts","diagnostics":[]}}
   Info 5031 [21:46:36.511] Starting updateGraphWorker: Project: /Users/matb/projects/vscode/extensions/typescript-language-features/tsconfig.json
   Info 5032 [21:46:36.511] Finishing updateGraphWorker: Project: /Users/matb/projects/vscode/extensions/typescript-language-features/tsconfig.json Version: 43 structureChanged: false Elapsed: 0ms
   Info 5033 [21:46:36.529] event:
       {"seq":0,"type":"event","event":"semanticDiag","body":{"file":"/users/matb/projects/vscode/extensions/typescript-language-features/src/features/organizeimports.ts","diagnostics":[{"start":{"line":29,"offset":10},"end":{"line":29,"offset":27},"text":"Property 'fileConfigManager' does not exist on type 'OrganizeImportsCommand'.","code":2339,"category":"error"},{"start":{"line":29,"offset":59},"end":{"line":29,"offset":67},"text":"Cannot find name 'document'.","code":2304,"category":"error"},{"start":{"line":29,"offset":69},"end":{"line":29,"offset":74},"text":"Cannot find name 'token'.","code":2304,"category":"error"},{"start":{"line":53,"offset":22},"end":{"line":53,"offset":39},"text":"Property 'fileConfigManager' is declared but its value is never read.","code":6138,"category":"error","reportsUnnecessary":true},{"start":{"line":66,"offset":5},"end":{"line":66,"offset":10},"text":"'token' is declared but its value is never read.","code":6133,"category":"error","reportsUnnecessary":true}]}}

I believe this request returns errors at stale locations. The full text of the line in VS Code is now:

        this.fileConfigManager.ensureConfigurationForDocument(document, token);
|----2 tabs----|

with the err span returned from character 10 - 27, which works out to be:

        this.fileConfigManager.ensureConfigurationForDocument(document, token);
               |------error-----|

In the editor here is what I see:

Here is a complete ts server log for this case: tsserver.log

[mhegazy]

@mjbvz is that something you see in older versions of tsserver? or is this a recent regression?

[mjbvz]

Yes but it is significantly worse in 3.0. This may be because we are now making more requests or it could be something else

[sheetalkamat]

@mjbvz do your have complete repro code and tsserver log. I am not able to repro this with master branch in vscode/vscode insiders/our test framework.

FYI This test passes correctly

        it("reports correct errors on format of a change", () => {
            const projectRootPath = "/user/username/projects/project";
            const file: File = {
                path: `${projectRootPath}/a.ts`,
                content: `class C {
    public execute(): string {

        return "";
    }
}`
            };
            const configFile: File = {
                path: `${projectRootPath}/tsconfig.json`,
                content: "{}"
            };
            const files = [file, configFile, libFile];
            const host = createServerHost(files);
            const session = createSession(host, { canUseEvents: true });
            session.executeCommandSeq<protocol.OpenRequest>({
                command: protocol.CommandTypes.Open,
                arguments: {
                    file: file.path,
                    projectRootPath,
                    fileContent: file.content
                }
            });
            const insertLine = 3;
            const insertOffset = 3;
            const insertString = "\t\tthis.fileConfigManager.ensureConfigurationForDocument();";
            session.executeCommandSeq<protocol.ChangeRequest>({
                command: protocol.CommandTypes.Change,
                arguments: {
                    file: file.path,
                    line: insertLine,
                    offset: insertOffset,
                    endLine: insertLine,
                    endOffset: insertOffset,
                    insertString
                }
            });
            const formatOptions = clone(server.getDefaultFormatCodeSettings(host));
            formatOptions.convertTabsToSpaces = false;
            session.executeCommandSeq<protocol.ConfigureRequest>({
                command: protocol.CommandTypes.Configure,
                arguments: {
                    file: file.path,
                    formatOptions
                }
            });
            const formatResponse = session.executeCommandSeq<protocol.FormatRequest>({
                command: protocol.CommandTypes.Format,
                arguments: {
                    file: file.path,
                    line: insertLine,
                    offset: insertOffset,
                    endLine: insertLine + 1,
                    endOffset: 1
                }
            }).response! as protocol.CodeEdit[];
            assert.deepEqual(formatResponse, [{
                start: { line: insertLine, offset: 1 },
                end: { line: insertLine, offset: 5 },
                newText: "\t\t"
            }]);
            session.executeCommandSeq<protocol.ChangeRequest>({
                command: protocol.CommandTypes.Change,
                arguments: {
                    file: file.path,
                    line: formatResponse[0].start.line,
                    offset: formatResponse[0].start.offset,
                    endLine: formatResponse[0].end.line,
                    endOffset: formatResponse[0].end.offset,
                    insertString: formatResponse[0].newText
                }
            });
            session.executeCommandSeq<protocol.GeterrRequest>({
                command: protocol.CommandTypes.Geterr,
                arguments: {
                    files: [file.path],
                    delay: 0
                }
            });
            session.clearMessages();
            host.checkTimeoutQueueLengthAndRun(1);
            checkErrorMessage(session, "syntaxDiag", { file: file.path, diagnostics: [] });

            session.clearMessages();
            host.runQueuedImmediateCallbacks();
            const propertyName = "fileConfigManager";
            const startOffset = insertString.indexOf(propertyName) + 1;
            checkErrorMessage(session, "semanticDiag", {
                file: file.path, diagnostics: [
                    createDiagnostic({ line: insertLine, offset: startOffset }, { line: insertLine, offset: startOffset + propertyName.length }, Diagnostics.Property_0_does_not_exist_on_type_1, [propertyName, "C"])
                ]
            });

            session.clearMessages();
            host.runQueuedImmediateCallbacks();
            checkErrorMessage(session, "suggestionDiag", { file: file.path, diagnostics: [] });
        });

[mjbvz]

TS Server log from above: https://github.com/Microsoft/TypeScript/files/2191362/tsserver.log

Repo steps that works 50% of the time for me on OSX:

1. Open VS Code code base
2. Make sure format on paste is enabled
3. Open vscode/extensions/typescript-language-features/src/features/organizeImports.ts
4. Make sure TS is initialized
5. copy the entire line this.fileConfigManager.ensureConfigurationForDocument(document, token); (with spaces)
6. Paste the line on after execute on line 28

[mjbvz]

@sheetalkamat Have you made progress investigating this? Any additional information needed?

[sheetalkamat]

@mjbvz Looking into this today. Sorry was oof last few days to look into this.

[sheetalkamat]

@mjbvz I am not able to reproduce this in latest vscode-insiders or running just tsserver from either vscode or master of typescript. I also followed exact sequence of commands and still the error reports correctly. (and i do see that in your case the error is returned with expectedColumn+2. The tsserver version shown in your log is Version: 3.0.0-dev. Do you mind checking if you are able to repro this with typescript@next.

[sheetalkamat]

Moving this to 3.1.0 after chatting with @mjbvz that this repros only when plugin typescript-lit-html-plugin is enabled.

[mjbvz]

@sheetalkamat Can you or someone else on the ts team help look through https://github.com/Microsoft/typescript-template-language-service-decorator to see what may be going wrong here. It almost seems like something in the plugin can cause the language service to use an old version of the ast but I can't track what could be causing this or why this only happens in specific cases.

Possible places to investigate:

• Where we wrap the language service calls

• Where we get nodes from the ast

• Where we get the template nodes from the ast

Let me know if you have any questions about the code or want to pair on the investigation

[sheetalkamat]

@mjbvz Will take a look.

[sheetalkamat]

Here is the issue: When getFormattingEditsForRange is called, we do not update the program (since its syntax only operation, we keep program as is and want to just use updated snapshot of changed file and nothing else) and then call const edits = languageService.getFormattingEditsForRange(file, startPosition, endPosition, this.getFormatOptions(file)); which redirects it to getFormattingEditsForRange of template language service and as part of that call, it tries to get All nodes by updating the program in language service. At this point the program in service gets updated but project doesn’t know about it. When next change request is sent, the projectVersion is not updated since the project thinks its still dirty. And as a result when getDiagnostics is called, we miss this change all together and operate on the program when format is called.

I think your language service plugin should not depend on program if its syntax only operation. In the mean time you can pass around the project instead of LS to StandardScriptSourceHelper and call getLanguageServie from there to avoid this. (note that just making project incrementing version all the time is not a good solution because project when its updating program does lot of work and we want it to not miss that). The temporary fix would loose a bit of efficiency since project would be updated on syntax operations that you override which isn’t needed.

Just so you know this is what I did to repro and investigate:

node  c:\typescript\built\local\tsserver.js --useInferredProjectPerProjectRoot --globalPlugins typescript-lit-html-plugin --pluginProbeLocations C:\Users\shkamat\.vscode\extensions\bierner.lit-html-1.6.2 --locale en --noGetErrOnBackgroundUpdate

Typed these commants one by one

{"seq":2,"type":"request","command":"open","arguments":{"file":"c:/temp/test4/src/a.ts","fileContent":"class c {\r\n\tpublic execute() {\r\n\r\n\t\tconsole.log(\"in execute\");\r\n\t}\r\n}"}}

{"seq":16,"type":"request","command":"change","arguments":{"insertString":"\t\t\t\tthis.fileConfigManager.ensureConfigurationForDocument(document, token);\r\n","file":"c:/temp/test4/src/a.ts","line":3,"offset":1,"endLine":3,"endOffset":1}}

{"seq":18,"type":"request","command":"format","arguments":{"file":"c:/temp/test4/src/a.ts","line":3,"offset":1,"endLine":4,"endOffset":1}}

{"seq":19,"type":"request","command":"change","arguments":{"insertString":"","file":"c:/temp/test4/src/a.ts","line":3,"offset":3,"endLine":3,"endOffset":5}}

{"seq":21,"type":"request","command":"geterr","arguments":{"delay":0,"files":["c:/temp/test4/src/a.ts"]}}