[Logging] Add Debug logs to git.Merge/Commit (#879)

git/adapter/shared_repo.go

@@ -412,9 +412,11 @@ func (r *SharedRepo) push(
 		} else if gitea.IsErrPushRejected(err) {
 			rejectErr := new(gitea.ErrPushRejected)
 			if errors.As(err, &rejectErr) {
-				log.Ctx(ctx).Info().Msgf("Unable to push back to repo from temporary repo due to rejection:"+
+				log.Ctx(ctx).Warn().Str("repo_uid", r.repoUID).Err(rejectErr).Msgf(
-					" %s \nStdout: %s\nStderr: %s\nError: %v",
+					"Unable to push back to repo from temporary repo due to rejection:\nStdout: %s\nStderr: %s",
-					r.repoUID, rejectErr.StdOut, rejectErr.StdErr, rejectErr.Err)
+					rejectErr.StdOut,
+					rejectErr.StdErr,
+				)
 			}
 			return err
 		}

git/merge.go

@@ -124,6 +124,8 @@ func (s *Service) Merge(ctx context.Context, params *MergeParams) (MergeOutput,
 		return MergeOutput{}, fmt.Errorf("Merge: params not valid: %w", err)
 	}
 
+	log := log.Ctx(ctx).With().Str("repo_uid", params.RepoUID).Logger()
+
 	repoPath := getFullPathForRepo(s.reposRoot, params.RepoUID)
 
 	baseBranch := "base"
@@ -135,6 +137,8 @@ func (s *Service) Merge(ctx context.Context, params *MergeParams) (MergeOutput,
 		HeadBranch:   params.HeadBranch,
 	}
 
+	log.Debug().Msg("create temporary repository")
+
 	// Clone base repo.
 	tmpRepo, err := s.adapter.CreateTemporaryRepoForPR(ctx, s.tmpDir, pr, baseBranch, trackingBranch)
 	if err != nil {
@@ -143,10 +147,12 @@ func (s *Service) Merge(ctx context.Context, params *MergeParams) (MergeOutput,
 	defer func() {
 		rmErr := tempdir.RemoveTemporaryPath(tmpRepo.Path)
 		if rmErr != nil {
-			log.Ctx(ctx).Warn().Msgf("Removing temporary location %s for merge operation was not successful", tmpRepo.Path)
+			log.Warn().Msgf("Removing temporary location %s for merge operation was not successful", tmpRepo.Path)
 		}
 	}()
 
+	log.Debug().Msg("get merge base")
+
 	mergeBaseCommitSHA, _, err := s.adapter.GetMergeBase(ctx, tmpRepo.Path, "origin", baseBranch, trackingBranch)
 	if err != nil {
 		return MergeOutput{}, fmt.Errorf("failed to get merge base: %w", err)
@@ -165,6 +171,8 @@ func (s *Service) Merge(ctx context.Context, params *MergeParams) (MergeOutput,
 			params.HeadExpectedSHA)
 	}
 
+	log.Debug().Msg("get diff tree")
+
 	var outbuf, errbuf strings.Builder
 	// Enable sparse-checkout
 	sparseCheckoutList, err := s.adapter.GetDiffTree(ctx, tmpRepo.Path, baseBranch, trackingBranch)
@@ -172,6 +180,8 @@ func (s *Service) Merge(ctx context.Context, params *MergeParams) (MergeOutput,
 		return MergeOutput{}, fmt.Errorf("execution of GetDiffTree failed: %w", err)
 	}
 
+	log.Debug().Msg("prepare sparse-checkout")
+
 	infoPath := filepath.Join(tmpRepo.Path, ".git", "info")
 	if err = os.MkdirAll(infoPath, 0o700); err != nil {
 		return MergeOutput{}, fmt.Errorf("unable to create .git/info in tmpRepo.Path: %w", err)
@@ -183,12 +193,16 @@ func (s *Service) Merge(ctx context.Context, params *MergeParams) (MergeOutput,
 			fmt.Errorf("unable to write .git/info/sparse-checkout file in tmpRepo.Path: %w", err)
 	}
 
+	log.Debug().Msg("get diff stats")
+
 	shortStat, err := s.adapter.DiffShortStat(ctx, tmpRepo.Path, tmpRepo.BaseSHA, tmpRepo.HeadSHA, true)
 	if err != nil {
 		return MergeOutput{}, fmt.Errorf("execution of DiffShortStat failed: %w", err)
 	}
 	changedFileCount := shortStat.Files
 
+	log.Debug().Msg("get commit divergene")
+
 	divergences, err := s.adapter.GetCommitDivergences(ctx, tmpRepo.Path,
 		[]types.CommitDivergenceRequest{{From: tmpRepo.HeadSHA, To: tmpRepo.BaseSHA}}, 0)
 	if err != nil {
@@ -196,6 +210,8 @@ func (s *Service) Merge(ctx context.Context, params *MergeParams) (MergeOutput,
 	}
 	commitCount := int(divergences[0].Ahead)
 
+	log.Debug().Msg("update git configuration")
+
 	// Switch off LFS process (set required, clean and smudge here also)
 	if err = s.adapter.Config(ctx, tmpRepo.Path, "filter.lfs.process", ""); err != nil {
 		return MergeOutput{}, err
@@ -217,6 +233,8 @@ func (s *Service) Merge(ctx context.Context, params *MergeParams) (MergeOutput,
 		return MergeOutput{}, err
 	}
 
+	log.Debug().Msg("read tree")
+
 	// Read base branch index
 	if err = s.adapter.ReadTree(ctx, tmpRepo.Path, "HEAD", io.Discard); err != nil {
 		return MergeOutput{}, fmt.Errorf("failed to read tree: %w", err)
@@ -262,6 +280,8 @@ func (s *Service) Merge(ctx context.Context, params *MergeParams) (MergeOutput,
 		params.Method = enum.MergeMethodMerge
 	}
 
+	log.Debug().Msg("perform merge")
+
 	result, err := s.adapter.Merge(
 		ctx,
 		pr,
@@ -291,12 +311,16 @@ func (s *Service) Merge(ctx context.Context, params *MergeParams) (MergeOutput,
 		}, nil
 	}
 
+	log.Debug().Msg("get commit id")
+
 	mergeCommitSHA, err := s.adapter.GetFullCommitID(ctx, tmpRepo.Path, baseBranch)
 	if err != nil {
 		return MergeOutput{}, fmt.Errorf("failed to get full commit id for the new merge: %w", err)
 	}
 
 	if params.RefType == enum.RefTypeUndefined {
+		log.Debug().Msg("done (merge-check only)")
+
 		return MergeOutput{
 			BaseSHA:          tmpRepo.BaseSHA,
 			HeadSHA:          tmpRepo.HeadSHA,
@@ -316,6 +340,8 @@ func (s *Service) Merge(ctx context.Context, params *MergeParams) (MergeOutput,
 	}
 	pushRef := baseBranch + ":" + refPath
 
+	log.Debug().Msg("push to original repo")
+
 	if err = s.adapter.Push(ctx, tmpRepo.Path, types.PushOptions{
 		Remote: "origin",
 		Branch: pushRef,
@@ -325,6 +351,8 @@ func (s *Service) Merge(ctx context.Context, params *MergeParams) (MergeOutput,
 		return MergeOutput{}, fmt.Errorf("failed to push merge commit to ref '%s': %w", refPath, err)
 	}
 
+	log.Debug().Msg("done")
+
 	return MergeOutput{
 		BaseSHA:          tmpRepo.BaseSHA,
 		HeadSHA:          tmpRepo.HeadSHA,

git/operations.go

@@ -30,6 +30,7 @@ import (
 
 	"code.gitea.io/gitea/modules/git"
 	"code.gitea.io/gitea/services/repository/files"
+	"github.com/rs/zerolog/log"
 	"golang.org/x/exp/slices"
 )
 
@@ -95,6 +96,8 @@ func (s *Service) CommitFiles(ctx context.Context, params *CommitFilesParams) (C
 		return CommitFilesResponse{}, err
 	}
 
+	log := log.Ctx(ctx).With().Str("repo_uid", params.RepoUID).Logger()
+
 	committer := params.Actor
 	if params.Committer != nil {
 		committer = *params.Committer
@@ -115,11 +118,15 @@ func (s *Service) CommitFiles(ctx context.Context, params *CommitFilesParams) (C
 
 	repoPath := getFullPathForRepo(s.reposRoot, params.RepoUID)
 
+	log.Debug().Msg("open repository")
+
 	repo, err := s.adapter.OpenRepository(ctx, repoPath)
 	if err != nil {
 		return CommitFilesResponse{}, fmt.Errorf("CommitFiles: failed to open repo: %w", err)
 	}
 
+	log.Debug().Msg("check if empty")
+
 	// check if repo is empty
 	// IMPORTANT: we don't use gitea's repo.IsEmpty() as that only checks whether the default branch exists (in HEAD).
 	// This can be an issue in case someone created a branch already in the repo (just default branch is missing).
@@ -130,11 +137,15 @@ func (s *Service) CommitFiles(ctx context.Context, params *CommitFilesParams) (C
 		return CommitFilesResponse{}, fmt.Errorf("CommitFiles: failed to determine if repository is empty: %w", err)
 	}
 
+	log.Debug().Msg("validate and prepare input")
+
 	// ensure input data is valid
 	if err = s.validateAndPrepareHeader(repo, isEmpty, params); err != nil {
 		return CommitFilesResponse{}, err
 	}
 
+	log.Debug().Msg("create shared repo")
+
 	// create a new shared repo
 	shared, err := s.adapter.SharedRepository(s.tmpDir, params.RepoUID, repo.Path)
 	if err != nil {
@@ -142,6 +153,8 @@ func (s *Service) CommitFiles(ctx context.Context, params *CommitFilesParams) (C
 	}
 	defer shared.Close(ctx)
 
+	log.Debug().Msgf("prepare tree (empty: %t)", isEmpty)
+
 	// handle empty repo separately (as branch doesn't exist, no commit exists, ...)
 	var parentCommitSHA string
 	if isEmpty {
@@ -156,6 +169,8 @@ func (s *Service) CommitFiles(ctx context.Context, params *CommitFilesParams) (C
 		}
 	}
 
+	log.Debug().Msg("write tree")
+
 	// Now write the tree
 	treeHash, err := shared.WriteTree(ctx)
 	if err != nil {
@@ -167,6 +182,8 @@ func (s *Service) CommitFiles(ctx context.Context, params *CommitFilesParams) (C
 		message += "\n\n" + strings.TrimSpace(params.Message)
 	}
 
+	log.Debug().Msg("commit tree")
+
 	// Now commit the tree
 	commitSHA, err := shared.CommitTreeWithDate(
 		ctx,
@@ -189,16 +206,22 @@ func (s *Service) CommitFiles(ctx context.Context, params *CommitFilesParams) (C
 		return CommitFilesResponse{}, fmt.Errorf("failed to commit the tree: %w", err)
 	}
 
+	log.Debug().Msg("push branch to original repo")
+
 	env := CreateEnvironmentForPush(ctx, params.WriteParams)
 	if err = shared.PushCommitToBranch(ctx, commitSHA, params.NewBranch, false, env...); err != nil {
 		return CommitFilesResponse{}, fmt.Errorf("failed to push commits to remote repository: %w", err)
 	}
 
+	log.Debug().Msg("get commit")
+
 	commit, err := shared.GetCommit(commitSHA)
 	if err != nil {
 		return CommitFilesResponse{}, fmt.Errorf("failed to get commit for SHA %s: %w", commitSHA, err)
 	}
 
+	log.Debug().Msg("done")
+
 	return CommitFilesResponse{
 		CommitID: commit.ID.String(),
 	}, nil