Stop using VS buffer version numbers in the language server

[davidwengier]

Currently in VS we use the version numbers from the VS text buffer to drive our language server version numbers. This falls down due to a race condition, and due to VS buffer version numbers only changing with literal buffer changes. What is actually happening sometimes is that sometimes we can produce two versions of the generated code, one without tag helper info, and one with, but both appear as "version 1" since the .razor file content doesn't change. This means that requests that go to Roslyn which should be waiting on v2 of the generated file, actually wait on v1, and therefore don't wait for synchronization because v1 has already been seen, it was just the wrong v1.

In theory we should be able to track version numbers inside our language server, independent of the client. If we can trust the client to send us didChange/didOpen/didClose correctly then we shouldn't lose any information, and we can add our own entropy in with DocumentChanged and/or ProjectChanged events when tag helpers are discovered etc.

See the log below. Note the two UpdateCSharpBuffer requests, both with version 1, but for different sets of changes. The second semanticTokens/range request comes in and makes a request of Roslyn for the larger C# file, which the langauge server knows about, but as luck would have it Roslyn has not been updated yet. Our normal process to handle this, the document sync service, is not called because the version numbers are "seen".

1:55:46.892 Opening document 'C:/Users/dawengie/AppData/Local/Temp/razor-test/y04fsndq.o4s/BlazorProject/Pages/Index.razor' in project 'ProjectKey { Id = C:/Users/dawengie/AppData/Local/Temp/razor-test/y04fsndq.o4s/BlazorProject/obj/Debug/net6.0/ }'.
1:55:46.910 Stop: textDocument/didOpen
1:55:46.912 Trying to create DocumentContext for textDocument/foldingRange for (no project context) for file:///C:/Users/dawengie/AppData/Local/Temp/razor-test/y04fsndq.o4s/BlazorProject/Pages/Index.razor
1:55:46.918 Start: textDocument/foldingRange
1:55:46.918 Start: textDocument/_vs_getProjectContexts
1:55:46.920 Trying to create DocumentContext for textDocument/_vs_spellCheckableRanges for (no project context) for file:///C:/Users/dawengie/AppData/Local/Temp/razor-test/y04fsndq.o4s/BlazorProject/Pages/Index.razor
1:55:46.921 Start: textDocument/_vs_spellCheckableRanges
1:55:46.924 Trying to create DocumentContext for textDocument/documentColor for (no project context) for file:///C:/Users/dawengie/AppData/Local/Temp/razor-test/y04fsndq.o4s/BlazorProject/Pages/Index.razor
1:55:46.925 Start: textDocument/documentColor
1:55:46.942 Trying to create DocumentContext for textDocument/linkedEditingRange for (no project context) for file:///C:/Users/dawengie/AppData/Local/Temp/razor-test/y04fsndq.o4s/BlazorProject/Pages/Index.razor
1:55:46.943 Start: textDocument/linkedEditingRange
1:55:47.020 Trying to create DocumentContext for textDocument/documentHighlight for (no project context) for file:///C:/Users/dawengie/AppData/Local/Temp/razor-test/y04fsndq.o4s/BlazorProject/Pages/Index.razor
1:55:47.022 Start: textDocument/documentHighlight
1:55:47.029 Stop: textDocument/_vs_getProjectContexts
1:55:47.061 Trying to create DocumentContext for textDocument/semanticTokens/range for (no project context) for file:///C:/Users/dawengie/AppData/Local/Temp/razor-test/y04fsndq.o4s/BlazorProject/Pages/Index.razor
1:55:47.061 Start: textDocument/semanticTokens/range
1:55:47.072 LinkedEditingRange request was null at (41:2,28) for file:///C:/Users/dawengie/AppData/Local/Temp/razor-test/y04fsndq.o4s/BlazorProject/Pages/Index.razor
1:55:47.073 Stop: textDocument/linkedEditingRange
1:55:47.096 UpdateCSharpBuffer for 1 of file:///C:/Users/dawengie/AppData/Local/Temp/razor-test/y04fsndq.o4s/BlazorProject/Pages/Index.razor in C:/Users/dawengie/AppData/Local/Temp/razor-test/y04fsndq.o4s/BlazorProject/obj/Debug/net6.0/. Changes: [Entire C# file]
1:55:47.097 UpdateCSharpBuffer virtual doc for 1 of file:///C:/Users/dawengie/AppData/Local/Temp/razor-test/y04fsndq.o4s/BlazorProject/Pages/Index.razor.9DQwssepQkEHMnF7.ide.g.cs
1:55:47.111 Updating project 'ProjectKey { Id = C:/Users/dawengie/AppData/Local/Temp/razor-test/y04fsndq.o4s/BlazorProject/obj/Debug/net6.0/ }' TagHelpers (264) and C# Language Version (CSharp10).
1:55:47.112 Stop: textDocument/documentHighlight
1:55:47.129 Trying to create DocumentContext for textDocument/semanticTokens/range for C:/Users/dawengie/AppData/Local/Temp/razor-test/y04fsndq.o4s/BlazorProject/obj/Debug/net6.0/ for file:///C:/Users/dawengie/AppData/Local/Temp/razor-test/y04fsndq.o4s/BlazorProject/Pages/Index.razor
1:55:47.130 Start: textDocument/semanticTokens/range
1:55:47.152 Trying to create DocumentContext for textDocument/documentSymbol for C:/Users/dawengie/AppData/Local/Temp/razor-test/y04fsndq.o4s/BlazorProject/obj/Debug/net6.0/ for file:///C:/Users/dawengie/AppData/Local/Temp/razor-test/y04fsndq.o4s/BlazorProject/Pages/Index.razor
1:55:47.152 Start: textDocument/documentSymbol
1:55:47.227 Stop: textDocument/_vs_spellCheckableRanges
1:55:47.399 UpdateCSharpBuffer for 1 of file:///C:/Users/dawengie/AppData/Local/Temp/razor-test/y04fsndq.o4s/BlazorProject/Pages/Index.razor in C:/Users/dawengie/AppData/Local/Temp/razor-test/y04fsndq.o4s/BlazorProject/obj/Debug/net6.0/. Changes: TextChange: { [3316..3316), "            __builder.AddAttribute(-1, "ChildContent", (global::Microsoft.AspNetCore.Components.RenderFragment)((__builder2) => {
            }
            ));
#nullable restore
#line 3 "C:/Users/dawengie/AppData/Local/Temp/razor-test/y04fsndq.o4s/BlazorProject/Pages/Index.razor"
__o = typeof(global::Microsoft.AspNetCore.Components.Web.PageTitle);

#line default
#line hidden
#nullable disable
            __o = "";
            __builder.AddAttribute(-1, "ChildContent", (global::Microsoft.AspNetCore.Components.RenderFragment)((__builder2) => {
            }
            ));
            #pragma warning disable BL0005
            ((global::BlazorProject.Shared.SurveyPrompt)default).
#nullable restore
#line 9 "C:/Users/dawengie/AppData/Local/Temp/razor-test/y04fsndq.o4s/BlazorProject/Pages/Index.razor"
              Title

#line default
#line hidden
#nullable disable
             = default;
            #pragma warning restore BL0005
#nullable restore
#line 9 "C:/Users/dawengie/AppData/Local/Temp/razor-test/y04fsndq.o4s/BlazorProject/Pages/Index.razor"
__o = typeof(global::BlazorProject.Shared.SurveyPrompt);

#line default
#line hidden
#nullable disable
" }
1:55:47.399 UpdateCSharpBuffer virtual doc for 1 of file:///C:/Users/dawengie/AppData/Local/Temp/razor-test/y04fsndq.o4s/BlazorProject/Pages/Index.razor.9DQwssepQkEHMnF7.ide.g.cs
1:55:47.403 Trying to create DocumentContext for textDocument/semanticTokens/range for C:/Users/dawengie/AppData/Local/Temp/razor-test/y04fsndq.o4s/BlazorProject/obj/Debug/net6.0/ for file:///C:/Users/dawengie/AppData/Local/Temp/razor-test/y04fsndq.o4s/BlazorProject/Pages/Index.razor
1:55:47.404 Start: textDocument/semanticTokens/range
1:55:47.411 Got a bad response from C#. Out of sync? for C:/Users/dawengie/AppData/Local/Temp/razor-test/y04fsndq.o4s/BlazorProject/Pages/Index.razor.9DQwssepQkEHMnF7.ide.g.cs|BlazorProject ()|C:/Users/dawengie/AppData/Local/Temp/razor-test/y04fsndq.o4s/BlazorProject/obj/Debug/net6.0/
1:55:47.411 We thought we were synced on v1 with doc from ProjectKey { Id = C:/Users/dawengie/AppData/Local/Temp/razor-test/y04fsndq.o4s/BlazorProject/obj/Debug/net6.0/ } with file:///C:/Users/dawengie/AppData/Local/Temp/razor-test/y04fsndq.o4s/BlazorProject/Pages/Index.razor.9DQwssepQkEHMnF7.ide.g.cs

Worth noting this issue created by deduction based on looking at the log above, and the code in question. If my theory is correct it should be possible to reproduce this behaviour by opening a .razor file that uses a component, and opening the component .razor file itself, and then adding a @namespace Goo directive to the component. This should cause us to regenerate the first files generated code, requery semantic tokens etc. and the colour of the component should change, without a version number change.

The error that appears in the log that illustrates this problem is:

StreamJsonRpc.RemoteInvocationException: Range={ Start={ Line=89, Character=37 }, End={ Line=122, Character=19 } }. text.Length=3405. text.Lines.Count=110
   at StreamJsonRpc.JsonRpc.<InvokeCoreAsync>d__151`1.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1.ConfiguredTaskAwaiter.GetResult()
   at Microsoft.AspNetCore.Razor.LanguageServer.DefaultClientNotifierService.<SendRequestAsync>d__3`2.MoveNext() in D:\Code\alt-razor\src\Razor\src\Microsoft.AspNetCore.Razor.LanguageServer\DefaultClientNotifierService.cs:line 35
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1.ConfiguredTaskAwaiter.GetResult()
   at Microsoft.AspNetCore.Razor.LanguageServer.Semantic.RazorSemanticTokensInfoService.<GetMatchingCSharpResponseAsync>d__12.MoveNext() in D:\Code\alt-razor\src\Razor\src\Microsoft.AspNetCore.Razor.LanguageServer\Semantic\Services\RazorSemanticTokensInfoService.cs:line 282
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1.ConfiguredTaskAwaiter.GetResult()
   at Microsoft.AspNetCore.Razor.LanguageServer.Semantic.RazorSemanticTokensInfoService.<GetCSharpSemanticRangesAsync>d__8.MoveNext() in D:\Code\alt-razor\src\Razor\src\Microsoft.AspNetCore.Razor.LanguageServer\Semantic\Services\RazorSemanticTokensInfoService.cs:line 131
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1.ConfiguredTaskAwaiter.GetResult()
   at Microsoft.AspNetCore.Razor.LanguageServer.Semantic.RazorSemanticTokensInfoService.<GetSemanticTokensAsync>d__6.MoveNext() in D:\Code\alt-razor\src\Razor\src\Microsoft.AspNetCore.Razor.LanguageServer\Semantic\Services\RazorSemanticTokensInfoService.cs:line 66
RPC server exception:
StreamJsonRpc.RemoteInvocationException: Range={ Start={ Line=89, Character=37 }, End={ Line=122, Character=19 } }. text.Length=3405. text.Lines.Count=110
      at StreamJsonRpc.JsonRpc.<InvokeCoreAsync>d__151`1.MoveNext()
   --- End of stack trace from previous location where exception was thrown ---
      at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
      at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
      at Microsoft.VisualStudio.LanguageServer.Client.JsonRpcExtensionMethods.<SendMethodRequestWithTelemetryAsync>d__0`2.MoveNext()
   --- End of stack trace from previous location where exception was thrown ---
      at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
      at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
      at Microsoft.VisualStudio.LanguageServer.Client.RemoteLanguageClientInstance.<TrackTaskAsync>d__119`1.MoveNext()
   --- End of stack trace from previous location where exception was thrown ---
      at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
      at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
      at Microsoft.VisualStudio.LanguageServer.Client.MefClient.<SendRequestAsync>d__20`2.MoveNext()
   --- End of stack trace from previous location where exception was thrown ---
      at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
      at System.Threading.Tasks.Sources.ManualResetValueTaskSourceCore`1.GetResult(Int16 token)
      at Microsoft.VisualStudio.LanguageServer.Client.AsyncEnumerableExtensions.<<UndeferExecutionUpToFirstYieldAsync>g__UnwrapRemainingItemsAsync|2_0>d`1.MoveNext()
   --- End of stack trace from previous location where exception was thrown ---
      at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
      at Microsoft.VisualStudio.LanguageServer.Client.AsyncEnumerableExtensions.<<UndeferExecutionUpToFirstYieldAsync>g__UnwrapRemainingItemsAsync|2_0>d`1.MoveNext()
   --- End of stack trace from previous location where exception was thrown ---
      at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
      at System.Threading.Tasks.Sources.ManualResetValueTaskSourceCore`1.GetResult(Int16 token)
      at Microsoft.VisualStudio.LanguageServer.Client.EnqueuedMessage`2.<GetResponsesAsync>d__17`1.MoveNext()
   --- End of stack trace from previous location where exception was thrown ---
      at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
      at Microsoft.VisualStudio.LanguageServer.Client.EnqueuedMessage`2.<GetResponsesAsync>d__17`1.MoveNext()
   --- End of stack trace from previous location where exception was thrown ---
      at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
      at System.Threading.Tasks.Sources.ManualResetValueTaskSourceCore`1.GetResult(Int16 token)
      at Microsoft.VisualStudio.LanguageServer.Client.AsyncEnumerableExtensions.<MoveNextWrappedAsync>d__3`1.MoveNext()
   --- End of stack trace from previous location where exception was thrown ---
      at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
      at Microsoft.VisualStudio.LanguageServer.Client.AsyncEnumerableExtensions.<SelectManyAsync>d__1`1.MoveNext()
   --- End of stack trace from previous location where exception was thrown ---
      at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
      at System.Threading.Tasks.Sources.ManualResetValueTaskSourceCore`1.GetResult(Int16 token)
      at Microsoft.VisualStudio.LanguageServer.Client.LanguageServiceClientManager.<RequestFromSpecificClientsAsync>d__48`2.MoveNext()
   --- End of stack trace from previous location where exception was thrown ---
      at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
      at Microsoft.VisualStudio.LanguageServer.Client.LanguageServiceClientManager.<RequestFromSpecificClientsAsync>d__48`2.MoveNext()
   --- End of stack trace from previous location where exception was thrown ---
      at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
      at System.Threading.Tasks.Sources.ManualResetValueTaskSourceCore`1.GetResult(Int16 token)
      at Microsoft.VisualStudio.LanguageServer.Client.RemoteLanguageServiceBroker.<RequestAsync>d__43.MoveNext()
   --- End of stack trace from previous location where exception was thrown ---
      at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
      at Microsoft.VisualStudio.LanguageServer.Client.RemoteLanguageServiceBroker.<RequestAsync>d__43.MoveNext()
   --- End of stack trace from previous location where exception was thrown ---
      at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
      at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
      at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
      at Microsoft.VisualStudio.LanguageServer.ContainedLanguage.DefaultLSPRequestInvoker.<ReinvokeRequestOnServerAsync>d__9`2.MoveNext() in D:\Code\alt-razor\src\Razor\src\Microsoft.VisualStudio.LanguageServer.ContainedLanguage\DefaultLSPRequestInvoker.cs:line 116
   --- End of stack trace from previous location where exception was thrown ---
      at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
      at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
      at System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1.ConfiguredTaskAwaiter.GetResult()
      at Microsoft.VisualStudio.LanguageServerClient.Razor.RazorCustomMessageTarget.<ProvideSemanticTokensRangeAsync>d__25.MoveNext() in D:\Code\alt-razor\src\Razor\src\Microsoft.VisualStudio.LanguageServerClient.Razor\Endpoints\SemanticTokens.cs:line 91

[davidwengier]

Full log from an instance of this happening on my machine: RazorLog.txt

[davidwengier]

It would seem the Roslyn side of this exception is tracked by this PRISM fault: https://prism.vsdata.io/failure/?eventType=Fault&failureHash=fb578b03-40b2-a3c3-8705-a482b78a0769 and this issue: https://devdiv.visualstudio.com/DevDiv/_workitems/edit/1841559