Create System.Diagnostic.Activity spans for parsing and invocation of S.CL commands

Directory.Packages.props

@@ -24,7 +24,8 @@
     <PackageVersion Include="Microsoft.CSharp" Version="4.7.0" />
     <PackageVersion Include="Microsoft.DotNet.PlatformAbstractions" Version="3.1.6" />
     <PackageVersion Include="Newtonsoft.Json" Version="13.0.2" />
-    <PackageVersion Include="System.Memory" Version="4.5.4" />
+    <PackageVersion Include="System.Memory" Version="4.5.5" />
+    <PackageVersion Include="System.Diagnostics.DiagnosticSource" Version="8.0.0" />
     <PackageVersion Include="system.reactive.core" Version="5.0.0" />
   </ItemGroup>
 

eng/SourceBuildPrebuiltBaseline.xml

@@ -7,4 +7,7 @@
          build because it will be retrieved from the N-1 artifacts. -->
     <UsagePattern IdentityGlob="Microsoft.NET.ILLink.Tasks/8.*" />
   </IgnorePatterns>
-</UsageData>
+  <Usages>
+    <Usage Id="System.Diagnostics.DiagnosticSource" Version="8.0.0" />
+  </Usages>
+</UsageData>

src/System.CommandLine.Tests/ObservabilityTests.cs

@@ -0,0 +1,131 @@
+using System.CommandLine.Parsing;
+using FluentAssertions;
+using System.Linq;
+using Xunit;
+using System.Diagnostics;
+using System.Collections.Generic;
+using System.Threading.Tasks;
+using Xunit.Abstractions;
+
+namespace System.CommandLine.Tests
+{
+    public class ObservabilityTests
+    {
+        private readonly ITestOutputHelper log;
+
+        public ObservabilityTests(ITestOutputHelper output)
+        {
+            log = output;
+        }
+
+        [Fact]
+        public void It_creates_activity_spans_for_parsing()
+        {
+            var (listener, activities) = SetupListener();
+
+            var command = new Command("the-command")
+            {
+                new Option<string>("--option")
+            };
+
+            var args = new[] { "--option", "the-argument" };
+
+            var result = command.Parse(args);
+            listener.Dispose();
+            activities
+                    .Should()
+                    .ContainSingle(
+                        a => a.OperationName == "System.CommandLine.Parse"
+                             && a.Status == ActivityStatusCode.Ok
+                             && a.Tags.Any(t => t.Key == "command" && t.Value == "the-command"));
+        }
+
+        [Fact]
+        public void It_creates_activity_spans_for_parsing_errors()
+        {
+            var (listener, activities) = SetupListener();
+
+            var command = new Command("the-command")
+            {
+                new Option<string>("--option")
+            };
+
+            var args = new[] { "--opt", "the-argument" };
+            var result = command.Parse(args);
+            listener.Dispose();
+            activities
+                    .Should()
+                    .ContainSingle(
+                        a => a.OperationName == "System.CommandLine.Parse"
+                             && a.Status == ActivityStatusCode.Error
+                             && a.Tags.Any(t => t.Key == "command" && t.Value == "the-command")
+                             && a.Baggage.Any(t => t.Key == "errors"));
+        }
+
+        [Fact]
+        public async Task It_creates_activity_spans_for_invocations()
+        {
+            var (listener, activities) = SetupListener();
+
+            var command = new Command("the-command");
+            command.SetAction(async (pr, ctok) => await Task.FromResult(0));
+
+            var result = await command.Parse(Array.Empty<string>()).InvokeAsync();
+            listener.Dispose();
+
+            activities
+                    .Should()
+                    .ContainSingle(
+                        a => a.OperationName == "System.CommandLine.Invoke"
+                             && a.DisplayName == "the-command"
+                             && a.Status == ActivityStatusCode.Ok
+                             && a.Tags.Any(t => t.Key == "command" && t.Value == "the-command")
+                             && a.Tags.Any(t => t.Key == "invoke.type" && t.Value == "async")
+                             && a.TagObjects.Any(t => t.Key == "exitcode" && (int)t.Value == 0));
+        }
+
+        [Fact]
+        public async Task It_creates_activity_spans_for_invocation_errors()
+        {
+            var (listener, activities) = SetupListener();
+
+            var command = new Command("the-command");
+#pragma warning disable CS1998 // Async method lacks 'await' operators and will run synchronously
+            command.SetAction(async (pr, ctok) =>
+            {
+                throw new Exception("Something went wrong");
+            });
+#pragma warning restore CS1998 // Async method lacks 'await' operators and will run synchronously
+
+            var result = await command.Parse(Array.Empty<string>()).InvokeAsync();
+            listener.Dispose();
+
+            foreach (var x in activities)
+            {
+                log.WriteLine($"{x.DisplayName}({x.OperationName})/{x.Status}({x.Duration}) - {x.TagObjects} - {string.Join(",", x.Events.Select((k) => $"{k.Name},{k.Tags}"))}");
+            }
+
+            activities
+                    .Should()
+                    .ContainSingle(
+                        a => a.OperationName == "System.CommandLine.Invoke"
+                             && a.DisplayName == "the-command"
+                             && a.Status == ActivityStatusCode.Error
+                             && a.Tags.Any(t => t.Key == "command" && t.Value == "the-command")
+                             && a.Tags.Any(t => t.Key == "invoke.type" && t.Value == "async")
+                             && a.TagObjects.Any(t => t.Key == "exitcode" && (int)t.Value == 1)
+                             && a.Events.Any(t => t.Name == "exception"));
+        }
+
+        private static (ActivityListener, List<Activity>) SetupListener()
+        {
+            List<Activity> activities = new();
+            var listener = new ActivityListener();
+            listener.ShouldListenTo = s => true;
+            listener.Sample = (ref ActivityCreationOptions<ActivityContext> options) => ActivitySamplingResult.AllData;
+            listener.ActivityStopped = a => activities.Add(a);
+            ActivitySource.AddActivityListener(listener);
+            return new(listener, activities);
+        }
+    }
+}

src/System.CommandLine/Activities.cs

@@ -0,0 +1,46 @@
+using System.Diagnostics;
+
+namespace System.CommandLine;
+
+internal static class DiagnosticsStrings
+{
+    internal const string LibraryNamespace = "System.CommandLine";
+    internal const string ParseMethod = LibraryNamespace + ".Parse";
+    internal const string InvokeMethod = LibraryNamespace + ".Invoke";
+    internal const string InvokeType = "invoke.type";
+    internal const string Async = "async";
+    internal const string Sync = "sync";
+    internal const string ExitCode = "exitcode";
+    internal const string Exception = "exception";
+    internal const string Errors = "errors";
+    internal const string Command = "command";
+}
+
+internal static class Activities
+{
+    internal static readonly ActivitySource ActivitySource = new ActivitySource(DiagnosticsStrings.LibraryNamespace);
+}
+
+internal static class ActivityExtensions
+{
+
+    /// <summary>
+    /// Walks up the command tree to get the build the command name by prepending the parent command names to the 'leaf' command name.
+    /// </summary>
+    /// <param name="commandResult"></param>
+    /// <returns>The full command name, like 'dotnet package add'.</returns>
+    internal static string FullCommandName(this Parsing.CommandResult commandResult)
+    {
+        var command = commandResult.Command;
+        var path = command.Name;
+
+        while (commandResult.Parent is Parsing.CommandResult parent)
+        {
+            command = parent.Command;
+            path = $"{command.Name} {path}";
+            commandResult = parent;
+        }
+
+        return path;
+    }
+}

src/System.CommandLine/Invocation/InvocationPipeline.cs

@@ -1,6 +1,7 @@
 // Copyright (c) .NET Foundation and contributors. All rights reserved.
 // Licensed under the MIT license. See LICENSE file in the project root for full license information.
 
+using System.Runtime.CompilerServices;
 using System.Threading;
 using System.Threading.Tasks;
 
@@ -10,8 +11,17 @@ internal static class InvocationPipeline
     {
         internal static async Task<int> InvokeAsync(ParseResult parseResult, CancellationToken cancellationToken)
         {
+            using var invokeActivity = Activities.ActivitySource.StartActivity(DiagnosticsStrings.InvokeMethod);
+            if (invokeActivity is not null)
+            {
+                invokeActivity.DisplayName = parseResult.CommandResult.FullCommandName();
+                invokeActivity.AddTag(DiagnosticsStrings.Command, parseResult.CommandResult.Command.Name);
+                invokeActivity.AddTag(DiagnosticsStrings.InvokeType, DiagnosticsStrings.Async);
+            }
+
             if (parseResult.Action is null)
             {
+                invokeActivity?.SetStatus(Diagnostics.ActivityStatusCode.Error);
                 return ReturnCodeForMissingAction(parseResult);
             }
 
@@ -41,7 +51,9 @@ internal static async Task<int> InvokeAsync(ParseResult parseResult, Cancellatio
                 switch (parseResult.Action)
                 {
                     case SynchronousCommandLineAction syncAction:
-                        return syncAction.Invoke(parseResult);
+                        var syncResult = syncAction.Invoke(parseResult);
+                        invokeActivity?.SetExitCode(syncResult);
+                        return syncResult;
 
                     case AsynchronousCommandLineAction asyncAction:
                         var startedInvocation = asyncAction.InvokeAsync(parseResult, cts.Token);
@@ -52,23 +64,30 @@ internal static async Task<int> InvokeAsync(ParseResult parseResult, Cancellatio
 
                         if (terminationHandler is null)
                         {
-                            return await startedInvocation;
+                            var asyncResult = await startedInvocation;
+                            invokeActivity?.SetExitCode(asyncResult);
+                            return asyncResult;
                         }
                         else
                         {
                             // Handlers may not implement cancellation.
                             // In such cases, when CancelOnProcessTermination is configured and user presses Ctrl+C,
                             // ProcessTerminationCompletionSource completes first, with the result equal to native exit code for given signal.
                             Task<int> firstCompletedTask = await Task.WhenAny(startedInvocation, terminationHandler.ProcessTerminationCompletionSource.Task);
-                            return await firstCompletedTask; // return the result or propagate the exception
+                            var asyncResult = await firstCompletedTask;  // return the result or propagate the exception
+                            invokeActivity?.SetExitCode(asyncResult);
+                            return asyncResult;
                         }
 
                     default:
-                        throw new ArgumentOutOfRangeException(nameof(parseResult.Action));
+                        var error = new ArgumentOutOfRangeException(nameof(parseResult.Action));
+                        invokeActivity?.Error(error);
+                        throw error;
                 }
             }
             catch (Exception ex) when (parseResult.Configuration.EnableDefaultExceptionHandler)
             {
+                invokeActivity?.Error(ex);
                 return DefaultExceptionHandler(ex, parseResult.Configuration);
             }
             finally
@@ -79,9 +98,18 @@ internal static async Task<int> InvokeAsync(ParseResult parseResult, Cancellatio
 
         internal static int Invoke(ParseResult parseResult)
         {
+            using var invokeActivity = Activities.ActivitySource.StartActivity(DiagnosticsStrings.InvokeMethod);
+            if (invokeActivity is not null)
+            {
+                invokeActivity.DisplayName = parseResult.CommandResult.FullCommandName();
+                invokeActivity.AddTag(DiagnosticsStrings.Command, parseResult.CommandResult.Command.Name);
+                invokeActivity.AddTag(DiagnosticsStrings.InvokeType, DiagnosticsStrings.Sync);
+            }
+
             switch (parseResult.Action)
             {
                 case null:
+                    invokeActivity?.Error();
                     return ReturnCodeForMissingAction(parseResult);
 
                 case SynchronousCommandLineAction syncAction:
@@ -112,15 +140,20 @@ internal static int Invoke(ParseResult parseResult)
                             }
                         }
 
-                        return syncAction.Invoke(parseResult);
+                        var result = syncAction.Invoke(parseResult);
+                        invokeActivity?.SetExitCode(result);
+                        return result;
                     }
                     catch (Exception ex) when (parseResult.Configuration.EnableDefaultExceptionHandler)
                     {
+                        invokeActivity?.Error(ex);
                         return DefaultExceptionHandler(ex, parseResult.Configuration);
                     }
 
                 default:
-                    throw new InvalidOperationException($"{nameof(AsynchronousCommandLineAction)} called within non-async invocation.");
+                    var error = new InvalidOperationException($"{nameof(AsynchronousCommandLineAction)} called within non-async invocation.");
+                    invokeActivity?.Error(error);
+                    throw error;
             }
         }
 
@@ -150,5 +183,43 @@ private static int ReturnCodeForMissingAction(ParseResult parseResult)
                 return 0;
             }
         }
+
+        private static void Succeed(this Diagnostics.Activity activity)
+        {
+            activity.SetStatus(Diagnostics.ActivityStatusCode.Ok);
+            activity.AddTag(DiagnosticsStrings.ExitCode, 0);
+        }
+        private static void Error(this Diagnostics.Activity activity, int statusCode)
+        {
+            activity.SetStatus(Diagnostics.ActivityStatusCode.Error);
+            activity.AddTag(DiagnosticsStrings.ExitCode, statusCode);
+        }
+
+        private static void Error(this Diagnostics.Activity activity, Exception? exception = null)
+        {
+            activity.SetStatus(Diagnostics.ActivityStatusCode.Error);
+            activity.AddTag(DiagnosticsStrings.ExitCode, 1);
+            if (exception is not null)
+            {
+                var tagCollection = new Diagnostics.ActivityTagsCollection
+                {
+                    { DiagnosticsStrings.Exception, exception.ToString() }
+                };
+                var evt = new Diagnostics.ActivityEvent(DiagnosticsStrings.Exception, tags: tagCollection);
+                activity.AddEvent(evt);
+            }
+        }
+
+        private static void SetExitCode(this Diagnostics.Activity activity, int exitCode)
+        {
+            if (exitCode == 0)
+            {
+                activity.Succeed();
+            }
+            else
+            {
+                activity.Error(exitCode);
+            }
+        }
     }
 }

src/System.CommandLine/ParseResult.cs

@@ -236,6 +236,7 @@ public Task<int> InvokeAsync(CancellationToken cancellationToken = default)
         /// <returns>A value that can be used as a process exit code.</returns>
         public int Invoke()
         {
+
             var useAsync = false;
 
             if (Action is AsynchronousCommandLineAction)

src/System.CommandLine/Parsing/CommandLineParser.cs

@@ -146,6 +146,8 @@ private static ParseResult Parse(
                 throw new ArgumentNullException(nameof(arguments));
             }
 
+            using var parseActivity = Activities.ActivitySource.StartActivity(DiagnosticsStrings.ParseMethod);
+
             configuration ??= new CommandLineConfiguration(command);
 
             arguments.Tokenize(
@@ -160,7 +162,18 @@ private static ParseResult Parse(
                 tokenizationErrors,
                 rawInput);
 
-            return operation.Parse();
+            var result = operation.Parse();
+            parseActivity?.SetTag(DiagnosticsStrings.Command, result.CommandResult?.Command.Name);
+            if (result.Errors.Count > 0)
+            {
+                parseActivity?.SetStatus(Diagnostics.ActivityStatusCode.Error);
+                parseActivity?.AddBaggage(DiagnosticsStrings.Errors, string.Join("\n", result.Errors.Select(e => e.Message)));
+            }
+            else
+            {
+                parseActivity?.SetStatus(Diagnostics.ActivityStatusCode.Ok);
+            }
+            return result;
         }
 
         private enum Boundary