Make RestoreCommand handle unexpected exceptions.

[Nigusu-Allehu]

Bug

Fixes: NuGet/Home#13188

Description

recreates #5878

• Catch all exceptions, and write them to the projects asset file.
• This is done in RestoreCommad
• That means, RestoreCommand.ExecuteAsync never throws an exception.

For the screenshots below, the following synthetic projects were used:
- bad.csproj : A project that throws an exception upon restore.
- good.csproj: A project that restores successfully.
- multiprojectWithOneErrors.csproj: A project

Currently, restoring this solution will result in an exception that interrupts the restore from restoring projects that did not cause the exception.

After this change, exception are caught allowing restore to complete for other projects as following:

VS side

After the change, here's how the errors will be displayed on VS:

PR Checklist

• Meaningful title, helpful description and a linked NuGet/Home issue
• Added tests
• Link to an issue or pull request to update docs if this PR changes settings, environment variables, new feature, etc.

[Nigusu-Allehu]

Comment from closed PR: #5878 (review)
@nkolev92

 I'm glad we're getting this fixed. 

A few things that'd be interesting to me before we commit to the particular solution. 

* How does Visual Studio behave in the same scenario? Ideally the experience is actionable in all scenarios.
* What kind of error in particular are we trying to solve? Can we add a test for that?
* Ideally for "uncontrolled" errors, we have a code and something telling our customers to file an issue. 

Some design considerations around restore changes that aren't really documented in a single space.

* For each restore, the output is an assets file, nuget.g.props and nuget.g.targets files. We try to generate that regardless of the reason for failure.
* All warnings and errors generated for a project must be part of the assets file. To achieve that, the errors/warnigns need to be generated in the RestoreCommand.
* In .NET SDK based projects, this is needed, because otherwise the warning/error will not even show up in the error list.

[Nigusu-Allehu]

Comment from closed PR: #5878 (review) @nkolev92

 I'm glad we're getting this fixed. 

A few things that'd be interesting to me before we commit to the particular solution. 

* How does Visual Studio behave in the same scenario? Ideally the experience is actionable in all scenarios.
* What kind of error in particular are we trying to solve? Can we add a test for that?
* Ideally for "uncontrolled" errors, we have a code and something telling our customers to file an issue. 

Some design considerations around restore changes that aren't really documented in a single space.

* For each restore, the output is an assets file, nuget.g.props and nuget.g.targets files. We try to generate that regardless of the reason for failure.
* All warnings and errors generated for a project must be part of the assets file. To achieve that, the errors/warnigns need to be generated in the RestoreCommand.
* In .NET SDK based projects, this is needed, because otherwise the warning/error will not even show up in the error list.

Currently, the idea is to catch all exceptions in RestoreCOmmand.ExecuteAsync(). This would ensure no unhandled exceptions interrupt the restore operation, at least at the RestoreCommand Level. I am not able to think of a scenario where we would want an exception to be thrown by RestoreCommand.

Regarding the error code, I agree that we should have a general error code for this scenario. However, if the exception thrown has an error code with it, we should use the exceptions error code.

[nkolev92]

Currently, the idea is to catch all exceptions in RestoreCOmmand.ExecuteAsync(). This would ensure no unhandled exceptions interrupt the restore operation, at least at the RestoreCommand Level. I am not able to think of a scenario where we would want an exception to be thrown by RestoreCommand.

That makes sense to me.
There's already some exceptions being caught, such as FatalProtocolException. In that case, the log message is assumed to have been logged.

Regarding the error code, I agree that we should have a general error code for this scenario. However, if the exception thrown has an error code with it, we should use the exceptions error code.

One thing that might be tricky is that in the current implementation when we catch FatalProtocolException we don't really log the message, we assume it's already been logged.
So we need to make sure we don't double log messages.
It is very possible this is enough, a generic error message indicating that something uncontrolled happened and that people need to file an issue to get us to implement a more concrete error.

[Nigusu-Allehu]

Currently, the idea is to catch all exceptions in RestoreCOmmand.ExecuteAsync(). This would ensure no unhandled exceptions interrupt the restore operation, at least at the RestoreCommand Level. I am not able to think of a scenario where we would want an exception to be thrown by RestoreCommand.

That makes sense to me. There's already some exceptions being caught, such as FatalProtocolException. In that case, the log message is assumed to have been logged.

Regarding the error code, I agree that we should have a general error code for this scenario. However, if the exception thrown has an error code with it, we should use the exceptions error code.

One thing that might be tricky is that in the current implementation when we catch FatalProtocolException we don't really log the message, we assume it's already been logged. So we need to make sure we don't double log messages. It is very possible this is enough, a generic error message indicating that something uncontrolled happened and that people need to file an issue to get us to implement a more concrete error.

Currently, the idea is to catch all exceptions in RestoreCOmmand.ExecuteAsync(). This would ensure no unhandled exceptions interrupt the restore operation, at least at the RestoreCommand Level. I am not able to think of a scenario where we would want an exception to be thrown by RestoreCommand.

That makes sense to me. There's already some exceptions being caught, such as FatalProtocolException. In that case, the log message is assumed to have been logged.

Regarding the error code, I agree that we should have a general error code for this scenario. However, if the exception thrown has an error code with it, we should use the exceptions error code.

One thing that might be tricky is that in the current implementation when we catch FatalProtocolException we don't really log the message, we assume it's already been logged. So we need to make sure we don't double log messages. It is very possible this is enough, a generic error message indicating that something uncontrolled happened and that people need to file an issue to get us to implement a more concrete error.

Erro code:

• I decided to go with Nu1000

Double logging

• The idea is to catch all exceptions in RestoreCommand and add the errors to the asset file for the project
• Which would eventually be logged both in CLI and VS
• On the other hand, as you said, we do catch exceptions like FatalProtocolException. Here:

  NuGet.Client/src/NuGet.Core/NuGet.Commands/RestoreCommand/SourceRepositoryDependencyProvider.cs

  Line 215 in 3db80da

  catch (FatalProtocolException e)

  , We do catch the exception and rethrow it if it is an error. And it would probably end up being caught again in RestoreCommand. I personally think we should create another task item that aims to remove these types of loggings - Caught exception being logged and thrown again. After catching an exception, we should: either rethrow without logging or log an error and not rethrow. THis way we avoid double logging.

[zivkan]

Your CLI restore example shows that MSBuild is attributing the exception to NuGet.targets, and not the csproj file. There's a property on AssetsLogMessage so NuGet tells MSBuild which project file the error is related to, which should be filled in.

[Nigusu-Allehu]

I just updated the CLI example in the description section. The screenshot I had was an old one - before I started adding the error to an assets file.

[nkolev92]

What about building the assets file after you log the message to the logger.

Currently this adds another place where we can create a discrepancy.

The pattern currently is:

• You log warnings to the "collector" logger.
• When you create the assets file, the "collector" logger creates assets file warnings.
• It'd also be ideal if the failed restore result is created into fewer places. Same reason as above, fewer chances of a discrepancy.

[Nigusu-Allehu]

We need the assets file, as it’s responsible for capturing all log messages. is the suggestion to do _logger.Log(error) instead? or to do _logger.log(error) and then follow it up with asset.LogMessage(error)

[nkolev92]

No, don't add messages to the assets file.
There's a collector logger that ensures that all warnings/errors will be part of the built assets file.

Compare that to how we log errors like NU1008, or warnings like NU1603. You call the logger.

[zivkan]

Where does the collector logger write the assets file? This try-catch block is shallow in the call stack, and I wouldn't be surprised if an exception that bubbles all the way up here will not be written to the assets file by the collector logger.

[Nigusu-Allehu]

I wasn't able to find out if the collector logger writes to the asset file. From my understanding, we do the writing into the assets file in RestoreCommand.ExecuteAsync

NuGet.Client/src/NuGet.Core/NuGet.Commands/RestoreCommand/RestoreCommand.cs

Line 457 in 46b470c

var logsEnumerable = _logger.Errors

[nkolev92]

You do all the logic restore ever would and you just write to the logger and that's it.
The try catch should end before we do the transformation at line 457.

Similarly, don't create a new RestoreResult and keep it in one place. That reduces the changes we end up with restore results that don't end up getting everything and either the output is broken or the result is misinterpreted.

[aortiz-msft]

Can we please add a test for this change that documents the desired behavior?

[zivkan]

This would have saved me half a day of debugging, if it was merged about a month ago 😁

[nkolev92]

No, don't add messages to the assets file.
There's a collector logger that ensures that all warnings/errors will be part of the built assets file.

Compare that to how we log errors like NU1008, or warnings like NU1603. You call the logger.

[zivkan]

none of the tests modified in this PR validate that the assets file contains the log message. I'd expect the in-memory results to contain the log because the logger has scope longer than RestoreCommand. However, RestoreCommand needs to write the assets file, including the logger's messages, and if there's an unhandled exception, there's a decent chance that isn't happening.