From 528663249b61d9cac446d0b427b54ac9451b6c7c Mon Sep 17 00:00:00 2001 From: Chet Husk Date: Mon, 3 Aug 2026 15:23:12 -0500 Subject: [PATCH 1/8] Fix MSBuild server telemetry activity lifecycle Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> Copilot-Session: f900a161-9261-47ee-823b-369cb6ee3cb7 --- .../dotnet/Commands/MSBuild/MSBuildLogger.cs | 36 +++++++- src/Cli/dotnet/Telemetry/TelemetryClient.cs | 25 +++++- .../dotnet/Telemetry/TelemetryDiskLogger.cs | 5 +- .../MSBuild/GivenMSBuildLogger.cs | 32 +++++++ .../TelemetryTests/TelemetryClientTests.cs | 90 +++++++++++++++++++ 5 files changed, 183 insertions(+), 5 deletions(-) diff --git a/src/Cli/dotnet/Commands/MSBuild/MSBuildLogger.cs b/src/Cli/dotnet/Commands/MSBuild/MSBuildLogger.cs index d6175487222e..722007a72574 100644 --- a/src/Cli/dotnet/Commands/MSBuild/MSBuildLogger.cs +++ b/src/Cli/dotnet/Commands/MSBuild/MSBuildLogger.cs @@ -1,9 +1,11 @@ // Licensed to the .NET Foundation under one or more agreements. // The .NET Foundation licenses this file to you under the MIT license. +using System.Diagnostics; using System.Globalization; using Microsoft.Build.Framework; using Microsoft.DotNet.Cli.Telemetry; +using Microsoft.DotNet.Cli.Utils; using Microsoft.DotNet.Utilities; namespace Microsoft.DotNet.Cli.Commands.MSBuild; @@ -11,6 +13,7 @@ namespace Microsoft.DotNet.Cli.Commands.MSBuild; public sealed class MSBuildLogger : INodeLogger { private readonly ITelemetryClient? _telemetry; + private Activity? _activity; internal const string TargetFrameworkTelemetryEventName = "targetframeworkeval"; internal const string BuildTelemetryEventName = "build"; @@ -65,10 +68,12 @@ public MSBuildLogger() { string? sessionId = Environment.GetEnvironmentVariable(EnvironmentVariableNames.DOTNET_CLI_TELEMETRY_SESSIONID); - if (sessionId != null) + if (!TelemetryClient.IsInitialized) { - _telemetry = new TelemetryClient(sessionId); + _ = new TelemetryClient(sessionId); } + + _telemetry = TelemetryClient.Instance; } catch (Exception) { @@ -106,6 +111,8 @@ public void Initialize(IEventSource eventSource) { eventSource2.TelemetryLogged += OnTelemetryLogged; } + + eventSource.BuildStarted += OnBuildStarted; } eventSource.BuildFinished += OnBuildFinished; @@ -116,9 +123,20 @@ public void Initialize(IEventSource eventSource) } } + private void OnBuildStarted(object sender, BuildStartedEventArgs e) + { + ActivityContext parentContext = Activity.Current?.Context ?? TelemetryClient.ParentActivityContext; + _activity = Activities.Source.StartActivity( + "msbuild", + ActivityKind.Internal, + parentContext); + } + private void OnBuildFinished(object sender, BuildFinishedEventArgs e) { SendAggregatedEventsOnBuildFinished(_telemetry); + _activity?.SetStatus(e.Succeeded ? ActivityStatusCode.Ok : ActivityStatusCode.Error); + StopActivity(); } internal void SendAggregatedEventsOnBuildFinished(ITelemetryClient? telemetry) @@ -267,6 +285,20 @@ private void OnTelemetryLogged(object sender, TelemetryEventArgs args) public void Shutdown() { + StopActivity(); + + if (_telemetry is TelemetryClient telemetryClient) + { + telemetryClient.WaitForPendingEvents(); + } + + TelemetryClient.WriteLogIfNecessary(); + } + + private void StopActivity() + { + _activity?.Stop(); + _activity = null; } public LoggerVerbosity Verbosity { get; set; } diff --git a/src/Cli/dotnet/Telemetry/TelemetryClient.cs b/src/Cli/dotnet/Telemetry/TelemetryClient.cs index 244ba62c821a..6c126d4aa122 100644 --- a/src/Cli/dotnet/Telemetry/TelemetryClient.cs +++ b/src/Cli/dotnet/Telemetry/TelemetryClient.cs @@ -82,6 +82,8 @@ private static int GetShutdownTimeoutMs() } public static string? CurrentSessionId { get; private set; } = null; + internal static bool IsInitialized { get; private set; } + internal static TelemetryClient? Instance { get; private set; } public static bool DisabledForTests { get => field; @@ -92,6 +94,8 @@ public static bool DisabledForTests if (field) { CurrentSessionId = null; + IsInitialized = false; + Instance = null; } } } = false; @@ -167,6 +171,9 @@ public TelemetryClient() : this(null) { } public TelemetryClient(string? sessionId, IEnvironmentProvider? environmentProvider = null) { + Instance = this; + IsInitialized = true; + // This is some kind of special condition for MSBuild-related tests. if (DisabledForTests) { @@ -271,9 +278,18 @@ public static void FlushProviders() public static void WriteLogIfNecessary() { - if (!string.IsNullOrWhiteSpace(s_diskLogPath) && s_activities.Any()) + if (string.IsNullOrWhiteSpace(s_diskLogPath)) + { + return; + } + + Activity[] activities = [.. s_activities]; + if (activities.Length > 0 && TelemetryDiskLogger.WriteLog(s_diskLogPath, activities)) { - TelemetryDiskLogger.WriteLog(s_diskLogPath, s_activities); + foreach (Activity activity in activities) + { + s_activities.Remove(activity); + } } } @@ -300,6 +316,11 @@ public void ThreadBlockingTrackEvent(string eventName, IDictionary? properties) { try diff --git a/src/Cli/dotnet/Telemetry/TelemetryDiskLogger.cs b/src/Cli/dotnet/Telemetry/TelemetryDiskLogger.cs index fbabe813200c..761d193d6fcd 100644 --- a/src/Cli/dotnet/Telemetry/TelemetryDiskLogger.cs +++ b/src/Cli/dotnet/Telemetry/TelemetryDiskLogger.cs @@ -47,23 +47,26 @@ static TelemetryDiskLogger() s_jsonContext = new(s_jsonOptions); } - public static void WriteLog(string logPath, IEnumerable activies) + public static bool WriteLog(string logPath, IEnumerable activies) { try { var jsonText = !File.Exists(logPath) ? """{"activities":[]}""" : File.ReadAllText(logPath); var root = JsonNode.Parse(jsonText)!; var activitiesArray = root["activities"]!.AsArray(); + foreach (var activity in activies) { activitiesArray.Add(JsonNode.Parse(JsonSerializer.Serialize(CreateActivityJsonModel(activity), s_jsonContext.ActivityModel))); } root["activities"] = activitiesArray; File.WriteAllText(logPath, root.ToJsonString(s_jsonOptions)); + return true; } catch { // Swallow any exceptions to avoid interfering with telemetry shutdown. + return false; } } diff --git a/test/dotnet.Tests/CommandTests/MSBuild/GivenMSBuildLogger.cs b/test/dotnet.Tests/CommandTests/MSBuild/GivenMSBuildLogger.cs index bbd49c1b314f..1e360c09007c 100644 --- a/test/dotnet.Tests/CommandTests/MSBuild/GivenMSBuildLogger.cs +++ b/test/dotnet.Tests/CommandTests/MSBuild/GivenMSBuildLogger.cs @@ -3,6 +3,7 @@ #nullable disable +using System.Diagnostics; using Microsoft.Build.Framework; using Microsoft.DotNet.Cli.Commands.MSBuild; using Microsoft.DotNet.Cli.Utils; @@ -240,5 +241,36 @@ public void ItForwardsTaskDetailsEvent() fakeTelemetry.LogEntry.Properties["TaskCount"].Should().Be("1"); fakeTelemetry.LogEntry.Properties["TotalTaskCount"].Should().Be("1"); } + + [TestMethod] + public void ItCreatesAnInternalActivityForEachBuild() + { + ActivitySource activitySource = Activities.Source; + Activity stoppedActivity = null; + using var listener = new ActivityListener + { + ShouldListenTo = source => source == activitySource, + Sample = (ref ActivityCreationOptions _) => ActivitySamplingResult.AllDataAndRecorded, + ActivityStopped = activity => stoppedActivity = activity, + }; + ActivitySource.AddActivityListener(listener); + + using Activity parentActivity = new Activity("parent").Start(); + var eventSource = new PersistentDispatcher([]); + var logger = new MSBuildLogger(new FakeTelemetry()); + logger.Initialize(eventSource); + + eventSource.Dispatch(new BuildStartedEventArgs("Build started.", helpKeyword: null)); + + Activity.Current.Should().NotBeSameAs(parentActivity); + Activity.Current.Kind.Should().Be(ActivityKind.Internal); + Activity.Current.ParentSpanId.Should().Be(parentActivity.SpanId); + + eventSource.Dispatch(new BuildFinishedEventArgs("Build finished.", helpKeyword: null, succeeded: true)); + + Activity.Current.Should().BeSameAs(parentActivity); + stoppedActivity.Should().NotBeNull(); + stoppedActivity.Status.Should().Be(ActivityStatusCode.Ok); + } } } diff --git a/test/dotnet.Tests/TelemetryTests/TelemetryClientTests.cs b/test/dotnet.Tests/TelemetryTests/TelemetryClientTests.cs index f53c7e6fc782..82cd29f7726a 100644 --- a/test/dotnet.Tests/TelemetryTests/TelemetryClientTests.cs +++ b/test/dotnet.Tests/TelemetryTests/TelemetryClientTests.cs @@ -3,8 +3,10 @@ using System.Text.Json.Nodes; using Microsoft.DotNet.Cli; +using Microsoft.DotNet.Cli.Commands.MSBuild; using Microsoft.DotNet.Cli.Telemetry; using Microsoft.DotNet.Cli.Utils; +using Microsoft.DotNet.Tools.Test.Utilities; using Moq; namespace Microsoft.DotNet.Tests.TelemetryTests; @@ -71,6 +73,85 @@ public void ItProcessesTelemetryData(string[] commandArgs, string exitCodeExpect exitCode.Should().Be(exitCodeExpected); } + [TestMethod] + [OSCondition(OperatingSystems.Windows)] + [DoNotParallelize] + public void ItProcessesMSBuildTelemetryWithTheServerEnabled() + { + var testAsset = TestAssetsManager.CopyTestAsset("HelloWorld") + .WithSource(); + var logFile = Path.Combine(testAsset.TestRoot, "msbuild-server-telemetry.json"); + File.Delete(logFile); + + ShutdownMSBuildServer(testAsset.TestRoot); + + try + { + new BuildCommand(testAsset) + .WithEnvironmentVariable("DOTNET_CLI_TELEMETRY_OPTOUT", "false") + .WithEnvironmentVariable("DOTNET_CLI_TELEMETRY_DISABLE_TRACE_EXPORT", "true") + .WithEnvironmentVariable("DOTNET_CLI_TELEMETRY_LOG_PATH", logFile) + .WithEnvironmentVariable("MSBUILDUSESERVER", "1") + .Execute() + .Should() + .Pass(); + + new BuildCommand(testAsset) + .WithEnvironmentVariable("DOTNET_CLI_TELEMETRY_OPTOUT", "false") + .WithEnvironmentVariable("DOTNET_CLI_TELEMETRY_DISABLE_TRACE_EXPORT", "true") + .WithEnvironmentVariable("DOTNET_CLI_TELEMETRY_LOG_PATH", logFile) + .WithEnvironmentVariable("MSBUILDUSESERVER", "1") + .Execute() + .Should() + .Pass(); + + var telemetryJson = JsonNode.Parse(File.ReadAllText(logFile)); + var activities = telemetryJson?["activities"]?.AsArray(); + activities.Should().NotBeNull(); + + var msbuildActivities = activities.Where(activity => + activity?["events"]?.AsArray() + .Any(@event => @event?["name"]?.GetValue().StartsWith("dotnet/cli/msbuild/") == true) == true); + + var msbuildTraceIds = msbuildActivities + .Select(activity => activity?["identifiers"]?["traceId"]?.GetValue()) + .Distinct(); + msbuildTraceIds.Should().HaveCount(2); + } + finally + { + ShutdownMSBuildServer(testAsset.TestRoot); + } + } + + [TestMethod] + [DoNotParallelize] + public void MSBuildLoggerDoesNotReinitializeDisabledTelemetry() + { + var environmentProvider = new Mock(MockBehavior.Strict); + + TelemetryClient.DisabledForTests = true; + TelemetryClient.DisabledForTests = false; + + try + { + environmentProvider + .Setup(p => p.GetEnvironmentVariableAsBool(EnvironmentVariableNames.TELEMETRY_OPTOUT, It.IsAny())) + .Returns(true); + + var telemetry = new TelemetryClient(sessionId: null, environmentProvider: environmentProvider.Object); + _ = new MSBuildLogger(); + + telemetry.Enabled.Should().BeFalse(); + TelemetryClient.IsInitialized.Should().BeTrue(); + TelemetryClient.Instance.Should().BeSameAs(telemetry); + } + finally + { + TelemetryClient.DisabledForTests = true; + } + } + [TestMethod] [DoNotParallelize] public void ItSeedsCurrentSessionIdFromEnvironmentWhenSessionIdIsNotProvided() @@ -127,4 +208,13 @@ public void ItPrefersExplicitSessionIdOverEnvironmentSeed() TelemetryClient.DisabledForTests = true; } } + + private void ShutdownMSBuildServer(string workingDirectory) + { + new BuildServerCommand(Log) + .WithWorkingDirectory(workingDirectory) + .Execute("shutdown", "--msbuild") + .Should() + .Pass(); + } } From 5e5c8c1d3ac7fa58a1a41554cdf83c790a9d7f3d Mon Sep 17 00:00:00 2001 From: Chet Husk Date: Mon, 3 Aug 2026 16:05:07 -0500 Subject: [PATCH 2/8] Nest MSBuild telemetry under CLI invocations Forward the current W3C trace context to MSBuild and refresh the parent for each persistent-server build. Extend focused coverage to verify propagated and exported parent relationships. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> Copilot-Session: f900a161-9261-47ee-823b-369cb6ee3cb7 --- .../ActivityContextFactory.cs | 28 +++------ .../Commands/MSBuild/MSBuildForwardingApp.cs | 9 +++ .../dotnet/Commands/MSBuild/MSBuildLogger.cs | 5 +- src/Cli/dotnet/Telemetry/TelemetryClient.cs | 2 +- .../MSBuild/GivenMSBuildLogger.cs | 59 +++++++++++++++++++ .../MSBuild/GivenMsbuildForwardingApp.cs | 16 +++++ .../TelemetryTests/TelemetryClientTests.cs | 21 ++++++- 7 files changed, 117 insertions(+), 23 deletions(-) diff --git a/src/Cli/dotnet/CommandFactory/CommandResolution/ActivityContextFactory.cs b/src/Cli/dotnet/CommandFactory/CommandResolution/ActivityContextFactory.cs index bd8616a1e06a..ea1b1e7532f7 100644 --- a/src/Cli/dotnet/CommandFactory/CommandResolution/ActivityContextFactory.cs +++ b/src/Cli/dotnet/CommandFactory/CommandResolution/ActivityContextFactory.cs @@ -3,10 +3,6 @@ using System.Diagnostics; using Microsoft.DotNet.Cli.Utils; -#if TARGET_WINDOWS -using OpenTelemetry; -using OpenTelemetry.Context.Propagation; -#endif namespace Microsoft.DotNet.Cli.CommandFactory.CommandResolution; @@ -25,24 +21,16 @@ public static class ActivityContextFactory return null; } - var environment = new Dictionary(capacity: 2); -#if TARGET_WINDOWS - var propagationContext = new PropagationContext(activityContext, Baggage.Current); - Propagators.DefaultTextMapPropagator.Inject(propagationContext, environment, WriteTraceStateIntoEnvironment); -#endif - return environment; - } + var environment = new Dictionary(capacity: 2) + { + [Activities.TRACEPARENT] = $"00-{activityContext.TraceId}-{activityContext.SpanId}-{(activityContext.TraceFlags == ActivityTraceFlags.Recorded ? "01" : "00")}" + }; - private static void WriteTraceStateIntoEnvironment(Dictionary environment, string key, string value) - { - switch (key) + if (!string.IsNullOrEmpty(activityContext.TraceState)) { - case "traceparent": - environment[Activities.TRACEPARENT] = value; - break; - case "tracestate": - environment[Activities.TRACESTATE] = value; - break; + environment[Activities.TRACESTATE] = activityContext.TraceState; } + + return environment; } } diff --git a/src/Cli/dotnet/Commands/MSBuild/MSBuildForwardingApp.cs b/src/Cli/dotnet/Commands/MSBuild/MSBuildForwardingApp.cs index f0ecb746b403..b71e0fb8eace 100644 --- a/src/Cli/dotnet/Commands/MSBuild/MSBuildForwardingApp.cs +++ b/src/Cli/dotnet/Commands/MSBuild/MSBuildForwardingApp.cs @@ -7,6 +7,7 @@ using System.Reflection; #endif using Microsoft.DotNet.Cli.Commands.Run; +using Microsoft.DotNet.Cli.CommandFactory.CommandResolution; using Microsoft.DotNet.Cli.Telemetry; using Microsoft.DotNet.Cli.Utils; using Microsoft.DotNet.Cli.Utils.Extensions; @@ -112,6 +113,14 @@ public void EnvironmentVariable(string name, string? value) private void InitializeRequiredEnvironmentVariables() { EnvironmentVariable(EnvironmentVariableNames.DOTNET_CLI_TELEMETRY_SESSIONID, TelemetryClient.CurrentSessionId); + + if (ActivityContextFactory.MakeActivityContextEnvironment() is { } activityContextEnvironment) + { + foreach ((string name, string value) in activityContextEnvironment) + { + EnvironmentVariable(name, value); + } + } } /// diff --git a/src/Cli/dotnet/Commands/MSBuild/MSBuildLogger.cs b/src/Cli/dotnet/Commands/MSBuild/MSBuildLogger.cs index 722007a72574..6d3f798e626c 100644 --- a/src/Cli/dotnet/Commands/MSBuild/MSBuildLogger.cs +++ b/src/Cli/dotnet/Commands/MSBuild/MSBuildLogger.cs @@ -125,7 +125,10 @@ public void Initialize(IEventSource eventSource) private void OnBuildStarted(object sender, BuildStartedEventArgs e) { - ActivityContext parentContext = Activity.Current?.Context ?? TelemetryClient.ParentActivityContext; + ActivityContext parentContext = + Activity.Current?.Context + ?? TelemetryClient.GetParentActivityContext() + ?? TelemetryClient.ParentActivityContext; _activity = Activities.Source.StartActivity( "msbuild", ActivityKind.Internal, diff --git a/src/Cli/dotnet/Telemetry/TelemetryClient.cs b/src/Cli/dotnet/Telemetry/TelemetryClient.cs index 6c126d4aa122..79071f61663e 100644 --- a/src/Cli/dotnet/Telemetry/TelemetryClient.cs +++ b/src/Cli/dotnet/Telemetry/TelemetryClient.cs @@ -211,7 +211,7 @@ public TelemetryClient(string? sessionId, IEnvironmentProvider? environmentProvi /// bridge via hostfxr_set_runtime_property_value), then falls back to the /// TRACEPARENT / TRACESTATE environment variables. /// - private static ActivityContext? GetParentActivityContext() + internal static ActivityContext? GetParentActivityContext() { // Runtime properties take precedence — they are set by the AOT bridge when it // falls back to the managed CLI so that the managed spans become children of the diff --git a/test/dotnet.Tests/CommandTests/MSBuild/GivenMSBuildLogger.cs b/test/dotnet.Tests/CommandTests/MSBuild/GivenMSBuildLogger.cs index 1e360c09007c..ad03dba3b89f 100644 --- a/test/dotnet.Tests/CommandTests/MSBuild/GivenMSBuildLogger.cs +++ b/test/dotnet.Tests/CommandTests/MSBuild/GivenMSBuildLogger.cs @@ -272,5 +272,64 @@ public void ItCreatesAnInternalActivityForEachBuild() stoppedActivity.Should().NotBeNull(); stoppedActivity.Status.Should().Be(ActivityStatusCode.Ok); } + + [TestMethod] + [DoNotParallelize] + public void ItUsesTheCurrentParentContextForEachServerBuild() + { + string originalTraceParent = Environment.GetEnvironmentVariable(Activities.TRACEPARENT); + Activity ambientActivity = Activity.Current; + Activity.Current = null; + + try + { + ActivitySource activitySource = Activities.Source; + using var listener = new ActivityListener + { + ShouldListenTo = source => source == activitySource, + Sample = (ref ActivityCreationOptions _) => ActivitySamplingResult.AllDataAndRecorded, + }; + ActivitySource.AddActivityListener(listener); + + var firstParent = new ActivityContext( + ActivityTraceId.CreateRandom(), + ActivitySpanId.CreateRandom(), + ActivityTraceFlags.Recorded, + isRemote: true); + var firstActivity = RunBuildWithParent(firstParent); + + var secondParent = new ActivityContext( + ActivityTraceId.CreateRandom(), + ActivitySpanId.CreateRandom(), + ActivityTraceFlags.Recorded, + isRemote: true); + var secondActivity = RunBuildWithParent(secondParent); + + firstActivity.TraceId.Should().Be(firstParent.TraceId); + firstActivity.ParentSpanId.Should().Be(firstParent.SpanId); + secondActivity.TraceId.Should().Be(secondParent.TraceId); + secondActivity.ParentSpanId.Should().Be(secondParent.SpanId); + } + finally + { + Environment.SetEnvironmentVariable(Activities.TRACEPARENT, originalTraceParent); + Activity.Current = ambientActivity; + } + + static Activity RunBuildWithParent(ActivityContext parentContext) + { + Environment.SetEnvironmentVariable( + Activities.TRACEPARENT, + $"00-{parentContext.TraceId}-{parentContext.SpanId}-01"); + + var eventSource = new PersistentDispatcher([]); + var logger = new MSBuildLogger(new FakeTelemetry()); + logger.Initialize(eventSource); + eventSource.Dispatch(new BuildStartedEventArgs("Build started.", helpKeyword: null)); + Activity activity = Activity.Current; + eventSource.Dispatch(new BuildFinishedEventArgs("Build finished.", helpKeyword: null, succeeded: true)); + return activity; + } + } } } diff --git a/test/dotnet.Tests/CommandTests/MSBuild/GivenMsbuildForwardingApp.cs b/test/dotnet.Tests/CommandTests/MSBuild/GivenMsbuildForwardingApp.cs index 48f2618bee76..d1471ccb6db3 100644 --- a/test/dotnet.Tests/CommandTests/MSBuild/GivenMsbuildForwardingApp.cs +++ b/test/dotnet.Tests/CommandTests/MSBuild/GivenMsbuildForwardingApp.cs @@ -3,6 +3,7 @@ #nullable disable +using System.Diagnostics; using Microsoft.DotNet.Cli; using Microsoft.DotNet.Cli.Commands.MSBuild; using Microsoft.DotNet.Cli.Telemetry; @@ -47,6 +48,21 @@ public void ItSetsEnvironmentalVariables(string envVarName) startInfo.Environment.ContainsKey(envVarName).Should().BeTrue(); } + [TestMethod] + public void ItPropagatesTheCurrentActivityContext() + { + using var activity = new Activity("invocation") + .SetIdFormat(ActivityIdFormat.W3C) + .Start(); + activity.TraceStateString = "vendor=value"; + + var startInfo = new MSBuildForwardingApp(Array.Empty(), "").GetProcessStartInfo(); + + startInfo.Environment[Activities.TRACEPARENT] + .Should().Be($"00-{activity.TraceId}-{activity.SpanId}-{(activity.ActivityTraceFlags == ActivityTraceFlags.Recorded ? "01" : "00")}"); + startInfo.Environment[Activities.TRACESTATE].Should().Be(activity.TraceStateString); + } + [TestMethod] public void ItSetsMSBuildExtensionPathToExistingPath() { diff --git a/test/dotnet.Tests/TelemetryTests/TelemetryClientTests.cs b/test/dotnet.Tests/TelemetryTests/TelemetryClientTests.cs index 82cd29f7726a..d3b44cbb623d 100644 --- a/test/dotnet.Tests/TelemetryTests/TelemetryClientTests.cs +++ b/test/dotnet.Tests/TelemetryTests/TelemetryClientTests.cs @@ -111,12 +111,31 @@ public void ItProcessesMSBuildTelemetryWithTheServerEnabled() var msbuildActivities = activities.Where(activity => activity?["events"]?.AsArray() - .Any(@event => @event?["name"]?.GetValue().StartsWith("dotnet/cli/msbuild/") == true) == true); + .Any(@event => @event?["name"]?.GetValue().StartsWith("dotnet/cli/msbuild/") == true) == true) + .ToArray(); var msbuildTraceIds = msbuildActivities .Select(activity => activity?["identifiers"]?["traceId"]?.GetValue()) .Distinct(); msbuildTraceIds.Should().HaveCount(2); + + var invocationTraceIds = activities + .Where(activity => activity?["operationName"]?.GetValue() == "invocation") + .Select(activity => activity?["identifiers"]?["traceId"]?.GetValue()) + .ToHashSet(); + var activityContexts = activities + .Select(activity => ( + traceId: activity?["identifiers"]?["traceId"]?.GetValue(), + spanId: activity?["identifiers"]?["spanId"]?.GetValue())) + .ToHashSet(); + + var msbuildParentContexts = msbuildActivities + .Select(activity => ( + traceId: activity?["identifiers"]?["traceId"]?.GetValue(), + spanId: activity?["identifiers"]?["parentSpanId"]?.GetValue())) + .ToArray(); + msbuildParentContexts.Should().OnlyContain( + context => invocationTraceIds.Contains(context.traceId) && activityContexts.Contains(context)); } finally { From 1ca3831051a40571fb0f410f85d7574f09fc69aa Mon Sep 17 00:00:00 2001 From: Chet Husk Date: Mon, 3 Aug 2026 16:12:16 -0500 Subject: [PATCH 3/8] Preserve OpenTelemetry context propagation Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> Copilot-Session: f900a161-9261-47ee-823b-369cb6ee3cb7 --- .../ActivityContextFactory.cs | 29 +++++++++++++++---- .../MSBuild/GivenMsbuildForwardingApp.cs | 2 +- 2 files changed, 25 insertions(+), 6 deletions(-) diff --git a/src/Cli/dotnet/CommandFactory/CommandResolution/ActivityContextFactory.cs b/src/Cli/dotnet/CommandFactory/CommandResolution/ActivityContextFactory.cs index ea1b1e7532f7..7499d491ec84 100644 --- a/src/Cli/dotnet/CommandFactory/CommandResolution/ActivityContextFactory.cs +++ b/src/Cli/dotnet/CommandFactory/CommandResolution/ActivityContextFactory.cs @@ -3,6 +3,10 @@ using System.Diagnostics; using Microsoft.DotNet.Cli.Utils; +#if TARGET_WINDOWS +using OpenTelemetry; +using OpenTelemetry.Context.Propagation; +#endif namespace Microsoft.DotNet.Cli.CommandFactory.CommandResolution; @@ -21,16 +25,31 @@ public static class ActivityContextFactory return null; } - var environment = new Dictionary(capacity: 2) - { - [Activities.TRACEPARENT] = $"00-{activityContext.TraceId}-{activityContext.SpanId}-{(activityContext.TraceFlags == ActivityTraceFlags.Recorded ? "01" : "00")}" - }; - + var environment = new Dictionary(capacity: 2); +#if TARGET_WINDOWS + var propagationContext = new PropagationContext(activityContext, Baggage.Current); + Propagators.DefaultTextMapPropagator.Inject(propagationContext, environment, WriteTraceStateIntoEnvironment); +#else + environment[Activities.TRACEPARENT] = $"00-{activityContext.TraceId}-{activityContext.SpanId}-{(byte)activityContext.TraceFlags:x2}"; if (!string.IsNullOrEmpty(activityContext.TraceState)) { environment[Activities.TRACESTATE] = activityContext.TraceState; } +#endif return environment; } + + private static void WriteTraceStateIntoEnvironment(Dictionary environment, string key, string value) + { + switch (key) + { + case "traceparent": + environment[Activities.TRACEPARENT] = value; + break; + case "tracestate": + environment[Activities.TRACESTATE] = value; + break; + } + } } diff --git a/test/dotnet.Tests/CommandTests/MSBuild/GivenMsbuildForwardingApp.cs b/test/dotnet.Tests/CommandTests/MSBuild/GivenMsbuildForwardingApp.cs index d1471ccb6db3..ba21c406136f 100644 --- a/test/dotnet.Tests/CommandTests/MSBuild/GivenMsbuildForwardingApp.cs +++ b/test/dotnet.Tests/CommandTests/MSBuild/GivenMsbuildForwardingApp.cs @@ -59,7 +59,7 @@ public void ItPropagatesTheCurrentActivityContext() var startInfo = new MSBuildForwardingApp(Array.Empty(), "").GetProcessStartInfo(); startInfo.Environment[Activities.TRACEPARENT] - .Should().Be($"00-{activity.TraceId}-{activity.SpanId}-{(activity.ActivityTraceFlags == ActivityTraceFlags.Recorded ? "01" : "00")}"); + .Should().Be($"00-{activity.TraceId}-{activity.SpanId}-{(byte)activity.Context.TraceFlags:x2}"); startInfo.Environment[Activities.TRACESTATE].Should().Be(activity.TraceStateString); } From d9224409b0c721b93f1d7b5166eccd6143de0133 Mon Sep 17 00:00:00 2001 From: Chet Husk Date: Mon, 3 Aug 2026 20:15:55 -0500 Subject: [PATCH 4/8] Document MSBuild logger as an SDK entry point Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> Copilot-Session: f900a161-9261-47ee-823b-369cb6ee3cb7 --- .github/copilot-instructions.md | 18 +++++++++++++---- documentation/project-docs/developer-guide.md | 20 +++++++++++++++++++ src/Cli/AGENTS.md | 19 +++++++++++++++++- 3 files changed, 52 insertions(+), 5 deletions(-) diff --git a/.github/copilot-instructions.md b/.github/copilot-instructions.md index 48adec2c9a9a..8eae04ab4eee 100644 --- a/.github/copilot-instructions.md +++ b/.github/copilot-instructions.md @@ -68,10 +68,20 @@ runtime-library generators or `dotnet/sdk` for SDK analyzers. ### Architecture and major components -The managed CLI dispatches commands registered in -[`Parser.cs`](../src/Cli/dotnet/Parser.cs). Unmatched input goes through external command -resolution and then file-based app fallback, as implemented by -[`Program.cs`](../src/Cli/dotnet/Program.cs). +SDK-owned CLI code has three conceptually equal process entry points: + +- The managed CLI dispatches commands registered in + [`Parser.cs`](../src/Cli/dotnet/Parser.cs). Unmatched input goes through external command + resolution and then file-based app fallback, as implemented by + [`Program.cs`](../src/Cli/dotnet/Program.cs). +- The Native AOT CLI begins at + [`NativeEntryPoint.cs`](../src/Cli/dotnet-aot/NativeEntryPoint.cs), handles supported + commands directly, and falls through to the managed CLI for unsupported operations. +- [`MSBuildLogger.cs`](../src/Cli/dotnet/Commands/MSBuild/MSBuildLogger.cs) is a separate + SDK entry point loaded by MSBuild as an `INodeLogger`. It may execute in the CLI process, + a child MSBuild process, or a persistent MSBuild server, so code reached through it must + not assume either CLI bootstrap already initialized process-wide state. Treat + `BuildStarted`/`BuildFinished` as request boundaries and `Shutdown` as host teardown. Major source areas under [`src/`](../src/): diff --git a/documentation/project-docs/developer-guide.md b/documentation/project-docs/developer-guide.md index 60d97f1ccd24..9973501f56c3 100644 --- a/documentation/project-docs/developer-guide.md +++ b/documentation/project-docs/developer-guide.md @@ -57,6 +57,26 @@ Run the following command from the root of the repository: The build script will output a .NET Core installation to `artifacts\bin\redist\Debug\dotnet` that will include any local changes to the .NET Core CLI. +## SDK process entry points + +Contributor changes under `src/Cli` must account for three conceptually equal ways that +SDK-owned code can begin executing: + +| Entry point | Source | Host | +| --- | --- | --- | +| Managed CLI | [`src/Cli/dotnet/Program.cs`](../../src/Cli/dotnet/Program.cs) | CoreCLR runs the full command implementation. | +| Native AOT CLI | [`src/Cli/dotnet-aot/NativeEntryPoint.cs`](../../src/Cli/dotnet-aot/NativeEntryPoint.cs) | The native `dotnet` host calls the exported `dotnet_execute` fast path, which can fall through to the managed CLI. See the [NativeAOT design](../../src/Cli/dotnet-aot/DESIGN.md). | +| MSBuild logger | [`src/Cli/dotnet/Commands/MSBuild/MSBuildLogger.cs`](../../src/Cli/dotnet/Commands/MSBuild/MSBuildLogger.cs) | MSBuild loads `dotnet.dll` as an `INodeLogger` using the `-distributedlogger` argument assembled by [`MSBuildForwardingApp`](../../src/Cli/dotnet/Commands/MSBuild/MSBuildForwardingApp.cs). | + +The MSBuild logger is a separate process entry point even though it is not a standalone +executable. It may run in the managed CLI process, a child MSBuild process, or a persistent +MSBuild server. Code reached through the logger must not assume that managed +`Program.Main` or the Native AOT bootstrap already initialized process-wide state. +Per-build state belongs to the MSBuild `BuildStarted`/`BuildFinished` lifecycle, while +logger `Shutdown` represents host teardown. Persistent servers can run multiple builds in +one process, so request-specific environment and trace context must be refreshed for each +build rather than retained globally. + ## Running tests ### Windows diff --git a/src/Cli/AGENTS.md b/src/Cli/AGENTS.md index e2f4d778245c..7b35ef98192c 100644 --- a/src/Cli/AGENTS.md +++ b/src/Cli/AGENTS.md @@ -2,7 +2,24 @@ Guidance for changes under `src/Cli`. -## Three-project split +## SDK process entry points + +SDK-owned CLI code can begin executing through three conceptually equal entry points: + +| Entry point | Source | Host and lifecycle | +|-------------|--------|--------------------| +| Managed CLI | `dotnet/Program.cs` | CoreCLR process; normal `Program.Main` startup and process shutdown. | +| Native AOT CLI | `dotnet-aot/NativeEntryPoint.cs` | Native host calls the exported `dotnet_execute`; unsupported operations can fall through to the managed CLI. | +| MSBuild logger | `dotnet/Commands/MSBuild/MSBuildLogger.cs` | MSBuild loads the SDK assembly as an `INodeLogger` through the `-distributedlogger` argument added by `MSBuildForwardingApp`. It can run inside the CLI process, a child MSBuild process, or a persistent MSBuild server. | + +Treat the logger as an independent entry point, not as code that necessarily runs beneath +managed `Program.Main` or the Native AOT bootstrap in the same process. Any process-wide +state it uses, including telemetry and tracing, must initialize correctly when MSBuild +loads it directly. Use `BuildStarted`/`BuildFinished` for request-scoped state and +`Shutdown` for host teardown; a persistent server can execute multiple builds in the same +process, with different environment and trace context for each request. + +## Three-project command split A `dotnet` command or option spans three cooperating projects: From 4a567f02a4208fc1d232eda4ce22a4ef4924df53 Mon Sep 17 00:00:00 2001 From: Chet Husk Date: Mon, 3 Aug 2026 20:20:25 -0500 Subject: [PATCH 5/8] Explain MSBuild logger lifecycle in XML docs Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> Copilot-Session: f900a161-9261-47ee-823b-369cb6ee3cb7 --- .github/copilot-instructions.md | 3 +- documentation/project-docs/developer-guide.md | 7 +- src/Cli/AGENTS.md | 5 +- .../dotnet/Commands/MSBuild/MSBuildLogger.cs | 102 ++++++++++++++++++ 4 files changed, 111 insertions(+), 6 deletions(-) diff --git a/.github/copilot-instructions.md b/.github/copilot-instructions.md index 8eae04ab4eee..cf8acbc216b8 100644 --- a/.github/copilot-instructions.md +++ b/.github/copilot-instructions.md @@ -81,7 +81,8 @@ SDK-owned CLI code has three conceptually equal process entry points: SDK entry point loaded by MSBuild as an `INodeLogger`. It may execute in the CLI process, a child MSBuild process, or a persistent MSBuild server, so code reached through it must not assume either CLI bootstrap already initialized process-wide state. Treat - `BuildStarted`/`BuildFinished` as request boundaries and `Shutdown` as host teardown. + `BuildStarted`/`BuildFinished` as request boundaries and `Shutdown` as logger-instance + completion, which does not necessarily mean process exit. Major source areas under [`src/`](../src/): diff --git a/documentation/project-docs/developer-guide.md b/documentation/project-docs/developer-guide.md index 9973501f56c3..67ecd1b58dcf 100644 --- a/documentation/project-docs/developer-guide.md +++ b/documentation/project-docs/developer-guide.md @@ -73,9 +73,10 @@ executable. It may run in the managed CLI process, a child MSBuild process, or a MSBuild server. Code reached through the logger must not assume that managed `Program.Main` or the Native AOT bootstrap already initialized process-wide state. Per-build state belongs to the MSBuild `BuildStarted`/`BuildFinished` lifecycle, while -logger `Shutdown` represents host teardown. Persistent servers can run multiple builds in -one process, so request-specific environment and trace context must be refreshed for each -build rather than retained globally. +logger `Shutdown` represents completion of that logger instance, not necessarily process +exit. Persistent servers can run multiple builds in one process, so request-specific +environment and trace context must be refreshed for each build rather than retained +globally. ## Running tests diff --git a/src/Cli/AGENTS.md b/src/Cli/AGENTS.md index 7b35ef98192c..da31e98c1079 100644 --- a/src/Cli/AGENTS.md +++ b/src/Cli/AGENTS.md @@ -16,8 +16,9 @@ Treat the logger as an independent entry point, not as code that necessarily run managed `Program.Main` or the Native AOT bootstrap in the same process. Any process-wide state it uses, including telemetry and tracing, must initialize correctly when MSBuild loads it directly. Use `BuildStarted`/`BuildFinished` for request-scoped state and -`Shutdown` for host teardown; a persistent server can execute multiple builds in the same -process, with different environment and trace context for each request. +`Shutdown` for logger-instance completion; it does not imply process exit. A persistent +server can execute multiple builds in the same process, with different environment and +trace context for each request. ## Three-project command split diff --git a/src/Cli/dotnet/Commands/MSBuild/MSBuildLogger.cs b/src/Cli/dotnet/Commands/MSBuild/MSBuildLogger.cs index 6d3f798e626c..864f5f497f84 100644 --- a/src/Cli/dotnet/Commands/MSBuild/MSBuildLogger.cs +++ b/src/Cli/dotnet/Commands/MSBuild/MSBuildLogger.cs @@ -10,9 +10,37 @@ namespace Microsoft.DotNet.Cli.Commands.MSBuild; +/// +/// Receives telemetry emitted by MSBuild and SDK build logic and forwards it through the +/// .NET SDK telemetry pipeline. +/// +/// +/// MSBuild loads this type from dotnet.dll as a distributed logger. This makes the +/// logger a separate SDK entry point: it can run inside the managed CLI process, in a child +/// MSBuild process, or in a persistent MSBuild server where neither CLI bootstrap runs. +/// Consequently, process-wide telemetry is initialized here when necessary, while +/// request-specific activity state is created and cleared at MSBuild's per-build event +/// boundaries. +/// public sealed class MSBuildLogger : INodeLogger { + /// + /// The process-wide telemetry client used by this logger instance. + /// + /// + /// In-process builds reuse the client initialized by the managed CLI. An out-of-process + /// host, including the persistent MSBuild server, initializes the same process-wide + /// client through the parameterless constructor. + /// private readonly ITelemetryClient? _telemetry; + + /// + /// The activity owned by the current build. + /// + /// + /// This must never outlive BuildFinished: a persistent MSBuild server can handle + /// later builds with unrelated parent trace contexts in the same process. + /// private Activity? _activity; internal const string TargetFrameworkTelemetryEventName = "targetframeworkeval"; @@ -62,6 +90,17 @@ public sealed class MSBuildLogger : INodeLogger /// private Dictionary> _aggregatedEvents = new(); + /// + /// Initializes telemetry for the process hosting the logger. + /// + /// + /// MSBuild constructs loggers through their parameterless constructor. The managed CLI + /// may already have initialized telemetry for an in-process build, but a child process + /// or persistent server enters the SDK through this logger and has no such guarantee. + /// Reusing an initialized client preserves CLI-owned state; initializing only when + /// necessary gives standalone MSBuild hosts the same enablement and session behavior. + /// Telemetry failures are isolated because diagnostics must never fail the build. + /// public MSBuildLogger() { try @@ -89,11 +128,29 @@ internal MSBuildLogger(ITelemetryClient telemetry) _telemetry = telemetry; } + /// + /// Connects this node logger to MSBuild's event lifecycle. + /// + /// + /// The node-count overload exists for and intentionally shares + /// the same subscriptions as the standard logger overload. Activity ownership follows + /// build events rather than logger construction because a server process can execute + /// multiple builds and supply different request context to each one. + /// public void Initialize(IEventSource eventSource, int nodeCount) { Initialize(eventSource); } + /// + /// Connects this logger to the events needed to collect telemetry and delimit a build. + /// + /// + /// Telemetry events and BuildStarted are observed only when telemetry is enabled, + /// avoiding collection and activity work for opted-out builds. BuildFinished is + /// always observed as a defensive cleanup boundary so any activity owned by this logger + /// cannot leak into a later request. + /// public void Initialize(IEventSource eventSource) { // Declare lack of dependency on having properties/items in ProjectStarted events @@ -123,6 +180,16 @@ public void Initialize(IEventSource eventSource) } } + /// + /// Starts the activity that contains telemetry for one MSBuild request. + /// + /// + /// The parent is resolved here, not in the constructor, because a persistent server's + /// environment and trace context can change for every request. An ambient activity is + /// preferred for in-process builds; otherwise the context forwarded by the invoking CLI + /// is re-read from the current request environment. The activity is internal because it + /// represents SDK work within the invoking command rather than a remote client call. + /// private void OnBuildStarted(object sender, BuildStartedEventArgs e) { ActivityContext parentContext = @@ -135,6 +202,15 @@ private void OnBuildStarted(object sender, BuildStartedEventArgs e) parentContext); } + /// + /// Completes telemetry and activity state for one MSBuild request. + /// + /// + /// Aggregated events are emitted before the activity is stopped so they remain attached + /// to the build span. The overall MSBuild result supplies the span status. Stopping and + /// clearing the activity here prevents a persistent server from parenting a later build + /// to the completed request. + /// private void OnBuildFinished(object sender, BuildFinishedEventArgs e) { SendAggregatedEventsOnBuildFinished(_telemetry); @@ -142,6 +218,13 @@ private void OnBuildFinished(object sender, BuildFinishedEventArgs e) StopActivity(); } + /// + /// Emits telemetry that is intentionally accumulated across nodes during a build. + /// + /// + /// Removing each emitted aggregate is essential for persistent servers: process state + /// can survive into another build, but counts from the completed request must not. + /// internal void SendAggregatedEventsOnBuildFinished(ITelemetryClient? telemetry) { if (telemetry is null) return; @@ -286,6 +369,17 @@ private void OnTelemetryLogged(object sender, TelemetryEventArgs args) } } + /// + /// Completes this MSBuild logger instance and drains its telemetry. + /// + /// + /// BuildFinished is the normal activity boundary. The additional stop is an + /// idempotent fallback for aborted builds whose finish event was not delivered. + /// Exporter draining and diagnostic-log writing belong here rather than in + /// BuildFinished because MSBuild defines as the logger + /// completion hook. In a persistent server this does not imply process shutdown; the + /// process-wide telemetry client remains reusable by a later logger instance. + /// public void Shutdown() { StopActivity(); @@ -298,6 +392,14 @@ public void Shutdown() TelemetryClient.WriteLogIfNecessary(); } + /// + /// Stops only the activity owned by this logger and clears the reference. + /// + /// + /// The ambient parent belongs to the invoking host and must not be stopped here. + /// Clearing the field also makes cleanup safe when both BuildFinished and + /// run. + /// private void StopActivity() { _activity?.Stop(); From 8d93dae69b4e2ab76bbcf3c6beed5f710f7bca03 Mon Sep 17 00:00:00 2001 From: Chet Husk Date: Mon, 3 Aug 2026 20:56:01 -0500 Subject: [PATCH 6/8] Address MSBuild telemetry review feedback Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> Copilot-Session: f900a161-9261-47ee-823b-369cb6ee3cb7 --- documentation/project-docs/telemetry.md | 8 +++++++ .../dotnet/Commands/MSBuild/MSBuildLogger.cs | 19 ++++++++++++----- src/Cli/dotnet/Telemetry/TelemetryClient.cs | 6 +++--- .../dotnet/Telemetry/TelemetryDiskLogger.cs | 4 ++-- .../TelemetryTests/TelemetryClientTests.cs | 21 +++++++++++++++++++ 5 files changed, 48 insertions(+), 10 deletions(-) diff --git a/documentation/project-docs/telemetry.md b/documentation/project-docs/telemetry.md index d4451908ecf5..97d0899fe616 100644 --- a/documentation/project-docs/telemetry.md +++ b/documentation/project-docs/telemetry.md @@ -274,6 +274,14 @@ Every telemetry event automatically includes these common properties: ### SDK-Collected Build Events +These existing events are collected by +[`MSBuildLogger`](../../src/Cli/dotnet/Commands/MSBuild/MSBuildLogger.cs), which MSBuild +loads from the SDK as a distributed logger. The logger can run inside the CLI process, in +a child MSBuild process, or in a persistent MSBuild server. Each build gets its own +internal activity, parented to the invoking CLI trace when context is available, so server +reuse changes only telemetry delivery and correlation, not the data points or properties +listed below. + #### `msbuild/targetframeworkeval` **When fired**: When target framework is evaluated diff --git a/src/Cli/dotnet/Commands/MSBuild/MSBuildLogger.cs b/src/Cli/dotnet/Commands/MSBuild/MSBuildLogger.cs index 864f5f497f84..236194790318 100644 --- a/src/Cli/dotnet/Commands/MSBuild/MSBuildLogger.cs +++ b/src/Cli/dotnet/Commands/MSBuild/MSBuildLogger.cs @@ -206,10 +206,10 @@ private void OnBuildStarted(object sender, BuildStartedEventArgs e) /// Completes telemetry and activity state for one MSBuild request. /// /// - /// Aggregated events are emitted before the activity is stopped so they remain attached - /// to the build span. The overall MSBuild result supplies the span status. Stopping and - /// clearing the activity here prevents a persistent server from parenting a later build - /// to the completed request. + /// MSBuild events are attached synchronously, so all events are present before the + /// activity is stopped and exporters snapshot it. The overall MSBuild result supplies + /// the span status. Stopping and clearing the activity here prevents a persistent server + /// from parenting a later build to the completed request. /// private void OnBuildFinished(object sender, BuildFinishedEventArgs e) { @@ -354,7 +354,16 @@ private static void TrackEvent(ITelemetryClient? telemetry, string eventName, ID } } - telemetry?.TrackEvent(eventName, properties ?? eventProperties); + if (telemetry is TelemetryClient telemetryClient) + { + // This activity ends at BuildFinished, so production events must be attached before + // an exporter observes Activity.Stop. Test clients retain the ITelemetryClient seam. + telemetryClient.ThreadBlockingTrackEvent(eventName, properties ?? eventProperties); + } + else + { + telemetry?.TrackEvent(eventName, properties ?? eventProperties); + } } private void OnTelemetryLogged(object sender, TelemetryEventArgs args) diff --git a/src/Cli/dotnet/Telemetry/TelemetryClient.cs b/src/Cli/dotnet/Telemetry/TelemetryClient.cs index 79071f61663e..51f374321529 100644 --- a/src/Cli/dotnet/Telemetry/TelemetryClient.cs +++ b/src/Cli/dotnet/Telemetry/TelemetryClient.cs @@ -171,15 +171,15 @@ public TelemetryClient() : this(null) { } public TelemetryClient(string? sessionId, IEnvironmentProvider? environmentProvider = null) { - Instance = this; - IsInitialized = true; - // This is some kind of special condition for MSBuild-related tests. if (DisabledForTests) { return; } + Instance = this; + IsInitialized = true; + environmentProvider ??= new EnvironmentProvider(); Enabled = !environmentProvider.GetEnvironmentVariableAsBool(EnvironmentVariableNames.TELEMETRY_OPTOUT, // When building in the official CI pipeline, this makes the complier enable telemetry by default. Otherwise, it is disabled. diff --git a/src/Cli/dotnet/Telemetry/TelemetryDiskLogger.cs b/src/Cli/dotnet/Telemetry/TelemetryDiskLogger.cs index 761d193d6fcd..ffbe4f1fa893 100644 --- a/src/Cli/dotnet/Telemetry/TelemetryDiskLogger.cs +++ b/src/Cli/dotnet/Telemetry/TelemetryDiskLogger.cs @@ -47,7 +47,7 @@ static TelemetryDiskLogger() s_jsonContext = new(s_jsonOptions); } - public static bool WriteLog(string logPath, IEnumerable activies) + public static bool WriteLog(string logPath, IEnumerable activities) { try { @@ -55,7 +55,7 @@ public static bool WriteLog(string logPath, IEnumerable activies) var root = JsonNode.Parse(jsonText)!; var activitiesArray = root["activities"]!.AsArray(); - foreach (var activity in activies) + foreach (var activity in activities) { activitiesArray.Add(JsonNode.Parse(JsonSerializer.Serialize(CreateActivityJsonModel(activity), s_jsonContext.ActivityModel))); } diff --git a/test/dotnet.Tests/TelemetryTests/TelemetryClientTests.cs b/test/dotnet.Tests/TelemetryTests/TelemetryClientTests.cs index d3b44cbb623d..e535a3c86181 100644 --- a/test/dotnet.Tests/TelemetryTests/TelemetryClientTests.cs +++ b/test/dotnet.Tests/TelemetryTests/TelemetryClientTests.cs @@ -143,6 +143,27 @@ public void ItProcessesMSBuildTelemetryWithTheServerEnabled() } } + [TestMethod] + [DoNotParallelize] + public void DisabledForTestsDoesNotInitializeTelemetry() + { + TelemetryClient.DisabledForTests = true; + + try + { + _ = new TelemetryClient(); + TelemetryClient.DisabledForTests = false; + + TelemetryClient.IsInitialized.Should().BeFalse(); + TelemetryClient.Instance.Should().BeNull(); + TelemetryClient.CurrentSessionId.Should().BeNull(); + } + finally + { + TelemetryClient.DisabledForTests = true; + } + } + [TestMethod] [DoNotParallelize] public void MSBuildLoggerDoesNotReinitializeDisabledTelemetry() From 1a2ffa69349704127c538e591430787d1e1ce0b5 Mon Sep 17 00:00:00 2001 From: Chet Husk Date: Tue, 4 Aug 2026 09:02:43 -0500 Subject: [PATCH 7/8] Simplify MSBuild logger documentation Use shorter, active sentences and consistent lifecycle terms across contributor guidance and XML documentation. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> Copilot-Session: f900a161-9261-47ee-823b-369cb6ee3cb7 --- .github/copilot-instructions.md | 30 +++--- documentation/project-docs/developer-guide.md | 26 +++-- documentation/project-docs/telemetry.md | 14 +-- src/Cli/AGENTS.md | 23 +++-- .../dotnet/Commands/MSBuild/MSBuildLogger.cs | 96 +++++++++---------- 5 files changed, 91 insertions(+), 98 deletions(-) diff --git a/.github/copilot-instructions.md b/.github/copilot-instructions.md index cf8acbc216b8..725ef5c1a9ac 100644 --- a/.github/copilot-instructions.md +++ b/.github/copilot-instructions.md @@ -68,21 +68,21 @@ runtime-library generators or `dotnet/sdk` for SDK analyzers. ### Architecture and major components -SDK-owned CLI code has three conceptually equal process entry points: - -- The managed CLI dispatches commands registered in - [`Parser.cs`](../src/Cli/dotnet/Parser.cs). Unmatched input goes through external command - resolution and then file-based app fallback, as implemented by - [`Program.cs`](../src/Cli/dotnet/Program.cs). -- The Native AOT CLI begins at - [`NativeEntryPoint.cs`](../src/Cli/dotnet-aot/NativeEntryPoint.cs), handles supported - commands directly, and falls through to the managed CLI for unsupported operations. -- [`MSBuildLogger.cs`](../src/Cli/dotnet/Commands/MSBuild/MSBuildLogger.cs) is a separate - SDK entry point loaded by MSBuild as an `INodeLogger`. It may execute in the CLI process, - a child MSBuild process, or a persistent MSBuild server, so code reached through it must - not assume either CLI bootstrap already initialized process-wide state. Treat - `BuildStarted`/`BuildFinished` as request boundaries and `Shutdown` as logger-instance - completion, which does not necessarily mean process exit. +SDK-owned CLI code has three process entry points of equal importance: + +- The managed CLI dispatches commands that + [`Parser.cs`](../src/Cli/dotnet/Parser.cs) registers. + [`Program.cs`](../src/Cli/dotnet/Program.cs) handles unmatched input through external + command resolution and file-based app fallback. +- The Native AOT CLI starts in + [`NativeEntryPoint.cs`](../src/Cli/dotnet-aot/NativeEntryPoint.cs). It handles supported + commands directly. Unsupported operations continue in the managed CLI. +- MSBuild loads [`MSBuildLogger`](../src/Cli/dotnet/Commands/MSBuild/MSBuildLogger.cs) from + `dotnet.dll` as an `INodeLogger`. The logger can run in the CLI process, a child MSBuild + process, or a persistent MSBuild server. Code called through the logger must not assume + that a CLI bootstrap initialized process-wide state. Use `BuildStarted` and + `BuildFinished` as request boundaries. `Shutdown` completes one logger instance. It does + not necessarily end the process. Major source areas under [`src/`](../src/): diff --git a/documentation/project-docs/developer-guide.md b/documentation/project-docs/developer-guide.md index 67ecd1b58dcf..eddbcb90bf33 100644 --- a/documentation/project-docs/developer-guide.md +++ b/documentation/project-docs/developer-guide.md @@ -59,24 +59,22 @@ The build script will output a .NET Core installation to `artifacts\bin\redist\D ## SDK process entry points -Contributor changes under `src/Cli` must account for three conceptually equal ways that -SDK-owned code can begin executing: +Changes under `src/Cli` must support three process entry points of equal importance: | Entry point | Source | Host | | --- | --- | --- | | Managed CLI | [`src/Cli/dotnet/Program.cs`](../../src/Cli/dotnet/Program.cs) | CoreCLR runs the full command implementation. | -| Native AOT CLI | [`src/Cli/dotnet-aot/NativeEntryPoint.cs`](../../src/Cli/dotnet-aot/NativeEntryPoint.cs) | The native `dotnet` host calls the exported `dotnet_execute` fast path, which can fall through to the managed CLI. See the [NativeAOT design](../../src/Cli/dotnet-aot/DESIGN.md). | -| MSBuild logger | [`src/Cli/dotnet/Commands/MSBuild/MSBuildLogger.cs`](../../src/Cli/dotnet/Commands/MSBuild/MSBuildLogger.cs) | MSBuild loads `dotnet.dll` as an `INodeLogger` using the `-distributedlogger` argument assembled by [`MSBuildForwardingApp`](../../src/Cli/dotnet/Commands/MSBuild/MSBuildForwardingApp.cs). | - -The MSBuild logger is a separate process entry point even though it is not a standalone -executable. It may run in the managed CLI process, a child MSBuild process, or a persistent -MSBuild server. Code reached through the logger must not assume that managed -`Program.Main` or the Native AOT bootstrap already initialized process-wide state. -Per-build state belongs to the MSBuild `BuildStarted`/`BuildFinished` lifecycle, while -logger `Shutdown` represents completion of that logger instance, not necessarily process -exit. Persistent servers can run multiple builds in one process, so request-specific -environment and trace context must be refreshed for each build rather than retained -globally. +| Native AOT CLI | [`src/Cli/dotnet-aot/NativeEntryPoint.cs`](../../src/Cli/dotnet-aot/NativeEntryPoint.cs) | The native `dotnet` host calls the exported `dotnet_execute`. Unsupported operations can continue in the managed CLI. See the [NativeAOT design](../../src/Cli/dotnet-aot/DESIGN.md). | +| MSBuild logger | [`src/Cli/dotnet/Commands/MSBuild/MSBuildLogger.cs`](../../src/Cli/dotnet/Commands/MSBuild/MSBuildLogger.cs) | MSBuild loads the logger type from `dotnet.dll` as an `INodeLogger`. [`MSBuildForwardingApp`](../../src/Cli/dotnet/Commands/MSBuild/MSBuildForwardingApp.cs) adds the `-distributedlogger` argument. | + +The MSBuild logger is a separate process entry point. It is not a standalone executable. +The logger can run in the managed CLI process, a child MSBuild process, or a persistent +MSBuild server. Code called through the logger must not assume that a CLI bootstrap +initialized process-wide state. + +Use `BuildStarted` and `BuildFinished` to manage state for one build. `Shutdown` completes +one logger instance. It does not necessarily end the process. A persistent server can run +multiple builds in one process. Refresh the environment and trace context for each build. ## Running tests diff --git a/documentation/project-docs/telemetry.md b/documentation/project-docs/telemetry.md index 97d0899fe616..3a563b552e9a 100644 --- a/documentation/project-docs/telemetry.md +++ b/documentation/project-docs/telemetry.md @@ -274,13 +274,13 @@ Every telemetry event automatically includes these common properties: ### SDK-Collected Build Events -These existing events are collected by -[`MSBuildLogger`](../../src/Cli/dotnet/Commands/MSBuild/MSBuildLogger.cs), which MSBuild -loads from the SDK as a distributed logger. The logger can run inside the CLI process, in -a child MSBuild process, or in a persistent MSBuild server. Each build gets its own -internal activity, parented to the invoking CLI trace when context is available, so server -reuse changes only telemetry delivery and correlation, not the data points or properties -listed below. +[`MSBuildLogger`](../../src/Cli/dotnet/Commands/MSBuild/MSBuildLogger.cs) collects the +existing events below. MSBuild loads the logger from the SDK. The logger can run in the +CLI process, a child MSBuild process, or a persistent MSBuild server. + +The logger creates an internal activity for each build. When trace context is available, +the activity is a child of the invoking CLI trace. Server reuse changes telemetry delivery +and correlation only. It does not change the listed data points or properties. #### `msbuild/targetframeworkeval` diff --git a/src/Cli/AGENTS.md b/src/Cli/AGENTS.md index da31e98c1079..aca1a8abaa4f 100644 --- a/src/Cli/AGENTS.md +++ b/src/Cli/AGENTS.md @@ -4,21 +4,20 @@ Guidance for changes under `src/Cli`. ## SDK process entry points -SDK-owned CLI code can begin executing through three conceptually equal entry points: +SDK-owned CLI code has three process entry points of equal importance: | Entry point | Source | Host and lifecycle | |-------------|--------|--------------------| -| Managed CLI | `dotnet/Program.cs` | CoreCLR process; normal `Program.Main` startup and process shutdown. | -| Native AOT CLI | `dotnet-aot/NativeEntryPoint.cs` | Native host calls the exported `dotnet_execute`; unsupported operations can fall through to the managed CLI. | -| MSBuild logger | `dotnet/Commands/MSBuild/MSBuildLogger.cs` | MSBuild loads the SDK assembly as an `INodeLogger` through the `-distributedlogger` argument added by `MSBuildForwardingApp`. It can run inside the CLI process, a child MSBuild process, or a persistent MSBuild server. | - -Treat the logger as an independent entry point, not as code that necessarily runs beneath -managed `Program.Main` or the Native AOT bootstrap in the same process. Any process-wide -state it uses, including telemetry and tracing, must initialize correctly when MSBuild -loads it directly. Use `BuildStarted`/`BuildFinished` for request-scoped state and -`Shutdown` for logger-instance completion; it does not imply process exit. A persistent -server can execute multiple builds in the same process, with different environment and -trace context for each request. +| Managed CLI | `dotnet/Program.cs` | CoreCLR calls `Program.Main`. The process ends after the command completes. | +| Native AOT CLI | `dotnet-aot/NativeEntryPoint.cs` | The native host calls the exported `dotnet_execute`. Unsupported operations can continue in the managed CLI. | +| MSBuild logger | `dotnet/Commands/MSBuild/MSBuildLogger.cs` | MSBuild loads the SDK assembly as an `INodeLogger`. `MSBuildForwardingApp` adds the `-distributedlogger` argument. The logger can run in the CLI process, a child process, or a persistent server. | + +Treat the logger as an independent entry point. Do not assume that it runs after managed +`Program.Main` or the Native AOT bootstrap. Initialize process-wide telemetry and tracing +when MSBuild loads the logger directly. Use `BuildStarted` and `BuildFinished` for +request-specific state. `Shutdown` completes one logger instance. It does not necessarily +end the process. Refresh the environment and trace context for each persistent-server +request. ## Three-project command split diff --git a/src/Cli/dotnet/Commands/MSBuild/MSBuildLogger.cs b/src/Cli/dotnet/Commands/MSBuild/MSBuildLogger.cs index 236194790318..e2b242091543 100644 --- a/src/Cli/dotnet/Commands/MSBuild/MSBuildLogger.cs +++ b/src/Cli/dotnet/Commands/MSBuild/MSBuildLogger.cs @@ -11,16 +11,15 @@ namespace Microsoft.DotNet.Cli.Commands.MSBuild; /// -/// Receives telemetry emitted by MSBuild and SDK build logic and forwards it through the -/// .NET SDK telemetry pipeline. +/// Receives telemetry from MSBuild and SDK build logic. The logger sends the telemetry +/// through the .NET SDK telemetry pipeline. /// /// -/// MSBuild loads this type from dotnet.dll as a distributed logger. This makes the -/// logger a separate SDK entry point: it can run inside the managed CLI process, in a child -/// MSBuild process, or in a persistent MSBuild server where neither CLI bootstrap runs. -/// Consequently, process-wide telemetry is initialized here when necessary, while -/// request-specific activity state is created and cleared at MSBuild's per-build event -/// boundaries. +/// MSBuild loads this type from dotnet.dll as a distributed logger. The logger is a +/// separate SDK entry point. It can run in the managed CLI process, a child MSBuild +/// process, or a persistent MSBuild server. Some hosts do not run either CLI bootstrap. +/// The logger initializes process-wide telemetry when necessary. It creates and clears +/// request-specific activity state at BuildStarted and BuildFinished. /// public sealed class MSBuildLogger : INodeLogger { @@ -28,9 +27,8 @@ public sealed class MSBuildLogger : INodeLogger /// The process-wide telemetry client used by this logger instance. /// /// - /// In-process builds reuse the client initialized by the managed CLI. An out-of-process - /// host, including the persistent MSBuild server, initializes the same process-wide - /// client through the parameterless constructor. + /// The managed CLI initializes this client for in-process builds. Other hosts use the + /// parameterless constructor to initialize the same process-wide client. /// private readonly ITelemetryClient? _telemetry; @@ -38,8 +36,9 @@ public sealed class MSBuildLogger : INodeLogger /// The activity owned by the current build. /// /// - /// This must never outlive BuildFinished: a persistent MSBuild server can handle - /// later builds with unrelated parent trace contexts in the same process. + /// This activity belongs to one build. It must not remain active after + /// BuildFinished. A persistent server can run later builds with unrelated parent + /// trace contexts in the same process. /// private Activity? _activity; @@ -94,12 +93,11 @@ public sealed class MSBuildLogger : INodeLogger /// Initializes telemetry for the process hosting the logger. /// /// - /// MSBuild constructs loggers through their parameterless constructor. The managed CLI - /// may already have initialized telemetry for an in-process build, but a child process - /// or persistent server enters the SDK through this logger and has no such guarantee. - /// Reusing an initialized client preserves CLI-owned state; initializing only when - /// necessary gives standalone MSBuild hosts the same enablement and session behavior. - /// Telemetry failures are isolated because diagnostics must never fail the build. + /// MSBuild uses the parameterless constructor to create loggers. The managed CLI can + /// initialize telemetry before an in-process build. A child process or persistent + /// server cannot depend on that initialization. The constructor reuses an existing + /// client to preserve CLI state. If no client exists, it creates one with the same + /// enablement and session behavior. Telemetry failures must not fail the build. /// public MSBuildLogger() { @@ -132,10 +130,9 @@ internal MSBuildLogger(ITelemetryClient telemetry) /// Connects this node logger to MSBuild's event lifecycle. /// /// - /// The node-count overload exists for and intentionally shares - /// the same subscriptions as the standard logger overload. Activity ownership follows - /// build events rather than logger construction because a server process can execute - /// multiple builds and supply different request context to each one. + /// requires this node-count overload. Both overloads use the + /// same event subscriptions. Build events control the activity lifetime because a + /// server can run multiple builds. Each build can have different request context. /// public void Initialize(IEventSource eventSource, int nodeCount) { @@ -146,10 +143,9 @@ public void Initialize(IEventSource eventSource, int nodeCount) /// Connects this logger to the events needed to collect telemetry and delimit a build. /// /// - /// Telemetry events and BuildStarted are observed only when telemetry is enabled, - /// avoiding collection and activity work for opted-out builds. BuildFinished is - /// always observed as a defensive cleanup boundary so any activity owned by this logger - /// cannot leak into a later request. + /// The logger subscribes to telemetry events and BuildStarted only when telemetry + /// is enabled. This avoids work for opted-out builds. The logger always subscribes to + /// BuildFinished. This lets the logger clear its activity before a later request. /// public void Initialize(IEventSource eventSource) { @@ -184,11 +180,11 @@ public void Initialize(IEventSource eventSource) /// Starts the activity that contains telemetry for one MSBuild request. /// /// - /// The parent is resolved here, not in the constructor, because a persistent server's - /// environment and trace context can change for every request. An ambient activity is - /// preferred for in-process builds; otherwise the context forwarded by the invoking CLI - /// is re-read from the current request environment. The activity is internal because it - /// represents SDK work within the invoking command rather than a remote client call. + /// A persistent server can receive different environment and trace context for each + /// request. This method resolves the parent at BuildStarted, not in the + /// constructor. It uses the ambient activity for an in-process build. Otherwise, it + /// reads the context that the invoking CLI forwarded. The activity is internal because + /// it represents SDK work in the invoking command, not a remote client call. /// private void OnBuildStarted(object sender, BuildStartedEventArgs e) { @@ -206,10 +202,10 @@ private void OnBuildStarted(object sender, BuildStartedEventArgs e) /// Completes telemetry and activity state for one MSBuild request. /// /// - /// MSBuild events are attached synchronously, so all events are present before the - /// activity is stopped and exporters snapshot it. The overall MSBuild result supplies - /// the span status. Stopping and clearing the activity here prevents a persistent server - /// from parenting a later build to the completed request. + /// The logger attaches MSBuild events before it stops the activity. This order ensures + /// that exporters include the events when they capture the stopped activity. The method + /// sets the span status from the overall build result. It then clears the activity so a + /// later server build cannot use the completed activity as its parent. /// private void OnBuildFinished(object sender, BuildFinishedEventArgs e) { @@ -222,8 +218,9 @@ private void OnBuildFinished(object sender, BuildFinishedEventArgs e) /// Emits telemetry that is intentionally accumulated across nodes during a build. /// /// - /// Removing each emitted aggregate is essential for persistent servers: process state - /// can survive into another build, but counts from the completed request must not. + /// A persistent server retains process state for the next build. This method removes + /// each aggregate after it sends the aggregate. The next build cannot reuse counts from + /// the completed request. /// internal void SendAggregatedEventsOnBuildFinished(ITelemetryClient? telemetry) { @@ -356,8 +353,8 @@ private static void TrackEvent(ITelemetryClient? telemetry, string eventName, ID if (telemetry is TelemetryClient telemetryClient) { - // This activity ends at BuildFinished, so production events must be attached before - // an exporter observes Activity.Stop. Test clients retain the ITelemetryClient seam. + // Add production events before BuildFinished stops the activity. + // Test clients use ITelemetryClient without a real telemetry client. telemetryClient.ThreadBlockingTrackEvent(eventName, properties ?? eventProperties); } else @@ -379,15 +376,14 @@ private void OnTelemetryLogged(object sender, TelemetryEventArgs args) } /// - /// Completes this MSBuild logger instance and drains its telemetry. + /// Completes this MSBuild logger instance and writes its diagnostic telemetry log. /// /// - /// BuildFinished is the normal activity boundary. The additional stop is an - /// idempotent fallback for aborted builds whose finish event was not delivered. - /// Exporter draining and diagnostic-log writing belong here rather than in - /// BuildFinished because MSBuild defines as the logger - /// completion hook. In a persistent server this does not imply process shutdown; the - /// process-wide telemetry client remains reusable by a later logger instance. + /// BuildFinished normally stops the build activity. also + /// stops the activity if an aborted build did not deliver BuildFinished. MSBuild + /// calls this method when the logger instance ends. The method waits for queued events + /// before it writes the diagnostic log. In a persistent server, logger shutdown does not + /// end the process. A later logger instance can reuse the process-wide telemetry client. /// public void Shutdown() { @@ -405,9 +401,9 @@ public void Shutdown() /// Stops only the activity owned by this logger and clears the reference. /// /// - /// The ambient parent belongs to the invoking host and must not be stopped here. - /// Clearing the field also makes cleanup safe when both BuildFinished and - /// run. + /// The invoking host owns the ambient parent activity. This method does not stop the + /// parent. Because this method clears the field, both BuildFinished and + /// can call it safely. /// private void StopActivity() { From 2d4b23d42b8f2442636f79c39a1cf36d102cba04 Mon Sep 17 00:00:00 2001 From: Chet Husk Date: Tue, 4 Aug 2026 09:52:04 -0500 Subject: [PATCH 8/8] Run MSBuild server telemetry test through dotnet Force the integration test to invoke the built dotnet CLI so Full Framework test lanes do not bypass the telemetry logger through Visual Studio MSBuild. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> Copilot-Session: f900a161-9261-47ee-823b-369cb6ee3cb7 --- test/dotnet.Tests/TelemetryTests/TelemetryClientTests.cs | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/test/dotnet.Tests/TelemetryTests/TelemetryClientTests.cs b/test/dotnet.Tests/TelemetryTests/TelemetryClientTests.cs index e535a3c86181..5fe1cc28815e 100644 --- a/test/dotnet.Tests/TelemetryTests/TelemetryClientTests.cs +++ b/test/dotnet.Tests/TelemetryTests/TelemetryClientTests.cs @@ -87,7 +87,8 @@ public void ItProcessesMSBuildTelemetryWithTheServerEnabled() try { - new BuildCommand(testAsset) + new DotnetCommand(Log, "build") + .WithWorkingDirectory(testAsset.TestRoot) .WithEnvironmentVariable("DOTNET_CLI_TELEMETRY_OPTOUT", "false") .WithEnvironmentVariable("DOTNET_CLI_TELEMETRY_DISABLE_TRACE_EXPORT", "true") .WithEnvironmentVariable("DOTNET_CLI_TELEMETRY_LOG_PATH", logFile) @@ -96,7 +97,8 @@ public void ItProcessesMSBuildTelemetryWithTheServerEnabled() .Should() .Pass(); - new BuildCommand(testAsset) + new DotnetCommand(Log, "build") + .WithWorkingDirectory(testAsset.TestRoot) .WithEnvironmentVariable("DOTNET_CLI_TELEMETRY_OPTOUT", "false") .WithEnvironmentVariable("DOTNET_CLI_TELEMETRY_DISABLE_TRACE_EXPORT", "true") .WithEnvironmentVariable("DOTNET_CLI_TELEMETRY_LOG_PATH", logFile)