Create new hook to export git trace 2 events in gitaly logs

13 files changed, 475 insertions, 131 deletions

diff --git a/doc/trace2_integration.md b/doc/trace2_integration.md
index 28757d671..3f4e9ea44 100644
--- a/doc/trace2_integration.md
+++ b/doc/trace2_integration.md
@@ -358,6 +358,9 @@ We must also add the hook to the
 [default list of Trace2 hooks](https://gitlab.com/gitlab-org/gitaly/-/blob/d15b9c84faee3eb178e7c7d9360832f26d4107a2/internal/git/command_factory.go#L90-99)
 to make it effective.
 
+There is an additional hook in the default list of Trace2 hooks called `LogExporter` which is enabled by turning on the feature flag `log_git_traces`. This hook will log the trace2 events to Gitaly logs. 
+Follow [Configure Gitaly](https://docs.gitlab.com/ee/administration/gitaly/configure_gitaly.html) to setup the feature flag.
+
 ## Custom Trace2 instrumentation
 
 Although Trace comes bundled with numerous events and data, they may not be
diff --git a/internal/featureflag/ff_log_git_traces.go b/internal/featureflag/ff_log_git_traces.go
new file mode 100644
index 000000000..c8307c578
--- /dev/null
+++ b/internal/featureflag/ff_log_git_traces.go
@@ -0,0 +1,9 @@
+package featureflag
+
+// LogGitTraces enables the collection of distributed traces via the git trace 2 API
+var LogGitTraces = NewFeatureFlag(
+	"log_git_traces",
+	"v16.9.0",
+	"https://gitlab.com/gitlab-org/gitaly/-/issues/5700",
+	false,
+)
diff --git a/internal/git/command_factory.go b/internal/git/command_factory.go
index 5cf710ca2..a22df685b 100644
--- a/internal/git/command_factory.go
+++ b/internal/git/command_factory.go
@@ -13,6 +13,7 @@ import (
 	"github.com/prometheus/client_golang/prometheus"
 	"gitlab.com/gitlab-org/gitaly/v16/internal/cgroups"
 	"gitlab.com/gitlab-org/gitaly/v16/internal/command"
+	"gitlab.com/gitlab-org/gitaly/v16/internal/featureflag"
 	"gitlab.com/gitlab-org/gitaly/v16/internal/git/alternates"
 	"gitlab.com/gitlab-org/gitaly/v16/internal/git/trace2"
 	"gitlab.com/gitlab-org/gitaly/v16/internal/git/trace2hooks"
@@ -21,12 +22,18 @@ import (
 	"gitlab.com/gitlab-org/gitaly/v16/internal/log"
 	"gitlab.com/gitlab-org/gitaly/v16/internal/tracing"
 	"gitlab.com/gitlab-org/labkit/correlation"
+	"golang.org/x/time/rate"
 )
 
 const (
 	// BigFileThresholdMB is the threshold we configure via `core.bigFileThreshold` and determines the maximum size
 	// after which Git considers files to be big. Please refer to `GlobalConfiguration()` for more details.
 	BigFileThresholdMB = 50
+	// maxTrace2EventPerSecond is the maximum number of events that can be processed per second
+	maxTrace2EventPerSecond = 40
+	// Rate limiter is immediately allocated the maxBurstToken value. Burst is the maximum number of tokens
+	// that can be consumed in a single call
+	maxBurstToken = 40
 )
 
 // CommandFactory is designed to create and run git commands in a protected and fully managed manner.
@@ -48,6 +55,7 @@ type execCommandFactoryConfig struct {
 	gitBinaryPath       string
 	cgroupsManager      cgroups.Manager
 	trace2Hooks         []trace2.Hook
+	traceRateLimiter    *rate.Limiter
 	execEnvConstructors []ExecutionEnvironmentConstructor
 }
 
@@ -91,7 +99,7 @@ func WithTrace2Hooks(hooks []trace2.Hook) ExecCommandFactoryOption {
 
 // DefaultTrace2HooksFor creates a list of all Trace2 hooks. It doesn't mean all hooks are triggered.
 // Each hook's activation status will be evaluated before the command starts.
-func DefaultTrace2HooksFor(ctx context.Context, subCmd string) []trace2.Hook {
+func DefaultTrace2HooksFor(ctx context.Context, subCmd string, logger log.Logger, rl *rate.Limiter) []trace2.Hook {
 	var hooks []trace2.Hook
 	if tracing.IsSampled(ctx) {
 		hooks = append(hooks, trace2hooks.NewTracingExporter())
@@ -99,6 +107,9 @@ func DefaultTrace2HooksFor(ctx context.Context, subCmd string) []trace2.Hook {
 	if subCmd == "pack-objects" {
 		hooks = append(hooks, trace2hooks.NewPackObjectsMetrics())
 	}
+	if featureflag.LogGitTraces.IsEnabled(ctx) {
+		hooks = append(hooks, trace2hooks.NewLogExporter(rl, logger))
+	}
 	return hooks
 }
 
@@ -127,6 +138,7 @@ type ExecCommandFactory struct {
 	logger                log.Logger
 	cgroupsManager        cgroups.Manager
 	trace2Hooks           []trace2.Hook
+	traceRateLimiter      *rate.Limiter
 	invalidCommandsMetric *prometheus.CounterVec
 	hookDirs              hookDirectories
 
@@ -172,13 +184,19 @@ func NewExecCommandFactory(cfg config.Cfg, logger log.Logger, opts ...ExecComman
 		cgroupsManager = cgroups.NewManager(cfg.Cgroups, logger, os.Getpid())
 	}
 
+	traceRateLimiter := factoryCfg.traceRateLimiter
+	if traceRateLimiter == nil {
+		traceRateLimiter = rate.NewLimiter(maxTrace2EventPerSecond, maxBurstToken)
+	}
+
 	gitCmdFactory := &ExecCommandFactory{
-		cfg:            cfg,
-		execEnvs:       execEnvs,
-		logger:         logger,
-		locator:        config.NewLocator(cfg),
-		cgroupsManager: cgroupsManager,
-		trace2Hooks:    factoryCfg.trace2Hooks,
+		cfg:              cfg,
+		execEnvs:         execEnvs,
+		logger:           logger,
+		locator:          config.NewLocator(cfg),
+		cgroupsManager:   cgroupsManager,
+		trace2Hooks:      factoryCfg.trace2Hooks,
+		traceRateLimiter: traceRateLimiter,
 		invalidCommandsMetric: prometheus.NewCounterVec(
 			prometheus.CounterOpts{
 				Name: "gitaly_invalid_commands_total",
@@ -469,7 +487,7 @@ func (cf *ExecCommandFactory) newCommand(ctx context.Context, repo storage.Repos
 
 	trace2Hooks := cf.trace2Hooks
 	if trace2Hooks == nil {
-		trace2Hooks = DefaultTrace2HooksFor(ctx, sc.Name)
+		trace2Hooks = DefaultTrace2HooksFor(ctx, sc.Name, cf.logger, cf.traceRateLimiter)
 	}
 	if len(trace2Hooks) != 0 {
 		trace2Manager, err := trace2.NewManager(correlation.ExtractFromContextOrGenerate(ctx), trace2Hooks)
diff --git a/internal/git/command_factory_test.go b/internal/git/command_factory_test.go
index f1dfca0b4..6e04ceb3a 100644
--- a/internal/git/command_factory_test.go
+++ b/internal/git/command_factory_test.go
@@ -16,6 +16,7 @@ import (
 	"testing"
 
 	"github.com/stretchr/testify/require"
+	"gitlab.com/gitlab-org/gitaly/v16/internal/featureflag"
 	"gitlab.com/gitlab-org/gitaly/v16/internal/git"
 	"gitlab.com/gitlab-org/gitaly/v16/internal/git/gittest"
 	"gitlab.com/gitlab-org/gitaly/v16/internal/git/trace2"
@@ -26,6 +27,7 @@ import (
 	"gitlab.com/gitlab-org/gitaly/v16/internal/testhelper"
 	"gitlab.com/gitlab-org/gitaly/v16/internal/testhelper/testcfg"
 	"gitlab.com/gitlab-org/gitaly/v16/internal/tracing"
+	"golang.org/x/time/rate"
 )
 
 func TestGitCommandProxy(t *testing.T) {
@@ -1061,13 +1063,30 @@ func TestDefaultTrace2HooksFor(t *testing.T) {
 				return ctx, hooks
 			},
 		},
+		{
+			desc:   "subcmd is pack-objects, active span is sampled and feature flag LogGitTraces enabled",
+			subCmd: "pack-objects",
+			setup: func(t *testing.T) (context.Context, []trace2.Hook) {
+				ctx := testhelper.Context(t)
+				ctx = featureflag.ContextWithFeatureFlag(ctx, featureflag.LogGitTraces, true)
+				_, ctx = tracing.StartSpan(ctx, "root", nil)
+
+				hooks := []trace2.Hook{
+					trace2hooks.NewTracingExporter(),
+					trace2hooks.NewPackObjectsMetrics(),
+					trace2hooks.NewLogExporter(rate.NewLimiter(1, 1), testhelper.SharedLogger(t)),
+				}
+
+				return ctx, hooks
+			},
+		},
 	} {
 		t.Run(tc.desc, func(t *testing.T) {
 			_, cleanup := testhelper.StubTracingReporter(t, tc.tracerOptions...)
 			defer cleanup()
 
 			ctx, expectedHooks := tc.setup(t)
-			hooks := git.DefaultTrace2HooksFor(ctx, tc.subCmd)
+			hooks := git.DefaultTrace2HooksFor(ctx, tc.subCmd, testhelper.SharedLogger(t), rate.NewLimiter(1, 1))
 
 			require.Equal(t, hookNames(expectedHooks), hookNames(hooks))
 		})
diff --git a/internal/git/trace2/parser.go b/internal/git/trace2/parser.go
index 58248cf13..e5ecbdec7 100644
--- a/internal/git/trace2/parser.go
+++ b/internal/git/trace2/parser.go
@@ -73,6 +73,9 @@ type jsonEvent struct {
 	ChildID        int      `json:"child_id"`
 	Msg            string   `json:"msg"`
 	Code           int      `json:"code"`
+	Exe            string   `json:"exe"`
+	Evt            string   `json:"evt"`
+	Worktree       string   `json:"worktree"`
 }
 
 var ignoredEvents = map[string]struct{}{
@@ -137,11 +140,11 @@ func (p *parser) parseEvent(event *jsonEvent) error {
 	switch event.Name {
 	case "atexit":
 		p.currentNode.FinishTime = eventTime
-		p.currentNode.setMetadata("code", fmt.Sprintf("%d", event.Code))
+		p.currentNode.SetMetadata("code", fmt.Sprintf("%d", event.Code))
 		return nil
 	case "child_exit":
 		p.currentNode.FinishTime = eventTime
-		p.currentNode.setMetadata("code", fmt.Sprintf("%d", event.Code))
+		p.currentNode.SetMetadata("code", fmt.Sprintf("%d", event.Code))
 		p.currentNode = p.currentNode.Parent
 		return nil
 	case "region_leave":
@@ -159,17 +162,24 @@ func (p *parser) parseEvent(event *jsonEvent) error {
 		Depth:      p.currentNode.Depth + 1,
 	}
 	if event.Msg != "" {
-		trace.setMetadata("msg", event.Msg)
+		trace.SetMetadata("msg", event.Msg)
 	}
 	p.currentNode.Children = append(p.currentNode.Children, trace)
 
 	switch event.Name {
+	case "version":
+		trace.setName([]string{event.Name, event.Category, event.Label})
+		trace.SetMetadata("exe", event.Exe)
+		trace.SetMetadata("evt", event.Evt)
+	case "def_repo":
+		trace.setName([]string{event.Name, event.Category, event.Label})
+		trace.SetMetadata("worktree", event.Worktree)
 	case "start":
 		trace.setName([]string{event.Name, event.Category, event.Label})
-		trace.setMetadata("argv", strings.Join(event.Argv, " "))
+		trace.SetMetadata("argv", strings.Join(event.Argv, " "))
 	case "child_start":
 		trace.setName([]string{event.Name, event.Category, event.Label})
-		trace.setMetadata("argv", strings.Join(event.Argv, " "))
+		trace.SetMetadata("argv", strings.Join(event.Argv, " "))
 		trace.ChildID = fmt.Sprintf("%d", event.ChildID)
 		p.currentNode = trace
 	case "region_enter":
@@ -185,12 +195,12 @@ func (p *parser) parseEvent(event *jsonEvent) error {
 			if err != nil {
 				return fmt.Errorf("mismatched data value: %w", err)
 			}
-			trace.setMetadata("data", data)
+			trace.SetMetadata("data", data)
 		}
 	case "data_json":
 		trace.setName([]string{event.Name, event.Category, event.Label, event.DataKey})
 		if event.DataValue != nil {
-			trace.setMetadata("data", string(*event.DataValue))
+			trace.SetMetadata("data", string(*event.DataValue))
 		}
 	default:
 		trace.setName([]string{event.Name, event.Category, event.Label})
diff --git a/internal/git/trace2/parser_test.go b/internal/git/trace2/parser_test.go
index 8d53f6885..cda886b70 100644
--- a/internal/git/trace2/parser_test.go
+++ b/internal/git/trace2/parser_test.go
@@ -114,9 +114,9 @@ func TestParser_Parse(t *testing.T) {
 `,
 			expectedTrace: `
 2023-02-22T12:05:04.840009Z | 0001-01-01T00:00:00Z |   | main | root
-2023-02-22T12:05:04.840009Z | 2023-02-22T12:05:04.840009Z |   | main | .version
+2023-02-22T12:05:04.840009Z | 2023-02-22T12:05:04.840009Z |   | main | .version (evt="3" exe="2.39.1")
 2023-02-22T12:05:04.842347Z | 2023-02-22T12:05:04.842347Z |   | main | .start (argv="git pack-objects toon --compression=0")
-2023-02-22T12:05:04.842347Z | 2023-02-22T12:05:04.842347Z |   | main | .def_repo
+2023-02-22T12:05:04.842347Z | 2023-02-22T12:05:04.842347Z |   | main | .def_repo (worktree="/gitaly")
 2023-02-22T12:05:04.842347Z | 2023-02-22T12:05:04.842347Z |   | main | .pack-objects:enumerate-objects
 2023-02-22T12:05:04.842347Z | 2023-02-22T12:05:04.84343Z |   | main | ..progress:Enumerating objects
 `,
@@ -150,9 +150,9 @@ func TestParser_Parse(t *testing.T) {
 			events: string(testhelper.MustReadFile(t, "testdata/git-status.event")),
 			expectedTrace: `
 2023-02-21T08:10:10.668546Z | 2023-02-21T08:10:10.687877Z |   | main | root (code="0")
-2023-02-21T08:10:10.668546Z | 2023-02-21T08:10:10.668546Z |   | main | .version
+2023-02-21T08:10:10.668546Z | 2023-02-21T08:10:10.668546Z |   | main | .version (evt="3" exe="2.39.1")
 2023-02-21T08:10:10.754608Z | 2023-02-21T08:10:10.754608Z |   | main | .start (argv="git status")
-2023-02-21T08:10:10.754608Z | 2023-02-21T08:10:10.754608Z |   | main | .def_repo
+2023-02-21T08:10:10.754608Z | 2023-02-21T08:10:10.754608Z |   | main | .def_repo (worktree="/Users/userx/www/gitlab-development-kit/gitaly")
 2023-02-21T08:10:10.754608Z | 2023-02-21T08:10:10.755102Z |   | main | .index:do_read_index (msg=".git/index")
 2023-02-21T08:10:10.754608Z | 2023-02-21T08:10:10.754732Z |   | main | ..cache_tree:read
 2023-02-21T08:10:10.758297Z | 2023-02-21T08:10:10.758297Z |   | main | ..data:index:read/version (data="2")
@@ -182,9 +182,9 @@ func TestParser_Parse(t *testing.T) {
 			events: string(testhelper.MustReadFile(t, "testdata/git-fetch.event")),
 			expectedTrace: `
 2023-02-22T07:24:36.291735Z | 2023-02-22T07:24:40.554407Z |   | main | root (code="0")
-2023-02-22T07:24:36.291735Z | 2023-02-22T07:24:36.291735Z |   | main | .version
+2023-02-22T07:24:36.291735Z | 2023-02-22T07:24:36.291735Z |   | main | .version (evt="3" exe="2.39.1")
 2023-02-22T07:24:36.293932Z | 2023-02-22T07:24:36.293932Z |   | main | .start (argv="git fetch origin master")
-2023-02-22T07:24:36.293932Z | 2023-02-22T07:24:36.293932Z |   | main | .def_repo
+2023-02-22T07:24:36.293932Z | 2023-02-22T07:24:36.293932Z |   | main | .def_repo (worktree="/gitaly")
 2023-02-22T07:24:36.293932Z | 2023-02-22T07:24:36.294119Z |   | main | .index:do_read_index (msg=".git/index")
 2023-02-22T07:24:36.293932Z | 2023-02-22T07:24:36.293975Z |   | main | ..cache_tree:read
 2023-02-22T07:24:36.294718Z | 2023-02-22T07:24:36.294718Z |   | main | ..data:index:read/version (data="2")
@@ -193,15 +193,15 @@ func TestParser_Parse(t *testing.T) {
 2023-02-22T07:24:36.294119Z | 2023-02-22T07:24:40.128447Z | 0 | main | ..child_start (argv="ssh -o SendEnv=GIT_PROTOCOL git@gitlab.com git-upload-pack 'gitlab-org/gitaly.git'")
 2023-02-22T07:24:39.314775Z | 2023-02-22T07:24:39.314775Z | 0 | main | ...data:transfer:negotiated-version (data="2")
 2023-02-22T07:24:40.128447Z | 2023-02-22T07:24:40.165067Z | 1 | main | ..child_start (argv="git rev-list --objects --stdin --not --all --quiet --alternate-refs" code="0")
-2023-02-22T07:24:40.148998Z | 2023-02-22T07:24:40.148998Z | 1 | main | ...version
+2023-02-22T07:24:40.148998Z | 2023-02-22T07:24:40.148998Z | 1 | main | ...version (evt="3" exe="2.39.1")
 2023-02-22T07:24:36.295636Z | 2023-02-22T07:24:36.295636Z | 1 | main | ...start (argv="git rev-list --objects --stdin --not --all --quiet --alternate-refs")
-2023-02-22T07:24:36.295636Z | 2023-02-22T07:24:36.295636Z | 1 | main | ...def_repo
+2023-02-22T07:24:36.295636Z | 2023-02-22T07:24:36.295636Z | 1 | main | ...def_repo (worktree="/gitaly")
 2023-02-22T07:24:40.165067Z | 2023-02-22T07:24:40.1658Z |   | main | ..fetch:consume_refs
 2023-02-22T07:24:40.539196Z | 2023-02-22T07:24:40.539281Z |   | main | .submodule:parallel/fetch (msg="max:1")
 2023-02-22T07:24:40.539281Z | 2023-02-22T07:24:40.550543Z | 2 | main | .child_start (argv="git maintenance run --auto --no-quiet" code="0")
-2023-02-22T07:24:40.54863Z | 2023-02-22T07:24:40.54863Z | 2 | main | ..version
+2023-02-22T07:24:40.54863Z | 2023-02-22T07:24:40.54863Z | 2 | main | ..version (evt="3" exe="2.39.1")
 2023-02-22T07:24:36.294627Z | 2023-02-22T07:24:36.294627Z | 2 | main | ..start (argv="git maintenance run --auto --no-quiet")
-2023-02-22T07:24:36.294627Z | 2023-02-22T07:24:36.294627Z | 2 | main | ..def_repo
+2023-02-22T07:24:36.294627Z | 2023-02-22T07:24:36.294627Z | 2 | main | ..def_repo (worktree="/gitaly")
 `,
 		},
 		{
@@ -209,9 +209,9 @@ func TestParser_Parse(t *testing.T) {
 			events: string(testhelper.MustReadFile(t, "testdata/git-commit.event")),
 			expectedTrace: `
 2023-02-22T11:26:37.174893Z | 2023-02-22T11:26:38.677971Z |   | main | root (code="0")
-2023-02-22T11:26:37.174893Z | 2023-02-22T11:26:37.174893Z |   | main | .version
+2023-02-22T11:26:37.174893Z | 2023-02-22T11:26:37.174893Z |   | main | .version (evt="3" exe="2.39.1")
 2023-02-22T11:26:37.180753Z | 2023-02-22T11:26:37.180753Z |   | main | .start (argv="git commit --amend")
-2023-02-22T11:26:37.180753Z | 2023-02-22T11:26:37.180753Z |   | main | .def_repo
+2023-02-22T11:26:37.180753Z | 2023-02-22T11:26:37.180753Z |   | main | .def_repo (worktree="/gitaly")
 2023-02-22T11:26:37.180753Z | 2023-02-22T11:26:37.181072Z |   | main | .index:do_read_index (msg=".git/index")
 2023-02-22T11:26:37.180753Z | 2023-02-22T11:26:37.180832Z |   | main | ..cache_tree:read
 2023-02-22T11:26:37.185091Z | 2023-02-22T11:26:37.185091Z |   | main | ..data:index:read/version (data="2")
@@ -243,16 +243,16 @@ func TestParser_Parse(t *testing.T) {
 2023-02-22T11:26:37.21406Z | 2023-02-22T11:26:37.214271Z |   | main | .status:print
 2023-02-22T11:26:37.214271Z | 2023-02-22T11:26:37.214297Z |   | main | .cache_tree:update
 2023-02-22T11:26:37.214297Z | 2023-02-22T11:26:38.663953Z | 0 | main | .child_start (argv="nvim /gitaly/.git/COMMIT_EDITMSG" code="0")
-2023-02-22T11:26:37.353241Z | 2023-02-22T11:26:37.353241Z | 0 | main | ..version
+2023-02-22T11:26:37.353241Z | 2023-02-22T11:26:37.353241Z | 0 | main | ..version (evt="3" exe="2.39.1")
 2023-02-22T11:26:37.175671Z | 2023-02-22T11:26:37.175671Z | 0 | main | ..start (argv="git diff --no-color --no-ext-diff -U0 -- COMMIT_EDITMSG")
 2023-02-22T11:26:37.175671Z | 2023-02-22T11:26:37.175671Z | 0 | main | ..error (msg="this operation must be run in a work tree")
-2023-02-22T11:26:38.624567Z | 2023-02-22T11:26:38.624567Z | 0 | main | ..version
+2023-02-22T11:26:38.624567Z | 2023-02-22T11:26:38.624567Z | 0 | main | ..version (evt="3" exe="2.39.1")
 2023-02-22T11:26:37.175517Z | 2023-02-22T11:26:37.175517Z | 0 | main | ..start (argv="git branch --no-color --show-current")
-2023-02-22T11:26:37.175517Z | 2023-02-22T11:26:37.175517Z | 0 | main | ..def_repo
+2023-02-22T11:26:37.175517Z | 2023-02-22T11:26:37.175517Z | 0 | main | ..def_repo (worktree="/gitaly")
 2023-02-22T11:26:38.663953Z | 2023-02-22T11:26:38.672888Z | 1 | main | .child_start (argv="git maintenance run --auto --no-quiet" code="0")
-2023-02-22T11:26:38.667832Z | 2023-02-22T11:26:38.667832Z | 1 | main | ..version
+2023-02-22T11:26:38.667832Z | 2023-02-22T11:26:38.667832Z | 1 | main | ..version (evt="3" exe="2.39.1")
 2023-02-22T11:26:37.178802Z | 2023-02-22T11:26:37.178802Z | 1 | main | ..start (argv="git maintenance run --auto --no-quiet")
-2023-02-22T11:26:37.178802Z | 2023-02-22T11:26:37.178802Z | 1 | main | ..def_repo
+2023-02-22T11:26:37.178802Z | 2023-02-22T11:26:37.178802Z | 1 | main | ..def_repo (worktree="/gitaly")
 2023-02-22T11:26:38.672888Z | 2023-02-22T11:26:38.672902Z |   | main | .diff:setup
 2023-02-22T11:26:38.672902Z | 2023-02-22T11:26:38.672907Z |   | main | .diff:write back to queue
 2023-02-22T11:26:38.677965Z | 2023-02-22T11:26:38.677965Z |   | main | .data_json:traverse_trees:statistics (data="{\"traverse_trees_count\":2,\"traverse_trees_max_depth\":2}")
@@ -263,9 +263,9 @@ func TestParser_Parse(t *testing.T) {
 			events: string(testhelper.MustReadFile(t, "testdata/git-pack-objects.event")),
 			expectedTrace: `
 2023-02-22T12:05:04.840009Z | 2023-02-22T12:05:04.848504Z |   | main | root (code="0")
-2023-02-22T12:05:04.840009Z | 2023-02-22T12:05:04.840009Z |   | main | .version
+2023-02-22T12:05:04.840009Z | 2023-02-22T12:05:04.840009Z |   | main | .version (evt="3" exe="2.39.1")
 2023-02-22T12:05:04.842347Z | 2023-02-22T12:05:04.842347Z |   | main | .start (argv="git pack-objects toon --compression=0")
-2023-02-22T12:05:04.842347Z | 2023-02-22T12:05:04.842347Z |   | main | .def_repo
+2023-02-22T12:05:04.842347Z | 2023-02-22T12:05:04.842347Z |   | main | .def_repo (worktree="/gitaly")
 2023-02-22T12:05:04.842347Z | 2023-02-22T12:05:04.843782Z |   | main | .pack-objects:enumerate-objects
 2023-02-22T12:05:04.842347Z | 2023-02-22T12:05:04.84343Z |   | main | ..progress:Enumerating objects
 2023-02-22T12:05:04.843782Z | 2023-02-22T12:05:04.843872Z |   | main | .pack-objects:prepare-pack
diff --git a/internal/git/trace2/testdata/git-status.event b/internal/git/trace2/testdata/git-status.event
index be77a79f7..99e16d97e 100644
--- a/internal/git/trace2/testdata/git-status.event
+++ b/internal/git/trace2/testdata/git-status.event
@@ -1,6 +1,6 @@
 {"event":"version","sid":"1234/20230221T081010.667656Z-Ha0f0bee5-P000006c8","thread":"main","time":"2023-02-21T08:10:10.668546Z","evt":"3","exe":"2.39.1"}
 {"event":"start","sid":"1234/20230221T081010.667656Z-Ha0f0bee5-P000006c8","thread":"main","t_abs":0.086062,"argv":["git","status"]}
-{"event":"def_repo","sid":"1234/20230221T081010.667656Z-Ha0f0bee5-P000006c8","thread":"main","repo":1,"worktree":"/Users/qmnguyen/www/gitlab-development-kit/gitaly"}
+{"event":"def_repo","sid":"1234/20230221T081010.667656Z-Ha0f0bee5-P000006c8","thread":"main","repo":1,"worktree":"/Users/userx/www/gitlab-development-kit/gitaly"}
 {"event":"cmd_name","sid":"1234/20230221T081010.667656Z-Ha0f0bee5-P000006c8","thread":"main","name":"status","hierarchy":"status"}
 {"event":"region_enter","sid":"1234/20230221T081010.667656Z-Ha0f0bee5-P000006c8","thread":"main","repo":1,"nesting":1,"category":"index","label":"do_read_index","msg":".git/index"}
 {"event":"region_enter","sid":"1234/20230221T081010.667656Z-Ha0f0bee5-P000006c8","thread":"main","repo":1,"nesting":2,"category":"cache_tree","label":"read"}
diff --git a/internal/git/trace2/trace.go b/internal/git/trace2/trace.go
index 9a80d0253..cc15820e1 100644
--- a/internal/git/trace2/trace.go
+++ b/internal/git/trace2/trace.go
@@ -13,27 +13,28 @@ import (
 type Trace struct {
 	// Thread is the name of the thread of the corresponding event. The default thread name is
 	// "main". A new thread is assigned with a new name.
-	Thread string
+	Thread string `json:"thread"`
 	// Name denotes the name of the trace. The node name depends on the event types. Data-type
 	// trace name is the most significant. It can be used to access the accurate data trace node
 	// For example: data:index:refresh/sum_scan
-	Name string
+	Name string `json:"name"`
 	// StartTime is the starting time of the trace
-	StartTime time.Time
-	// FinishTime is the starting time of the trace
-	FinishTime time.Time
+	StartTime time.Time `json:"start_time"`
+	// FinishTime is the finishing time of the trace
+	FinishTime time.Time `json:"finish_time"`
 	// Metadata is a map of metadata and data extracted from the event. A data-type trace always
 	// stores its data under "data" key of this map
-	Metadata map[string]string
+	Metadata map[string]string `json:"metadata"`
 	// ChildID is the unique ID assigned by the parent process when it spawns a sub-process
 	// The ID of root process is empty.
-	ChildID string
-	// Parent points to the parent node of the current trace. The root node's parent is nil
-	Parent *Trace
+	ChildID string `json:"child_id,omitempty"`
+	// Parent points to the parent node of the current trace. The root node's parent is nil.
+	// Ignore this field when unmarshalling as it causes cyclic errors
+	Parent *Trace `json:"-"`
 	// Children stores the list of order-significant traces belong to the current trace
-	Children []*Trace
+	Children []*Trace `json:"children,omitempty"`
 	// Depth indicates the depth of the trace node
-	Depth int
+	Depth int `json:"depth"`
 }
 
 // IsRoot returns true if the current trace is the root of the tree
@@ -90,7 +91,8 @@ func (trace *Trace) setName(hints []string) {
 	trace.Name = strings.Join(parts, ":")
 }
 
-func (trace *Trace) setMetadata(key, value string) {
+// SetMetadata sets the metadata for the trace.
+func (trace *Trace) SetMetadata(key, value string) {
 	if trace.Metadata == nil {
 		trace.Metadata = map[string]string{}
 	}
diff --git a/internal/git/trace2hooks/log_exporter.go b/internal/git/trace2hooks/log_exporter.go
new file mode 100644
index 000000000..a714d7fb3
--- /dev/null
+++ b/internal/git/trace2hooks/log_exporter.go
@@ -0,0 +1,68 @@
+package trace2hooks
+
+import (
+	"context"
+	"encoding/json"
+	"fmt"
+
+	"gitlab.com/gitlab-org/gitaly/v16/internal/git/trace2"
+	"gitlab.com/gitlab-org/gitaly/v16/internal/log"
+	"golang.org/x/time/rate"
+)
+
+// NewLogExporter initializes LogExporter, which is a hook that uses the parsed
+// trace2 events from the manager to export them to the Gitaly log. It's invocations are limited
+// by the rateLimiter. The limiter allows maxBurstToken number of events to happen at once and then
+// replenishes by maxEventPerSecond. It works on the token bucket algorithm where you have a number
+// of tokens in the bucket to start and you can consume them in each call whilst the bucket gets
+// refilled at the specified rate.
+func NewLogExporter(rl *rate.Limiter, logger log.Logger) *LogExporter {
+	return &LogExporter{
+		rateLimiter: rl,
+		logger:      logger,
+	}
+}
+
+// LogExporter is a trace2 hook that adds trace2 api event logs to Gitaly's logs.
+type LogExporter struct {
+	logger      log.Logger
+	rateLimiter *rate.Limiter
+}
+
+// Name returns the name of tracing exporter
+func (t *LogExporter) Name() string {
+	return "log_exporter"
+}
+
+// Handle will log the trace in a readable json format in Gitaly's logs. Metadata is also collected
+// and additional information is added to the log. It is also rate limited to protect it from overload
+// when there are a lot of trace2 events triggered from git operations.
+func (t *LogExporter) Handle(rootCtx context.Context, trace *trace2.Trace) error {
+	if !t.rateLimiter.Allow() {
+		// When the event is not allowed, return an error to the caller, this may cause traces to be skipped/dropped.
+		return fmt.Errorf("rate has exceeded current limit")
+	}
+
+	trace.Walk(rootCtx, func(ctx context.Context, t *trace2.Trace) context.Context {
+		t.SetMetadata("elapsed_ms", fmt.Sprintf("%d", t.FinishTime.Sub(t.StartTime).Milliseconds()))
+
+		return ctx
+	})
+
+	childrenJSON, err := json.Marshal(trace.Children)
+	if err != nil {
+		return fmt.Errorf("marshal json: %w", err)
+	}
+	escapedChildren := json.RawMessage(childrenJSON)
+
+	t.logger.WithFields(log.Fields{
+		"name":        trace.Name,
+		"thread":      trace.Thread,
+		"component":   "trace2hooks." + t.Name(),
+		"start_time":  trace.StartTime,
+		"finish_time": trace.FinishTime,
+		"metadata":    trace.Metadata,
+		"children":    escapedChildren,
+	}).Info("Git Trace2 API")
+	return nil
+}
diff --git a/internal/git/trace2hooks/log_exporter_test.go b/internal/git/trace2hooks/log_exporter_test.go
new file mode 100644
index 000000000..6edf998f2
--- /dev/null
+++ b/internal/git/trace2hooks/log_exporter_test.go
@@ -0,0 +1,190 @@
+package trace2hooks
+
+import (
+	"context"
+	"encoding/json"
+	"regexp"
+	"testing"
+	"time"
+
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+	"gitlab.com/gitlab-org/gitaly/v16/internal/git/trace2"
+	"gitlab.com/gitlab-org/gitaly/v16/internal/testhelper"
+	"golang.org/x/time/rate"
+)
+
+func TestLogExporter_Handle(t *testing.T) {
+	current, err := time.Parse("2006-01-02T15:04:05Z", "2023-01-01T00:00:00Z")
+	require.NoError(t, err)
+	endTime := current.Add(7 * time.Second)
+	exampleTrace := createExampleTrace(current)
+
+	for _, tc := range []struct {
+		desc          string
+		setup         func(*testing.T) (context.Context, *trace2.Trace)
+		expectedTrace trace2.Trace
+	}{
+		{
+			desc: "receives trace consisting of root only",
+			setup: func(t *testing.T) (context.Context, *trace2.Trace) {
+				ctx := testhelper.Context(t)
+				return ctx, &trace2.Trace{
+					Thread:     "main",
+					Name:       "root",
+					StartTime:  current,
+					FinishTime: endTime,
+				}
+			},
+			expectedTrace: trace2.Trace{
+				Thread:     "main",
+				Name:       "root",
+				StartTime:  current,
+				FinishTime: endTime,
+				Metadata:   map[string]string{"elapsed_ms": "7000"},
+			},
+		},
+		{
+			desc: "receives a complete trace",
+			setup: func(t *testing.T) (context.Context, *trace2.Trace) {
+				ctx := testhelper.Context(t)
+				return ctx, exampleTrace
+			},
+			expectedTrace: trace2.Trace{
+				Thread:     "main",
+				Name:       "root",
+				StartTime:  current,
+				FinishTime: endTime,
+				Metadata:   map[string]string{"elapsed_ms": "7000"},
+				Children: []*trace2.Trace{
+					{
+						Thread:     "main",
+						Name:       "version",
+						StartTime:  current,
+						FinishTime: current.Add(1 * time.Second), Metadata: map[string]string{"exe": "2.42.0", "elapsed_ms": "1000"},
+						Depth: 1,
+					}, {
+						Thread:     "main",
+						Name:       "start",
+						StartTime:  current.Add(1 * time.Second),
+						FinishTime: current.Add(2 * time.Second),
+						Metadata:   map[string]string{"argv": "git fetch origin master", "elapsed_ms": "1000"},
+						Depth:      1,
+					}, {
+						Thread:     "main",
+						Name:       "def_repo",
+						StartTime:  current.Add(2 * time.Second),
+						FinishTime: current.Add(3 * time.Second),
+						Metadata:   map[string]string{"worktree": "/Users/userx123/Documents/gitlab-development-kit", "elapsed_ms": "1000"},
+						Depth:      1,
+					}, {
+						Thread:     "main",
+						Name:       "index:do_read_index",
+						StartTime:  current.Add(3 * time.Second),
+						FinishTime: current.Add(6 * time.Second),
+						Metadata:   map[string]string{"elapsed_ms": "3000"},
+						Depth:      1,
+						Children: []*trace2.Trace{
+							{
+								Thread:     "main",
+								ChildID:    "0",
+								Name:       "cache_tree:read",
+								StartTime:  current.Add(3 * time.Second),
+								FinishTime: current.Add(4 * time.Second),
+								Metadata:   map[string]string{"elapsed_ms": "1000"},
+								Depth:      2,
+							},
+							{
+								Thread:     "main",
+								ChildID:    "0",
+								Name:       "data:index:read/version",
+								StartTime:  current.Add(4 * time.Second),
+								FinishTime: current.Add(5 * time.Second),
+								Metadata:   map[string]string{"data": "2", "elapsed_ms": "1000"},
+								Depth:      2,
+							},
+							{
+								Thread:     "main",
+								ChildID:    "0",
+								Name:       "data:index:read/cache_nr",
+								StartTime:  current.Add(5 * time.Second),
+								FinishTime: current.Add(6 * time.Second),
+								Metadata: map[string]string{
+									"elapsed_ms": "1000",
+									"data":       "1500",
+								},
+								Depth: 2,
+							},
+						},
+					}, {
+						Thread:     "main",
+						Name:       "submodule:parallel/fetch",
+						StartTime:  current.Add(6 * time.Second),
+						FinishTime: current.Add(7 * time.Second),
+						Metadata:   map[string]string{"elapsed_ms": "1000"},
+						Depth:      1,
+					},
+				},
+			},
+		},
+	} {
+		t.Run(tc.desc, func(t *testing.T) {
+			ctx, trace := tc.setup(t)
+			logger := testhelper.NewLogger(t)
+			hook := testhelper.AddLoggerHook(logger)
+			exporter := NewLogExporter(rate.NewLimiter(1, 1), logger)
+			// execute and assertions
+			err := exporter.Handle(ctx, trace)
+			require.NoError(t, err)
+			logEntry := hook.LastEntry()
+
+			assert.Equal(t, tc.expectedTrace.Thread, logEntry.Data["thread"])
+			assert.Equal(t, tc.expectedTrace.Name, logEntry.Data["name"])
+			assert.Equal(t, tc.expectedTrace.Metadata, logEntry.Data["metadata"])
+			assert.Equal(t, tc.expectedTrace.StartTime, logEntry.Data["start_time"])
+			assert.Equal(t, tc.expectedTrace.FinishTime, logEntry.Data["finish_time"])
+			var children []*trace2.Trace
+			childErr := json.Unmarshal(logEntry.Data["children"].(json.RawMessage), &children)
+			require.NoError(t, childErr)
+			assert.Equal(t, tc.expectedTrace.Children, children)
+		})
+	}
+}
+
+func TestLogExporter_rateLimitFailureMock(t *testing.T) {
+	errorMsg := "rate has exceeded current limit"
+
+	for _, tc := range []struct {
+		desc          string
+		setup         func(*testing.T) (context.Context, *trace2.Trace)
+		expectedError *regexp.Regexp
+	}{
+		{
+			desc: "rate limit exceeded",
+			setup: func(t *testing.T) (context.Context, *trace2.Trace) {
+				ctx := testhelper.Context(t)
+				return ctx, &trace2.Trace{
+					Thread:     "main",
+					Name:       "root",
+					StartTime:  time.Time{},
+					FinishTime: time.Time{}.Add(1 * time.Second),
+				}
+			},
+			expectedError: regexp.MustCompile(errorMsg),
+		},
+	} {
+		t.Run(tc.desc, func(t *testing.T) {
+			ctx, trace := tc.setup(t)
+			logger := testhelper.SharedLogger(t)
+
+			rl := rate.NewLimiter(0, 1) // burst limit of 1, refreshing at 0 rps
+
+			exporter := LogExporter{rateLimiter: rl, logger: logger}
+			err := exporter.Handle(ctx, trace)
+			require.NoError(t, err)
+			err = exporter.Handle(ctx, trace)
+			require.Error(t, err)
+			require.Regexp(t, tc.expectedError, err)
+		})
+	}
+}
diff --git a/internal/git/trace2hooks/trace_helper_test.go b/internal/git/trace2hooks/trace_helper_test.go
new file mode 100644
index 000000000..267711990
--- /dev/null
+++ b/internal/git/trace2hooks/trace_helper_test.go
@@ -0,0 +1,101 @@
+package trace2hooks
+
+import (
+	"time"
+
+	"gitlab.com/gitlab-org/gitaly/v16/internal/git/trace2"
+)
+
+func createExampleTrace(startTime time.Time) *trace2.Trace {
+	//                         0s    1s    2s    3s    4s    5s    6s    7s
+	// root                    |---->|---->|---->|---->|---->|---->|---->|
+	// version                 |---->|     |     |     |     |     |     |
+	// start                   |     |---->|     |     |     |     |     |
+	// def_repo                |     |     |---->|     |     |     |     |
+	// index:do_read_index     |     |     |     |---->|---->|---->|     |
+	// cache_tree:read         |     |     |     |---->|     |     |     |
+	// data:index:read/version |     |     |     |     |---->|     |     |
+	// data:index:read/cache_nr|     |     |     |     |     |---->|     |
+	// submodule:parallel/fetch|     |     |     |     |     |     |---->|
+	return connectChildren(&trace2.Trace{
+		Thread:     "main",
+		Name:       "root",
+		StartTime:  startTime,
+		FinishTime: startTime.Add(7 * time.Second),
+		Depth:      0,
+		Children: []*trace2.Trace{
+			{
+				Thread:     "main",
+				Name:       "version",
+				StartTime:  startTime,
+				FinishTime: startTime.Add(1 * time.Second), Metadata: map[string]string{"exe": "2.42.0"},
+				Depth: 1,
+			},
+			{
+				Thread:     "main",
+				Name:       "start",
+				StartTime:  startTime.Add(1 * time.Second),
+				FinishTime: startTime.Add(2 * time.Second),
+				Metadata:   map[string]string{"argv": "git fetch origin master"},
+				Depth:      1,
+			},
+			{
+				Thread:     "main",
+				Name:       "def_repo",
+				StartTime:  startTime.Add(2 * time.Second),
+				FinishTime: startTime.Add(3 * time.Second),
+				Metadata:   map[string]string{"worktree": "/Users/userx123/Documents/gitlab-development-kit"},
+				Depth:      1,
+			},
+			connectChildren(&trace2.Trace{
+				Thread:     "main",
+				Name:       "index:do_read_index",
+				StartTime:  startTime.Add(3 * time.Second),
+				FinishTime: startTime.Add(6 * time.Second),
+				Depth:      1,
+				Children: []*trace2.Trace{
+					{
+						Thread:     "main",
+						Name:       "cache_tree:read",
+						ChildID:    "0",
+						StartTime:  startTime.Add(3 * time.Second),
+						FinishTime: startTime.Add(4 * time.Second),
+						Depth:      2,
+					},
+					{
+						Thread:     "main",
+						ChildID:    "0",
+						Name:       "data:index:read/version",
+						StartTime:  startTime.Add(4 * time.Second),
+						FinishTime: startTime.Add(5 * time.Second),
+						Metadata:   map[string]string{"data": "2"},
+						Depth:      2,
+					},
+					{
+						Thread:     "main",
+						ChildID:    "0",
+						Name:       "data:index:read/cache_nr",
+						StartTime:  startTime.Add(5 * time.Second),
+						FinishTime: startTime.Add(6 * time.Second),
+						Metadata:   map[string]string{"data": "1500"},
+						Depth:      2,
+					},
+				},
+			}),
+			{
+				Thread:     "main",
+				Name:       "submodule:parallel/fetch",
+				StartTime:  startTime.Add(6 * time.Second),
+				FinishTime: startTime.Add(7 * time.Second),
+				Depth:      1,
+			},
+		},
+	})
+}
+
+func connectChildren(trace *trace2.Trace) *trace2.Trace {
+	for _, t := range trace.Children {
+		t.Parent = trace
+	}
+	return trace
+}
diff --git a/internal/git/trace2hooks/tracingexporter_test.go b/internal/git/trace2hooks/tracingexporter_test.go
index 062f98a96..0c7ab5a91 100644
--- a/internal/git/trace2hooks/tracingexporter_test.go
+++ b/internal/git/trace2hooks/tracingexporter_test.go
@@ -20,80 +20,7 @@ func TestTracingExporter_Handle(t *testing.T) {
 	current, err := time.Parse("2006-01-02T15:04:05Z", "2023-01-01T00:00:00Z")
 	require.NoError(t, err)
 
-	//                         0s    1s    2s    3s    4s    5s    6s    7s
-	// root                    |---->|---->|---->|---->|---->|---->|---->|
-	// version                 |---->|     |     |     |     |     |     |
-	// start                   |     |---->|     |     |     |     |     |
-	// def_repo                |     |     |---->|     |     |     |     |
-	// index:do_read_index     |     |     |     |---->|---->|---->|     |
-	// cache_tree:read         |     |     |     |---->|     |     |     |
-	// data:index:read/version |     |     |     |     |---->|     |     |
-	// data:index:read/cache_nr|     |     |     |     |     |---->|     |
-	// submodule:parallel/fetch|     |     |     |     |     |     |---->|
-	exampleTrace := connectChildren(&trace2.Trace{
-		Thread:     "main",
-		Name:       "root",
-		StartTime:  current,
-		FinishTime: current.Add(7 * time.Second),
-		Children: []*trace2.Trace{
-			{
-				Thread:     "main",
-				Name:       "version",
-				StartTime:  current,
-				FinishTime: current.Add(1 * time.Second),
-			},
-			{
-				Thread:     "main",
-				Name:       "start",
-				StartTime:  current.Add(1 * time.Second),
-				FinishTime: current.Add(2 * time.Second),
-				Metadata:   map[string]string{"argv": "git fetch origin master"},
-			},
-			{
-				Thread:     "main",
-				Name:       "def_repo",
-				StartTime:  current.Add(2 * time.Second),
-				FinishTime: current.Add(3 * time.Second),
-			},
-			connectChildren(&trace2.Trace{
-				Thread:     "main",
-				Name:       "index:do_read_index",
-				StartTime:  current.Add(3 * time.Second),
-				FinishTime: current.Add(6 * time.Second),
-				Children: []*trace2.Trace{
-					{
-						Thread:     "main",
-						Name:       "cache_tree:read",
-						ChildID:    "0",
-						StartTime:  current.Add(3 * time.Second),
-						FinishTime: current.Add(4 * time.Second),
-					},
-					{
-						Thread:     "main",
-						ChildID:    "0",
-						Name:       "data:index:read/version",
-						StartTime:  current.Add(4 * time.Second),
-						FinishTime: current.Add(5 * time.Second),
-						Metadata:   map[string]string{"data": "2"},
-					},
-					{
-						Thread:     "main",
-						ChildID:    "0",
-						Name:       "data:index:read/cache_nr",
-						StartTime:  current.Add(5 * time.Second),
-						FinishTime: current.Add(6 * time.Second),
-						Metadata:   map[string]string{"data": "1500"},
-					},
-				},
-			}),
-			{
-				Thread:     "main",
-				Name:       "submodule:parallel/fetch",
-				StartTime:  current.Add(6 * time.Second),
-				FinishTime: current.Add(7 * time.Second),
-			},
-		},
-	})
+	exampleTrace := createExampleTrace(current)
 
 	for _, tc := range []struct {
 		desc          string
@@ -136,6 +63,7 @@ func TestTracingExporter_Handle(t *testing.T) {
 					Tags: map[string]string{
 						"childID": "",
 						"thread":  "main",
+						"exe":     "2.42.0",
 					},
 				},
 				{
@@ -153,8 +81,9 @@ func TestTracingExporter_Handle(t *testing.T) {
 					StartTime: current.Add(2 * time.Second),
 					Duration:  1 * time.Second,
 					Tags: map[string]string{
-						"childID": "",
-						"thread":  "main",
+						"childID":  "",
+						"thread":   "main",
+						"worktree": "/Users/userx123/Documents/gitlab-development-kit",
 					},
 				},
 				{
@@ -227,10 +156,3 @@ func TestTracingExporter_Handle(t *testing.T) {
 		})
 	}
 }
-
-func connectChildren(trace *trace2.Trace) *trace2.Trace {
-	for _, t := range trace.Children {
-		t.Parent = trace
-	}
-	return trace
-}
diff --git a/internal/testhelper/testhelper.go b/internal/testhelper/testhelper.go
index 59663b0ab..39f371de3 100644
--- a/internal/testhelper/testhelper.go
+++ b/internal/testhelper/testhelper.go
@@ -262,6 +262,8 @@ func ContextWithoutCancel(opts ...ContextOpt) context.Context {
 	ctx = featureflag.ContextWithFeatureFlag(ctx, featureflag.ExecCommandDirectlyInCgroup, rand.Int()%2 == 0)
 	// Randomly enable newer Git version.
 	ctx = featureflag.ContextWithFeatureFlag(ctx, featureflag.GitV243, rand.Int()%2 == 0)
+	// Disable LogGitTraces
+	ctx = featureflag.ContextWithFeatureFlag(ctx, featureflag.LogGitTraces, false)
 
 	for _, opt := range opts {
 		ctx = opt(ctx)