Concurrency bug fix - BuildManager instances acquire its own BuildTelemetry instance (#8444)

eng/Build.props

@@ -2,9 +2,13 @@
 <!-- Copyright (c) .NET Foundation and contributors. All rights reserved. Licensed under the MIT license. See License.txt in the project root for full license information. -->
 <Project>
 
+<!-- Commented out as a temporary fix for the msbuild CI.
+Waiting for https://github.com/NuGet/NuGet.Client/pull/5010 fix to flow to CI machines. -->
+<!--
   <PropertyGroup>
     <RestoreUseStaticGraphEvaluation Condition="'$(DotNetBuildFromSource)' != 'true'">true</RestoreUseStaticGraphEvaluation>
   </PropertyGroup>
+-->
 
   <ItemGroup>
 	<!-- Remove all sln files globbed by arcade so far and add only MSBuild.sln to the build.

eng/Versions.props

@@ -2,7 +2,7 @@
 <!-- Copyright (c) .NET Foundation and contributors. All rights reserved. Licensed under the MIT license. See License.txt in the project root for full license information. -->
 <Project>
   <PropertyGroup>
-    <VersionPrefix>17.4.1</VersionPrefix><DotNetFinalVersionKind>release</DotNetFinalVersionKind>
+    <VersionPrefix>17.4.2</VersionPrefix><DotNetFinalVersionKind>release</DotNetFinalVersionKind>
     <AssemblyVersion>15.1.0.0</AssemblyVersion>
     <PreReleaseVersionLabel>preview</PreReleaseVersionLabel>
     <DotNetUseShippingVersions>true</DotNetUseShippingVersions>

src/Build.UnitTests/BackEnd/KnownTelemetry_Tests.cs

@@ -15,19 +15,19 @@ public class KnownTelemetry_Tests
     [Fact]
     public void BuildTelemetryCanBeSetToNull()
     {
-        KnownTelemetry.BuildTelemetry = new BuildTelemetry();
-        KnownTelemetry.BuildTelemetry = null;
+        KnownTelemetry.PartialBuildTelemetry = new BuildTelemetry();
+        KnownTelemetry.PartialBuildTelemetry = null;
 
-        KnownTelemetry.BuildTelemetry.ShouldBeNull();
+        KnownTelemetry.PartialBuildTelemetry.ShouldBeNull();
     }
 
     [Fact]
     public void BuildTelemetryCanBeSet()
     {
         BuildTelemetry buildTelemetry = new BuildTelemetry();
-        KnownTelemetry.BuildTelemetry = buildTelemetry;
+        KnownTelemetry.PartialBuildTelemetry = buildTelemetry;
 
-        KnownTelemetry.BuildTelemetry.ShouldBeSameAs(buildTelemetry);
+        KnownTelemetry.PartialBuildTelemetry.ShouldBeSameAs(buildTelemetry);
     }
 
     [Fact]

src/Build/BackEnd/BuildManager/BuildManager.cs

@@ -253,6 +253,12 @@ public class BuildManager : INodePacketHandler, IBuildComponentHost, IDisposable
 
         private IEnumerable<DeferredBuildMessage> _deferredBuildMessages;
 
+        /// <summary>
+        /// Build telemetry to be send when this build ends.
+        /// <remarks>Could be null</remarks>
+        /// </summary>
+        private BuildTelemetry _buildTelemetry;
+
         private ProjectCacheService _projectCacheService;
 
         private bool _hasProjectCacheServiceInitializedVsScenario;
@@ -491,11 +497,22 @@ public void BeginBuild(BuildParameters parameters)
 
                 // Initiate build telemetry data
                 DateTime now = DateTime.UtcNow;
-                KnownTelemetry.BuildTelemetry ??= new()
+
+                // Acquire it from static variable so we can apply data collected up to this moment
+                _buildTelemetry = KnownTelemetry.PartialBuildTelemetry;
+                if (_buildTelemetry != null)
+                {
+                    KnownTelemetry.PartialBuildTelemetry = null;
+                }
+                else
                 {
-                    StartAt = now,
-                };
-                KnownTelemetry.BuildTelemetry.InnerStartAt = now;
+                    _buildTelemetry = new()
+                    {
+                        StartAt = now,
+                    };
+                }
+
+                _buildTelemetry.InnerStartAt = now;
 
                 if (BuildParameters.DumpOpportunisticInternStats)
                 {
@@ -805,10 +822,10 @@ public BuildSubmission PendBuildRequest(BuildRequestData requestData)
 
                 var newSubmission = new BuildSubmission(this, GetNextSubmissionId(), requestData, _buildParameters.LegacyThreadingSemantics);
 
-                if (KnownTelemetry.BuildTelemetry != null)
+                if (_buildTelemetry != null)
                 {
-                    KnownTelemetry.BuildTelemetry.Project ??= requestData.ProjectFullPath;
-                    KnownTelemetry.BuildTelemetry.Target ??= string.Join(",", requestData.TargetNames);
+                    _buildTelemetry.Project ??= requestData.ProjectFullPath;
+                    _buildTelemetry.Target ??= string.Join(",", requestData.TargetNames);
                 }
 
                 _buildSubmissions.Add(newSubmission.SubmissionId, newSubmission);
@@ -833,12 +850,12 @@ public GraphBuildSubmission PendBuildRequest(GraphBuildRequestData requestData)
 
                 var newSubmission = new GraphBuildSubmission(this, GetNextSubmissionId(), requestData);
 
-                if (KnownTelemetry.BuildTelemetry != null)
+                if (_buildTelemetry != null)
                 {
                     // Project graph can have multiple entry points, for purposes of identifying event for same build project,
                     // we believe that including only one entry point will provide enough precision.
-                    KnownTelemetry.BuildTelemetry.Project ??= requestData.ProjectGraphEntryPoints?.FirstOrDefault().ProjectFile;
-                    KnownTelemetry.BuildTelemetry.Target ??= string.Join(",", requestData.TargetNames);
+                    _buildTelemetry.Project ??= requestData.ProjectGraphEntryPoints?.FirstOrDefault().ProjectFile;
+                    _buildTelemetry.Target ??= string.Join(",", requestData.TargetNames);
                 }
 
                 _graphBuildSubmissions.Add(newSubmission.SubmissionId, newSubmission);
@@ -987,13 +1004,13 @@ public void EndBuild()
 
                         loggingService.LogBuildFinished(_overallBuildSuccess);
 
-                        if (KnownTelemetry.BuildTelemetry != null)
+                        if (_buildTelemetry != null)
                         {
-                            KnownTelemetry.BuildTelemetry.FinishedAt = DateTime.UtcNow;
-                            KnownTelemetry.BuildTelemetry.Success = _overallBuildSuccess;
-                            KnownTelemetry.BuildTelemetry.Version = ProjectCollection.Version;
-                            KnownTelemetry.BuildTelemetry.DisplayVersion = ProjectCollection.DisplayVersion;
-                            KnownTelemetry.BuildTelemetry.FrameworkName = NativeMethodsShared.FrameworkName;
+                            _buildTelemetry.FinishedAt = DateTime.UtcNow;
+                            _buildTelemetry.Success = _overallBuildSuccess;
+                            _buildTelemetry.Version = ProjectCollection.Version;
+                            _buildTelemetry.DisplayVersion = ProjectCollection.DisplayVersion;
+                            _buildTelemetry.FrameworkName = NativeMethodsShared.FrameworkName;
 
                             string host = null;
                             if (BuildEnvironmentState.s_runningInVisualStudio)
@@ -1008,12 +1025,12 @@ public void EndBuild()
                             {
                                 host = "VSCode";
                             }
-                            KnownTelemetry.BuildTelemetry.Host = host;
+                            _buildTelemetry.Host = host;
 
-                            KnownTelemetry.BuildTelemetry.UpdateEventProperties();
-                            loggingService.LogTelemetry(buildEventContext: null, KnownTelemetry.BuildTelemetry.EventName, KnownTelemetry.BuildTelemetry.Properties);
+                            _buildTelemetry.UpdateEventProperties();
+                            loggingService.LogTelemetry(buildEventContext: null, _buildTelemetry.EventName, _buildTelemetry.Properties);
                             // Clean telemetry to make it ready for next build submission.
-                            KnownTelemetry.BuildTelemetry = null;
+                            _buildTelemetry = null;
                         }
                     }
 

src/Build/BackEnd/Client/MSBuildClient.cs

@@ -166,9 +166,9 @@ public MSBuildClientExitResult Execute(CancellationToken cancellationToken)
 
             CommunicationsUtilities.Trace("Executing build with command line '{0}'", descriptiveCommandLine);
             bool serverIsAlreadyRunning = ServerIsRunning();
-            if (KnownTelemetry.BuildTelemetry != null)
+            if (KnownTelemetry.PartialBuildTelemetry != null)
             {
-                KnownTelemetry.BuildTelemetry.InitialServerState = serverIsAlreadyRunning ? "hot" : "cold";
+                KnownTelemetry.PartialBuildTelemetry.InitialServerState = serverIsAlreadyRunning ? "hot" : "cold";
             }
             if (!serverIsAlreadyRunning)
             {
@@ -524,14 +524,14 @@ private ServerNodeBuildCommand GetServerNodeBuildCommand()
             // 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.BuildTelemetry == null || KnownTelemetry.BuildTelemetry.StartAt.HasValue, "BuildTelemetry.StartAt was not initialized!");
+            Debug.Assert(KnownTelemetry.PartialBuildTelemetry == null || KnownTelemetry.PartialBuildTelemetry.StartAt.HasValue, "BuildTelemetry.StartAt was not initialized!");
 
-            PartialBuildTelemetry? partialBuildTelemetry = KnownTelemetry.BuildTelemetry == null
+            PartialBuildTelemetry? partialBuildTelemetry = KnownTelemetry.PartialBuildTelemetry == null
                 ? null
                 : new PartialBuildTelemetry(
-                    startedAt: KnownTelemetry.BuildTelemetry.StartAt.GetValueOrDefault(),
-                    initialServerState: KnownTelemetry.BuildTelemetry.InitialServerState,
-                    serverFallbackReason: KnownTelemetry.BuildTelemetry.ServerFallbackReason);
+                    startedAt: KnownTelemetry.PartialBuildTelemetry.StartAt.GetValueOrDefault(),
+                    initialServerState: KnownTelemetry.PartialBuildTelemetry.InitialServerState,
+                    serverFallbackReason: KnownTelemetry.PartialBuildTelemetry.ServerFallbackReason);
 
             return new ServerNodeBuildCommand(
                         _commandLine,

src/Build/BackEnd/Node/OutOfProcServerNode.cs

@@ -365,15 +365,13 @@ private void HandleServerNodeBuildCommand(ServerNodeBuildCommand command)
             ConsoleConfiguration.Provider = command.ConsoleConfiguration;
 
             // Initiate build telemetry
-            if (KnownTelemetry.BuildTelemetry == null)
-            {
-                KnownTelemetry.BuildTelemetry = new BuildTelemetry();
-            }
             if (command.PartialBuildTelemetry != null)
             {
-                KnownTelemetry.BuildTelemetry.StartAt = command.PartialBuildTelemetry.StartedAt;
-                KnownTelemetry.BuildTelemetry.InitialServerState = command.PartialBuildTelemetry.InitialServerState;
-                KnownTelemetry.BuildTelemetry.ServerFallbackReason = command.PartialBuildTelemetry.ServerFallbackReason;
+                BuildTelemetry buildTelemetry = KnownTelemetry.PartialBuildTelemetry ??= new BuildTelemetry();
+
+                buildTelemetry.StartAt = command.PartialBuildTelemetry.StartedAt;
+                buildTelemetry.InitialServerState = command.PartialBuildTelemetry.InitialServerState;
+                buildTelemetry.ServerFallbackReason = command.PartialBuildTelemetry.ServerFallbackReason;
             }
 
             // Also try our best to increase chance custom Loggers which use Console static members will work as expected.

src/Framework/Telemetry/KnownTelemetry.cs

@@ -9,9 +9,10 @@ namespace Microsoft.Build.Framework.Telemetry;
 internal static class KnownTelemetry
 {
     /// <summary>
-    /// Telemetry for build.
-    /// If null Telemetry is not supposed to be emitted.
-    /// After telemetry is emitted, sender shall null it.
+    /// Partial Telemetry for build.
+    /// This could be optionally initialized with some values from early in call stack, for example in Main method.
+    /// After this instance is acquired by a particular build, this is set to null.
+    /// Null means there are no prior collected build telemetry data, new clean instance shall be created for particular build.
     /// </summary>
-    public static BuildTelemetry? BuildTelemetry { get; set; }
+    public static BuildTelemetry? PartialBuildTelemetry { get; set; }
 }

src/MSBuild/MSBuildClientApp.cs

@@ -78,9 +78,9 @@ public static MSBuildApp.ExitType Execute(
                 exitResult.MSBuildClientExitType == MSBuildClientExitType.UnableToConnect ||
                 exitResult.MSBuildClientExitType == MSBuildClientExitType.LaunchError)
             {
-                if (KnownTelemetry.BuildTelemetry != null)
+                if (KnownTelemetry.PartialBuildTelemetry != null)
                 {
-                    KnownTelemetry.BuildTelemetry.ServerFallbackReason = exitResult.MSBuildClientExitType.ToString();
+                    KnownTelemetry.PartialBuildTelemetry.ServerFallbackReason = exitResult.MSBuildClientExitType.ToString();
                 }
 
                 // Server is busy, fallback to old behavior.

src/MSBuild/XMake.cs

@@ -220,7 +220,7 @@ string[] args
             DebuggerLaunchCheck();
 
             // Initialize new build telemetry and record start of this build.
-            KnownTelemetry.BuildTelemetry = new BuildTelemetry { StartAt = DateTime.UtcNow };
+            KnownTelemetry.PartialBuildTelemetry = new BuildTelemetry { StartAt = DateTime.UtcNow };
 
             using PerformanceLogEventListener eventListener = PerformanceLogEventListener.Create();
 
@@ -308,18 +308,18 @@ string[] commandLine
                     IsInteractiveBuild(commandLineSwitches))
                 {
                     canRunServer = false;
-                    if (KnownTelemetry.BuildTelemetry != null)
+                    if (KnownTelemetry.PartialBuildTelemetry != null)
                     {
-                        KnownTelemetry.BuildTelemetry.ServerFallbackReason = "Arguments";
+                        KnownTelemetry.PartialBuildTelemetry.ServerFallbackReason = "Arguments";
                     }
                 }
             }
             catch (Exception ex)
             {
                 CommunicationsUtilities.Trace("Unexpected exception during command line parsing. Can not determine if it is allowed to use Server. Fall back to old behavior. Exception: {0}", ex);
-                if (KnownTelemetry.BuildTelemetry != null)
+                if (KnownTelemetry.PartialBuildTelemetry != null)
                 {
-                    KnownTelemetry.BuildTelemetry.ServerFallbackReason = "ErrorParsingCommandLine";
+                    KnownTelemetry.PartialBuildTelemetry.ServerFallbackReason = "ErrorParsingCommandLine";
                 }
                 canRunServer = false;
             }
@@ -631,7 +631,7 @@ string[] commandLine
             DebuggerLaunchCheck();
 
             // Initialize new build telemetry and record start of this build, if not initialized already
-            KnownTelemetry.BuildTelemetry ??= new BuildTelemetry { StartAt = DateTime.UtcNow };
+            KnownTelemetry.PartialBuildTelemetry ??= new BuildTelemetry { StartAt = DateTime.UtcNow };
 
             // Indicate to the engine that it can toss extraneous file content
             // when it loads microsoft.*.targets. We can't do this in the general case,