Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Missing SdkResolverResolveSdk/Stop event #8519

Closed
rainersigwald opened this issue Mar 2, 2023 · 4 comments · Fixed by #8522 or #9393
Closed

Missing SdkResolverResolveSdk/Stop event #8519

rainersigwald opened this issue Mar 2, 2023 · 4 comments · Fixed by #8522 or #9393
Assignees
Labels
Area: Debuggability Issues impacting the diagnosability of builds, including logging and clearer error messages. bug needs-triage Have yet to determine what bucket this goes in.

Comments

@rainersigwald
Copy link
Member

I've been looking at a few ETW traces, and I can see Microsoft-Build/SdkResolverResolveSdk/Start events, but no corresponding Stop event.

Since the info about the resolver and the SDK to be resolved is in Stop, this is unfortunate:

MSBuildEventSource.Log.SdkResolverResolveSdkStart();
result = (SdkResult)sdkResolver.Resolve(sdk, context, resultFactory);
MSBuildEventSource.Log.SdkResolverResolveSdkStop(sdkResolver.Name, sdk.Name, solutionPath, projectPath, result?.Path, result?.Success ?? false);

Watching in the debugger, I can see that we're calling our event

[Event(65, Keywords = Keywords.All)]
public void SdkResolverResolveSdkStop(string resolverName, string sdkName, string solutionPath, string projectPath, string sdkPath, bool success)
{
WriteEvent(65, resolverName, sdkName, solutionPath, projectPath, sdkPath, success);
}

and it's getting into the underlying call:

>	mscorlib.dll!System.Diagnostics.Tracing.EventSource.WriteEventVarargs(int eventId, System.Guid* childActivityID, object[] args) Line 1894	C#
 	Microsoft.Build.Framework.dll!Microsoft.Build.Eventing.MSBuildEventSource.SdkResolverResolveSdkStop(string resolverName, string sdkName, string solutionPath, string projectPath, string sdkPath, bool success) Line 502	C#
 	Microsoft.Build.dll!Microsoft.Build.BackEnd.SdkResolution.SdkResolverService.TryResolveSdkUsingSpecifiedResolvers(System.Collections.Generic.IList<Microsoft.Build.Framework.SdkResolver> resolvers, int submissionId, Microsoft.Build.Framework.SdkReference sdk, Microsoft.Build.BackEnd.Logging.LoggingContext loggingContext, Microsoft.Build.Construction.ElementLocation sdkReferenceLocation, string solutionPath, string projectPath, bool interactive, bool isRunningInVisualStudio, out Microsoft.Build.BackEnd.SdkResolution.SdkResult sdkResult, out System.Collections.Generic.IEnumerable<string> errors, out System.Collections.Generic.IEnumerable<string> warnings) Line 326	C#
 	Microsoft.Build.dll!Microsoft.Build.BackEnd.SdkResolution.SdkResolverService.ResolveSdkUsingResolversWithPatternsFirst(int submissionId, Microsoft.Build.Framework.SdkReference sdk, Microsoft.Build.BackEnd.Logging.LoggingContext loggingContext, Microsoft.Build.Construction.ElementLocation sdkReferenceLocation, string solutionPath, string projectPath, bool interactive, bool isRunningInVisualStudio, bool failOnUnresolvedSdk) Line 204	C#
 	Microsoft.Build.dll!Microsoft.Build.BackEnd.SdkResolution.SdkResolverService.ResolveSdk(int submissionId, Microsoft.Build.Framework.SdkReference sdk, Microsoft.Build.BackEnd.Logging.LoggingContext loggingContext, Microsoft.Build.Construction.ElementLocation sdkReferenceLocation, string solutionPath, string projectPath, bool interactive, bool isRunningInVisualStudio, bool failOnUnresolvedSdk) Line 134	C#

I've seen this on 17.6.0-preview-23122-03+f93b24b5a for .NET Framework as well as 17.5.0-preview-23061-01+040e2a90e for .NET, and in some traces from others that should be on older released versions.

@rainersigwald rainersigwald added bug Area: Debuggability Issues impacting the diagnosability of builds, including logging and clearer error messages. needs-triage Have yet to determine what bucket this goes in. labels Mar 2, 2023
@jeffkl
Copy link
Contributor

jeffkl commented Mar 2, 2023

I think my PR would fix this but I never had time to really dive into it and my suggested fix wasn't well received.

#7497

@Forgind
Copy link
Member

Forgind commented Mar 2, 2023

I think my PR would fix this but I never had time to really dive into it and my suggested fix wasn't well received.

#7497

Would you mind explaining what versions have to do with events not firing? I'm confused as to what the versions are defaulting to or why they would be different from each other.

JaynieBai pushed a commit that referenced this issue Mar 13, 2023
May fix #8519

Context
Some SdkResolverResolveSdkStop events aren't being picked up. This is especially problematic, since those hold most of the interesting information. This tries to ensure that they are logged even if we throw.

Changes Made
Move stop event to finally block

Testing
None
@rainersigwald
Copy link
Member Author

The move to finally didn't solve this.

@rainersigwald rainersigwald reopened this Nov 3, 2023
@rainersigwald
Copy link
Member Author

Instead of the real events we get

EventSourceException while processing event "SdkResolverResolveSdkStop": Null passed as a event argument.
EventSourceException while processing event "CachedSdkResolverServiceResolveSdkStop": Null passed as a event argument.

@rainersigwald rainersigwald self-assigned this Nov 3, 2023
rainersigwald added a commit to rainersigwald/msbuild that referenced this issue Nov 3, 2023
`EventSource.WriteEvent()` can, instead of writing the specified event, instead
create `Microsoft-Build/EventSourceMessage` events that look like

```
EventSourceException while processing event "SdkResolverResolveSdkStop": Null passed as a event argument.
EventSourceException while processing event "CachedSdkResolverServiceResolveSdkStop": Null passed as a event argument.
```

Fix all instances of this by enabling nullable analysis in
`MSBuildEventSource.cs` and then fixing the errors that arose.

Fixes dotnet#8519.
rainersigwald added a commit to rainersigwald/msbuild that referenced this issue Nov 3, 2023
`EventSource.WriteEvent()` can, instead of writing the specified event, instead
create `Microsoft-Build/EventSourceMessage` events that look like

```
EventSourceException while processing event "SdkResolverResolveSdkStop": Null passed as a event argument.
EventSourceException while processing event "CachedSdkResolverServiceResolveSdkStop": Null passed as a event argument.
```

Fix all instances of this by enabling nullable analysis in
`MSBuildEventSource.cs` and then fixing the errors that arose.

Fixes dotnet#8519.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Area: Debuggability Issues impacting the diagnosability of builds, including logging and clearer error messages. bug needs-triage Have yet to determine what bucket this goes in.
Projects
None yet
3 participants