diff --git a/docs/development.md b/docs/development.md index d64b20978..4637f4574 100644 --- a/docs/development.md +++ b/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 diff --git a/src/shared/Core.Tests/Trace2MessageTests.cs b/src/shared/Core.Tests/Trace2MessageTests.cs new file mode 100644 index 000000000..fd46e430a --- /dev/null +++ b/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); + } +} diff --git a/src/shared/Core.Tests/Trace2Tests.cs b/src/shared/Core.Tests/Trace2Tests.cs index 445c177e2..60d89ac2f 100644 --- a/src/shared/Core.Tests/Trace2Tests.cs +++ b/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); - } } diff --git a/src/shared/Core/Authentication/OAuth/OAuth2Client.cs b/src/shared/Core/Authentication/OAuth/OAuth2Client.cs index 39b1d8d14..8818581be 100644 --- a/src/shared/Core/Authentication/OAuth/OAuth2Client.cs +++ b/src/shared/Core/Authentication/OAuth/OAuth2Client.cs @@ -183,6 +183,9 @@ public async Task GetAuthorizationCodeAsync(IEnum public async Task GetDeviceCodeAsync(IEnumerable 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 GetDeviceCodeAsync(IEnumerable public async Task GetTokenByAuthorizationCodeAsync(OAuth2AuthorizationCodeResult authorizationCodeResult, CancellationToken ct) { + var label = "get token by auth code"; + using IDisposable region = _trace2.CreateRegion(OAuth2Constants.Trace2Category, label); + var formData = new Dictionary { [OAuth2Constants.TokenEndpoint.GrantTypeParameter] = OAuth2Constants.TokenEndpoint.AuthorizationCodeGrantType, @@ -254,6 +260,9 @@ public async Task GetTokenByAuthorizationCodeAsync(OAuth2Auth public async Task GetTokenByRefreshTokenAsync(string refreshToken, CancellationToken ct) { + var label = "get token by refresh token"; + using IDisposable region = _trace2.CreateRegion(OAuth2Constants.Trace2Category, label); + var formData = new Dictionary { [OAuth2Constants.TokenEndpoint.GrantTypeParameter] = OAuth2Constants.TokenEndpoint.RefreshTokenGrantType, diff --git a/src/shared/Core/Authentication/OAuth/OAuth2Constants.cs b/src/shared/Core/Authentication/OAuth/OAuth2Constants.cs index d630d0282..0b96a6047 100644 --- a/src/shared/Core/Authentication/OAuth/OAuth2Constants.cs +++ b/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 { diff --git a/src/shared/Core/Trace2.cs b/src/shared/Core/Trace2.cs index 1f5236097..d8eba64b5 100644 --- a/src/shared/Core/Trace2.cs +++ b/src/shared/Core/Trace2.cs @@ -1,12 +1,9 @@ using System; using System.Collections.Generic; -using System.ComponentModel; using System.IO; using System.IO.Pipes; using System.Text; -using Newtonsoft.Json; -using Newtonsoft.Json.Converters; -using Newtonsoft.Json.Serialization; +using System.Threading; namespace GitCredentialManager; @@ -22,6 +19,8 @@ public enum Trace2Event ChildStart = 3, ChildExit = 4, Error = 5, + RegionEnter = 6, + RegionLeave = 7, } /// @@ -35,12 +34,19 @@ public enum Trace2ProcessClass Other = 3 } +/// +/// Stores various TRACE2 format targets user has enabled. +/// Check for supported formats. +/// public class Trace2Settings { public IDictionary FormatTargetsAndValues { get; set; } = new Dictionary(); } +/// +/// Specifies a "text span" (i.e. space between two pipes) for the performance format target. +/// public class PerformanceFormatSpan { public int Size { get; set; } @@ -50,6 +56,40 @@ public class PerformanceFormatSpan public int EndPadding { get; set; } } +/// +/// Class that manages regions. +/// +public class Region : DisposableObject +{ + private readonly ITrace2 _trace2; + private readonly string _category; + private readonly string _label; + private readonly string _filePath; + private readonly int _lineNumber; + private readonly string _message; + private readonly DateTimeOffset _startTime; + + public Region(ITrace2 trace2, string category, string label, string filePath, int lineNumber, string message = "") + { + _trace2 = trace2; + _category = category; + _label = label; + _filePath = filePath; + _lineNumber = lineNumber; + _message = message; + + _startTime = DateTimeOffset.UtcNow; + + _trace2.WriteRegionEnter(_category, _label, _message, _filePath, _lineNumber); + } + + protected override void ReleaseManagedResources() + { + double relativeTime = (DateTimeOffset.UtcNow - _startTime).TotalSeconds; + _trace2.WriteRegionLeave(relativeTime, _category, _label, _message, _filePath, _lineNumber); + } +} + /// /// Represents the application's TRACE2 tracing system. /// @@ -107,14 +147,13 @@ void WriteChildStart(DateTimeOffset startTime, /// /// Writes information related to exit of child process to trace writer. /// - /// Runtime of child process. + /// Runtime of child process. /// Id of exiting process. /// Process exit code. - /// The child process's session id. /// Path of the file this method is called from. /// Line number of file this method is called from. void WriteChildExit( - double elapsedTime, + double relativeTime, int pid, int code, [System.Runtime.CompilerServices.CallerFilePath] @@ -136,6 +175,59 @@ void WriteError( string filePath = "", [System.Runtime.CompilerServices.CallerLineNumber] int lineNumber = 0); + + /// + /// Creates a region and manages entry/leaving. + /// + /// Category of region. + /// Description of region. + /// Message associated with entering region. + /// Path of the file this method is called from. + /// Line number of file this method is called from. + Region CreateRegion( + string category, + string label, + string message = "", + [System.Runtime.CompilerServices.CallerFilePath] + string filePath = "", + [System.Runtime.CompilerServices.CallerLineNumber] + int lineNumber = 0); + + /// + /// Writes a region enter message to the trace writer. + /// + /// Category of region. + /// Description of region. + /// Message associated with entering region. + /// Path of the file this method is called from. + /// Line number of file this method is called from. + void WriteRegionEnter( + string category, + string label, + string message = "", + [System.Runtime.CompilerServices.CallerFilePath] + string filePath = "", + [System.Runtime.CompilerServices.CallerLineNumber] + int lineNumber = 0); + + /// + /// Writes a region leave message to the trace writer. + /// + /// Time of region execution. + /// Category of region. + /// Description of region. + /// Message associated with entering region. + /// Path of the file this method is called from. + /// Line number of file this method is called from. + void WriteRegionLeave( + double relativeTime, + string category, + string label, + string message = "", + [System.Runtime.CompilerServices.CallerFilePath] + string filePath = "", + [System.Runtime.CompilerServices.CallerLineNumber] + int lineNumber = 0); } public class Trace2 : DisposableObject, ITrace2 @@ -230,18 +322,20 @@ public void WriteChildStart(DateTimeOffset startTime, Event = Trace2Event.ChildStart, Sid = _sid, Time = startTime, + Thread = BuildThreadName(), File = Path.GetFileName(filePath), Line = lineNumber, Id = ++_childProcCounter, Classification = processClass, UseShell = useShell, Argv = procArgs, - Depth = ProcessManager.Depth + ElapsedTime = (DateTimeOffset.UtcNow - _applicationStartTime).TotalSeconds, + Depth = ProcessManager.Depth, }); } public void WriteChildExit( - double elapsedTime, + double relativeTime, int pid, int code, string filePath = "", @@ -261,12 +355,14 @@ public void WriteChildExit( Event = Trace2Event.ChildExit, Sid = _sid, Time = DateTimeOffset.UtcNow, + Thread = BuildThreadName(), File = Path.GetFileName(filePath), Line = lineNumber, Id = _childProcCounter, Pid = pid, Code = code, - ElapsedTime = elapsedTime, + ElapsedTime = (DateTimeOffset.UtcNow - _applicationStartTime).TotalSeconds, + RelativeTime = relativeTime, Depth = ProcessManager.Depth }); } @@ -291,6 +387,7 @@ public void WriteError( Event = Trace2Event.Error, Sid = _sid, Time = DateTimeOffset.UtcNow, + Thread = BuildThreadName(), File = Path.GetFileName(filePath), Line = lineNumber, Message = errorMessage, @@ -299,6 +396,64 @@ public void WriteError( }); } + public Region CreateRegion( + string category, + string label, + string message, + string filePath, + int lineNumber) + { + return new Region(this, category, label, filePath, lineNumber, message); + } + + public void WriteRegionEnter( + string category, + string label, + string message = "", + string filePath = "", + int lineNumber = 0) + { + WriteMessage(new RegionEnterMessage() + { + Event = Trace2Event.RegionEnter, + Sid = _sid, + Time = DateTimeOffset.UtcNow, + Category = category, + Label = label, + Message = message == "" ? label : message, + Thread = BuildThreadName(), + File = Path.GetFileName(filePath), + Line = lineNumber, + ElapsedTime = (DateTimeOffset.UtcNow - _applicationStartTime).TotalSeconds, + Depth = ProcessManager.Depth + }); + } + + public void WriteRegionLeave( + double relativeTime, + string category, + string label, + string message = "", + string filePath = "", + int lineNumber = 0) + { + WriteMessage(new RegionLeaveMessage() + { + Event = Trace2Event.RegionLeave, + Sid = _sid, + Time = DateTimeOffset.UtcNow, + Category = category, + Label = label, + Message = message == "" ? label : message, + Thread = BuildThreadName(), + File = Path.GetFileName(filePath), + Line = lineNumber, + ElapsedTime = (DateTimeOffset.UtcNow - _applicationStartTime).TotalSeconds, + RelativeTime = relativeTime, + Depth = ProcessManager.Depth + }); + } + protected override void ReleaseManagedResources() { lock (_writersLock) @@ -384,6 +539,7 @@ private void WriteVersion( Event = Trace2Event.Version, Sid = _sid, Time = DateTimeOffset.UtcNow, + Thread = BuildThreadName(), File = Path.GetFileName(filePath), Line = lineNumber, Evt = eventFormatVersion, @@ -413,6 +569,7 @@ private void WriteStart( Event = Trace2Event.Start, Sid = _sid, Time = DateTimeOffset.UtcNow, + Thread = BuildThreadName(), File = Path.GetFileName(filePath), Line = lineNumber, Argv = argv, @@ -428,7 +585,8 @@ private void WriteExit(int code, string filePath = "", int lineNumber = 0) { Event = Trace2Event.Exit, Sid = _sid, - Time = DateTimeOffset.Now, + Time = DateTimeOffset.UtcNow, + Thread = BuildThreadName(), File = Path.GetFileName(filePath), Line = lineNumber, Code = code, @@ -475,407 +633,28 @@ private void WriteMessage(Trace2Message message) } } } -} - -public abstract class Trace2Message -{ - private const int SourceColumnMaxWidth = 23; - private const string NormalPerfTimeFormat = "HH:mm:ss.ffffff"; - - protected const string EmptyPerformanceSpan = "| | | | "; - protected const string TimeFormat = "yyyy'-'MM'-'dd'T'HH':'mm':'ss'.'ffffff'Z'"; - - [JsonProperty("event")] - public Trace2Event Event { get; set; } - - [JsonProperty("sid")] - public string Sid { get; set; } - - // TODO: Remove this default value when TRACE2 regions are introduced. - [JsonProperty("thread")] - public string Thread { get; set; } = "main"; - - [JsonProperty("time")] - public DateTimeOffset Time { get; set; } - - [JsonProperty("file")] - - public string File { get; set; } - - [JsonProperty("line")] - public int Line { get; set; } - - [JsonProperty("depth")] - public int Depth { get; set; } - - public abstract string ToJson(); - - public abstract string ToNormalString(); - - public abstract string ToPerformanceString(); - - protected abstract string BuildPerformanceSpan(); - - protected string BuildNormalString() - { - string message = GetEventMessage(Trace2FormatTarget.Normal); - - // The normal format uses local time rather than UTC time. - string time = Time.ToLocalTime().ToString(NormalPerfTimeFormat); - string source = GetSource(); - - // Git's TRACE2 normal format is: - // [