Generated code (WPF, *.g.cs files) triggers infinite textDocument/diagnostic loop

michaelpduda commented 5 months ago

Type: Bug

Issue Description

Since version 2.22.3, for WPF projects (possibly other types as well), the extension sometimes gets stuck in a loop where it executes textDocument/diagnostic, which causes /obj/debug/.../*.g.cs files to be regenerated, which causes workspace/didChangeWatchedFiles to trigger, which causes the extension to run textDocument/diagnostic, and so on... resulting in instability and heavy CPU usage.

(This may not be the actual sequence of events, just my guess from observing and reading the logs.)

Steps to Reproduce

This has affected multiple projects of mine, and I was able to reproduce the issue using a fresh dotnet new wpf template project.

Create a new folder named test
Navigate into folder in powershell
Execute dotnet new wpf
Open folder in VSCode (code .)
Allow extension to create the suggested artifacts
Check #C Extension output logs

Expected Behavior

Extension executes the code Analysis once (or not at all?).

Actual Behavior

Infinite analysis loop (see description above).

Workarounds

Downgrading to version to version 2.18.16 stops the issue. Also, switching to Omnisharp ("dotnet.server.useOmnisharp": true) works as well.

Logs

The logs run infinitely, so they are quite long, but below I tried to capture two full loops. If more logs are necessary, I can record more.

C# log

``` [BuildHost PID 5936] Message from Process: Loading c:\repos\test\test.csproj [LanguageServerProjectSystem] Project c:\repos\test\test.csproj (net8.0-windows) now has 8 source file(s). [LanguageServerProjectSystem] Project c:\repos\test\test.csproj (net8.0-windows) now has 198 reference(s). [LanguageServerProjectSystem] Project c:\repos\test\test.csproj (net8.0-windows) now has 8 analyzer reference(s). [LanguageServerProjectSystem] Project c:\repos\test\test.csproj (net8.0-windows) now has 2 analyzer config file(s). [Info - 12:05:45 PM] [LanguageServerProjectSystem] Successfully completed load of c:\repos\test\test.csproj [Info - 12:05:45 PM] [LanguageServerProjectSystem] Completed (re)load of all projects in 00:00:01.1140673 [BuildHost PID 5936] Sending a Shutdown request to the BuildHost. [BuildHost PID 5936] Process shut down. [BuildHost PID 5936] Message from Process: info: Microsoft.CodeAnalysis.Workspaces.MSBuild.BuildHost.Program[0] [BuildHost PID 5936] Message from Process: RPC channel closed; process exiting. [LanguageServerHost] [07:05:46.241][Start]workspace/didChangeWatchedFiles [LanguageServerHost] [07:05:46.241][End]workspace/didChangeWatchedFiles [BuildHost PID 7532] Message from Process: info: Microsoft.CodeAnalysis.Workspaces.MSBuild.BuildHost.Program[0] [BuildHost PID 7532] Message from Process: BuildHost Runtime Version: .NET 8.0.3 [BuildHost PID 7532] Message from Process: info: Microsoft.CodeAnalysis.Workspaces.MSBuild.BuildHost.BuildHost[0] [BuildHost PID 7532] Message from Process: Registered MSBuild instance at C:\Program Files\dotnet\sdk\8.0.103 [BuildHost PID 7532] Message from Process: info: Microsoft.CodeAnalysis.Workspaces.MSBuild.BuildHost.BuildHost[0] [BuildHost PID 7532] Message from Process: Loading c:\repos\test\test.csproj [LanguageServerProjectSystem] Project c:\repos\test\test.csproj (net8.0-windows) now has 8 source file(s). [LanguageServerProjectSystem] Project c:\repos\test\test.csproj (net8.0-windows) now has 198 reference(s). [LanguageServerProjectSystem] Project c:\repos\test\test.csproj (net8.0-windows) now has 8 analyzer reference(s). [LanguageServerProjectSystem] Project c:\repos\test\test.csproj (net8.0-windows) now has 2 analyzer config file(s). [Info - 12:05:47 PM] [LanguageServerProjectSystem] Successfully completed load of c:\repos\test\test.csproj [Info - 12:05:47 PM] [LanguageServerProjectSystem] Completed (re)load of all projects in 00:00:01.1354488 [BuildHost PID 7532] Sending a Shutdown request to the BuildHost. [BuildHost PID 7532] Process shut down. [BuildHost PID 7532] Message from Process: info: Microsoft.CodeAnalysis.Workspaces.MSBuild.BuildHost.Program[0] [BuildHost PID 7532] Message from Process: RPC channel closed; process exiting. [LanguageServerHost] [07:05:47.868][Start]workspace/didChangeWatchedFiles [LanguageServerHost] [07:05:47.868][End]workspace/didChangeWatchedFiles [BuildHost PID 1056] Message from Process: info: Microsoft.CodeAnalysis.Workspaces.MSBuild.BuildHost.Program[0] [BuildHost PID 1056] Message from Process: BuildHost Runtime Version: .NET 8.0.3 [BuildHost PID 1056] Message from Process: info: Microsoft.CodeAnalysis.Workspaces.MSBuild.BuildHost.BuildHost[0] [BuildHost PID 1056] Message from Process: Registered MSBuild instance at C:\Program Files\dotnet\sdk\8.0.103 [BuildHost PID 1056] Message from Process: info: Microsoft.CodeAnalysis.Workspaces.MSBuild.BuildHost.BuildHost[0] [BuildHost PID 1056] Message from Process: Loading c:\repos\test\test.csproj ```

C# LSP Trace Logs

``` [Trace - 12:07:08 PM] Received notification 'window/logMessage'. Params: { "type": 4, "message": "[BuildHost PID 8976] Message from Process: Loading c:\\repos\\test\\test.csproj" } [Trace - 12:07:09 PM] Received notification 'window/logMessage'. Params: { "type": 4, "message": "[LanguageServerProjectSystem] Project c:\\repos\\test\\test.csproj (net8.0-windows) now has 8 source file(s)." } [Trace - 12:07:09 PM] Received notification 'window/logMessage'. Params: { "type": 4, "message": "[LanguageServerProjectSystem] Project c:\\repos\\test\\test.csproj (net8.0-windows) now has 198 reference(s)." } [Trace - 12:07:09 PM] Received notification 'window/logMessage'. Params: { "type": 4, "message": "[LanguageServerProjectSystem] Project c:\\repos\\test\\test.csproj (net8.0-windows) now has 8 analyzer reference(s)." } [Trace - 12:07:09 PM] Received notification 'window/logMessage'. Params: { "type": 4, "message": "[LanguageServerProjectSystem] Project c:\\repos\\test\\test.csproj (net8.0-windows) now has 2 analyzer config file(s)." } [Trace - 12:07:09 PM] Received notification 'window/logMessage'. Params: { "type": 3, "message": "[LanguageServerProjectSystem] Successfully completed load of c:\\repos\\test\\test.csproj" } [Trace - 12:07:09 PM] Received notification 'window/logMessage'. Params: { "type": 3, "message": "[LanguageServerProjectSystem] Completed (re)load of all projects in 00:00:01.1777036" } [Trace - 12:07:09 PM] Received notification 'window/logMessage'. Params: { "type": 4, "message": "[BuildHost PID 8976] Sending a Shutdown request to the BuildHost." } [Trace - 12:07:09 PM] Received notification 'window/logMessage'. Params: { "type": 4, "message": "[BuildHost PID 8976] Process shut down." } [Trace - 12:07:09 PM] Received notification 'window/logMessage'. Params: { "type": 4, "message": "[BuildHost PID 8976] Message from Process: info: Microsoft.CodeAnalysis.Workspaces.MSBuild.BuildHost.Program[0]" } [Trace - 12:07:09 PM] Received notification 'window/logMessage'. Params: { "type": 4, "message": "[BuildHost PID 8976] Message from Process: RPC channel closed; process exiting." } [Trace - 12:07:09 PM] Sending notification 'workspace/didChangeWatchedFiles'. Params: { "changes": [ { "uri": "file:///c:/repos/test/obj/Debug/net8.0-windows/MainWindow.g.cs", "type": 3 }, { "uri": "file:///c:/repos/test/obj/Debug/net8.0-windows/MainWindow.g.cs", "type": 3 }, { "uri": "file:///c:/repos/test/obj/Debug/net8.0-windows/MainWindow.g.cs", "type": 1 }, { "uri": "file:///c:/repos/test/obj/Debug/net8.0-windows/MainWindow.g.cs", "type": 1 } ] } [Trace - 12:07:09 PM] Received notification 'window/logMessage'. Params: { "type": 4, "message": "[LanguageServerHost] [07:07:09.844][Start]workspace/didChangeWatchedFiles" } [Trace - 12:07:09 PM] Received notification 'window/logMessage'. Params: { "type": 4, "message": "[LanguageServerHost] [07:07:09.844][End]workspace/didChangeWatchedFiles" } [Trace - 12:07:10 PM] Received notification 'window/logMessage'. Params: { "type": 4, "message": "[BuildHost PID 6620] Message from Process: info: Microsoft.CodeAnalysis.Workspaces.MSBuild.BuildHost.Program[0]" } [Trace - 12:07:10 PM] Received notification 'window/logMessage'. Params: { "type": 4, "message": "[BuildHost PID 6620] Message from Process: BuildHost Runtime Version: .NET 8.0.3" } [Trace - 12:07:10 PM] Received notification 'window/logMessage'. Params: { "type": 4, "message": "[BuildHost PID 6620] Message from Process: info: Microsoft.CodeAnalysis.Workspaces.MSBuild.BuildHost.BuildHost[0]" } [Trace - 12:07:10 PM] Received notification 'window/logMessage'. Params: { "type": 4, "message": "[BuildHost PID 6620] Message from Process: Registered MSBuild instance at C:\\Program Files\\dotnet\\sdk\\8.0.103" } [Trace - 12:07:10 PM] Received notification 'window/logMessage'. Params: { "type": 4, "message": "[BuildHost PID 6620] Message from Process: info: Microsoft.CodeAnalysis.Workspaces.MSBuild.BuildHost.BuildHost[0]" } [Trace - 12:07:10 PM] Received notification 'window/logMessage'. Params: { "type": 4, "message": "[BuildHost PID 6620] Message from Process: Loading c:\\repos\\test\\test.csproj" } [Trace - 12:07:11 PM] Received notification 'window/logMessage'. Params: { "type": 4, "message": "[LanguageServerProjectSystem] Project c:\\repos\\test\\test.csproj (net8.0-windows) now has 8 source file(s)." } [Trace - 12:07:11 PM] Received notification 'window/logMessage'. Params: { "type": 4, "message": "[LanguageServerProjectSystem] Project c:\\repos\\test\\test.csproj (net8.0-windows) now has 198 reference(s)." } [Trace - 12:07:11 PM] Received notification 'window/logMessage'. Params: { "type": 4, "message": "[LanguageServerProjectSystem] Project c:\\repos\\test\\test.csproj (net8.0-windows) now has 8 analyzer reference(s)." } [Trace - 12:07:11 PM] Received notification 'window/logMessage'. Params: { "type": 4, "message": "[LanguageServerProjectSystem] Project c:\\repos\\test\\test.csproj (net8.0-windows) now has 2 analyzer config file(s)." } [Trace - 12:07:11 PM] Received notification 'window/logMessage'. Params: { "type": 3, "message": "[LanguageServerProjectSystem] Successfully completed load of c:\\repos\\test\\test.csproj" } [Trace - 12:07:11 PM] Received notification 'window/logMessage'. Params: { "type": 3, "message": "[LanguageServerProjectSystem] Completed (re)load of all projects in 00:00:01.2671573" } [Trace - 12:07:11 PM] Received notification 'window/logMessage'. Params: { "type": 4, "message": "[BuildHost PID 6620] Sending a Shutdown request to the BuildHost." } [Trace - 12:07:11 PM] Received notification 'window/logMessage'. Params: { "type": 4, "message": "[BuildHost PID 6620] Process shut down." } [Trace - 12:07:11 PM] Received notification 'window/logMessage'. Params: { "type": 4, "message": "[BuildHost PID 6620] Message from Process: info: Microsoft.CodeAnalysis.Workspaces.MSBuild.BuildHost.Program[0]" } [Trace - 12:07:11 PM] Received notification 'window/logMessage'. Params: { "type": 4, "message": "[BuildHost PID 6620] Message from Process: RPC channel closed; process exiting." } [Trace - 12:07:11 PM] Sending notification 'workspace/didChangeWatchedFiles'. Params: { "changes": [ { "uri": "file:///c:/repos/test/obj/Debug/net8.0-windows/MainWindow.g.cs", "type": 3 }, { "uri": "file:///c:/repos/test/obj/Debug/net8.0-windows/MainWindow.g.cs", "type": 3 }, { "uri": "file:///c:/repos/test/obj/Debug/net8.0-windows/MainWindow.g.cs", "type": 1 }, { "uri": "file:///c:/repos/test/obj/Debug/net8.0-windows/MainWindow.g.cs", "type": 1 } ] } [Trace - 12:07:11 PM] Received notification 'window/logMessage'. Params: { "type": 4, "message": "[LanguageServerHost] [07:07:11.599][Start]workspace/didChangeWatchedFiles" } [Trace - 12:07:11 PM] Received notification 'window/logMessage'. Params: { "type": 4, "message": "[LanguageServerHost] [07:07:11.599][End]workspace/didChangeWatchedFiles" } [Trace - 12:07:11 PM] Received notification 'window/logMessage'. Params: { "type": 4, "message": "[BuildHost PID 18168] Message from Process: info: Microsoft.CodeAnalysis.Workspaces.MSBuild.BuildHost.Program[0]" } [Trace - 12:07:11 PM] Received notification 'window/logMessage'. Params: { "type": 4, "message": "[BuildHost PID 18168] Message from Process: BuildHost Runtime Version: .NET 8.0.3" } [Trace - 12:07:12 PM] Received notification 'window/logMessage'. Params: { "type": 4, "message": "[BuildHost PID 18168] Message from Process: info: Microsoft.CodeAnalysis.Workspaces.MSBuild.BuildHost.BuildHost[0]" } [Trace - 12:07:12 PM] Received notification 'window/logMessage'. Params: { "type": 4, "message": "[BuildHost PID 18168] Message from Process: Registered MSBuild instance at C:\\Program Files\\dotnet\\sdk\\8.0.103" } [Trace - 12:07:12 PM] Received notification 'window/logMessage'. Params: { "type": 4, "message": "[BuildHost PID 18168] Message from Process: info: Microsoft.CodeAnalysis.Workspaces.MSBuild.BuildHost.BuildHost[0]" } [Trace - 12:07:12 PM] Received notification 'window/logMessage'. Params: { "type": 4, "message": "[BuildHost PID 18168] Message from Process: Loading c:\\repos\\test\\test.csproj" } ```

Environment information

VSCode version: 1.87.2 C# Extension: 2.22.5 Using OmniSharp: false

Dotnet Information

.NET SDK: Version: 8.0.103 Commit: 6a90b4b4bc Workload version: 8.0.100-manifests.4e94be9c Runtime Environment: OS Name: Windows OS Version: 10.0.19045 OS Platform: Windows RID: win-x64 Base Path: C:\Program Files\dotnet\sdk\8.0.103\ .NET workloads installed: Workload version: 8.0.100-manifests.4e94be9c There are no installed workloads to display. Host: Version: 8.0.3 Architecture: x64 Commit: 9f4b1f5d66 .NET SDKs installed: 7.0.117 [C:\Program Files\dotnet\sdk] 8.0.103 [C:\Program Files\dotnet\sdk] .NET runtimes installed: Microsoft.AspNetCore.App 7.0.17 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App] Microsoft.AspNetCore.App 8.0.3 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App] Microsoft.NETCore.App 5.0.17 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 6.0.28 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 7.0.17 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 8.0.3 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.WindowsDesktop.App 5.0.17 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App] Microsoft.WindowsDesktop.App 6.0.28 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App] Microsoft.WindowsDesktop.App 7.0.17 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App] Microsoft.WindowsDesktop.App 8.0.3 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App] Other architectures found: None Environment variables: Not set global.json file: Not found Learn more: https://aka.ms/dotnet/info Download .NET: https://aka.ms/dotnet/download

Visual Studio Code Extensions

|Extension|Author|Version|Folder Name| |---|---|---|---| |auto-rename-tag|formulahendry|0.1.10|formulahendry.auto-rename-tag-0.1.10| |csharp|ms-dotnettools|2.22.5|ms-dotnettools.csharp-2.22.5-win32-x64| |dotnet-test-explorer|formulahendry|0.7.8|formulahendry.dotnet-test-explorer-0.7.8| |EditorConfig|EditorConfig|0.16.4|editorconfig.editorconfig-0.16.4| |gitlens|eamodio|14.9.0|eamodio.gitlens-14.9.0| |powershell|ms-vscode|2024.0.0|ms-vscode.powershell-2024.0.0| |prettier-vscode|esbenp|10.1.0|esbenp.prettier-vscode-10.1.0| |remote-wsl|ms-vscode-remote|0.86.0|ms-vscode-remote.remote-wsl-0.86.0| |sqlite-viewer|qwtel|0.3.13|qwtel.sqlite-viewer-0.3.13| |vscode-docker|ms-azuretools|1.29.0|ms-azuretools.vscode-docker-1.29.0| |vscode-dotnet-runtime|ms-dotnettools|2.0.2|ms-dotnettools.vscode-dotnet-runtime-2.0.2| |vscode-pull-request-github|GitHub|0.82.0|github.vscode-pull-request-github-0.82.0| |vscode-xml|redhat|0.26.1|redhat.vscode-xml-0.26.1-win32-x64|;

Extension version: 2.22.5 VS Code version: Code 1.87.2 (863d2581ecda6849923a2118d93a088b0745d9d6, 2024-03-08T15:20:17.278Z) OS version: Windows_NT x64 10.0.19045 Modes:

System Info

|Item|Value| |---|---| |CPUs|Intel(R) Core(TM) i7-8550U CPU @ 1.80GHz (8 x 1992)| |GPU Status|2d_canvas: enabled
canvas_oop_rasterization: enabled_on
direct_rendering_display_compositor: disabled_off_ok
gpu_compositing: enabled
multiple_raster_threads: enabled_on
opengl: enabled_on
rasterization: enabled
raw_draw: disabled_off_ok
skia_graphite: disabled_off
video_decode: enabled
video_encode: enabled
vulkan: disabled_off
webgl: enabled
webgl2: enabled
webgpu: enabled| |Load (avg)|undefined| |Memory (System)|15.89GB (6.27GB free)| |Process Argv|--crash-reporter-id 51e2f3ce-c37e-4d74-aa4d-b251dd852ed5| |Screen Reader|no| |VM|0%|

A/B Experiments

``` vsliv368:30146709 vspor879:30202332 vspor708:30202333 vspor363:30204092 vscorecescf:30445987 vscod805cf:30301675 binariesv615:30325510 vsaa593cf:30376535 py29gd2263:30899288 c4g48928:30535728 azure-dev_surveyone:30548225 a9j8j154:30646983 962ge761:30959799 pythongtdpath:30769146 welcomedialogc:30910334 pythonidxpt:30866567 pythonnoceb:30805159 asynctok:30898717 pythontestfixt:30902429 pythonregdiag2:30936856 pyreplss1:30897532 pythonmypyd1:30879173 pythoncet0:30885854 2e7ec940:30992800 pythontbext0:30879054 dsvsc016:30899300 dsvsc017:30899301 dsvsc018:30899302 cppperfnew:30979542 d34g3935:30971562 fegfb526:30981948 bg6jg535:30979843 ccp1r6:30993540 dsvsc020:30976470 666c4381:30973075 ```

michaelpduda commented 5 months ago

Attaching more logs from the start of a new session. logs.zip

dibarbet commented 5 months ago

Thanks for the detailed report. Think I know what the general issue here is.

The language server registers file watchers for all .cs files in the workspace - if .cs files are added or removed we know we need to reload the project in order to ensure the right files are reflected in the right projects. However - this is problematic for the xaml generated .g.cs files in the obj/ directory. When we reload the project, we call msbuild to do a design time build. It seems like this design time build is re-generating the .g.cs file - which causes a file watcher notification - which causes a project reload - which causes a file watcher change - ad infinitum.

A potential fix here is to ignore the obj/ directory for changes to .cs files. Since these are all generated, theoretically any changes to .cs files here would be triggered by changes to the project or other files outside of obj/, which we would hear about and reload the project to see the updated generated code. We shouldn't need to explicitly look for changes that only happen in obj/.

It is also a bit weird that text only changes to closed files cause a project reload - theoretically we should be able to just update the text of existing files. But that wouldn't solve this issue by itself since the file is getting added/removed/changed.

(cc @jasonmalinowski)

dibarbet commented 5 months ago

@michaelpduda As a workaround while we fix the issue, you can exclude all .cs files in the obj/ folder from VSCode's file watcher in vscode settings

dotnet / vscode-csharp