vscode-csharp icon indicating copy to clipboard operation
vscode-csharp copied to clipboard

Published 20 hours ago • verified publisher icon dotnet

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

Open michaelpduda opened this issue 1 year ago • 3 comments

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.

  1. Create a new folder named test
  2. Navigate into folder in powershell
  3. Execute dotnet new wpf
  4. Open folder in VSCode (code .)
  5. Allow extension to create the suggested artifacts
  6. 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 avatar Mar 19 '24 19:03 michaelpduda

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

michaelpduda avatar Mar 19 '24 19:03 michaelpduda

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 avatar Mar 20 '24 20:03 dibarbet

@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 image

dibarbet avatar Mar 20 '24 23:03 dibarbet