trace2: add infrastructure and initial events #1045

ldennington · 2023-01-20T22:41:47Z

Add initial TRACE2 functionality, including:

Small refactorings to make TryGetAssemblyVersion accessible
outside of the DiagnosticCommand class and shared trace logic
accessible from a TraceUtils class.
Addition of a Trace2CollectorWriter class, which handles writing
to the Telemetry Tool/OTel collector and a Trace2StreamWriter class,
which handles writing to stderr/files.
Basic TRACE2 functionality, including the ability to add writers to
different format targets, logic to send messages to these writers, and
the ability to release these writers before application exit.
Support for session IDs.
Ability for users to enable normal/event format targets.
Writing Version, Start, and Exit events.

While this patch series does not represent all the TRACE2 events we plan
to implement, it does provide the opportunity to review and suggest changes
to the foundation these events are built on. It also provides the general pattern
that additional patches will use to implement new events, just in case that
needs to be tweaked.

derrickstolee

Thanks for helping me refresh my C#. Lots of good stuff in here.

src/shared/Core/CollectorWriter.cs

src/shared/Core/Trace2.cs

src/shared/Core/Constants.cs

src/shared/Core/Trace2.cs

src/shared/Core.Tests/SettingsTests.cs

src/shared/Core/ApplicationBase.cs

src/shared/Core/CollectorWriter.cs

src/shared/Core/CommandContext.cs

src/shared/Core/Trace2.cs

jeffhostetler · 2023-01-23T22:52:50Z

This looks like a good start. Thanks for all your work on this.

mjcheetham

Looking good so far! I have some comments about simplifying the collector/queue, going all in on GIT_ variables, and how we're instantiating Trace2 and the stopwatch.

src/shared/Core/CollectorWriter.cs

src/shared/Core/Trace2.cs

src/shared/Core/Constants.cs

src/shared/Core/ApplicationBase.cs

src/shared/Core/CommandContext.cs

src/shared/Git-Credential-Manager.UI.Avalonia/Program.cs

jeffhostetler · 2023-01-24T21:53:02Z

I just responded to all of Matthew's questions that I had an opinion on.

ldennington · 2023-01-26T22:10:25Z

Changes since v1:

CollectorWriter now inherits from DisposableObject.
Removed the GCM-specific TRACE2 and TRACE2_SID environment variables in favor of piggybacking off Git’s existing variables.
Updated comments on AddListener() to better describe its purpose.
Removed Stopwatch() in favor of calculating elapsed times using Unix timestamps. Additionally, updated times that were using DateTime.Now to DateTime.UtcNow.
Ensured event target parsing is correct for both Posix and Windows systems (using TrimUntilLastIndexOf and moved the logic into a new TryParseEventTarget() method in Trace2.cs. Handling for other event targets will happen in future PRs with their respective implementations.
Ensured there is always a version (even if it’s just a placeholder) to send to WriteVersion().
Ensured messages sent to the telemetry daemon/OTel collector always end with a line feed.
Ensured we’re making a call to WriteExit().
Fixed incorrect implementation of DisposableObject in Trace2.cs and CollectorWriter.cs.
Removed state from CollectorWriter in favor of a Failed flag.
Condensed Sid logic - updated method name from GetSid() to SetSid() and moved call to Trace2 constructor.
Ensured we are writing the correct args in WriteStart().

src/shared/Core.Tests/SettingsTests.cs

src/shared/Core/Trace2.cs

jeffhostetler · 2023-01-27T23:10:54Z

src/shared/Git-Credential-Manager/Program.cs

        public static void Main(string[] args)
        {
+            // Set up timer for TRACE2
+            var applicationStartTime = DateTimeOffset.UtcNow.ToUnixTimeSeconds();


I just made a comment in Trace2.c about moving all of the time-math into it, but I wanted to say that we should be careful converting UTC times to seconds -- we're measuring mili- and micro-second times and here we're lopping of the time to integer seconds. There is a To...Milliseconds() method that would be better (inside the WriteFOO() events).

That is assuming that there isn't a way to have the WriteFOO() methods subtract two DateTime values directly and get an elapsed TimeSpan expressed in a microsecond value and then format that as a time-in-seconds floating point value in the JSON event.

I think I've got an extension method that's doing what we want here. Let me know what you think.

ldennington · 2023-01-31T20:14:39Z

Changes since v2:

Removed local pipe variable from CollectorWriter Start() method.
Removed af_unix:./test.uds and //./pipe/ string literals from IsTrace2TracingEnabled test.
Updated all times to microseconds (with the help of a new DateTimeOffset extension ToUnixTimeMicroseconds).
Calculated elapsed time for Start and Exit events in the methods that write these events (rather than calculating in the caller(s)).

mjcheetham

A few comments I have so far

src/shared/Core/ITrace2Writer.cs

src/shared/Core/DateTimeOffsetExtensions.cs

src/shared/Core/CommandContext.cs

ldennington · 2023-02-07T19:08:54Z

Changes since v3:

Re-architected solution to more easily extend to additional event format targets and outputs (stderr/file). I have diagrammed the main components of the new solution in the hopes it’ll make it easier for reviewers to parse this PR (recommended to open in a separate window for viewing):
Added support for the normal format target.
Refactored shared Trace logic into a new TraceUtils class.
Re-organized calling of current events (Version, Start, and Exit) to occur via Start and Stop methods.
Updated application start time to be a DateTimeOffset rather than a long. This removed the need for a DateTimeOffsetExtensions class to convert to and from Unix time stamps.
Formatting updates to correctly write all events to different event format targets and outputs:
- Writing all file names and paths in lower case.
- Ensuring the Time field is the time at which the event is being written (rather than the application start time).
- Writing in local time for the normal format target and UTC time for the event format target.
- Ensuring line numbers are written as integers (rather than doubles).

The implementation of TRACE2 tracing will require use of the TryGetAssemblyVersion method. To prepare for this, move this method out of the DiagnoseCommand class and into its own static class.

The implementation of TRACE2 tracing will require truncation of long file names just as TRACE does. To prepare for this, move this logic out of the TRACE class and into its own method in a new static TraceUtils class. Additionally, add a unit test to validate this logic.

Add initial TRACE2 functionality, including: 1. The ability to add writers (which will eventually write to Normal, Perf, and Event format targets). 2. An abstract Trace2Message class. 3. Logic to send Trace2Messages to writers. 4. Ability to release writers prior to application exit.

Add the Trace2CollectorWriter class to accept Trace2 messages in the event target format and write them to the OTel Collector/Telemetry Service.

Add Trace2StreamWriter class which will be used to write to stderr or a file, based on the TextWriter that is passed to it. It will also adapt the output format based on the format target that is passed to it.

derrickstolee

I took a quick look through, and only had some nitpicks along the way.

However, one thing I was looking forward to seeing was a test that could demonstrate that the git-credential-manager executable would output the trace2 output (in event or normal form) as much as possible. The event form creates a JSON event on a per-line basis, so being able to parse that JSON even and checking that it has the necessary items would be helpful. (Any issues with extra items?)

src/shared/Core/Trace2.cs

src/shared/Git-Credential-Manager/Program.cs

A key component of Git's TRACE2 tracing system is the session id (sid). This identifies the process instance to allow all events emitted by it to be identified. We check to see if a parent sid (i.e. from a Git process) exists. If so, we separate this sid from the GCM sid (a GUID) using a "/". If there is no parent sid, we simply generate a GUID for the GCM sid and use that. The above also requires addition of a new SetEnvironmentVariable() method in EnvironmentBase.cs to set the GCM-specific SID variable.

Add the infrastructure to detect whether a user has enabled the TRACE2 event format or normal format targets. This implementation has been designed to be extended to include the perf format target in a future series. Additionally it involved some refactoring/cleanup to set the Application Path and InstallationDirectory in the CommandContext, rather than in GCM/UI helper Program.cs files.

derrickstolee

Looks like a strong foundation and anything from here on out can be forward-fixed as we get more use out of it (and an end-to-end testing framework).

Write the TRACE2 version event, which identifies the event format version (currently hardcoded as 3 as it is in Git) and the version of GCM. Additionally, write the TRACE2 start event, which reflects the elapsed time and application arguments (including the application name). These are paired because the telemetry tool/OTel collector require both these events to be sent for a given session.

Add TRACE2 exit event, following the pattern established with the version and start events.

jeffhostetler · 2023-02-10T16:52:54Z

You merged it as I was about to push the approve button.... :-)
This looks good. Nice work.
This will give us a chance to kick the tires now. Thanks.

ldennington requested review from mjcheetham and jeffhostetler January 20, 2023 22:41

ldennington self-assigned this Jan 20, 2023

derrickstolee reviewed Jan 23, 2023

View reviewed changes