fix: trace git command correctly (#39520)

Help  #39410

modules/git/gitcmd/command.go

@@ -49,8 +49,8 @@ type Command struct {
 	cmd *process.Cmd
 
 	cmdCtx       context.Context
-	cmdCancel    process.CancelCauseFunc
+	cmdCtxCancel process.CancelCauseFunc
-	cmdFinished  process.FinishedFunc
+	cmdFinished  func()
 	cmdStartTime time.Time
 
 	pipelineFunc func(Context) error
@@ -428,19 +428,24 @@ func (c *Command) Start(ctx context.Context) (retErr error) {
 	if c.callerInfo == "" {
 		c.WithParentCallerInfo()
 	}
+
 	// these logs are for debugging purposes only, so no guarantee of correctness or stability
 	desc := fmt.Sprintf("git.Run(by:%s, repo:%s): %s", c.callerInfo, logArgSanitize(c.gitDir), cmdLogString)
 	log.Debug("git.Command: %s", desc)
 
 	_, span := gtprof.GetTracer().Start(ctx, gtprof.TraceSpanGitRun)
-	defer span.End()
 	span.SetAttributeString(gtprof.TraceAttrFuncCaller, c.callerInfo)
 	span.SetAttributeString(gtprof.TraceAttrGitCommand, cmdLogString)
 
+	var cmdCtxFinished func()
 	if c.cmdTimeout <= 0 {
-		c.cmdCtx, c.cmdCancel, c.cmdFinished = process.GetManager().AddContext(ctx, desc)
+		c.cmdCtx, c.cmdCtxCancel, cmdCtxFinished = process.GetManager().AddContext(ctx, desc)
 	} else {
-		c.cmdCtx, c.cmdCancel, c.cmdFinished = process.GetManager().AddContextTimeout(ctx, c.cmdTimeout, desc)
+		c.cmdCtx, c.cmdCtxCancel, cmdCtxFinished = process.GetManager().AddContextTimeout(ctx, c.cmdTimeout, desc)
+	}
+	c.cmdFinished = func() {
+		cmdCtxFinished()
+		span.End()
 	}
 
 	c.cmdStartTime = time.Now()

modules/git/gitcmd/context.go

@@ -27,6 +27,6 @@ func (c *cmdContext) CancelPipeline(err error) error {
 	// * context canceled by pipeline caller with/without error (normal cancellation)
 	// * context canceled by parent context (still context.Canceled error)
 	// * other causes
-	c.cmd.cmdCancel(pipelineError{err})
+	c.cmd.cmdCtxCancel(pipelineError{err})
 	return err
 }

modules/gtprof/trace.go

@@ -122,6 +122,8 @@ func (t *Tracer) Start(ctx context.Context, spanName string) (context.Context, *
 		ts.parent = parentSpan
 	}
 
+	// FIXME: this ctx handling is not right. The returned ctx should inherit the ctx passed in, but not from span's internal contexts
+	// The returned ctx only needs to inherit the values of the internal contexts of spans
 	parentCtx := ctx
 	for internalSpanIdx, tsp := range starters {
 		var internalSpan traceSpanInternal

modules/gtprof/trace_const.go

@@ -6,14 +6,17 @@ package gtprof
 // Some interesting names could be found in https://github.com/open-telemetry/opentelemetry-go/tree/main/semconv
 
 const (
+	TraceSpanContext  = "context"
 	TraceSpanHTTP     = "http"
 	TraceSpanGitRun   = "git-run"
 	TraceSpanDatabase = "database"
 )
 
 const (
-	TraceAttrFuncCaller = "func.caller"
+	TraceAttrGeneralName = "general.name"
-	TraceAttrDbSQL      = "db.sql"
+	TraceAttrGeneralDesc = "general.desc"
-	TraceAttrGitCommand = "git.command"
+	TraceAttrFuncCaller  = "func.caller"
-	TraceAttrHTTPRoute  = "http.route"
+	TraceAttrDbSQL       = "db.sql"
+	TraceAttrGitCommand  = "git.command"
+	TraceAttrHTTPRoute   = "http.route"
 )

routers/api/v1/repo/pull.go

@@ -1032,7 +1032,7 @@ func MergePullRequest(ctx *context.APIContext) {
 		}
 	}
 
-	if err := pull_service.Merge(pr.ID, ctx.Doer, repo_model.MergeStyle(form.Do), form.HeadCommitID, message, false); err != nil {
+	if err := pull_service.Merge(ctx, pr.ID, ctx.Doer, repo_model.MergeStyle(form.Do), form.HeadCommitID, message, false); err != nil {
 		if pull_service.IsErrInvalidMergeStyle(err) {
 			ctx.APIError(http.StatusMethodNotAllowed, fmt.Sprintf("%s is not allowed an allowed merge style for this repository", repo_model.MergeStyle(form.Do)))
 		} else if conflictError, ok := err.(pull_service.ErrMergeConflicts); ok {

routers/web/repo/pull.go

@@ -1145,7 +1145,7 @@ func MergePullRequest(ctx *context.Context) {
 		}
 	}
 
-	if err := pull_service.Merge(pr.ID, ctx.Doer, repo_model.MergeStyle(form.Do), form.HeadCommitID, message, false); err != nil {
+	if err := pull_service.Merge(ctx, pr.ID, ctx.Doer, repo_model.MergeStyle(form.Do), form.HeadCommitID, message, false); err != nil {
 		if pull_service.IsErrInvalidMergeStyle(err) {
 			ctx.JSONError(ctx.Tr("repo.pulls.invalid_merge_option"))
 		} else if conflictError, ok := err.(pull_service.ErrMergeConflicts); ok {

services/automerge/automerge.go

@@ -224,7 +224,7 @@ func handlePullRequestAutoMerge(ctx context.Context, pr *issues_model.PullReques
 
 	// although expectedHeadCommitID is checked before, we should pass it to the Merge function to
 	// make it be checked again in case the head commit id changed after the previous check.
-	if err := pull_service.Merge(pr.ID, doer, scheduledPRM.MergeStyle, expectedHeadCommitID, scheduledPRM.Message, true); err != nil {
+	if err := pull_service.Merge(ctx, pr.ID, doer, scheduledPRM.MergeStyle, expectedHeadCommitID, scheduledPRM.Message, true); err != nil {
 		if pull_service.IsErrSHADoesNotMatch(err) {
 			return errors.Join(errSkipAutoMerge, err)
 		}

services/pull/merge.go

@@ -14,6 +14,7 @@ import (
 	"strconv"
 	"strings"
 	"unicode"
+	"uuid"
 
 	"gitea.dev/models/db"
 	git_model "gitea.dev/models/git"
@@ -27,6 +28,7 @@ import (
 	"gitea.dev/modules/git/gitcmd"
 	"gitea.dev/modules/globallock"
 	"gitea.dev/modules/graceful"
+	"gitea.dev/modules/gtprof"
 	"gitea.dev/modules/httplib"
 	"gitea.dev/modules/log"
 	"gitea.dev/modules/references"
@@ -289,9 +291,22 @@ func hasPullRequestCommitBeenMerged(ctx context.Context, pr *issues_model.PullRe
 
 // Merge merges pull request to base repository.
 // Caller should check PR is ready to be merged (review and status checks)
-func Merge(prID int64, doer *user_model.User, mergeStyle repo_model.MergeStyle, expectedHeadCommitID, message string, wasAutoMerged bool) error {
+func Merge(outerCtx context.Context, prID int64, doer *user_model.User, mergeStyle repo_model.MergeStyle, expectedHeadCommitID, message string, wasAutoMerged bool) error {
+	outerCtxId := uuid.NewV4().String()
+
+	_, outerSpan := gtprof.GetTracer().Start(outerCtx, gtprof.TraceSpanContext)
+	outerSpan.SetAttributeString("context.trace-id", outerCtxId) // this attribute is only used internally for debugging purpose
+	defer outerSpan.End()
+
+	// TODO: in the future, the contexts from graceful.GetManager() should be wrapped with gtprof tracing, refactor the code to framework-level support
 	ctx := graceful.GetManager().HammerContext() // don't abort the git operation even if the user's request is canceled
 
+	ctx, span := gtprof.GetTracer().Start(ctx, gtprof.TraceSpanContext)
+	span.SetAttributeString(gtprof.TraceAttrGeneralName, "merge-pull-request")
+	span.SetAttributeString(gtprof.TraceAttrGeneralDesc, fmt.Sprintf("merge pull request %d with merge style %s", prID, mergeStyle))
+	span.SetAttributeString("context.trace-id-outer", outerCtxId) // this attribute is only used internally for debugging purpose
+	defer span.End()
+
 	err := globallock.LockAndDo(ctx, getPullWorkingLockKey(prID), func(ctx context.Context) error {
 		pr, err := issues_model.GetPullRequestByID(ctx, prID)
 		if err != nil {

tests/integration/pull_merge_test.go

@@ -378,11 +378,11 @@ func TestCantMergeConflict(t *testing.T) {
 			BaseBranch: "base",
 		})
 
-		err := pull_service.Merge(pr.ID, user1, repo_model.MergeStyleMerge, "", "CONFLICT", false)
+		err := pull_service.Merge(t.Context(), pr.ID, user1, repo_model.MergeStyleMerge, "", "CONFLICT", false)
 		assert.Error(t, err, "Merge should return an error due to conflict")
 		assert.True(t, pull_service.IsErrMergeConflicts(err), "Merge error is not a conflict error")
 
-		err = pull_service.Merge(pr.ID, user1, repo_model.MergeStyleRebase, "", "CONFLICT", false)
+		err = pull_service.Merge(t.Context(), pr.ID, user1, repo_model.MergeStyleRebase, "", "CONFLICT", false)
 		assert.Error(t, err, "Merge should return an error due to conflict")
 		assert.True(t, pull_service.IsErrRebaseConflicts(err), "Merge error is not a conflict error")
 	})
@@ -473,7 +473,7 @@ func TestCantMergeUnrelated(t *testing.T) {
 			BaseBranch: "base",
 		})
 
-		err = pull_service.Merge(pr.ID, user1, repo_model.MergeStyleMerge, "", "UNRELATED", false)
+		err = pull_service.Merge(t.Context(), pr.ID, user1, repo_model.MergeStyleMerge, "", "UNRELATED", false)
 		assert.Error(t, err, "Merge should return an error due to unrelated")
 		assert.True(t, pull_service.IsErrMergeUnrelatedHistories(err), "Merge error is not a unrelated histories error")
 	})
@@ -509,7 +509,7 @@ func TestFastForwardOnlyMerge(t *testing.T) {
 			BaseBranch: "master",
 		})
 
-		err := pull_service.Merge(pr.ID, user1, repo_model.MergeStyleFastForwardOnly, "", "FAST-FORWARD-ONLY", false)
+		err := pull_service.Merge(t.Context(), pr.ID, user1, repo_model.MergeStyleFastForwardOnly, "", "FAST-FORWARD-ONLY", false)
 		assert.NoError(t, err)
 	})
 }
@@ -596,7 +596,7 @@ func TestFastForwardOnlyMergeWithRequiredSignedCommits(t *testing.T) {
 		pb.RequireSignedCommits = false
 		require.NoError(t, git_model.UpdateProtectBranch(t.Context(), repo1, pb, git_model.WhitelistOptions{}))
 
-		require.NoError(t, pull_service.Merge(pr.ID, user1, repo_model.MergeStyleFastForwardOnly, "", "FAST-FORWARD-ONLY", false))
+		require.NoError(t, pull_service.Merge(t.Context(), pr.ID, user1, repo_model.MergeStyleFastForwardOnly, "", "FAST-FORWARD-ONLY", false))
 	})
 }
 
@@ -631,7 +631,7 @@ func TestCantFastForwardOnlyMergeDiverging(t *testing.T) {
 			BaseBranch: "master",
 		})
 
-		err := pull_service.Merge(pr.ID, user1, repo_model.MergeStyleFastForwardOnly, "", "DIVERGING", false)
+		err := pull_service.Merge(t.Context(), pr.ID, user1, repo_model.MergeStyleFastForwardOnly, "", "DIVERGING", false)
 		assert.Error(t, err, "Merge should return an error due to being for a diverging branch")
 		assert.True(t, pull_service.IsErrMergeDivergingFastForwardOnly(err), "Merge error is not a diverging fast-forward-only error")
 	})