log: add child process tracing

Add 'ChildProcess()' to 'log.TraceLogger()', with a corresponding
implementation in the Trace2 logger. 'ChildProcess()' works somewhat
similarly to 'Region()', writing a "child_start" log during its main
execution and returning two functions to write "child_ready" and
"child_exit" logs. The main difference from 'Region()', though, is that the
returned functions are meant to be invoked directly at the appropriate times
in the process execution (rather than deferred).

Add the child process logging to 'CommandExecutor.Run()'.

Signed-off-by: Victoria Dye <[email protected]>

Author: vdye

internal/cmd/command.go

@@ -58,12 +58,15 @@ func (c *commandExecutor) applyOptions(ctx context.Context, cmd *exec.Cmd, setti
 }
 
 func (c *commandExecutor) runCmd(ctx context.Context, cmd *exec.Cmd) (int, error) {
+	childReady, childExit := c.logger.ChildProcess(ctx, cmd)
 	err := cmd.Start()
+	childReady(err)
 	if err != nil {
 		return -1, c.logger.Errorf(ctx, "command failed to start: %w", err)
 	}
 
 	err = cmd.Wait()
+	childExit()
 	_, isExitError := err.(*exec.ExitError)
 
 	// If the command succeeded, or ran to completion but returned a nonzero

internal/log/logger.go

@@ -4,6 +4,7 @@ import (
 	"context"
 	"fmt"
 	"os"
+	"os/exec"
 	"runtime/debug"
 )
 
@@ -13,6 +14,7 @@ type loggedError error
 
 type TraceLogger interface {
 	Region(ctx context.Context, category string, label string) (context.Context, func())
+	ChildProcess(ctx context.Context, cmd *exec.Cmd) (func(error), func())
 	LogCommand(ctx context.Context, commandName string) context.Context
 	Error(ctx context.Context, err error) error
 	Errorf(ctx context.Context, format string, a ...any) error

internal/log/trace2.go

@@ -4,10 +4,12 @@ import (
 	"context"
 	"fmt"
 	"os"
+	"os/exec"
 	"path"
 	"path/filepath"
 	"runtime"
 	"strconv"
+	"sync/atomic"
 	"time"
 
 	"github.com/google/uuid"
@@ -41,7 +43,8 @@ type trace2Region struct {
 }
 
 type Trace2 struct {
-	logger *zap.Logger
+	logger      *zap.Logger
+	lastChildId int32
 }
 
 func getTrace2OutputPaths(envKey string) []string {
@@ -104,7 +107,8 @@ func createTrace2ZapLogger() *zap.Logger {
 
 func NewTrace2() traceLoggerInternal {
 	return &Trace2{
-		logger: createTrace2ZapLogger(),
+		logger:      createTrace2ZapLogger(),
+		lastChildId: -1,
 	}
 }
 
@@ -229,6 +233,47 @@ func (t *Trace2) Region(ctx context.Context, category string, label string) (con
 	}
 }
 
+func (t *Trace2) ChildProcess(ctx context.Context, cmd *exec.Cmd) (func(error), func()) {
+	var startTime time.Time
+	_, sharedFields := t.sharedFields(ctx)
+
+	// Get the child id by atomically incrementing the lastChildId
+	childId := atomic.AddInt32(&t.lastChildId, 1)
+	t.logger.Debug("child_start", sharedFields.with(
+		zap.Int32("child_id", childId),
+		zap.String("child_class", "?"),
+		zap.Bool("use_shell", false),
+		zap.Strings("argv", cmd.Args),
+	)...)
+
+	childReady := func(execError error) {
+		ready := zap.String("ready", "ready")
+		if execError != nil {
+			ready = zap.String("ready", "error")
+		}
+		t.logger.Debug("child_ready", sharedFields.with(
+			zap.Int32("child_id", childId),
+			zap.Int("pid", cmd.Process.Pid),
+			ready,
+			zap.Strings("argv", cmd.Args),
+		)...)
+	}
+
+	childExit := func() {
+		t.logger.Debug("child_exit", sharedFields.with(
+			zap.Int32("child_id", childId),
+			zap.Int("pid", cmd.ProcessState.Pid()),
+			zap.Int("code", cmd.ProcessState.ExitCode()),
+			zap.Duration("t_rel", time.Since(startTime)),
+		)...)
+	}
+
+	// Approximate the process runtime by starting the timer now
+	startTime = time.Now()
+
+	return childReady, childExit
+}
+
 func (t *Trace2) LogCommand(ctx context.Context, commandName string) context.Context {
 	ctx, sharedFields := t.sharedFields(ctx)
 

internal/testhelpers/mocks.go

@@ -3,6 +3,7 @@ package testhelpers
 import (
 	"context"
 	"fmt"
+	"os/exec"
 	"os/user"
 	"runtime"
 
@@ -62,6 +63,14 @@ func (l *MockTraceLogger) Region(ctx context.Context, category string, label str
 	return mockWithDefault(fnArgs, 0, ctx), mockWithDefault(fnArgs, 1, func() {})
 }
 
+func (l *MockTraceLogger) ChildProcess(ctx context.Context, cmd *exec.Cmd) (func(error), func()) {
+	fnArgs := mock.Arguments{}
+	if methodIsMocked(&l.Mock) {
+		fnArgs = l.Called(ctx, cmd)
+	}
+	return mockWithDefault(fnArgs, 0, func(error) {}), mockWithDefault(fnArgs, 1, func() {})
+}
+
 func (l *MockTraceLogger) LogCommand(ctx context.Context, commandName string) context.Context {
 	fnArgs := mock.Arguments{}
 	if methodIsMocked(&l.Mock) {