1 files changed, 61 insertions, 9 deletions

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
+}