trace2: Expose child events to logszj-trace2-support

While trace2 emits a lot of messages, this change disregards almost all
of them except Git shelling out to a child process. In that case we
capture only the most important details like the SID, arguments, and
exit code.

The trace2.CopyHandler has been renamed, and tests have been updated to
validate the messages in the logs.

Changelog: added

4 files changed, 88 insertions, 38 deletions

diff --git a/internal/git/command_factory.go b/internal/git/command_factory.go
index 183baef0a..0142d515f 100644
--- a/internal/git/command_factory.go
+++ b/internal/git/command_factory.go
@@ -4,7 +4,6 @@ import (
 	"context"
 	"errors"
 	"fmt"
-	"io"
 	"os/exec"
 
 	"github.com/prometheus/client_golang/prometheus"
@@ -52,7 +51,6 @@ type ExecCommandFactory struct {
 	cfg                   config.Cfg
 	cgroupsManager        cgroups.Manager
 	invalidCommandsMetric *prometheus.CounterVec
-	trace2Sink            io.Writer
 }
 
 // NewExecCommandFactory returns a new instance of initialized ExecCommandFactory.
@@ -102,10 +100,6 @@ func (cf *ExecCommandFactory) NewWithDir(ctx context.Context, dir string, sc Cmd
 	return cf.newCommand(ctx, nil, dir, sc, opts...)
 }
 
-func (cf *ExecCommandFactory) SetTrace2Sink(w io.Writer) {
-	cf.trace2Sink = w
-}
-
 func (cf *ExecCommandFactory) gitPath() string {
 	return cf.cfg.Git.BinPath
 }
@@ -142,8 +136,8 @@ func (cf *ExecCommandFactory) newCommand(ctx context.Context, repo repository.Gi
 	execCommand := exec.Command(cf.gitPath(), args...)
 	execCommand.Dir = dir
 
-	if featureflag.IsEnabled(ctx, featureflag.GitTrace2) && cf.trace2Sink != nil {
-		envVars, err := trace2.CopyHandler(ctx, execCommand, cf.trace2Sink)
+	if featureflag.IsEnabled(ctx, featureflag.GitTrace2) {
+		envVars, err := trace2.LogHandler(ctx, execCommand)
 		if err != nil {
 			return nil, err
 		}
diff --git a/internal/git/command_factory_test.go b/internal/git/command_factory_test.go
index cb4d3d2e2..40810e281 100644
--- a/internal/git/command_factory_test.go
+++ b/internal/git/command_factory_test.go
@@ -8,6 +8,8 @@ import (
 	"os"
 	"testing"
 
+	"github.com/grpc-ecosystem/go-grpc-middleware/logging/logrus/ctxlogrus"
+	"github.com/sirupsen/logrus"
 	"github.com/stretchr/testify/require"
 	"gitlab.com/gitlab-org/gitaly/v14/internal/git"
 	"gitlab.com/gitlab-org/gitaly/v14/internal/git/gittest"
@@ -108,26 +110,30 @@ func TestExecCommandFactory_Trace2EventCaptured(t *testing.T) {
 	const corrID = "correlation-id"
 	ctx = correlation.ContextWithCorrelation(ctx, corrID)
 
-	buf := &bytes.Buffer{}
-	gitCmdFactory := git.NewExecCommandFactory(cfg)
-	gitCmdFactory.SetTrace2Sink(buf)
+	logBuffer := &bytes.Buffer{}
+	log := &logrus.Logger{Out: logBuffer, Formatter: &logrus.JSONFormatter{}, Level: logrus.InfoLevel}
+	testCtx := ctxlogrus.ToContext(ctx, log.WithField("test", "logging"))
+
+	repo, _, cleanup := gittest.CloneRepoAtStorage(t, cfg.Storages[0], t.Name())
+	t.Cleanup(cleanup)
 
-	cmd, err := gitCmdFactory.NewWithoutRepo(ctx, git.SubCmd{Name: "version"})
+	gitCmdFactory := git.NewExecCommandFactory(cfg)
+	cmd, err := gitCmdFactory.New(testCtx, repo, git.SubCmd{
+		Name:  "repack",
+		Flags: []git.Option{git.Flag{Name: "--no-write-bitmap-index"}}},
+	)
 	require.NoError(t, err)
 	cmd.Wait()
 
-	// The buffer should contain at least info about:
-	require.NotEmpty(t, buf)
-
-	// Gits version
-	require.Contains(t, buf.String(), `"event":"version"`)
-
-	// Start the command and report the name
-	require.Contains(t, buf.String(), `"event":"cmd_name"`)
-
-	// report the exit
-	require.Contains(t, buf.String(), `"event":"exit"`)
-
-	// Propegates the SID to child events
-	require.Contains(t, buf.String(), `"sid":"`+corrID)
+	strBuf := logBuffer.String()
+
+	for _, expected := range []string{
+		`"SID":"correlation-id/`,
+		`"event":"child_start"`,
+		`"event":"child_exit"`,
+		`"exit_code":0`,
+		`"argv":["git","pack-objects"`,
+	} {
+		require.Contains(t, strBuf, expected)
+	}
 }
diff --git a/internal/git/trace2/handler.go b/internal/git/trace2/handler.go
index d4a507d4a..effd92f63 100644
--- a/internal/git/trace2/handler.go
+++ b/internal/git/trace2/handler.go
@@ -3,13 +3,18 @@
 package trace2
 
 import (
+	"bufio"
 	"context"
+	"encoding/json"
 	"fmt"
 	"io"
 	"os"
 	"os/exec"
 
+	"github.com/grpc-ecosystem/go-grpc-middleware/logging/logrus/ctxlogrus"
+	"github.com/sirupsen/logrus"
 	"gitlab.com/gitlab-org/labkit/correlation"
+	"gitlab.com/gitlab-org/labkit/log"
 )
 
 const (
@@ -25,20 +30,19 @@ const (
 	sessionIDKey = "GIT_TRACE2_PARENT_SID"
 )
 
-// CopyHandler takes the trace2 stream, and copies it over to a passed io.Writer
-// Note it still receives the stream on a fresh file descriptor, not 2.
-// Returns environment variables which MUST be injected by the
-// caller into the spawned Git process; else the sink will never be
-// closed and a resource leak occurs.
-func CopyHandler(ctx context.Context, cmd *exec.Cmd, sink io.Writer) ([]string, error) {
+// LogHandler takes the trace2 events and logs child processes starting as well
+// as their completion.
+// Note the exec.Cmd is altered to include a FD for git to write the output to.
+func LogHandler(ctx context.Context, cmd *exec.Cmd) ([]string, error) {
 	r, w, err := os.Pipe()
 	if err != nil {
 		return nil, err
 	}
 
-	cancelCtx, _ := context.WithCancel(ctx)
-
 	go func() {
+		cancelCtx, _ := context.WithCancel(ctx)
+		bufReader := bufio.NewReader(r)
+
 		for {
 			select {
 			case <-cancelCtx.Done():
@@ -46,7 +50,13 @@ func CopyHandler(ctx context.Context, cmd *exec.Cmd, sink io.Writer) ([]string,
 				r.Close()
 				break
 			default:
-				io.Copy(sink, r)
+				err := logTraceEvents(cancelCtx, bufReader)
+				if err == io.EOF {
+					continue
+				}
+				if err != nil {
+					log.WithError(err).Error("failed to parse trace2 event")
+				}
 			}
 
 		}
@@ -60,3 +70,45 @@ func CopyHandler(ctx context.Context, cmd *exec.Cmd, sink io.Writer) ([]string,
 		fmt.Sprintf("%s=%s", sessionIDKey, correlation.ExtractFromContextOrGenerate(ctx)),
 	}, nil
 }
+
+type trace2Event struct {
+	Event    string   `json:"event"`
+	Argv     []string `json:"argv"` // Only present at child_start events
+	SID      string   `json:"sid"`
+	ExitCode int      `json:"code"`
+}
+
+const (
+	childEventStart = "child_start"
+	childEventExit  = "child_exit"
+)
+
+func shouldLogEvent(e *trace2Event) bool {
+	return e.Event == childEventStart || e.Event == childEventExit
+}
+
+func logTraceEvents(ctx context.Context, r *bufio.Reader) error {
+	line, err := r.ReadBytes('\n')
+	if err != nil {
+		return err
+	}
+
+	event := &trace2Event{}
+	if err := json.Unmarshal(line, event); err != nil {
+		ctxlogrus.Extract(ctx).WithError(err).Warn("error decoding trace2 json")
+
+		// This is not an error the caller can handle
+		return nil
+	}
+
+	if shouldLogEvent(event) {
+		ctxlogrus.Extract(ctx).WithFields(logrus.Fields{
+			"event":     event.Event,
+			"SID":       event.SID,
+			"argv":      event.Argv,
+			"exit_code": event.ExitCode,
+		}).Info("trace2 event")
+	}
+
+	return nil
+}
diff --git a/internal/git/trace2/handler_test.go b/internal/git/trace2/handler_test.go
index df896cc62..90143e2dc 100644
--- a/internal/git/trace2/handler_test.go
+++ b/internal/git/trace2/handler_test.go
@@ -1,7 +1,6 @@
 package trace2
 
 import (
-	"bytes"
 	"fmt"
 	"os/exec"
 	"strings"
@@ -17,8 +16,7 @@ func TestCopyHandler(t *testing.T) {
 
 	cmd := exec.Command("env")
 
-	var sink bytes.Buffer
-	env, err := CopyHandler(ctx, cmd, &sink)
+	env, err := LogHandler(ctx, cmd)
 	require.NoError(t, err)
 
 	require.Len(t, cmd.ExtraFiles, 1)