dotnet / dotnet/project-system

NuGet Package resolver blocks operation progress forever

Open
#6,825 0 comments 0 reactions 1 assignee Assigned to @drewnoakes View on GitHub
Feature-NuGet Triage-Approved
Dominant language
C#
Stars
1k
Forks
415
PR merge metrics
No merged PRs in 30d

Description

This has been a problem for a while since the operation progress feature was introduced, and in random cases, the operation progress will never end, due to NuGet restore feature never reports it finishes the work. We have been seeing this once a while, but wasn't able to identify the root reason, and successfully fixed it.

Here is how it works: after NuGet restore is done, the feature will wait the project system to get the updated asset file propagated through the system including evaluation/DT build. When the system is in the consistent state, it calls it done. To do it, it captures a timestamp of the asset file (last write time) after NuGet restoring is done, and compare it with the timestamp of that file from the project system. When the timestamp from the project system is the same or newer, it calls its done. The project system/CPS got the timestamp when project is evaluated. When the file is changed, it triggers a new evaluation. It monitors the file by using a file watcher. In the last summer, we noticed this problem, and thought it might be the case that file watcher might miss an event, and now NET Core project also sends a notification to CPS, which triggers it to check the file timestamp again after NuGet restore is done.

In the captured dump file, when this issue happened recently, CPS got the timestamp which was one week earlier than NET Core captured. We don't know which one is correct. It also happened for all projects under a folder, so it is unlikely to be a race condition. One possible explanation is the asset file modification time could go backward (because NuGet does remove/and move it from a temporary location when it writes one), but going back for a week is hard to explain. (When the timestamp goes backward, CPS would update because of the file watcher, but NET Core will retain the time when it drives the update.)

I think we need modify the NET Core logic when it decides whether restoring is done to:
1, mitigates this problem to prevent product to hang
2, collect more information so we can do further investigation

When it runs to the logic to compare the two file timestamp, and the CPS one is older, instead of just waiting, please update the logic to do below:
1, check the configured project version number from the dataflow (which it might need update code to retain it) and compare it with configured project version number from configuredProject. If it is smaller, just wait (because we know more evaluation will follow, no need to waste time)

2, if it is the latest version, and the timestamp from CPS is older than NET Core one. Add code to get the file timestamp from the disk, use it to verify which one is wrong, send a new telemetry to report it (so we can do further investigation with this information).
If the NET Core one is wrong (file goes backward), please update the timestamp in the NET Core, which will address this deadlock (that scenario might happen if the file is updated outside of VS by other builds, or the solution is opened by two VS instances), which might be logic we do need.

If the one from CPS is incorrect, sends a notification by using the same logic done after a NuGet restore. This will trigger CPS to update the file timestamp, and drives a new round of evaluations. We will do further investigation on why it happens.

In any case, i think it should be a rare condition to run into, so the overhead should be minor, and it would unblock the product (as a mitigation of the problem),

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.