diff --git a/internal/git/command_factory.go b/internal/git/command_factory.go index c97663ed3ea8a4b314ff62e3248c7610defd64e6..0142d515faa7f3d5cfdd13f3b59287ddf55d089d 100644 --- a/internal/git/command_factory.go +++ b/internal/git/command_factory.go @@ -11,7 +11,9 @@ import ( "gitlab.com/gitlab-org/gitaly/v14/internal/command" "gitlab.com/gitlab-org/gitaly/v14/internal/git/alternates" "gitlab.com/gitlab-org/gitaly/v14/internal/git/repository" + "gitlab.com/gitlab-org/gitaly/v14/internal/git/trace2" "gitlab.com/gitlab-org/gitaly/v14/internal/gitaly/config" + "gitlab.com/gitlab-org/gitaly/v14/internal/metadata/featureflag" "gitlab.com/gitlab-org/gitaly/v14/internal/storage" ) @@ -134,6 +136,15 @@ 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) { + envVars, err := trace2.LogHandler(ctx, execCommand) + if err != nil { + return nil, err + } + + env = append(env, envVars...) + } + command, err := command.New(ctx, execCommand, config.stdin, config.stdout, config.stderr, env...) if err != nil { return nil, err diff --git a/internal/git/command_factory_test.go b/internal/git/command_factory_test.go index 566dbe6a1cd27974c0c20d28cb988ffccd9e78da..40810e281baa10b9fc25f56be729a59159e6168a 100644 --- a/internal/git/command_factory_test.go +++ b/internal/git/command_factory_test.go @@ -8,12 +8,15 @@ 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" "gitlab.com/gitlab-org/gitaly/v14/internal/helper/text" "gitlab.com/gitlab-org/gitaly/v14/internal/testhelper" "gitlab.com/gitlab-org/gitaly/v14/internal/testhelper/testcfg" + "gitlab.com/gitlab-org/labkit/correlation" ) func TestGitCommandProxy(t *testing.T) { @@ -98,3 +101,39 @@ func TestExecCommandFactory_NewWithDir(t *testing.T) { require.Contains(t, err.Error(), "no such file or directory") }) } + +func TestExecCommandFactory_Trace2EventCaptured(t *testing.T) { + cfg := testcfg.Build(t) + ctx, cancel := testhelper.Context() + defer cancel() + + const corrID = "correlation-id" + ctx = correlation.ContextWithCorrelation(ctx, corrID) + + 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) + + 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() + + 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 new file mode 100644 index 0000000000000000000000000000000000000000..effd92f63bf9e334e6192e39e048af6ede5daaca --- /dev/null +++ b/internal/git/trace2/handler.go @@ -0,0 +1,114 @@ +// trace2 provides utilities to leverage Gits trace2 functionalities within +// Gitaly. +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 ( + // By setting this environment variable for Git process, it will enable + // the trace 2. Furhter, the value it will be set to tells Git where + // to write the output to. Gitaly uses an open file descriptor. + trace2EventFDKey = "GIT_TRACE2_EVENT" + + // Git continiously shells out to child processes and will set the SID + // as environment variable. The child than appends their own unique ID. + // For Gitaly we set the SID to the correlation ID to allow for + // correlation throughout GitLabs components. + sessionIDKey = "GIT_TRACE2_PARENT_SID" +) + +// 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 + } + + go func() { + cancelCtx, _ := context.WithCancel(ctx) + bufReader := bufio.NewReader(r) + + for { + select { + case <-cancelCtx.Done(): + w.Close() + r.Close() + break + default: + err := logTraceEvents(cancelCtx, bufReader) + if err == io.EOF { + continue + } + if err != nil { + log.WithError(err).Error("failed to parse trace2 event") + } + } + + } + }() + + cmd.ExtraFiles = append(cmd.ExtraFiles, w) + + return []string{ + // Plus 2 accounts for stdin (0), stdout (1), and stderr (2). + fmt.Sprintf("%s=%d", trace2EventFDKey, 2+len(cmd.ExtraFiles)), + 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 new file mode 100644 index 0000000000000000000000000000000000000000..90143e2dc37e90a77bc45e40f41ed6e055f83398 --- /dev/null +++ b/internal/git/trace2/handler_test.go @@ -0,0 +1,25 @@ +package trace2 + +import ( + "fmt" + "os/exec" + "strings" + "testing" + + "github.com/stretchr/testify/require" + "gitlab.com/gitlab-org/gitaly/internal/testhelper" +) + +func TestCopyHandler(t *testing.T) { + ctx, cancel := testhelper.Context() + defer cancel() + + cmd := exec.Command("env") + + env, err := LogHandler(ctx, cmd) + require.NoError(t, err) + + require.Len(t, cmd.ExtraFiles, 1) + require.Equal(t, env[0], fmt.Sprintf("%s=3", trace2EventFDKey)) + require.True(t, strings.HasPrefix(env[1], sessionIDKey)) +} diff --git a/internal/metadata/featureflag/feature_flags.go b/internal/metadata/featureflag/feature_flags.go index 88f3d69e1f42ee2859f55d5bc7c00045031960e8..7e429dc353d584acd39cd61aab114e75cfaae02a 100644 --- a/internal/metadata/featureflag/feature_flags.go +++ b/internal/metadata/featureflag/feature_flags.go @@ -23,6 +23,8 @@ var ( TxConfig = FeatureFlag{Name: "tx_config", OnByDefault: false} // TxRemote enables transactional voting for AddRemote and DeleteRemote. TxRemote = FeatureFlag{Name: "tx_remote", OnByDefault: false} + // GitTrace2 enables the GIT_TRACE2_* environment variables required for Gitaly to ingest the trace events + GitTrace2 = FeatureFlag{Name: "git_trace2", OnByDefault: false} ) // All includes all feature flags. @@ -34,4 +36,5 @@ var All = []FeatureFlag{ FetchInternalRemoteErrors, TxConfig, TxRemote, + GitTrace2, }