From 7abeaf3eca9d74c7eaec56e11d280a8cb108289d Mon Sep 17 00:00:00 2001 From: Johannes Batzill Date: Thu, 7 Dec 2023 03:14:45 +0000 Subject: [PATCH] [Logging] Add Debug logs to git.Merge/Commit (#879) --- git/adapter/shared_repo.go | 8 +++++--- git/merge.go | 30 +++++++++++++++++++++++++++++- git/operations.go | 23 +++++++++++++++++++++++ 3 files changed, 57 insertions(+), 4 deletions(-) diff --git a/git/adapter/shared_repo.go b/git/adapter/shared_repo.go index c22cba663..7307004c4 100644 --- a/git/adapter/shared_repo.go +++ b/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:"+ - " %s \nStdout: %s\nStderr: %s\nError: %v", - r.repoUID, rejectErr.StdOut, rejectErr.StdErr, rejectErr.Err) + log.Ctx(ctx).Warn().Str("repo_uid", r.repoUID).Err(rejectErr).Msgf( + "Unable to push back to repo from temporary repo due to rejection:\nStdout: %s\nStderr: %s", + rejectErr.StdOut, + rejectErr.StdErr, + ) } return err } diff --git a/git/merge.go b/git/merge.go index 0b761fa5e..34e1e94db 100644 --- a/git/merge.go +++ b/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, diff --git a/git/operations.go b/git/operations.go index 1b97f0d94..3d029e337 100644 --- a/git/operations.go +++ b/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