NuGet.Commands.LockFileBuilder KeyNotFoundException Exception

[kpspence]

NuGet Product Used

dotnet.exe

Product Version

dotnet 7.0.201; nuget 6.5.0.136

Worked before?

dotnet 7.0.101; nuget 6.4.0.117

Impact

It's more difficult to complete my work

Repro Steps & Context

Error

• 7.0.201 sdk results in System.Collections.Generic.KeyNotFoundException exception during dotnet restore
• Exception during NuGet.Commands.LockFileBuilder.GetLibraryDependenciesForCentralTransitiveDependencies call
• Cannot duplicate on windows docker build but repeatedly on Jenkins server instance
• Always fails on same library System.Runtime.InteropServices which has been downloaded per logs and file listing at end.

Failure Setup - Docker build

From mcr.microsoft.com/dotnet/sdk:7.0.201-bullseye-slim

Step 13/57 : RUN dotnet nuget --version
NuGet Command Line
6.5.0.136
Step 14/57 : RUN dotnet --version
7.0.201

Step 56/57 : RUN dotnet restore -v diag "Source/src/spc/SpcService/SpcService.csproj"

Exception Details

21:07:13.724     1>/usr/share/dotnet/sdk/7.0.201/NuGet.targets(132,5): error : The given key 'System.Runtime.InteropServices' was not present in the dictionary. [/src/Source/src/spc/SpcService/SpcService.csproj]
                     System.Collections.Generic.KeyNotFoundException: The given key 'System.Runtime.InteropServices' was not present in the dictionary.
                        at System.Collections.Generic.Dictionary`2.get_Item(TKey key)
                        at NuGet.Commands.LockFileBuilder.GetLibraryDependenciesForCentralTransitiveDependencies(RestoreTargetGraph targetGraph, TargetFrameworkInformation targetFrameworkInformation, Boolean centralPackageTransitivePinningEnabled)+MoveNext()
                        at System.Collections.Generic.List`1..ctor(IEnumerable`1 collection)
                        at System.Linq.Enumerable.ToList[TSource](IEnumerable`1 source)
                        at NuGet.Commands.LockFileBuilder.AddCentralTransitiveDependencyGroupsForPackageReference(PackageSpec project, LockFile lockFile, IEnumerable`1 targetGraphs)
                        at NuGet.Commands.LockFileBuilder.CreateLockFile(LockFile previousLockFile, PackageSpec project, IEnumerable`1 targetGraphs, IReadOnlyList`1 localRepositories, RemoteWalkContext context, LockFileBuilderCache lockFileBuilderCache)
                        at NuGet.Commands.RestoreCommand.BuildAssetsFile(LockFile existingLockFile, PackageSpec project, IEnumerable`1 graphs, IReadOnlyList`1 localRepositories, RemoteWalkContext contextForProject)
                        at NuGet.Commands.RestoreCommand.ExecuteAsync(CancellationToken token)
                        at NuGet.Commands.RestoreRunner.ExecuteAsync(RestoreSummaryRequest summaryRequest, CancellationToken token)
                        at NuGet.Commands.RestoreRunner.ExecuteAndCommitAsync(RestoreSummaryRequest summaryRequest, IRestoreProgressReporter progressReporter, CancellationToken token)
                        at NuGet.Commands.RestoreRunner.CompleteTaskAsync(List`1 restoreTasks)
                        at NuGet.Commands.RestoreRunner.RunAsync(IEnumerable`1 restoreRequests, RestoreArgs restoreArgs, CancellationToken token)
                        at NuGet.Commands.RestoreRunner.RunAsync(RestoreArgs restoreContext, CancellationToken token)
                        at NuGet.Build.Tasks.BuildTasksUtility.RestoreAsync(DependencyGraphSpec dependencyGraphSpec, Boolean interactive, Boolean recursive, Boolean noCache, Boolean ignoreFailedSources, Boolean disableParallel, Boolean force, Boolean forceEvaluate, Boolean hideWarningsAndErrors, Boolean restorePC, Boolean cleanupAssetsForUnsupportedProjects, ILogger log, CancellationToken cancellationToken)
                        at NuGet.Build.Tasks.RestoreTask.ExecuteAsync(ILogger log) (TaskId:407)
                   Done executing task "RestoreTask" -- FAILED. (TaskId:407)

Successful Setup - Docker build

mcr.microsoft.com/dotnet/sdk:7.0.101-bullseye-slim
Step 13/57 : RUN dotnet nuget --version
NuGet Command Line
6.4.0.117

Step 14/57 : RUN dotnet --version
---> Running in 3937be4b4697
7.0.101

Step 56/57 : RUN dotnet restore -v diag "Source/src/spc/SpcService/SpcService.csproj"

Done executing task "RestoreTask". (TaskId:357)
22:32:24.804     1>Done building target "Restore" in project "SpcService.csproj".: (TargetId:411)
22:32:24.804     1>Done Building Project "/src/Source/src/spc/SpcService/SpcService.csproj" (Restore target(s)).

Failed-7.0.201.txt
Succeed-7.0.101.txt

Verbose Logs

Diagnostic logs attached above

[kpspence]

Appears to be broken in preview version 6.6.0.20 as well

Step 14/58 : RUN dotnet nuget --version
NuGet Command Line
6.6.0.20
Step 15/58 : RUN dotnet --version
8.0.100-preview.1.23115.2

20:08:06.347     1>/usr/share/dotnet/sdk/8.0.100-preview.1.23115.2/NuGet.targets(132,5): error : The given key 'System.Runtime.InteropServices' was not present in the dictionary. [/src/Source/src/spc/SpcService/SpcService.csproj]
                     System.Collections.Generic.KeyNotFoundException: The given key 'System.Runtime.InteropServices' was not present in the dictionary.
                        at System.Collections.Generic.Dictionary`2.get_Item(TKey key)
                        at NuGet.Commands.LockFileBuilder.GetLibraryDependenciesForCentralTransitiveDependencies(RestoreTargetGraph targetGraph, TargetFrameworkInformation targetFrameworkInformation, Boolean centralPackageTransitivePinningEnabled)+MoveNext()
                        at System.Collections.Generic.List`1..ctor(IEnumerable`1 collection)
                        at System.Linq.Enumerable.ToList[TSource](IEnumerable`1 source)
                        at NuGet.Commands.LockFileBuilder.AddCentralTransitiveDependencyGroupsForPackageReference(PackageSpec project, LockFile lockFile, IEnumerable`1 targetGraphs)
                        at NuGet.Commands.LockFileBuilder.CreateLockFile(LockFile previousLockFile, PackageSpec project, IEnumerable`1 targetGraphs, IReadOnlyList`1 localRepositories, RemoteWalkContext context, LockFileBuilderCache lockFileBuilderCache)
                        at NuGet.Commands.RestoreCommand.BuildAssetsFile(LockFile existingLockFile, PackageSpec project, IEnumerable`1 graphs, IReadOnlyList`1 localRepositories, RemoteWalkContext contextForProject)
                        at NuGet.Commands.RestoreCommand.ExecuteAsync(CancellationToken token)
                        at NuGet.Commands.RestoreRunner.ExecuteAsync(RestoreSummaryRequest summaryRequest, CancellationToken token)
                        at NuGet.Commands.RestoreRunner.ExecuteAndCommitAsync(RestoreSummaryRequest summaryRequest, IRestoreProgressReporter progressReporter, CancellationToken token)
                        at NuGet.Commands.RestoreRunner.CompleteTaskAsync(List`1 restoreTasks)
                        at NuGet.Commands.RestoreRunner.RunAsync(IEnumerable`1 restoreRequests, RestoreArgs restoreArgs, CancellationToken token)
                        at NuGet.Commands.RestoreRunner.RunAsync(RestoreArgs restoreContext, CancellationToken token)
                        at NuGet.Build.Tasks.BuildTasksUtility.RestoreAsync(DependencyGraphSpec dependencyGraphSpec, Boolean interactive, Boolean recursive, Boolean noCache, Boolean ignoreFailedSources, Boolean disableParallel, Boolean force, Boolean forceEvaluate, Boolean hideWarningsAndErrors, Boolean restorePC, Boolean cleanupAssetsForUnsupportedProjects, ILogger log, CancellationToken cancellationToken)
                        at NuGet.Build.Tasks.RestoreTask.ExecuteAsync(ILogger log) (TaskId:357)
                   Done executing task "RestoreTask" -- FAILED. (TaskId:357)
20:08:06.358     1>Done building target "Restore" in project "SpcService.csproj" -- FAILED.: (TargetId:411)
20:08:06.359     1>Done Building Project "/src/Source/src/spc/SpcService/SpcService.csproj" (Restore target(s)) -- FAILED.
Deferred Messages
20:08:06.359     0>
Detailed Build Summary

[kartheekp-ms]

Looks like there have been some recent commits to NuGet.Commands.LockFileBuilder.GetLibraryDependenciesForCentralTransitiveDependencies method which may be causing this regression.

https://github.com/NuGet/NuGet.Client/blame/c911884c370d24a46ae73b49a9857784dccc534a/src/NuGet.Core/NuGet.Commands/RestoreCommand/LockFileBuilder.cs#L516-L564

[jeffkl]

@kpspence can you provide a simple repro that exhibits this error? When I put together a trivial project with PackageReferences it does not happen. I'd be interested to see what combinations of packages cause it.

[kpspence]

@jeffkl Please see https://github.com/kpspence/NugetBugKeyNotFound

This was the minimum I could get to and have it still break.

It does break consistantly on the docker build on both Jenkins and my desktop.

It is an interaction of the following packages:

        <PackageReference Include="App.Metrics.AspNetCore" />
        <PackageReference Include="App.Metrics.AspNetCore.Health.Hosting" />
        <PackageReference Include="Microsoft.Extensions.Hosting.Abstractions" />
        <PackageReference Include="Serilog.AspNetCore" />

And the following package versions:

    <PackageVersion Include="System.Runtime.InteropServices" Version="4.3.0" /> 
    <PackageVersion Include="App.Metrics.AspNetCore" Version="4.3.0" />
    <PackageVersion Include="App.Metrics.AspNetCore.Health.Hosting" Version="3.2.0" />
    <PackageVersion Include="Serilog.AspNetCore" Version="6.1.0" />
	
    <PackageVersion Include="System.Net.Http" Version="4.3.4" /> 
		
    <PackageVersion Include="Microsoft.Extensions.Hosting.Abstractions" Version="7.0.0" />

[jeffkl]

@kpspence thank you that helps tremendously! I will investigate....

[mmtenez]

Nbehhejjj

[gtbuchanan]

I started receiving the same error and stack trace for System.Reflection.TypeExtensions after moving one of our solutions to central package management. My current workaround is to disable transitive pinning:

<CentralPackageTransitivePinningEnabled>false</CentralPackageTransitivePinningEnabled>

[marcin-krystianc]

FYI, I think I've found a code change that is necessary to fix this. I'm working on opening a PR and adding a test case for this.

[KirillOsenkov]

Not sure what is going on yet, but we're seeing the same callstack on 17.9.5 with the fix in PR 5293 applied. Either there's another scenario, or the fix is for a different situation, or the fix doesn't cover all the cases. I will have to debug tomorrow.

[marcin-krystianc]

Hi @KirillOsenkov, is it possible by any chance to provide a public repro for it?

[KirillOsenkov]

Unfortunately the repro disappeared and I couldn't reproduce it any more. If I ever run into this again I'll investigate and will ping you if it's related to the algorithm you've fixed. Thanks for fixing this!

[KirillOsenkov]

all I know is that the C:\Users\username\appdata\roaming\NuGet\NuGet.Config on the user's machine had an entry to disable a package source that was important:

<disabledPackageSources>
<add key="myfeed" value="true" />
</disabledPackageSources>

With this entry all sorts of weird problems were happening. We found and removed the entry, and now we can't get it to repro even if we add it back.