From cfe74c94c24fc7d2255b75626499eb98448e694d Mon Sep 17 00:00:00 2001 From: Rainer Sigwald <raines@microsoft.com> Date: Fri, 3 Nov 2023 09:51:48 -0500 Subject: [PATCH 1/4] Update ETW Version for modified event Per https://learn.microsoft.com/dotnet/api/system.diagnostics.tracing.eventsource#conventions, the version field for events must increment any time the payload is added to. I looked at https://github.com/dotnet/msbuild/blame/31c4d335325e858a3c4dba66d921d0e31bdee5ff/src/Framework/MSBuildEventSource.cs and added a version bump to every event that wasn't from 45e27c1, ad3e7d0, or an introduction of the event, and found only this one. --- src/Framework/MSBuildEventSource.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/Framework/MSBuildEventSource.cs b/src/Framework/MSBuildEventSource.cs index a5dbe84a3ee..be9b4ce07af 100644 --- a/src/Framework/MSBuildEventSource.cs +++ b/src/Framework/MSBuildEventSource.cs @@ -242,7 +242,7 @@ public void RarOverallStart() WriteEvent(27); } - [Event(28, Keywords = Keywords.All | Keywords.PerformanceLog)] + [Event(28, Keywords = Keywords.All | Keywords.PerformanceLog, Version = 1)] public void RarOverallStop(int assembliesCount, int assemblyFilesCount, int resolvedFilesCount, int resolvedDependencyFilesCount, int copyLocalFilesCount, bool findDependencies) { WriteEvent(28, assembliesCount, assemblyFilesCount, resolvedFilesCount, resolvedDependencyFilesCount, copyLocalFilesCount, findDependencies); From 187da8097a2f6db9aad994d852d17ec3050840cc Mon Sep 17 00:00:00 2001 From: Rainer Sigwald <raines@microsoft.com> Date: Fri, 3 Nov 2023 10:04:31 -0500 Subject: [PATCH 2/4] Never log a null string ETW arg `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 #8519. --- src/Build/BackEnd/Client/MSBuildClient.cs | 6 +++--- .../BackEnd/Components/ProjectCache/ProjectCacheService.cs | 4 ++-- src/Build/Evaluation/LazyItemEvaluator.IncludeOperation.cs | 4 ++-- src/Framework/MSBuildEventSource.cs | 2 -- 4 files changed, 7 insertions(+), 9 deletions(-) diff --git a/src/Build/BackEnd/Client/MSBuildClient.cs b/src/Build/BackEnd/Client/MSBuildClient.cs index e0782c3fbf3..642f1b1b024 100644 --- a/src/Build/BackEnd/Client/MSBuildClient.cs +++ b/src/Build/BackEnd/Client/MSBuildClient.cs @@ -225,7 +225,7 @@ public MSBuildClientExitResult Execute(CancellationToken cancellationToken) ReadPacketsLoop(cancellationToken); - MSBuildEventSource.Log.MSBuildServerBuildStop(descriptiveCommandLine, _numConsoleWritePackets, _sizeOfConsoleWritePackets, _exitResult.MSBuildClientExitType.ToString(), _exitResult.MSBuildAppExitTypeString); + MSBuildEventSource.Log.MSBuildServerBuildStop(descriptiveCommandLine, _numConsoleWritePackets, _sizeOfConsoleWritePackets, _exitResult.MSBuildClientExitType.ToString(), _exitResult.MSBuildAppExitTypeString ?? string.Empty); CommunicationsUtilities.Trace("Build finished."); } @@ -437,7 +437,7 @@ private bool TrySendPacket(Func<INodePacket> packetResolver) } /// <summary> - /// Launches MSBuild server. + /// Launches MSBuild server. /// </summary> /// <returns> Whether MSBuild server was started successfully.</returns> private bool TryLaunchServer() @@ -511,7 +511,7 @@ private ServerNodeBuildCommand GetServerNodeBuildCommand() envVars[pair.Key] = pair.Value; } - // We remove env variable used to invoke MSBuild server as that might be equal to 1, so we do not get an infinite recursion here. + // We remove env variable used to invoke MSBuild server as that might be equal to 1, so we do not get an infinite recursion here. envVars.Remove(Traits.UseMSBuildServerEnvVarName); Debug.Assert(KnownTelemetry.PartialBuildTelemetry == null || KnownTelemetry.PartialBuildTelemetry.StartAt.HasValue, "BuildTelemetry.StartAt was not initialized!"); diff --git a/src/Build/BackEnd/Components/ProjectCache/ProjectCacheService.cs b/src/Build/BackEnd/Components/ProjectCache/ProjectCacheService.cs index d684119e4e8..5c9016fba9c 100644 --- a/src/Build/BackEnd/Components/ProjectCache/ProjectCacheService.cs +++ b/src/Build/BackEnd/Components/ProjectCache/ProjectCacheService.cs @@ -525,7 +525,7 @@ private async Task<CacheResult> GetCacheResultAsync(BuildRequestData buildReques ErrorUtilities.VerifyThrow(plugin.Instance != null, "Plugin '{0}' instance is null", plugin.Name); - MSBuildEventSource.Log.ProjectCacheGetCacheResultStart(plugin.Name, buildRequest.ProjectFullPath, targetNames); + MSBuildEventSource.Log.ProjectCacheGetCacheResultStart(plugin.Name, buildRequest.ProjectFullPath, targetNames ?? "<default>"); cacheResult = await plugin.Instance!.GetCacheResultAsync(buildRequest, pluginLogger, cancellationToken); if (pluginLogger.HasLoggedErrors || cacheResult.ResultType == CacheResultType.None) @@ -548,7 +548,7 @@ private async Task<CacheResult> GetCacheResultAsync(BuildRequestData buildReques if (MSBuildEventSource.Log.IsEnabled()) { string cacheResultType = cacheResult?.ResultType.ToString() ?? nameof(CacheResultType.None); - MSBuildEventSource.Log.ProjectCacheGetCacheResultStop(plugin.Name, buildRequest.ProjectFullPath, targetNames, cacheResultType); + MSBuildEventSource.Log.ProjectCacheGetCacheResultStop(plugin.Name, buildRequest.ProjectFullPath, targetNames ?? "<default>", cacheResultType); } } } diff --git a/src/Build/Evaluation/LazyItemEvaluator.IncludeOperation.cs b/src/Build/Evaluation/LazyItemEvaluator.IncludeOperation.cs index 6adca4bf208..9dfd281b165 100644 --- a/src/Build/Evaluation/LazyItemEvaluator.IncludeOperation.cs +++ b/src/Build/Evaluation/LazyItemEvaluator.IncludeOperation.cs @@ -104,7 +104,7 @@ protected override ImmutableArray<I> SelectItems(OrderedItemDataCollection.Build string[] includeSplitFilesEscaped; if (MSBuildEventSource.Log.IsEnabled()) { - MSBuildEventSource.Log.ExpandGlobStart(_rootDirectory, glob, string.Join(", ", excludePatternsForGlobs)); + MSBuildEventSource.Log.ExpandGlobStart(_rootDirectory ?? string.Empty, glob, string.Join(", ", excludePatternsForGlobs)); } using (_lazyEvaluator._evaluationProfiler.TrackGlob(_rootDirectory, glob, excludePatternsForGlobs)) @@ -121,7 +121,7 @@ protected override ImmutableArray<I> SelectItems(OrderedItemDataCollection.Build if (MSBuildEventSource.Log.IsEnabled()) { - MSBuildEventSource.Log.ExpandGlobStop(_rootDirectory, glob, string.Join(", ", excludePatternsForGlobs)); + MSBuildEventSource.Log.ExpandGlobStop(_rootDirectory ?? string.Empty, glob, string.Join(", ", excludePatternsForGlobs)); } foreach (string includeSplitFileEscaped in includeSplitFilesEscaped) diff --git a/src/Framework/MSBuildEventSource.cs b/src/Framework/MSBuildEventSource.cs index be9b4ce07af..f96d17a98e3 100644 --- a/src/Framework/MSBuildEventSource.cs +++ b/src/Framework/MSBuildEventSource.cs @@ -3,8 +3,6 @@ using System.Diagnostics.Tracing; -#nullable disable - namespace Microsoft.Build.Eventing { /// <summary> From d8d045848038c4512302b4b50ff483fbe5aacaeb Mon Sep 17 00:00:00 2001 From: Rainer Sigwald <raines@microsoft.com> Date: Fri, 3 Nov 2023 11:09:44 -0500 Subject: [PATCH 3/4] Avoid logging null ETW strings in SDK resolvers --- .../Components/SdkResolution/CachingSdkResolverService.cs | 4 ++-- .../BackEnd/Components/SdkResolution/SdkResolverService.cs | 6 +++--- 2 files changed, 5 insertions(+), 5 deletions(-) diff --git a/src/Build/BackEnd/Components/SdkResolution/CachingSdkResolverService.cs b/src/Build/BackEnd/Components/SdkResolution/CachingSdkResolverService.cs index 2e198bf29f6..0f79c18d598 100644 --- a/src/Build/BackEnd/Components/SdkResolution/CachingSdkResolverService.cs +++ b/src/Build/BackEnd/Components/SdkResolution/CachingSdkResolverService.cs @@ -41,7 +41,7 @@ public override SdkResult ResolveSdk(int submissionId, SdkReference sdk, Logging bool wasResultCached = true; - MSBuildEventSource.Log.CachedSdkResolverServiceResolveSdkStart(sdk.Name, solutionPath, projectPath); + MSBuildEventSource.Log.CachedSdkResolverServiceResolveSdkStart(sdk.Name, solutionPath ?? string.Empty, projectPath ?? string.Empty); if (Traits.Instance.EscapeHatches.DisableSdkResolutionCache) { @@ -79,7 +79,7 @@ public override SdkResult ResolveSdk(int submissionId, SdkReference sdk, Logging loggingContext.LogWarning(null, new BuildEventFileInfo(sdkReferenceLocation), "ReferencingMultipleVersionsOfTheSameSdk", sdk.Name, result.Version, result.ElementLocation, sdk.Version); } - MSBuildEventSource.Log.CachedSdkResolverServiceResolveSdkStop(sdk.Name, solutionPath, projectPath, result.Success, wasResultCached); + MSBuildEventSource.Log.CachedSdkResolverServiceResolveSdkStop(sdk.Name, solutionPath ?? string.Empty, projectPath ?? string.Empty, result.Success, wasResultCached); return result; } diff --git a/src/Build/BackEnd/Components/SdkResolution/SdkResolverService.cs b/src/Build/BackEnd/Components/SdkResolution/SdkResolverService.cs index a684c59618a..d371a71db15 100644 --- a/src/Build/BackEnd/Components/SdkResolution/SdkResolverService.cs +++ b/src/Build/BackEnd/Components/SdkResolution/SdkResolverService.cs @@ -248,7 +248,7 @@ private List<SdkResolver> GetResolvers(IList<SdkResolverManifest> resolversManif MSBuildEventSource.Log.SdkResolverServiceLoadResolversStart(); newResolvers = _sdkResolverLoader.LoadResolversFromManifest(resolverManifest, loggingContext, sdkReferenceLocation); _manifestToResolvers[resolverManifest] = newResolvers; - MSBuildEventSource.Log.SdkResolverServiceLoadResolversStop(resolverManifest.DisplayName, newResolvers.Count); + MSBuildEventSource.Log.SdkResolverServiceLoadResolversStop(resolverManifest.DisplayName ?? string.Empty, newResolvers.Count); } } } @@ -340,7 +340,7 @@ private bool TryResolveSdkUsingSpecifiedResolvers( } finally { - MSBuildEventSource.Log.SdkResolverResolveSdkStop(sdkResolver.Name, sdk.Name, solutionPath, projectPath, result?.Path, result?.Success ?? false); + MSBuildEventSource.Log.SdkResolverResolveSdkStop(sdkResolver.Name, sdk.Name, solutionPath ?? string.Empty, projectPath ?? string.Empty, result?.Path ?? string.Empty, result?.Success ?? false); } SetResolverState(submissionId, sdkResolver, context.State); @@ -481,7 +481,7 @@ private void RegisterResolversManifests(LoggingContext loggingContext, ElementLo SdkResolverManifest sdkDefaultResolversManifest = new SdkResolverManifest(DisplayName: "DefaultResolversManifest", Path: null, ResolvableSdkRegex: null); allResolversManifests.Add(sdkDefaultResolversManifest); _manifestToResolvers[sdkDefaultResolversManifest] = defaultResolvers; - MSBuildEventSource.Log.SdkResolverServiceLoadResolversStop(sdkDefaultResolversManifest.DisplayName, defaultResolvers.Count); + MSBuildEventSource.Log.SdkResolverServiceLoadResolversStop(sdkDefaultResolversManifest.DisplayName ?? string.Empty, defaultResolvers.Count); } MSBuildEventSource.Log.SdkResolverServiceFindResolversManifestsStop(allResolversManifests.Count); From e77aa194169d9bd990806c3f026706dd61b2fe59 Mon Sep 17 00:00:00 2001 From: Rainer Sigwald <raines@microsoft.com> Date: Fri, 10 Nov 2023 13:34:45 -0600 Subject: [PATCH 4/4] Use named constant for default set of targets --- .../BackEnd/Components/ProjectCache/ProjectCacheService.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/Build/BackEnd/Components/ProjectCache/ProjectCacheService.cs b/src/Build/BackEnd/Components/ProjectCache/ProjectCacheService.cs index 5c9016fba9c..4d695e99076 100644 --- a/src/Build/BackEnd/Components/ProjectCache/ProjectCacheService.cs +++ b/src/Build/BackEnd/Components/ProjectCache/ProjectCacheService.cs @@ -525,7 +525,7 @@ private async Task<CacheResult> GetCacheResultAsync(BuildRequestData buildReques ErrorUtilities.VerifyThrow(plugin.Instance != null, "Plugin '{0}' instance is null", plugin.Name); - MSBuildEventSource.Log.ProjectCacheGetCacheResultStart(plugin.Name, buildRequest.ProjectFullPath, targetNames ?? "<default>"); + MSBuildEventSource.Log.ProjectCacheGetCacheResultStart(plugin.Name, buildRequest.ProjectFullPath, targetNames ?? MSBuildConstants.DefaultTargetsMarker); cacheResult = await plugin.Instance!.GetCacheResultAsync(buildRequest, pluginLogger, cancellationToken); if (pluginLogger.HasLoggedErrors || cacheResult.ResultType == CacheResultType.None)