Yellow 'CACHE' bar shown in Visual Studio on add operations from PM UI

[timheuer]

NuGet Product Used

Visual Studio Package Management UI

Product Version

17.11 preview

Worked before?

Wasn't their prior

Impact

It bothers me. A fix would be nice

Repro Steps & Context

Add a package and see a CACHE goldbar above the PM UI

Verbose Logs

No response

[jgonz120]

I downloaded BaGet but wasn't able to repro. Can you give some details on how you have BaGet setup?

[timheuer]

This isn’t dependent on an BaGet. I get this cache bar all the time

[nkolev92]

Adding the content from e-mail here:

• @jgonz120 did the investigation here, so I'm borrowing from his findings + some code analysis to summarize the current status.

1. Yellow bar during installation is standard. The idea is that the status from the installation operation is posted on that yellow bar, somewhere visible to the user.
   This yellow bar would normally be very quick, and not raise much suspicion in general.

2. The process of operations for an installation in PackageReference is really a restore.
   Restore itself is broken in a few parts, for simplicity, I'll call out that it's package resolution and package download, assets selection and then vulnerability checking.
   Based on the internal video + investigation, we think it might be that restore is stuck waiting for a request to complete acquiring vulnerability data (which is why it gets stuck at vulnerability info cache consistently).

Some guesses were because that's the first time that source is being accessed, details on PackageReference and requiring sources to always be available - https://learn.microsoft.com/en-us/nuget/consume-packages/package-references-in-project-files#packagereference-and-sources, which could due to the source mapping existing.

We're yet unable to confirm the repro.

Assigning to current hotseat @kartheekp-ms to investigate more.
Feel free to chat with us (@jgonz120 and me) offline.

[nkolev92]

Team Triage:

A few ideas:

• The yellow bar, being treated as status bar, should it really have normal verbosity messages (which the http hit or cache are?) We should consider moving to minimal verbosity.
• When an http timeout is happening (likely the case here), we would spend timeout amount (100s) waiting for a status update, it might be a good idea to add a periodic update.

[nkolev92]

@kartheekp-ms Please continue the investigation so we can confirm our assumptions.
If you find anything not aligning with our assumptions, please let us know so we can retriage.

[kartheekp-ms]

I am able to reproduce the yellow bar in Visual Studio by following below steps.

1. Clone https://github.com/dotnet/aspire-samples/tree/main repo (I found this repo name from the video that was shared internally to reproduce this issue.)
2. Navigate to https://github.com/dotnet/aspire-samples/tree/main/samples/AspireShop
3. Launch AspireShop.sln in Visual Studio internal preview version.
4. Right click on AspireShop.AppHost project and select Manage NuGet Packages..
5. Select Microsoft.Extensions.DependencyInjection package
6. Click Install

Actual:
I noticed the yellow bar for only a fraction of second that has the same message mentioned in the issue description.

Upon debugging, I found the exact line of code and call stack that resulted in this yellow bar. Looking at the commit history it looks like commit has introduced a new method to run NuGet audit while enabling vulnerability checking for packages.config projects during commandline restore. There have been some changes to the same file in NuGet/NuGet.Client#5646 PR. These changes were pointing to the packages.config style projects but not sure yet why this change impacts package reference style projects also.

NuGet Call Stack Trace

1. NuGet.PackageManagement.UI.dll

   • NuGet.PackageManagement.UI.PackageRestoreBar.ShowMessage(string message) Line 367
   • NuGet.PackageManagement.UI.PackageRestoreBar.Log(MessageLevel level, string message, object[] args) Line 300

2. NuGet.PackageManagement.dll

   • NuGet.ProjectManagement.LoggerAdapter.LogInformation(string data) Line 34

3. NuGet.Protocol.dll

   • NuGet.Protocol.HttpSource.GetAsync.AnonymousMethod__0(CancellationToken lockedToken) Line 87
   • NuGet.Protocol.HttpSource.GetAsync<CaseInsensitiveDictionary<IReadOnlyList<PackageVulnerabilityInfo>>>(HttpSourceCachedRequest request, Func<HttpSourceResult, Task<CaseInsensitiveDictionary<IReadOnlyList<PackageVulnerabilityInfo>>>> processAsync, ILogger log, CancellationToken token) Line 79
   • NuGet.Protocol.Resources.VulnerabilityInfoResourceV3.GetVulnerabilityDataAsync(V3VulnerabilityIndexEntry vulnerabilityPage, SourceCacheContext cacheContext, ILogger logger, CancellationToken cancellationToken) Line 98
   • NuGet.Protocol.Resources.VulnerabilityInfoResourceV3.GetVulnerabilityInfoAsync(SourceCacheContext cacheContext, ILogger logger, CancellationToken cancellationToken) Line 151

4. NuGet.Common.dll

   • NuGet.Common.ConcurrencyUtilities.ExecuteWithFileLockedAsync<CaseInsensitiveDictionary<IReadOnlyList<PackageVulnerabilityInfo>>>(string filePath, Func<CancellationToken, Task<CaseInsensitiveDictionary<IReadOnlyList<PackageVulnerabilityInfo>>>> action, CancellationToken token) Line 102

5. NuGet.PackageManagement.dll (Async)

   • NuGet.PackageManagement.AuditChecker.GetAllVulnerabilityDataAsync.__GetVulnerabilityInfoAsync|5_0(SourceRepository source, SourceCacheContext cacheContext, ILogger logger) Line 186
   • NuGet.PackageManagement.AuditChecker.GetAllVulnerabilityDataAsync(List<SourceRepository> sourceRepositories, SourceCacheContext sourceCacheContext, ILogger logger, CancellationToken cancellationToken) Line 141
   • NuGet.PackageManagement.AuditChecker.CheckPackageVulnerabilitiesAsync(IEnumerable<PackageRestoreData> packages, Dictionary<string, RestoreAuditProperties> restoreAuditProperties, CancellationToken cancellationToken) Line 58
   • NuGet.PackageManagement.PackageRestoreManager.RunNuGetAudit(PackageRestoreContext packageRestoreContext, List<SourceRepository> sourceRepositories) Line 457
   • NuGet.PackageManagement.PackageRestoreManager.RestoreMissingPackagesAsync(PackageRestoreContext packageRestoreContext, INuGetProjectContext nuGetProjectContext, PackageDownloadContext downloadContext) Line 405
   • NuGet.PackageManagement.PackageRestoreManager.RestoreMissingPackagesAsync(string solutionDirectory, IEnumerable<PackageRestoreData> packages, INuGetProjectContext nuGetProjectContext, PackageDownloadContext downloadContext, ILogger logger, CancellationToken token) Line 360
   • NuGet.PackageManagement.PackageRestoreManager.RestoreMissingPackagesInSolutionAsync(string solutionDirectory, INuGetProjectContext nuGetProjectContext, ILogger logger, CancellationToken token) Line 280

6. NuGet.PackageManagement.UI.dll (Async)

   • NuGet.PackageManagement.UI.PackageRestoreBar.UIRestorePackagesAsync(CancellationToken token) Line 264
   • NuGet.PackageManagement.UI.PackageManagerControl.ExecuteAction.AnonymousMethod__0() Line 1616

[nkolev92]

I noticed the yellow bar for only a fraction of second that has the same message mentioned in the issue description.

That matches @jgonz120's summary that I copied here in #13407 (comment).

These changes were pointing to the packages.config style projects but not sure yet why this change impacts package reference style projects also

The PackageReference one has been implemented for some time in https://github.com/NuGet/NuGet.Client/blob/12d5c661b77d4933f82a293008c0d56d1d6ce32b/src/NuGet.Core/NuGet.Commands/RestoreCommand/Utility/AuditUtility.cs#L334. Runs the same logic, which is what Tim's scenario is hitting.

Sounds to me like we're reaching the same conclusions, and the slowdown is due to a slow responding source.

I think #13407 (comment) still makes sense for improvements.

Thanks for the analysis @kartheekp-ms