trace2: add regions (#1162)

Add `TRACE2` region tracing capability.

The first six commits contain minor refactors, bug fixes, and cleanups.
The first moves Trace2 messages into their own file. The second removes
the unnecessary `AddDots()` method. The third fixes certain conflated
timing information in `child_start` and `child_exit` events. The fourth
ensures we're writing exit message times in UTC. The fifth adds
descriptive comments to Trace2-related classes that did not yet have
them. The sixth adds best-effort logic to capture thread names.

The next three commits are dedicated to preparing for and adding
region-related logic. The seventh commit updates custom performance
format span handling to account for the repo and category fields, which
are used in region tracing. The eighth adds region-related events,
encapsulated in a class that inherits from `DisposableObject` (which in
turn inherits from `IDisposable`). The ninth adds region tracing to
methods of interest pertaining to OAuth authentication.

The final commit updates GCM's documentation to inform users of how to
enable and utilize Trace2 tracing.

A final note: This implementation does not support nested regions, as it
is not required for the current regions of interest.

Author: ldennington

docs/development.md

@@ -98,6 +98,12 @@ Git to be the one launching us.
 
 ### Collect trace output
 
+GCM has two tracing systems - one that is distinctly GCM's and one that
+implements certain features of [Git's Trace2 API][trace2]. Below are
+instructions for how to use each.
+
+#### `GCM_TRACE`
+
 If you want to debug a release build or installation of GCM, you can set the
 `GCM_TRACE` environment variable to `1` to print trace information to standard
 error, or to an absolute file path to write trace information to a file.
@@ -110,6 +116,80 @@ $ GCM_TRACE=1 git-credential-manager version
 > Git Credential Manager version 2.0.124-beta+e1ebbe1517 (macOS, .NET 5.0)
 ```
 
+#### Git's Trace2 API
+
+This API can also be used to print debug, performance, and telemetry information
+to stderr or a file in various formats.
+
+##### Supported format targets
+
+1. The Normal Format Target: Similar to `GCM_TRACE`, this target writes
+human-readable output and is best suited for debugging. It can be enabled via
+environment variable or config, for example:
+
+    ```shell
+    export GIT_TRACE2=1
+    ```
+
+    or
+
+    ```shell
+    git config --global trace2.normalTarget ~/log.normal
+    ```
+
+0. The Performance Format Target: This format is column-based and geared toward
+analyzing performance during development and testing. It can be enabled via
+environment variable or config, for example:
+
+    ```shell
+    export GIT_TRACE2_PERF=1
+    ```
+
+    or
+
+    ```shell
+    git config --global trace2.perfTarget ~/log.perf
+    ```
+
+0. The Event Format Target: This format is json-based and is geared toward
+collection of large quantities of data for advanced analysis. It can be enabled
+via environment variable or config, for example:
+
+    ```shell
+    export GIT_TRACE2_EVENT=1
+    ```
+
+    or
+
+    ```shell
+    git config --global trace2.eventTarget ~/log.event
+    ```
+
+You can read more about each of these format targets in the [corresponding
+section][trace2-targets] of Git's Trace2 API documentation.
+
+##### Supported events
+
+The below describes, at a high level, the Trace2 API events that are currently
+supported in GCM and the information they provide:
+
+1. `version`: contains the version of the current executable (e.g. GCM or a
+helper exe)
+0. `start`: contains the complete argv received by current executable's `Main()`
+method
+0. `exit`: contains current executable's exit code
+0. `child_start`: describes a child process that is about to be spawned
+0. `child_exit`: describes a child process at exit
+0. `region_enter`: describes a region (e.g. a timer for a section of code that
+is interesting) on entry
+0. `region_leave`: describes a region on leaving
+
+You can read more about each of these format targets in the [corresponding
+section][trace2-events] of Git's Trace2 API documentation.
+
+Want to see more events? Consider contributing! We'd :love: to see your
+awesome work in support of building out this API.
+
 ### Code coverage metrics
 
 If you want code coverage metrics these can be generated either from the command
@@ -169,4 +249,7 @@ Some URLs are ignored by lychee, per the [lycheeignore][lycheeignore].
 [lycheeignore]: ../.lycheeignore
 [markdownlint]: https://github.com/DavidAnson/markdownlint-cli2
 [markdownlint-config]: ../.markdownlint.jsonc
+[trace2]: https://git-scm.com/docs/api-trace2
+[trace2-events]: https://git-scm.com/docs/api-trace2#_event_specific_keyvalue_pairs
+[trace2-targets]: https://git-scm.com/docs/api-trace2#_trace2_targets
 [vscode-markdownlint]: https://github.com/DavidAnson/vscode-markdownlint

src/shared/Core.Tests/Trace2MessageTests.cs

@@ -0,0 +1,38 @@
+using GitCredentialManager;
+using Xunit;
+
+namespace Core.Tests;
+
+public class Trace2MessageTests
+{
+    [Theory]
+    [InlineData(0.013772,     "  0.013772 ")]
+    [InlineData(26.316083,    " 26.316083 ")]
+    [InlineData(100.316083,   "100.316083 ")]
+    [InlineData(1000.316083,  "1000.316083")]
+    public void BuildTimeSpan_Match_Returns_Expected_String(double input, string expected)
+    {
+        var actual = Trace2Message.BuildTimeSpan(input);
+        Assert.Equal(expected, actual);
+    }
+
+    [Fact]
+    public void BuildRepoSpan_Match_Returns_Expected_String()
+    {
+        var input = 1;
+        var expected = " r1  ";
+        var actual = Trace2Message.BuildRepoSpan(input);
+        Assert.Equal(expected, actual);
+    }
+
+    [Theory]
+    [InlineData("foo",               " foo         ")]
+    [InlineData("foobar",            " foobar      ")]
+    [InlineData("foo_bar_baz",       " foo_bar_baz ")]
+    [InlineData("foobarbazfoo",      " foobarbazfo ")]
+    public void BuildCategorySpan_Match_Returns_Expected_String(string input, string expected)
+    {
+        var actual = Trace2Message.BuildCategorySpan(input);
+        Assert.Equal(expected, actual);
+    }
+}

src/shared/Core.Tests/Trace2Tests.cs

@@ -27,14 +27,4 @@ public void TryGetPipeName_Windows_Returns_Expected_Value(string input, string e
         Assert.True(isSuccessful);
         Assert.Matches(actual, expected);
     }
-
-    [Theory]
-    [InlineData(0.013772,    "  0.013772 ")]
-    [InlineData(26.316083,   " 26.316083 ")]
-    [InlineData(100.316083,  "100.316083 ")]
-    public void BuildTimeSpan_Match_Returns_Expected_String(double input, string expected)
-    {
-        var actual = Trace2Message.BuildTimeSpan(input);
-        Assert.Equal(expected, actual);
-    }
 }

src/shared/Core/Authentication/OAuth/OAuth2Client.cs

@@ -183,6 +183,9 @@ public async Task<OAuth2AuthorizationCodeResult> GetAuthorizationCodeAsync(IEnum
 
         public async Task<OAuth2DeviceCodeResult> GetDeviceCodeAsync(IEnumerable<string> scopes, CancellationToken ct)
         {
+            var label = "get device code";
+            using IDisposable region = _trace2.CreateRegion(OAuth2Constants.Trace2Category, label);
+
             if (_endpoints.DeviceAuthorizationEndpoint is null)
             {
                 throw new Trace2InvalidOperationException(_trace2,
@@ -218,6 +221,9 @@ public async Task<OAuth2DeviceCodeResult> GetDeviceCodeAsync(IEnumerable<string>
 
         public async Task<OAuth2TokenResult> GetTokenByAuthorizationCodeAsync(OAuth2AuthorizationCodeResult authorizationCodeResult, CancellationToken ct)
         {
+            var label = "get token by auth code";
+            using IDisposable region = _trace2.CreateRegion(OAuth2Constants.Trace2Category, label);
+
             var formData = new Dictionary<string, string>
             {
                 [OAuth2Constants.TokenEndpoint.GrantTypeParameter] = OAuth2Constants.TokenEndpoint.AuthorizationCodeGrantType,
@@ -254,6 +260,9 @@ public async Task<OAuth2TokenResult> GetTokenByAuthorizationCodeAsync(OAuth2Auth
 
         public async Task<OAuth2TokenResult> GetTokenByRefreshTokenAsync(string refreshToken, CancellationToken ct)
         {
+            var label = "get token by refresh token";
+            using IDisposable region = _trace2.CreateRegion(OAuth2Constants.Trace2Category, label);
+
             var formData = new Dictionary<string, string>
             {
                 [OAuth2Constants.TokenEndpoint.GrantTypeParameter] = OAuth2Constants.TokenEndpoint.RefreshTokenGrantType,

src/shared/Core/Authentication/OAuth/OAuth2Constants.cs

@@ -7,6 +7,7 @@ public static class OAuth2Constants
         public const string ClientSecretParameter = "client_secret";
         public const string RedirectUriParameter = "redirect_uri";
         public const string ScopeParameter = "scope";
+        public const string Trace2Category = "oauth2";
 
         public static class AuthorizationEndpoint
         {