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.

Sign up for GitHub

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

Jump to bottom

Stop using VS buffer version numbers in the language server #9197

Closed
davidwengier opened this issue Aug 30, 2023 · 3 comments · Fixed by #10747
Closed

Stop using VS buffer version numbers in the language server #9197

davidwengier opened this issue Aug 30, 2023 · 3 comments · Fixed by #10747
Labels
bug Something isn't working reliability 📊
Milestone
17.12 P2

Comments

@davidwengier
Copy link
Contributor

davidwengier commented Aug 30, 2023 •
edited
Loading

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
@ghost ghost added the untriaged label Aug 30, 2023
@davidwengier davidwengier added bug Something isn't working reliability 📊 labels Aug 30, 2023
@davidwengier davidwengier mentioned this issue Aug 31, 2023
Merged
@phil-allen-msft phil-allen-msft added this to the 17.9 Planning milestone Sep 14, 2023
@ghost ghost removed the untriaged label Sep 14, 2023
@davidwengier
Copy link
Contributor Author

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

@davidwengier
Copy link
Contributor Author

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

@davidwengier davidwengier mentioned this issue Oct 19, 2023
Merged
davidwengier added a commit that referenced this issue Oct 19, 2023
@davidwengier
Don't report that we're synchronized if the line count is wrong (#9437)
dfa3607 
Fixes https://devdiv.visualstudio.com/DevDiv/_workitems/edit/1841559
while we wait for the real fix, either
#9197 or The Great Merge™
@davidwengier davidwengier mentioned this issue Oct 22, 2023
Merged
@davidwengier davidwengier mentioned this issue Nov 14, 2024
Merged
@davidwengier
Copy link
Contributor Author

Whoops, this was fixed by #10747 in 17.12 P2

@davidwengier davidwengier modified the milestones: 17.13 Planning, 17.12 P2 Nov 14, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working reliability 📊
Projects
None yet
Milestone
17.12 P2
Development

Successfully merging a pull request may close this issue.

Self-versioned documents dotnet/razor
2 participants
@davidwengier @phil-allen-msft