Add BuildCheck basic telemetry (#10652)

* Add initial version of telemetry data extracting

* Initial tracing data transport

* Move buildcheck enabled telemetry to buildtelemetry

* Add unittests

* Fix typos

* Add CheckFriendlyName to telemetry

* Add SAC telemetry

* Adjust after merging

src/Build.UnitTests/BackEnd/NodePackets_Tests.cs

@@ -8,6 +8,7 @@
 using FluentAssertions;
 using Microsoft.Build.BackEnd;
 using Microsoft.Build.Execution;
+using Microsoft.Build.Experimental.BuildCheck;
 using Microsoft.Build.Framework;
 using Microsoft.Build.Shared;
 using Xunit;
@@ -77,6 +78,7 @@ public void VerifyEventType()
             EnvironmentVariableReadEventArgs environmentVariableRead = new("env", "message", "file", 0, 0);
             GeneratedFileUsedEventArgs generatedFileUsed = new GeneratedFileUsedEventArgs("path", "some content");
             BuildSubmissionStartedEventArgs buildSubmissionStarted = new(new Dictionary<string, string> { { "Value1", "Value2" } }, ["Path1"], ["TargetName"], BuildRequestDataFlags.ReplaceExistingProjectInstance, 123);
+            BuildCheckTracingEventArgs buildCheckTracing = new();
 
             VerifyLoggingPacket(buildFinished, LoggingEventType.BuildFinishedEvent);
             VerifyLoggingPacket(buildStarted, LoggingEventType.BuildStartedEvent);
@@ -111,6 +113,7 @@ public void VerifyEventType()
             VerifyLoggingPacket(environmentVariableRead, LoggingEventType.EnvironmentVariableReadEvent);
             VerifyLoggingPacket(generatedFileUsed, LoggingEventType.GeneratedFileUsedEvent);
             VerifyLoggingPacket(buildSubmissionStarted, LoggingEventType.BuildSubmissionStartedEvent);
+            VerifyLoggingPacket(buildCheckTracing, LoggingEventType.BuildCheckTracingEvent);
         }
 
         private static BuildEventContext CreateBuildEventContext()

src/Build.UnitTests/BuildEventArgsSerialization_Tests.cs

@@ -4,11 +4,13 @@
 using System;
 using System.Collections;
 using System.Collections.Generic;
+using System.Globalization;
 using System.IO;
 using System.Linq;
 using System.Text;
 using FluentAssertions;
 using Microsoft.Build.BackEnd;
+using Microsoft.Build.Experimental.BuildCheck;
 using Microsoft.Build.Framework;
 using Microsoft.Build.Framework.Profiler;
 using Microsoft.Build.Logging;
@@ -530,6 +532,27 @@ public void RoundtripAssemblyLoadBuild()
                 e => string.Join(", ", e.RawArguments ?? Array.Empty<object>()));
         }
 
+        [Fact]
+        public void RoundtripBuildCheckTracingEventArgs()
+        {
+            string key1 = "AA";
+            TimeSpan span1 = TimeSpan.FromSeconds(5);
+            string key2 = "b";
+            TimeSpan span2 = TimeSpan.FromSeconds(15);
+            string key3 = "cCc";
+            TimeSpan span3 = TimeSpan.FromSeconds(50);
+
+            Dictionary<string, TimeSpan> stats = new() { { key1, span1 }, { key2, span2 }, { key3, span3 } };
+
+            BuildCheckTracingEventArgs args = new BuildCheckTracingEventArgs(stats);
+
+            Roundtrip(args,
+                e => e.TracingData.InfrastructureTracingData.Keys.Count.ToString(),
+                e => e.TracingData.InfrastructureTracingData.Keys.ToCsvString(false),
+                e => e.TracingData.InfrastructureTracingData.Values
+                    .Select(v => v.TotalSeconds.ToString(CultureInfo.InvariantCulture)).ToCsvString(false));
+        }
+
         [Theory]
         [InlineData(true)]
         [InlineData(false)]

src/Build/BackEnd/BuildManager/BuildManager.cs

@@ -1070,6 +1070,11 @@ public void EndBuild()
                             }
                             _buildTelemetry.Host = host;
 
+                            _buildTelemetry.BuildCheckEnabled = _buildParameters!.IsBuildCheckEnabled;
+                            var sacState = NativeMethodsShared.GetSACState();
+                            // The Enforcement would lead to build crash - but let's have the check for completeness sake.
+                            _buildTelemetry.SACEnabled = sacState == NativeMethodsShared.SAC_State.Evaluation || sacState == NativeMethodsShared.SAC_State.Enforcement;
+
                             loggingService.LogTelemetry(buildEventContext: null, _buildTelemetry.EventName, _buildTelemetry.GetProperties());
                             // Clean telemetry to make it ready for next build submission.
                             _buildTelemetry = null;

src/Build/BuildCheck/API/Check.cs

@@ -43,6 +43,8 @@ public abstract class Check : IDisposable
     /// </param>
     public abstract void RegisterActions(IBuildCheckRegistrationContext registrationContext);
 
+    internal virtual bool IsBuiltIn => false;
+
     public virtual void Dispose()
     { }
 }

src/Build/BuildCheck/API/InternalCheck.cs

@@ -28,4 +28,6 @@ public override void RegisterActions(IBuildCheckRegistrationContext registration
 
         this.RegisterInternalActions(internalRegistrationContext);
     }
+
+    internal override bool IsBuiltIn => true;
 }

src/Build/BuildCheck/Acquisition/BuildCheckAcquisitionModule.cs

@@ -7,6 +7,7 @@
 using System.Reflection;
 using Microsoft.Build.Experimental.BuildCheck.Infrastructure;
 using Microsoft.Build.Framework;
+using Microsoft.Build.Framework.Telemetry;
 using Microsoft.Build.Shared;
 
 namespace Microsoft.Build.Experimental.BuildCheck.Acquisition;
@@ -53,21 +54,24 @@ public List<CheckFactory> CreateCheckFactories(
                     .ForEach(t => checkContext.DispatchAsComment(MessageImportance.Normal, "CustomCheckBaseTypeNotAssignable", t.Name, t.Assembly));
             }
         }
-        catch (ReflectionTypeLoadException ex)
+        catch (ReflectionTypeLoadException ex) when (ex.LoaderExceptions.Length != 0)
         {
-            if (ex.LoaderExceptions.Length != 0)
+            foreach (Exception? unrolledEx in ex.LoaderExceptions.Where(e => e != null).Prepend(ex))
             {
-                foreach (Exception? loaderException in ex.LoaderExceptions)
-                {
-                    checkContext.DispatchAsComment(MessageImportance.Normal, "CustomCheckFailedRuleLoading", loaderException?.Message);
-                }
+                ReportLoadingError(unrolledEx!);
             }
         }
         catch (Exception ex)
         {
-            checkContext.DispatchAsComment(MessageImportance.Normal, "CustomCheckFailedRuleLoading", ex?.Message);
+            ReportLoadingError(ex);
         }
 
         return checksFactories;
+
+        void ReportLoadingError(Exception ex)
+        {
+            checkContext.DispatchAsComment(MessageImportance.Normal, "CustomCheckFailedRuleLoading", ex.Message);
+            checkContext.DispatchFailedAcquisitionTelemetry(System.IO.Path.GetFileName(checkAcquisitionData.AssemblyPath), ex);
+        }
     }
 }

src/Build/BuildCheck/Checks/DoubleWritesCheck.cs

@@ -42,6 +42,8 @@ public override void RegisterActions(IBuildCheckRegistrationContext registration
         registrationContext.RegisterTaskInvocationAction(TaskInvocationAction);
     }
 
+    internal override bool IsBuiltIn => true;
+
     /// <summary>
     /// Contains the first project file + task that wrote the given file during the build.
     /// </summary>
@@ -126,5 +128,5 @@ private void CheckWrite(BuildCheckDataContext<TaskInvocationCheckData> context,
                 _filesWritten.Add(fileBeingWritten, (context.Data.ProjectFilePath, context.Data.TaskName));
             }
         }
-   }
+    }
 }

src/Build/BuildCheck/Checks/NoEnvironmentVariablePropertyCheck.cs

@@ -49,6 +49,8 @@ public override void Initialize(ConfigurationContext configurationContext)
 
     public override void RegisterActions(IBuildCheckRegistrationContext registrationContext) => registrationContext.RegisterEnvironmentVariableReadAction(ProcessEnvironmentVariableReadAction);
 
+    internal override bool IsBuiltIn => true;
+
     private void ProcessEnvironmentVariableReadAction(BuildCheckDataContext<EnvironmentVariableCheckData> context)
     {
         EnvironmentVariableIdentityKey identityKey = new(context.Data.EnvironmentVariableName, context.Data.EnvironmentVariableLocation);

src/Build/BuildCheck/Checks/PropertiesUsageCheck.cs

@@ -118,6 +118,8 @@ public override void RegisterInternalActions(IInternalCheckRegistrationContext r
         }
     }
 
+    internal override bool IsBuiltIn => true;
+
     private Dictionary<string, IMSBuildElementLocation?> _writenProperties = new(MSBuildNameIgnoreCaseComparer.Default);
     private HashSet<string> _readProperties = new(MSBuildNameIgnoreCaseComparer.Default);
     // For the 'Property Initialized after used' check - we are interested in cases where:

src/Build/BuildCheck/Checks/SharedOutputPathCheck.cs

@@ -35,6 +35,8 @@ public override void RegisterActions(IBuildCheckRegistrationContext registration
         registrationContext.RegisterEvaluatedPropertiesAction(EvaluatedPropertiesAction);
     }
 
+    internal override bool IsBuiltIn => true;
+
     private readonly Dictionary<string, string> _projectsPerOutputPath = new(StringComparer.CurrentCultureIgnoreCase);
     private readonly HashSet<string> _projects = new(StringComparer.CurrentCultureIgnoreCase);
 

src/Build/BuildCheck/Infrastructure/BuildCheckBuildEventHandler.cs

@@ -107,7 +107,7 @@ private void HandleBuildCheckTracingEvent(BuildCheckTracingEventArgs eventArgs)
     {
         if (!eventArgs.IsAggregatedGlobalReport)
         {
-            _stats.Merge(eventArgs.TracingData, (span1, span2) => span1 + span2);
+            _tracingData.MergeIn(eventArgs.TracingData);
         }
     }
 
@@ -138,36 +138,25 @@ private void HandleEnvironmentVariableReadEvent(EnvironmentVariableReadEventArgs
 
     private bool IsMetaProjFile(string? projectFile) => projectFile?.EndsWith(".metaproj", StringComparison.OrdinalIgnoreCase) == true;
 
-    private readonly Dictionary<string, TimeSpan> _stats = new Dictionary<string, TimeSpan>();
+    private readonly BuildCheckTracingData _tracingData = new BuildCheckTracingData();
 
     private void HandleBuildFinishedEvent(BuildFinishedEventArgs eventArgs)
     {
         _buildCheckManager.ProcessBuildFinished(_checkContextFactory.CreateCheckContext(eventArgs.BuildEventContext!));
 
-        _stats.Merge(_buildCheckManager.CreateCheckTracingStats(), (span1, span2) => span1 + span2);
+        _tracingData.MergeIn(_buildCheckManager.CreateCheckTracingStats());
 
         LogCheckStats(_checkContextFactory.CreateCheckContext(GetBuildEventContext(eventArgs)));
     }
 
     private void LogCheckStats(ICheckContext checkContext)
     {
-        Dictionary<string, TimeSpan> infraStats = new Dictionary<string, TimeSpan>();
-        Dictionary<string, TimeSpan> checkStats = new Dictionary<string, TimeSpan>();
+        Dictionary<string, TimeSpan>  infraStats = _tracingData.InfrastructureTracingData;
+        // Stats are per rule, while runtime is per check - and check can have multiple rules.
+        // In case of multi-rule check, the runtime stats are duplicated for each rule.
+        Dictionary<string, TimeSpan> checkStats = _tracingData.ExtractCheckStats();
 
-        foreach (var stat in _stats)
-        {
-            if (stat.Key.StartsWith(BuildCheckConstants.infraStatPrefix))
-            {
-                string newKey = stat.Key.Substring(BuildCheckConstants.infraStatPrefix.Length);
-                infraStats[newKey] = stat.Value;
-            }
-            else
-            {
-                checkStats[stat.Key] = stat.Value;
-            }
-        }
-
-        BuildCheckTracingEventArgs statEvent = new BuildCheckTracingEventArgs(_stats, true)
+        BuildCheckTracingEventArgs statEvent = new BuildCheckTracingEventArgs(_tracingData, true)
         { BuildEventContext = checkContext.BuildEventContext };
 
         checkContext.DispatchBuildEvent(statEvent);
@@ -177,6 +166,7 @@ private void LogCheckStats(ICheckContext checkContext)
         checkContext.DispatchAsCommentFromText(MessageImportance.Low, infraData);
         string checkData = BuildCsvString("Checks run times", checkStats);
         checkContext.DispatchAsCommentFromText(MessageImportance.Low, checkData);
+        checkContext.DispatchTelemetry(_tracingData);
     }
 
     private string BuildCsvString(string title, Dictionary<string, TimeSpan> rowData)

src/Build/BuildCheck/Infrastructure/BuildCheckManagerProvider.cs

@@ -229,10 +229,10 @@ private void SetupSingleCheck(CheckFactoryContext checkFactoryContext, string pr
             CheckConfigurationEffective[] configurations;
             if (checkFactoryContext.MaterializedCheck == null)
             {
-                CheckConfiguration[] userConfigs =
+                CheckConfiguration[] userEditorConfigs =
                     _configurationProvider.GetUserConfigurations(projectFullPath, checkFactoryContext.RuleIds);
 
-                if (userConfigs.All(c => !(c.IsEnabled ?? checkFactoryContext.IsEnabledByDefault)))
+                if (userEditorConfigs.All(c => !(c.IsEnabled ?? checkFactoryContext.IsEnabledByDefault)))
                 {
                     // the check was not yet instantiated nor mounted - so nothing to do here now.
                     return;
@@ -242,7 +242,7 @@ private void SetupSingleCheck(CheckFactoryContext checkFactoryContext, string pr
                     _configurationProvider.GetCustomConfigurations(projectFullPath, checkFactoryContext.RuleIds);
 
                 Check uninitializedCheck = checkFactoryContext.Factory();
-                configurations = _configurationProvider.GetMergedConfigurations(userConfigs, uninitializedCheck);
+                configurations = _configurationProvider.GetMergedConfigurations(userEditorConfigs, uninitializedCheck);
 
                 ConfigurationContext configurationContext = ConfigurationContext.FromDataEnumeration(customConfigData, configurations);
 
@@ -271,21 +271,23 @@ private void SetupSingleCheck(CheckFactoryContext checkFactoryContext, string pr
                 // price to be paid in that case is slight performance cost.
 
                 // Create the wrapper and register to central context
-                wrapper.StartNewProject(projectFullPath, configurations);
+                wrapper.StartNewProject(projectFullPath, configurations, userEditorConfigs);
                 var wrappedContext = new CheckRegistrationContext(wrapper, _buildCheckCentralContext);
                 check.RegisterActions(wrappedContext);
             }
             else
             {
                 wrapper = checkFactoryContext.MaterializedCheck;
 
-                configurations = _configurationProvider.GetMergedConfigurations(projectFullPath, wrapper.Check);
+                CheckConfiguration[] userEditorConfigs =
+                    _configurationProvider.GetUserConfigurations(projectFullPath, checkFactoryContext.RuleIds);
+                configurations = _configurationProvider.GetMergedConfigurations(userEditorConfigs, wrapper.Check);
 
                 _configurationProvider.CheckCustomConfigurationDataValidity(projectFullPath,
                     checkFactoryContext.RuleIds[0]);
 
                 // Update the wrapper
-                wrapper.StartNewProject(projectFullPath, configurations);
+                wrapper.StartNewProject(projectFullPath, configurations, userEditorConfigs);
             }
         }
 
@@ -346,7 +348,7 @@ private void RemoveCheck(CheckFactoryContext checkToRemove)
             if (checkToRemove.MaterializedCheck is not null)
             {
                 _buildCheckCentralContext.DeregisterCheck(checkToRemove.MaterializedCheck);
-                _tracingReporter.AddCheckStats(checkToRemove.MaterializedCheck.Check.FriendlyName, checkToRemove.MaterializedCheck.Elapsed);
+				_ruleTelemetryData.AddRange(checkToRemove.MaterializedCheck.GetRuleTelemetryData());
                 checkToRemove.MaterializedCheck.Check.Dispose();
             }
         }
@@ -411,19 +413,18 @@ public void ProcessTaskParameterEventArgs(
             => _buildEventsProcessor
                 .ProcessTaskParameterEventArgs(checkContext, taskParameterEventArgs);
 
-        public Dictionary<string, TimeSpan> CreateCheckTracingStats()
+        private readonly List<BuildCheckRuleTelemetryData> _ruleTelemetryData = [];
+        public BuildCheckTracingData CreateCheckTracingStats()
         {
             foreach (CheckFactoryContext checkFactoryContext in _checkRegistry)
             {
                 if (checkFactoryContext.MaterializedCheck != null)
                 {
-                    _tracingReporter.AddCheckStats(checkFactoryContext.FriendlyName, checkFactoryContext.MaterializedCheck.Elapsed);
-                    checkFactoryContext.MaterializedCheck.ClearStats();
+                    _ruleTelemetryData.AddRange(checkFactoryContext.MaterializedCheck.GetRuleTelemetryData());
                 }
             }
 
-            _tracingReporter.AddCheckInfraStats();
-            return _tracingReporter.TracingStats;
+            return new BuildCheckTracingData(_ruleTelemetryData, _tracingReporter.GetInfrastructureTracingStats());
         }
 
         public void FinalizeProcessing(LoggingContext loggingContext)

src/Build/BuildCheck/Infrastructure/CheckContext/CheckDispatchingContext.cs

@@ -69,4 +69,12 @@ public void DispatchAsWarningFromText(string? subcategoryResourceName, string? e
 
         _eventDispatcher.Dispatch(buildEvent);
     }
+
+    public void DispatchFailedAcquisitionTelemetry(string assemblyName, Exception exception)
+    // This is it - no action for replay mode.
+    { }
+
+    public void DispatchTelemetry(BuildCheckTracingData data)
+    // This is it - no action for replay mode.
+    { }
 }

src/Build/BuildCheck/Infrastructure/CheckContext/CheckLoggingContext.cs

@@ -8,6 +8,7 @@
 using System.Threading.Tasks;
 using Microsoft.Build.BackEnd.Logging;
 using Microsoft.Build.Framework;
+using Microsoft.Build.Framework.Telemetry;
 using Microsoft.Build.Shared;
 
 namespace Microsoft.Build.Experimental.BuildCheck;
@@ -43,4 +44,18 @@ public void DispatchAsErrorFromText(string? subcategoryResourceName, string? err
     public void DispatchAsWarningFromText(string? subcategoryResourceName, string? errorCode, string? helpKeyword, BuildEventFileInfo file, string message)
         => loggingService
             .LogWarningFromText(eventContext, subcategoryResourceName, errorCode, helpKeyword, file, message);
+
+    public void DispatchFailedAcquisitionTelemetry(string assemblyName, Exception exception)
+    {
+        var telemetryTransportData = KnownTelemetry.BuildCheckTelemetry.ProcessCustomCheckLoadingFailure(assemblyName, exception);
+        loggingService.LogTelemetry(eventContext, telemetryTransportData.Item1, telemetryTransportData.Item2);
+    }
+
+    public void DispatchTelemetry(BuildCheckTracingData data)
+    {
+        foreach ((string, IDictionary<string, string>) telemetryTransportData in KnownTelemetry.BuildCheckTelemetry.ProcessBuildCheckTracingData(data))
+        {
+            loggingService.LogTelemetry(eventContext, telemetryTransportData.Item1, telemetryTransportData.Item2);
+        }
+    }
 }

src/Build/BuildCheck/Infrastructure/CheckContext/ICheckContext.cs

@@ -45,4 +45,14 @@ internal interface ICheckContext
     /// Dispatch the instance of <see cref="BuildEventContext"/> as a warning message.
     /// </summary>
     void DispatchAsWarningFromText(string? subcategoryResourceName, string? errorCode, string? helpKeyword, BuildEventFileInfo file, string message);
+
+    /// <summary>
+    /// Dispatch the telemetry data for a failed acquisition.
+    /// </summary>
+    void DispatchFailedAcquisitionTelemetry(string assemblyName, Exception exception);
+
+    /// <summary>
+    /// If supported - dispatches the telemetry data.
+    /// </summary>
+    void DispatchTelemetry(BuildCheckTracingData data);
 }