Log SDK resolution result

[surayya-MS]

Fixes #9413

Context

We currently log when we are starting to resolve SDK and when we failed to resolve SDK but not when we succeeded or any resolvers' attempts.

Currently we log:

• If any of the resolvers succeeded, we log warnings only from its result
• If all the resolvers fail, we accumulate the warnings and errors from each of them. In the end, depending on the log flag, we either log one error containing all the errors or do not to log any errors, while logging all warnings.

Changes Made

1. Log each resolver's unsuccessful attempt with its warnings and errors as a message
2. Log success message when SDK is resolved by the resolver
3. Remove "Resolving SDK ..." message as it doesn't give us much

Testing

Unit tests + manual

Notes

Example of new log output:

[surayya-MS]

I didn't include the SDK resolver info that resolved the SDK in the success message since we don't mention it in the failure message. Let me know if you think we should log anything else.

[ladipro]

Can you please include examples of the new log output in the PR description? Thank you!

[rokonec]

I am still trying to figure out how useful would be to log particular SDK resolvers outcome so user UX would be:

- Resolving SDK net8.1
  - DefaultSDK resolver: Can't find SDK on path C:\VS\Current\SDK\8.1
  - DevSDK resolver: Env variable PICK_ME_PICK_ME_I_AM_THE_BEST_SDK is not set
  - Nuget SDK resolver: Selected SDK from downloaded JozoMrkvicka.SDKs.TrueSDK-8.1 nuget
- SDK 8.1 resolved to C:\NugetCache\JozoMrkvicka.SDKs.TrueSDK\8.1

as oppose to

- Resolving SDK net8.1
- SDK 8.1 resolved to C:\NugetCache\JozoMrkvicka.SDKs.TrueSDK\8.1

with reasoning that when user investigate why it stopped resolving when it just worked fine so far he could see the differences and details.

@rainersigwald @baronfel what is your take at this?

[baronfel]

Agree 💯 @rokonec - getting all results could be very helpful.

[rokonec]

We need to fully localize log messages

[ladipro]

Looks great! If resolution fails, warnings and errors will now be logged twice - as low-important messages and as actual warnings and errors by pre-existing code. I may be splitting hair but I think ideally they would appear in the log exactly once. It is also somewhat inconsistent that the existing logic uses individual log events and the new one string-joins all warnings into one message.

I don't fell strongly about fixing it, though. cc @rokonec

[surayya-MS]

If resolution fails, warnings and errors will now be logged twice - as low-important messages and as actual warnings and errors by pre-existing code. I may be splitting hair but I think ideally they would appear in the log exactly once. It is also somewhat inconsistent that the existing logic uses individual log events and the new one string-joins all warnings into one message.

Yes, warnings and errors will now be logged twice - as low-important messages and as actual warnings and errors in case when all resolvers failed. I don't like the duplication too. I opted for this approach because we aim to preserve timestamps for each resolver's attempt. The current logic is that in case of resolver succeeded then we want to see only warnings coming from its result and don't want to see other resolvers' warnings. That is why I log them as joined warnings in low-importance message and not as warnings.

Alternatively, we could log warnings and errors for each resolver in a single low-importance message before resolution succeeds. In this way, if the resolution fails, we would only see the warnings and errors at the end, a per the current behavior. However, we would lose the timestamps of each resolver's attempt, as opposed to the original change.
What do you think @ladipro, @rokonec ?

[surayya-MS]

/azp run

[azure-pipelines]

Commenter does not have sufficient privileges for PR 9621 in repo dotnet/msbuild

[rokonec]

However, we would lose the timestamps of each resolver's attempt, as opposed to the original change.
What do you think @ladipro, @rokonec ?

I like it the way it is now. i.e.:

1. low priority messages for each resolver, visible only in /bl and detailed verbosity
2. if it failed summarize high importance error visible with almost every verbosity which will repeat all from 1)
3. if if succeed just show the final outcome and customer can find details in 1)

I believe it will deliver customers clear intuitive UX. In this particular case I don't mind duplication as I believe it is better UX with it than without it. It can be optimized to not show 1) when 2) but I prefer consistency of logging in both success and failure path.