diff options
| -rw-r--r-- | internal/git/command_factory.go | 10 | ||||
| -rw-r--r-- | internal/git/command_factory_test.go | 42 | ||||
| -rw-r--r-- | internal/git/trace2/handler.go | 70 | ||||
| -rw-r--r-- | internal/git/trace2/handler_test.go | 4 |
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) |