trace2: add child start and exit events

[ldennington]

This change adds the child_start and child_exit events to GCM's TRACE2 tracing system.

The first two patches are small bug fixes. The first fix ensures all events are written in snake case. Up until this point, we've only written single word events, but the TRACE2 convention for multi-word events is to write in snake case, so for simplicity we update all events to use this convention. The second fix ensures we do not redirect standard error for Git-related processes, as this causes deadlocks with TRACE2 tracing enabled.

The third patch contains a refactor of the Trace2 class necessary to support child_start and child_exit.
The main change is addition of an Initialize() method to Trace2.cs to detect whether TRACE2 tracing is enabled and to set long-lived variables. This also sets a new _initialized property that allows us to determine whether TRACE2 tracing has been initialized. GCM TRACE2 tracing is disabled until _initialized is set to true by the Initialize() method (although it is worth noting that Git's TRACE2 tracing is not disabled and will be reflected in logs).

The third patch pulls Sid-related logic into a separate SidManager class to improve separation of concerns and make Sid logic less error-prone/easier to reason about.

The fourth patch adds a ChildProcess class that wraps Process and gives us the required control to write process-related TRACE2 events. It also decouples process-related logic from environment logic to maintain a functional, non-circular order of dependencies with the new wrapper. All Process invocations have been updated to use ChildProcess.

The fifth patch adds the appropriate Trace2 methods to write child_start and child_exit events.

[jeffhostetler]

I'm not sure I understand what you're doing with the SidManager class. A first skim makes me think
you're making it more complicated that it needs to be.

Basically, when your process starts it needs to read the value of GIT_TRACE2_PARENT_SID from the
environment. That is GCM.exe's parent's SID. In GCM.exe (or in any of the helper exe's), read that
value, append a GUID (prepended with a slash if the parent's is not empty), and save that in a process
global AND update the value of GIT_TRACE2_PARENT_SID in the environment of your process
(so that any child processes that you create will inherit the new value).

Then if GCM.exe launches SomeUI.exe, SomeUI.exe will inherit that extended value. (If you pass
an explicit environment vector to CreateProcess() rather than letting the child inherit, use the
updated SID value. Then when the SomeUI.exe runs, the value of GIT_TRACE2_PARENT_SID that
IT sees will be that of GCM.exe and it can add it's own "/" when the UI process creates
its own SID (and sets a global and updates its environment).

The net-net is that you don't need to build custom SIDs for each child nor do any other SID
manipulation. Just set up yours and let the children set up theirs. (That's assuming that I
understood the code, which I'm beginning to doubt...)

I'm not sure I understood the thread references in the commit message.

I'm also concerned about how the different uses of the SidManager.Append() and .Remove()
calls. They are updating global state. Which makes me think there needs to be locking, but
again, I'm not sure how these calls are used. In the way I describe above, the ctor() and Append()
would only be called once from main() in GCM.exe and never updated again, so we wouldn't need
locking.

[ldennington]

I'm not sure I understand what you're doing with the SidManager class. A first skim makes me think you're making it more complicated that it needs to be.

You were right - I went ahead and dropped that commit. The sid for a child process is now appended using the SetSid method, called from the ChildProcess class to ensure that it can be passed to each child process-related Trace2 method.

We could also set the sid in Trace2.cs, but then we'd have to modify Trace2's _sid variable both to append to the child process GUID and remove the appended value which felt a bit messy/dangerous.

[mjcheetham]

Looking good so far! I have some comments initially after a first pass.

[jeffhostetler]

I'm not sure I understand what you're doing with the SidManager class. A first skim makes me think you're making it more complicated that it needs to be.

You were right - I went ahead and dropped that commit. The sid for a child process is now appended using the SetSid method, called from the ChildProcess class to ensure that it can be passed to each child process-related Trace2 method.

We could also set the sid in Trace2.cs, but then we'd have to modify Trace2's _sid variable both to append to the child process GUID and remove the appended value which felt a bit messy/dangerous.

I think the solution is actually simpler than this. All events generated by the GCM.exe process
should have the same SID on them. The child_start and child_exit events are written from
the point of view of the invoking process (in this case GCM.exe) -- in a sense, GCM is saying that
IT is creating a child process (and may or may not wait for it to finish) and here are the args
that it is using. This is the "outer span" on the lifetime of the child process. That is, the
time from CreateProcess() thru WaitForSingleObject(). I digress, the point is that the SID needs
to be that of GCM.exe so that we can attach it to GCM's trace graph.

The child process itself should receive the inherited parent-SID and compute it's own and use that
for the child's events. So when the child process does it's version, start, and exit events
with the child's new SID, we get the "internal span" on the lifetime of the child process. That is,
the internal time between main() and exit()/return. The child's data with the child's SID will be
used to create a new and independent trace graph for the child's lifetime.

The two trace graphs will be stitched together in the datastore after both have been converted
to OTLP (using OTel TraceIDs/SpanIDs synthesized from the two SIDs). (And the outer and
inner lifetime spans will be adjacent, but distinct, in the combined graph.)

If the child process is not Trace2-aware, then there will not be a child trace graph for it,
so the parent trace graph needs to be self-sufficient. That is, we'll only see the outer span.
Which is the case for Git hooks which are usually shell scripts. But there's nothing we can
do about that.

Anyway, hope this helps. And sorry for the confusion.

[jeffhostetler]

I don't understand the need for any of the snake casing changes, but then again, my C# is rusty.

It seems to me that we could (a) continue with the existing model and just add new events to the enum:

public enum Trace2Event {
    [EnumMember(Value = "version")]
    Version,
    ...
    [EnumMember(Value = "child_start")]
    ChildStart,
    ...
}

Or (b) since the set of enums is very fixed and not changing and we already have to have a
per-event Trace2Message derived class (like StartMessage), we could just have a
static const string event name field in each of those derived classes set to the string literal
of the event name. Then have the ToJson() or ToNormal() formatters just reference
the constant or pass it to the formatters in the abstract class.

Or (c) do (b) and update the Event property getter in the abstract class to call a function
to get the string constant from the derived class.

[mjcheetham]

The child process itself should receive the inherited parent-SID and compute it's own and use that
for the child's events. So when the child process does it's version, start, and exit events
with the child's new SID, we get the "internal span" on the lifetime of the child process. That is,
the internal time between main() and exit()/return. The child's data with the child's SID will be
used to create a new and independent trace graph for the child's lifetime.

Just to check my understanding here, this would look like this in pseudo GCM code?

// Program.cs
static void Main(string[] args)
{
    using var context = new CommandContext();
    using var app = new Application(context);

    context.Trace2.Initialize(context.Environment, context.Settings.GetTrace2Settings(), DateTimeOffset.UtcNow);
    context.Trace2.Start(context.ApplicationPath, args);

    var exitCode = app.RunAsync(args)....;

    context.Trace2.Stop(exitCode);
}

// CommandContext.cs
public CommandContext()
{
    ...
    Trace2 = new Trace2();
    ...
}

// Trace2.cs
private string _sid;

public void Initialize(IEnvironment env, ...)
{
    ...
    _sid = CreateSid(env);
    env.SetEnvironmentVariable("GIT_TRACE2_PARENT_SID", _sid);
}

private static string CreateSid(IEnvironment env)
{
    if (env.Variables.TryGet("GIT_TRACE2_PARENT_SID", out string parentSid))
    {
        // We are a child process; append to the parent to create our new SID
        return $"{parentSid}/{Guid.NewGuid():D}";
    }
    else
    {
        // We are the root process; create our own 'root' SID
        return Guid.NewGuid().ToString("D");
    }
}

public void Start(...)
{
    ...
    WriteVersion(...);
    ...
}

private void WriteVersion(...)
{
    WriteMessage(
        new VersionMessage(...)
        {
            Sid = _sid
        }
    );
}

public void WriteChildStart(...)
{
    WriteMessage(
        new ChildStartMessage(...)
        {
            Sid = _sid // this is OUR sid, the child will compute its own
        }
    );
}

[mjcheetham]

Or (b) since the set of enums is very fixed and not changing and we already have to have a
per-event Trace2Message derived class (like StartMessage), we could just have a
static const string event name field in each of those derived classes set to the string literal
of the event name. Then have the ToJson() or ToNormal() formatters just reference
the constant or pass it to the formatters in the abstract class.

Something like this shouldn't be too hard to maintain?

private static string GetEventName(Trace2Event event)
{
    return event switch
    {
        Trace2Event.Version => "version",
        Trace2Event.ChildStart => "child_start",
        ...
        _ => throw new ArgumentOutOfRangeException()
// OR if we don't want to die..
        _ => event.ToString()
    };
}

[jeffhostetler]

WRT the SID computation, yes.

I saw your note over the weekend and realized that perhaps the original confusion lies in my use of English when naming the event -- a noun-verb vs verb-noun issue, if you will. Think of the "child-start" event as "i'm-starting-a-child" and likewise for "child-exit" is actually a "my-child-exited-with-code". The parent emits those events and does so with it's SID. If the child is Trace2-aware, it will create it's own SID using the append trick; if the child is not Trace2 aware, we won't get any telemetry from it.

Sorry for the confusion. That naming scheme keep the event pairs symmetric "foo-start" and "foo-exit", "region-enter" and "region-leave" and etc.

[mjcheetham]

That naming scheme keep the event pairs symmetric "foo-start" and "foo-exit", "region-enter" and "region-leave" and etc.

Interesting question.. what should we do, if anything, about tracing child process starts that we don't subsequently wait for? A child-start without a child-end?

The example we have is clicking a link and having it open a web browser, for example.
I'd imagine we don't care about this, and every -start event should only be emitted when we can pair it with an -end event.

[jeffhostetler]

I have a "child-ready" event for children that we start and release into the wild. I use it for example when something like "git fsmonitor--daemon start" disassociates with the TTY and spawns a background process "git fsmonitor--daemon run".

The idea was that I wanted to be able to see that the child successfully got started (the exe was found and we had 0755 access and etc) -- even if it immediately died because of a bad CL arg or something.

In the fsmonitor example, the test suite can use "... start" and know that that process will do whatever is necessary (and not return before) the actual "run" process gets going. the test can then talk to the background "run" process over the socket/pipe/whatever -- and not have to worry about spinning until it is ready. (and not have to rely on polling stdin/out or anything).

[jeffhostetler]

So we should see either a "child-start" ... "child-exit" -or- "child-start" ... "child-ready" pair. If the child cannot get started (bad exe or accesss or whatever), emit a "child-exit" with the usual exit code.

All of this is a bit hacky, but given the unix and windows process models, my hands were kinda tied...

[jeffhostetler]

private static string GetEventName(Trace2Event event)
{
return event switch
{
Trace2Event.Version => "version",
Trace2Event.ChildStart => "child_start",
...

Yeah, that's one way of doing it that is relatively easy to maintain and efficient.
I do question the need for the Trace2Event type at all, but that may just be style
and/or might help in the testing, so that's OK.

I'm just wondering whether we actually use the enum anywhere else? I mean, in the following explicitly pass the event type to the initializer following the ctor.

   public void WriteChildStart(DateTimeOffset startTime,
        Trace2ProcessClass processClass,
        bool useShell,
        string appName,
        string argv,
        string sid,
        string filePath = "",
        int lineNumber = 0)
    {
        ...  
        WriteMessage(new ChildStartMessage()
        {
            Event = Trace2Event.ChildStart,
            Sid = sid,
            Time = startTime,
            File = Path.GetFileName(filePath).ToLower(),
            Line = lineNumber,
            Id = ++_childProcCounter,
            Classification = processClass,
            UseShell = useShell,
            Argv = procArgs
        });
        ...

The call to the ChildStartMessage() ctor already knows it is a child start event (and the set of required fields for that message is already encoded in the class definition). The spelling of the event name could also be hidden inside that message class. Passing in an event type to the ctor (or whatever we call the property bucket attached to the trivial ctor call), seems like an opportunity for error.

Is it possible to do something like (my C# is rusty):

public class ChildStartMessage : Trace2Message
{
    static const MyEventName = "child_start"
    public ChildStartMessage()
        : Trace2Message(MyEventName)
    {
    }
    ...

and let the rest of the initializer (following the new()) take care of the rest?

Just a thought and I could go either way here.

[ldennington]

public void WriteChildStart(...)
{
    WriteMessage(
        new ChildStartMessage(...)
        {
            Sid = _sid // this is OUR sid, the child will compute its own
        }
    );
}

@mjcheetham - since the child is computing its own Sid and CreateSid is private, do we need to start passing an IEnvironment to ChildProcess? Will it have its own CreateSid method? Just want to clarify before going down that path.

[ldennington]

@mjcheetham, @jeffhostetler - I believe this latest series addresses all your feedback. A couple things to call out:

1. I decided to keep the snake casing patch. Although we don't necessarily need the Trace2Event enum (as Jeff pointed out), we do (in my opinion) need the new Trace2ProcessClass to structure the information child process callers are passing in. Leaving the Trace2Event enum just follows this pattern for consistency.
2. I also kept the SidManager around, although it's now a static class that is invoked directly from Program.cs so that we immediately set the environment variable. This means that invoked Git processes will have the correct Sid, even if they're called before TRACE2 is initialized. I also adjusted so that the start time is recorded just as the application starts.

[jeffhostetler]

Nicely done! Thanks for putting up with me and all my comments. 😄

[mjcheetham]

Looks great! Happy to merge as is.