diff --git a/.github/copilot-instructions.md b/.github/copilot-instructions.md index 48adec2c9a9a..725ef5c1a9ac 100644 --- a/.github/copilot-instructions.md +++ b/.github/copilot-instructions.md @@ -68,10 +68,21 @@ 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 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 60d97f1ccd24..eddbcb90bf33 100644 --- a/documentation/project-docs/developer-guide.md +++ b/documentation/project-docs/developer-guide.md @@ -57,6 +57,25 @@ 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 + +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`. 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 ### Windows diff --git a/documentation/project-docs/telemetry.md b/documentation/project-docs/telemetry.md index d4451908ecf5..3a563b552e9a 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 +[`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` **When fired**: When target framework is evaluated diff --git a/src/Cli/AGENTS.md b/src/Cli/AGENTS.md index e2f4d778245c..aca1a8abaa4f 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 has three process entry points of equal importance: + +| Entry point | Source | Host and lifecycle | +|-------------|--------|--------------------| +| 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 A `dotnet` command or option spans three cooperating projects: diff --git a/src/Cli/dotnet/CommandFactory/CommandResolution/ActivityContextFactory.cs b/src/Cli/dotnet/CommandFactory/CommandResolution/ActivityContextFactory.cs index bd8616a1e06a..7499d491ec84 100644 --- a/src/Cli/dotnet/CommandFactory/CommandResolution/ActivityContextFactory.cs +++ b/src/Cli/dotnet/CommandFactory/CommandResolution/ActivityContextFactory.cs @@ -29,7 +29,14 @@ public static class ActivityContextFactory #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; } 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 d6175487222e..e2b242091543 100644 --- a/src/Cli/dotnet/Commands/MSBuild/MSBuildLogger.cs +++ b/src/Cli/dotnet/Commands/MSBuild/MSBuildLogger.cs @@ -1,17 +1,47 @@ // 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; +/// +/// 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. 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 { + /// + /// The process-wide telemetry client used by this logger instance. + /// + /// + /// 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; + /// + /// The activity owned by the current build. + /// + /// + /// 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; + internal const string TargetFrameworkTelemetryEventName = "targetframeworkeval"; internal const string BuildTelemetryEventName = "build"; internal const string LoggingConfigurationTelemetryEventName = "loggingConfiguration"; @@ -59,16 +89,28 @@ public sealed class MSBuildLogger : INodeLogger /// private Dictionary> _aggregatedEvents = new(); + /// + /// Initializes telemetry for the process hosting the logger. + /// + /// + /// 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() { try { 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) { @@ -84,11 +126,27 @@ internal MSBuildLogger(ITelemetryClient telemetry) _telemetry = telemetry; } + /// + /// Connects this node logger to MSBuild's event lifecycle. + /// + /// + /// 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) { Initialize(eventSource); } + /// + /// Connects this logger to the events needed to collect telemetry and delimit a build. + /// + /// + /// 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) { // Declare lack of dependency on having properties/items in ProjectStarted events @@ -106,6 +164,8 @@ public void Initialize(IEventSource eventSource) { eventSource2.TelemetryLogged += OnTelemetryLogged; } + + eventSource.BuildStarted += OnBuildStarted; } eventSource.BuildFinished += OnBuildFinished; @@ -116,11 +176,52 @@ public void Initialize(IEventSource eventSource) } } + /// + /// Starts the activity that contains telemetry for one MSBuild request. + /// + /// + /// 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) + { + ActivityContext parentContext = + Activity.Current?.Context + ?? TelemetryClient.GetParentActivityContext() + ?? TelemetryClient.ParentActivityContext; + _activity = Activities.Source.StartActivity( + "msbuild", + ActivityKind.Internal, + parentContext); + } + + /// + /// Completes telemetry and activity state for one MSBuild 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) { SendAggregatedEventsOnBuildFinished(_telemetry); + _activity?.SetStatus(e.Succeeded ? ActivityStatusCode.Ok : ActivityStatusCode.Error); + StopActivity(); } + /// + /// Emits telemetry that is intentionally accumulated across nodes during a build. + /// + /// + /// 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) { if (telemetry is null) return; @@ -250,7 +351,16 @@ private static void TrackEvent(ITelemetryClient? telemetry, string eventName, ID } } - telemetry?.TrackEvent(eventName, properties ?? eventProperties); + if (telemetry is TelemetryClient telemetryClient) + { + // Add production events before BuildFinished stops the activity. + // Test clients use ITelemetryClient without a real telemetry client. + telemetryClient.ThreadBlockingTrackEvent(eventName, properties ?? eventProperties); + } + else + { + telemetry?.TrackEvent(eventName, properties ?? eventProperties); + } } private void OnTelemetryLogged(object sender, TelemetryEventArgs args) @@ -265,8 +375,40 @@ private void OnTelemetryLogged(object sender, TelemetryEventArgs args) } } + /// + /// Completes this MSBuild logger instance and writes its diagnostic telemetry log. + /// + /// + /// 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() { + StopActivity(); + + if (_telemetry is TelemetryClient telemetryClient) + { + telemetryClient.WaitForPendingEvents(); + } + + TelemetryClient.WriteLogIfNecessary(); + } + + /// + /// Stops only the activity owned by this logger and clears the reference. + /// + /// + /// 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() + { + _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..51f374321529 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; @@ -173,6 +177,9 @@ public TelemetryClient(string? sessionId, IEnvironmentProvider? environmentProvi 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. @@ -204,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 @@ -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..ffbe4f1fa893 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 activities) { 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) + + foreach (var activity in activities) { 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..ad03dba3b89f 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,95 @@ 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); + } + + [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..ba21c406136f 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}-{(byte)activity.Context.TraceFlags:x2}"); + 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 f53c7e6fc782..5fe1cc28815e 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,127 @@ 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 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) + .WithEnvironmentVariable("MSBUILDUSESERVER", "1") + .Execute() + .Should() + .Pass(); + + 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) + .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) + .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 + { + ShutdownMSBuildServer(testAsset.TestRoot); + } + } + + [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() + { + 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 +250,13 @@ public void ItPrefersExplicitSessionIdOverEnvironmentSeed() TelemetryClient.DisabledForTests = true; } } + + private void ShutdownMSBuildServer(string workingDirectory) + { + new BuildServerCommand(Log) + .WithWorkingDirectory(workingDirectory) + .Execute("shutdown", "--msbuild") + .Should() + .Pass(); + } }