From e4238583db1647e05d0d664e5b2adae80b6270dc Mon Sep 17 00:00:00 2001 From: zeripath Date: Mon, 13 Feb 2023 03:17:36 +0000 Subject: [PATCH] Improve trace logging for pulls and processes (#22633) (#22812) Backport #22633 Our trace logging is far from perfect and is difficult to follow. This PR: * Add trace logging for process manager add and remove. * Fixes an errant read file for git refs in getMergeCommit * Brings in the pullrequest `String` and `ColorFormat` methods introduced in #22568 * Adds a lot more logging in to testPR etc. Ref #22578 --------- Signed-off-by: Andrew Thornton --- models/issues/pull.go | 62 +++++++++- modules/log/colors.go | 7 ++ modules/log/log.go | 11 ++ modules/process/manager.go | 22 ++-- modules/process/manager_test.go | 2 +- routers/web/repo/pull.go | 51 ++++----- services/automerge/automerge.go | 26 ++--- services/pull/check.go | 194 ++++++++++++++++---------------- services/pull/patch.go | 2 +- 9 files changed, 230 insertions(+), 147 deletions(-) diff --git a/models/issues/pull.go b/models/issues/pull.go index f03cabc3c828..e772fb1e4369 100644 --- a/models/issues/pull.go +++ b/models/issues/pull.go @@ -9,6 +9,7 @@ import ( "context" "fmt" "io" + "strconv" "strings" "code.gitea.io/gitea/models/db" @@ -133,6 +134,27 @@ const ( PullRequestStatusAncestor ) +func (status PullRequestStatus) String() string { + switch status { + case PullRequestStatusConflict: + return "CONFLICT" + case PullRequestStatusChecking: + return "CHECKING" + case PullRequestStatusMergeable: + return "MERGEABLE" + case PullRequestStatusManuallyMerged: + return "MANUALLY_MERGED" + case PullRequestStatusError: + return "ERROR" + case PullRequestStatusEmpty: + return "EMPTY" + case PullRequestStatusAncestor: + return "ANCESTOR" + default: + return strconv.Itoa(int(status)) + } +} + // PullRequestFlow the flow of pull request type PullRequestFlow int @@ -204,6 +226,42 @@ func DeletePullsByBaseRepoID(ctx context.Context, repoID int64) error { return err } +// ColorFormat writes a colored string to identify this struct +func (pr *PullRequest) ColorFormat(s fmt.State) { + if pr == nil { + log.ColorFprintf(s, "PR[%d]%s#%d[%s...%s:%s]", + log.NewColoredIDValue(0), + log.NewColoredValue("/"), + log.NewColoredIDValue(0), + log.NewColoredValue(""), + log.NewColoredValue("/"), + log.NewColoredValue(""), + ) + return + } + + log.ColorFprintf(s, "PR[%d]", log.NewColoredIDValue(pr.ID)) + if pr.BaseRepo != nil { + log.ColorFprintf(s, "%s#%d[%s...", log.NewColoredValue(pr.BaseRepo.FullName()), + log.NewColoredIDValue(pr.Index), log.NewColoredValue(pr.BaseBranch)) + } else { + log.ColorFprintf(s, "Repo[%d]#%d[%s...", log.NewColoredIDValue(pr.BaseRepoID), + log.NewColoredIDValue(pr.Index), log.NewColoredValue(pr.BaseBranch)) + } + if pr.HeadRepoID == pr.BaseRepoID { + log.ColorFprintf(s, "%s]", log.NewColoredValue(pr.HeadBranch)) + } else if pr.HeadRepo != nil { + log.ColorFprintf(s, "%s:%s]", log.NewColoredValue(pr.HeadRepo.FullName()), log.NewColoredValue(pr.HeadBranch)) + } else { + log.ColorFprintf(s, "Repo[%d]:%s]", log.NewColoredIDValue(pr.HeadRepoID), log.NewColoredValue(pr.HeadBranch)) + } +} + +// String represents the pr as a simple string +func (pr *PullRequest) String() string { + return log.ColorFormatAsString(pr) +} + // MustHeadUserName returns the HeadRepo's username if failed return blank func (pr *PullRequest) MustHeadUserName() string { if err := pr.LoadHeadRepo(); err != nil { @@ -255,7 +313,7 @@ func (pr *PullRequest) LoadHeadRepoCtx(ctx context.Context) (err error) { pr.HeadRepo, err = repo_model.GetRepositoryByIDCtx(ctx, pr.HeadRepoID) if err != nil && !repo_model.IsErrRepoNotExist(err) { // Head repo maybe deleted, but it should still work - return fmt.Errorf("getRepositoryByID(head): %w", err) + return fmt.Errorf("pr[%d].LoadHeadRepo[%d]: %w", pr.ID, pr.HeadRepoID, err) } pr.isHeadRepoLoaded = true } @@ -290,7 +348,7 @@ func (pr *PullRequest) LoadBaseRepoCtx(ctx context.Context) (err error) { pr.BaseRepo, err = repo_model.GetRepositoryByIDCtx(ctx, pr.BaseRepoID) if err != nil { - return fmt.Errorf("repo_model.GetRepositoryByID(base): %w", err) + return fmt.Errorf("pr[%d].LoadBaseRepo[%d]: %w", pr.ID, pr.BaseRepoID, err) } return nil } diff --git a/modules/log/colors.go b/modules/log/colors.go index 15e23a0dac21..d512202f21b5 100644 --- a/modules/log/colors.go +++ b/modules/log/colors.go @@ -384,6 +384,13 @@ func (cv *ColoredValue) Format(s fmt.State, c rune) { s.Write(*cv.resetBytes) } +// ColorFormatAsString returns the result of the ColorFormat without the color +func ColorFormatAsString(colorVal ColorFormatted) string { + s := new(strings.Builder) + _, _ = ColorFprintf(&protectedANSIWriter{w: s, mode: removeColor}, "%-v", colorVal) + return s.String() +} + // SetColorBytes will allow a user to set the colorBytes of a colored value func (cv *ColoredValue) SetColorBytes(colorBytes []byte) { cv.colorBytes = &colorBytes diff --git a/modules/log/log.go b/modules/log/log.go index 4303ecf4c03c..e0a116e5e6b5 100644 --- a/modules/log/log.go +++ b/modules/log/log.go @@ -10,6 +10,8 @@ import ( "runtime" "strings" "sync" + + "code.gitea.io/gitea/modules/process" ) type loggerMap struct { @@ -286,6 +288,15 @@ func (l *LoggerAsWriter) Log(msg string) { } func init() { + process.Trace = func(start bool, pid process.IDType, description string, parentPID process.IDType, typ string) { + if start && parentPID != "" { + Log(1, TRACE, "Start %s: %s (from %s) (%s)", NewColoredValue(pid, FgHiYellow), description, NewColoredValue(parentPID, FgYellow), NewColoredValue(typ, Reset)) + } else if start { + Log(1, TRACE, "Start %s: %s (%s)", NewColoredValue(pid, FgHiYellow), description, NewColoredValue(typ, Reset)) + } else { + Log(1, TRACE, "Done %s: %s", NewColoredValue(pid, FgHiYellow), NewColoredValue(description, Reset)) + } + } _, filename, _, _ := runtime.Caller(0) prefix = strings.TrimSuffix(filename, "modules/log/log.go") if prefix == filename { diff --git a/modules/process/manager.go b/modules/process/manager.go index 7f14287de508..cbdc88cc4b9c 100644 --- a/modules/process/manager.go +++ b/modules/process/manager.go @@ -7,6 +7,7 @@ package process import ( "context" + "log" "runtime/pprof" "strconv" "sync" @@ -44,6 +45,18 @@ type IDType string // - it is simply an alias for context.CancelFunc and is only for documentary purposes type FinishedFunc = context.CancelFunc +var Trace = defaultTrace // this global can be overridden by particular logging packages - thus avoiding import cycles + +func defaultTrace(start bool, pid IDType, description string, parentPID IDType, typ string) { + if start && parentPID != "" { + log.Printf("start process %s: %s (from %s) (%s)", pid, description, parentPID, typ) + } else if start { + log.Printf("start process %s: %s (%s)", pid, description, typ) + } else { + log.Printf("end process %s: %s", pid, description) + } +} + // Manager manages all processes and counts PIDs. type Manager struct { mutex sync.Mutex @@ -155,6 +168,7 @@ func (pm *Manager) Add(ctx context.Context, description string, cancel context.C pm.processMap[pid] = process pm.mutex.Unlock() + Trace(true, pid, description, parentPID, processType) pprofCtx := pprof.WithLabels(ctx, pprof.Labels(DescriptionPProfLabel, description, PPIDPProfLabel, string(parentPID), PIDPProfLabel, string(pid), ProcessTypePProfLabel, processType)) if currentlyRunning { @@ -186,18 +200,12 @@ func (pm *Manager) nextPID() (start time.Time, pid IDType) { return start, pid } -// Remove a process from the ProcessManager. -func (pm *Manager) Remove(pid IDType) { - pm.mutex.Lock() - delete(pm.processMap, pid) - pm.mutex.Unlock() -} - func (pm *Manager) remove(process *process) { pm.mutex.Lock() defer pm.mutex.Unlock() if p := pm.processMap[process.PID]; p == process { delete(pm.processMap, process.PID) + Trace(false, process.PID, process.Description, process.ParentPID, process.Type) } } diff --git a/modules/process/manager_test.go b/modules/process/manager_test.go index 30eabeb37a48..a6d32d950d80 100644 --- a/modules/process/manager_test.go +++ b/modules/process/manager_test.go @@ -83,7 +83,7 @@ func TestManager_Remove(t *testing.T) { assert.NotEqual(t, GetContext(p1Ctx).GetPID(), GetContext(p2Ctx).GetPID(), "expected to get different pids got %s == %s", GetContext(p2Ctx).GetPID(), GetContext(p1Ctx).GetPID()) - pm.Remove(GetPID(p2Ctx)) + finished() _, exists := pm.processMap[GetPID(p2Ctx)] assert.False(t, exists, "PID %d is in the list but shouldn't", GetPID(p2Ctx)) diff --git a/routers/web/repo/pull.go b/routers/web/repo/pull.go index 98b78645dc00..387853677c11 100644 --- a/routers/web/repo/pull.go +++ b/routers/web/repo/pull.go @@ -912,59 +912,54 @@ func MergePullRequest(ctx *context.Context) { pr := issue.PullRequest pr.Issue = issue pr.Issue.Repo = ctx.Repo.Repository - manuallMerge := repo_model.MergeStyle(form.Do) == repo_model.MergeStyleManuallyMerged + manualMerge := repo_model.MergeStyle(form.Do) == repo_model.MergeStyleManuallyMerged forceMerge := form.ForceMerge != nil && *form.ForceMerge // start with merging by checking - if err := pull_service.CheckPullMergable(ctx, ctx.Doer, &ctx.Repo.Permission, pr, manuallMerge, forceMerge); err != nil { - if errors.Is(err, pull_service.ErrIsClosed) { + if err := pull_service.CheckPullMergable(ctx, ctx.Doer, &ctx.Repo.Permission, pr, manualMerge, forceMerge); err != nil { + switch { + case errors.Is(err, pull_service.ErrIsClosed): if issue.IsPull { ctx.Flash.Error(ctx.Tr("repo.pulls.is_closed")) - ctx.Redirect(issue.Link()) } else { ctx.Flash.Error(ctx.Tr("repo.issues.closed_title")) - ctx.Redirect(issue.Link()) } - } else if errors.Is(err, pull_service.ErrUserNotAllowedToMerge) { + case errors.Is(err, pull_service.ErrUserNotAllowedToMerge): ctx.Flash.Error(ctx.Tr("repo.pulls.update_not_allowed")) - ctx.Redirect(issue.Link()) - } else if errors.Is(err, pull_service.ErrHasMerged) { + case errors.Is(err, pull_service.ErrHasMerged): ctx.Flash.Error(ctx.Tr("repo.pulls.has_merged")) - ctx.Redirect(issue.Link()) - } else if errors.Is(err, pull_service.ErrIsWorkInProgress) { + case errors.Is(err, pull_service.ErrIsWorkInProgress): ctx.Flash.Error(ctx.Tr("repo.pulls.no_merge_wip")) - ctx.Redirect(issue.Link()) - } else if errors.Is(err, pull_service.ErrNotMergableState) { + case errors.Is(err, pull_service.ErrNotMergableState): ctx.Flash.Error(ctx.Tr("repo.pulls.no_merge_not_ready")) - ctx.Redirect(issue.Link()) - } else if models.IsErrDisallowedToMerge(err) { + case models.IsErrDisallowedToMerge(err): ctx.Flash.Error(ctx.Tr("repo.pulls.no_merge_not_ready")) - ctx.Redirect(issue.Link()) - } else if asymkey_service.IsErrWontSign(err) { - ctx.Flash.Error(err.Error()) // has not translation ... - ctx.Redirect(issue.Link()) - } else if errors.Is(err, pull_service.ErrDependenciesLeft) { + case asymkey_service.IsErrWontSign(err): + ctx.Flash.Error(err.Error()) // has no translation ... + case errors.Is(err, pull_service.ErrDependenciesLeft): ctx.Flash.Error(ctx.Tr("repo.issues.dependency.pr_close_blocked")) - ctx.Redirect(issue.Link()) - } else { + default: ctx.ServerError("WebCheck", err) + return } + + ctx.Redirect(issue.Link()) return } // handle manually-merged mark - if manuallMerge { + if manualMerge { if err := pull_service.MergedManually(pr, ctx.Doer, ctx.Repo.GitRepo, form.MergeCommitID); err != nil { - if models.IsErrInvalidMergeStyle(err) { + switch { + + case models.IsErrInvalidMergeStyle(err): ctx.Flash.Error(ctx.Tr("repo.pulls.invalid_merge_option")) - ctx.Redirect(issue.Link()) - } else if strings.Contains(err.Error(), "Wrong commit ID") { + case strings.Contains(err.Error(), "Wrong commit ID"): ctx.Flash.Error(ctx.Tr("repo.pulls.wrong_commit_id")) - ctx.Redirect(issue.Link()) - } else { + default: ctx.ServerError("MergedManually", err) + return } - return } ctx.Redirect(issue.Link()) diff --git a/services/automerge/automerge.go b/services/automerge/automerge.go index ca008ebfe6c8..49bd1d0c0296 100644 --- a/services/automerge/automerge.go +++ b/services/automerge/automerge.go @@ -165,7 +165,7 @@ func getPullRequestsByHeadSHA(ctx context.Context, sha string, repo *repo_model. func handlePull(pullID int64, sha string) { ctx, _, finished := process.GetManager().AddContext(graceful.GetManager().HammerContext(), - fmt.Sprintf("Handle AutoMerge of pull[%d] with sha[%s]", pullID, sha)) + fmt.Sprintf("Handle AutoMerge of PR[%d] with sha[%s]", pullID, sha)) defer finished() pr, err := issues_model.GetPullRequestByID(ctx, pullID) @@ -177,7 +177,7 @@ func handlePull(pullID int64, sha string) { // Check if there is a scheduled pr in the db exists, scheduledPRM, err := pull_model.GetScheduledMergeByPullID(ctx, pr.ID) if err != nil { - log.Error("pull[%d] GetScheduledMergeByPullID: %v", pr.ID, err) + log.Error("%-v GetScheduledMergeByPullID: %v", pr, err) return } if !exists { @@ -189,13 +189,13 @@ func handlePull(pullID int64, sha string) { // did not succeed or was not finished yet. if err = pr.LoadHeadRepoCtx(ctx); err != nil { - log.Error("pull[%d] LoadHeadRepoCtx: %v", pr.ID, err) + log.Error("%-v LoadHeadRepo: %v", pr, err) return } headGitRepo, err := git.OpenRepository(ctx, pr.HeadRepo.RepoPath()) if err != nil { - log.Error("OpenRepository: %v", err) + log.Error("OpenRepository %-v: %v", pr.HeadRepo, err) return } defer headGitRepo.Close() @@ -203,40 +203,40 @@ func handlePull(pullID int64, sha string) { headBranchExist := headGitRepo.IsBranchExist(pr.HeadBranch) if pr.HeadRepo == nil || !headBranchExist { - log.Warn("Head branch of auto merge pr does not exist [HeadRepoID: %d, Branch: %s, PR ID: %d]", pr.HeadRepoID, pr.HeadBranch, pr.ID) + log.Warn("Head branch of auto merge %-v does not exist [HeadRepoID: %d, Branch: %s]", pr, pr.HeadRepoID, pr.HeadBranch) return } // Check if all checks succeeded pass, err := pull_service.IsPullCommitStatusPass(ctx, pr) if err != nil { - log.Error("IsPullCommitStatusPass: %v", err) + log.Error("%-v IsPullCommitStatusPass: %v", pr, err) return } if !pass { - log.Info("Scheduled auto merge pr has unsuccessful status checks [PullID: %d]", pr.ID) + log.Info("Scheduled auto merge %-v has unsuccessful status checks", pr) return } // Merge if all checks succeeded doer, err := user_model.GetUserByIDCtx(ctx, scheduledPRM.DoerID) if err != nil { - log.Error("GetUserByIDCtx: %v", err) + log.Error("Unable to get scheduled User[%d]: %v", scheduledPRM.DoerID, err) return } perm, err := access_model.GetUserRepoPermission(ctx, pr.HeadRepo, doer) if err != nil { - log.Error("GetUserRepoPermission: %v", err) + log.Error("GetUserRepoPermission %-v: %v", pr.HeadRepo, err) return } if err := pull_service.CheckPullMergable(ctx, doer, &perm, pr, false, false); err != nil { if errors.Is(pull_service.ErrUserNotAllowedToMerge, err) { - log.Info("PR %d was scheduled to automerge by an unauthorized user", pr.ID) + log.Info("%-v was scheduled to automerge by an unauthorized user", pr) return } - log.Error("pull[%d] CheckPullMergable: %v", pr.ID, err) + log.Error("%-v CheckPullMergable: %v", pr, err) return } @@ -245,13 +245,13 @@ func handlePull(pullID int64, sha string) { baseGitRepo = headGitRepo } else { if err = pr.LoadBaseRepoCtx(ctx); err != nil { - log.Error("LoadBaseRepoCtx: %v", err) + log.Error("%-v LoadBaseRepo: %v", pr, err) return } baseGitRepo, err = git.OpenRepository(ctx, pr.BaseRepo.RepoPath()) if err != nil { - log.Error("OpenRepository: %v", err) + log.Error("OpenRepository %-v: %v", pr.BaseRepo, err) return } defer baseGitRepo.Close() diff --git a/services/pull/check.go b/services/pull/check.go index 1780f1e989b6..d828ee8cd7fa 100644 --- a/services/pull/check.go +++ b/services/pull/check.go @@ -9,7 +9,6 @@ import ( "context" "errors" "fmt" - "os" "strconv" "strings" @@ -27,7 +26,6 @@ import ( "code.gitea.io/gitea/modules/process" "code.gitea.io/gitea/modules/queue" "code.gitea.io/gitea/modules/timeutil" - "code.gitea.io/gitea/modules/util" asymkey_service "code.gitea.io/gitea/services/asymkey" ) @@ -50,14 +48,14 @@ func AddToTaskQueue(pr *issues_model.PullRequest) { pr.Status = issues_model.PullRequestStatusChecking err := pr.UpdateColsIfNotMerged("status") if err != nil { - log.Error("AddToTaskQueue.UpdateCols[%d].(add to queue): %v", pr.ID, err) + log.Error("AddToTaskQueue(%-v).UpdateCols.(add to queue): %v", pr, err) } else { - log.Trace("Adding PR ID: %d to the test pull requests queue", pr.ID) + log.Trace("Adding %-v to the test pull requests queue", pr) } return err }) if err != nil && err != queue.ErrAlreadyInQueue { - log.Error("Error adding prID %d to the test pull requests queue: %v", pr.ID, err) + log.Error("Error adding %-v to the test pull requests queue: %v", pr, err) } } @@ -69,12 +67,14 @@ func CheckPullMergable(stdCtx context.Context, doer *user_model.User, perm *acce } if err := pr.LoadIssueCtx(ctx); err != nil { + log.Error("Unable to load issue[%d] for %-v: %v", pr.IssueID, pr, err) return err } else if pr.Issue.IsClosed { return ErrIsClosed } if allowedMerge, err := IsUserAllowedToMerge(ctx, pr, *perm, doer); err != nil { + log.Error("Error whilst checking if %-v is allowed to merge %-v: %v", doer, pr, err) return err } else if !allowedMerge { return ErrUserNotAllowedToMerge @@ -98,15 +98,19 @@ func CheckPullMergable(stdCtx context.Context, doer *user_model.User, perm *acce } if err := CheckPullBranchProtections(ctx, pr, false); err != nil { - if models.IsErrDisallowedToMerge(err) { - if force { - if isRepoAdmin, err2 := access_model.IsUserRepoAdmin(ctx, pr.BaseRepo, doer); err2 != nil { - return err2 - } else if !isRepoAdmin { - return err - } - } - } else { + if !models.IsErrDisallowedToMerge(err) { + log.Error("Error whilst checking pull branch protection for %-v: %v", pr, err) + return err + } + + if !force { + return err + } + + if isRepoAdmin, err2 := access_model.IsUserRepoAdmin(ctx, pr.BaseRepo, doer); err2 != nil { + log.Error("Unable to check if %-v is a repo admin in %-v: %v", doer, pr.BaseRepo, err2) + return err2 + } else if !isRepoAdmin { return err } } @@ -143,7 +147,7 @@ func isSignedIfRequired(ctx context.Context, pr *issues_model.PullRequest, doer // checkAndUpdateStatus checks if pull request is possible to leaving checking status, // and set to be either conflict or mergeable. func checkAndUpdateStatus(pr *issues_model.PullRequest) { - // Status is not changed to conflict means mergeable. + // If status has not been changed to conflict by testPatch then we are mergeable if pr.Status == issues_model.PullRequestStatusChecking { pr.Status = issues_model.PullRequestStatusMergeable } @@ -151,79 +155,69 @@ func checkAndUpdateStatus(pr *issues_model.PullRequest) { // Make sure there is no waiting test to process before leaving the checking status. has, err := prPatchCheckerQueue.Has(strconv.FormatInt(pr.ID, 10)) if err != nil { - log.Error("Unable to check if the queue is waiting to reprocess pr.ID %d. Error: %v", pr.ID, err) + log.Error("Unable to check if the queue is waiting to reprocess %-v. Error: %v", pr, err) } - if !has { - if err := pr.UpdateColsIfNotMerged("merge_base", "status", "conflicted_files", "changed_protected_files"); err != nil { - log.Error("Update[%d]: %v", pr.ID, err) - } + if has { + log.Trace("Not updating status for %-v as it is due to be rechecked", pr) + return + } + + if err := pr.UpdateColsIfNotMerged("merge_base", "status", "conflicted_files", "changed_protected_files"); err != nil { + log.Error("Update[%-v]: %v", pr, err) } } -// getMergeCommit checks if a pull request got merged +// getMergeCommit checks if a pull request has been merged // Returns the git.Commit of the pull request if merged func getMergeCommit(ctx context.Context, pr *issues_model.PullRequest) (*git.Commit, error) { - if pr.BaseRepo == nil { - var err error - pr.BaseRepo, err = repo_model.GetRepositoryByID(pr.BaseRepoID) - if err != nil { - return nil, fmt.Errorf("GetRepositoryByID: %w", err) - } + if err := pr.LoadBaseRepoCtx(ctx); err != nil { + return nil, fmt.Errorf("unable to load base repo for %s: %w", pr, err) } - indexTmpPath, err := os.MkdirTemp(os.TempDir(), "gitea-"+pr.BaseRepo.Name) - if err != nil { - return nil, fmt.Errorf("Failed to create temp dir for repository %s: %w", pr.BaseRepo.RepoPath(), err) - } - defer func() { - if err := util.RemoveAll(indexTmpPath); err != nil { - log.Warn("Unable to remove temporary index path: %s: Error: %v", indexTmpPath, err) - } - }() + prHeadRef := pr.GetGitRefName() - headFile := pr.GetGitRefName() - - // Check if a pull request is merged into BaseBranch - _, _, err = git.NewCommand(ctx, "merge-base", "--is-ancestor").AddDynamicArguments(headFile, pr.BaseBranch). - RunStdString(&git.RunOpts{Dir: pr.BaseRepo.RepoPath(), Env: []string{"GIT_INDEX_FILE=" + indexTmpPath, "GIT_DIR=" + pr.BaseRepo.RepoPath()}}) - if err != nil { - // Errors are signaled by a non-zero status that is not 1 + // Check if the pull request is merged into BaseBranch + if _, _, err := git.NewCommand(ctx, "merge-base", "--is-ancestor"). + AddDynamicArguments(prHeadRef, pr.BaseBranch). + RunStdString(&git.RunOpts{Dir: pr.BaseRepo.RepoPath()}); err != nil { if strings.Contains(err.Error(), "exit status 1") { + // prHeadRef is not an ancestor of the base branch return nil, nil } - return nil, fmt.Errorf("git merge-base --is-ancestor: %w", err) + // Errors are signaled by a non-zero status that is not 1 + return nil, fmt.Errorf("%-v git merge-base --is-ancestor: %w", pr, err) } - commitIDBytes, err := os.ReadFile(pr.BaseRepo.RepoPath() + "/" + headFile) + // If merge-base successfully exits then prHeadRef is an ancestor of pr.BaseBranch + + // Find the head commit id + prHeadCommitID, err := git.GetFullCommitID(ctx, pr.BaseRepo.RepoPath(), prHeadRef) if err != nil { - return nil, fmt.Errorf("ReadFile(%s): %w", headFile, err) + return nil, fmt.Errorf("GetFullCommitID(%s) in %s: %w", prHeadRef, pr.BaseRepo.FullName(), err) } - commitID := string(commitIDBytes) - if len(commitID) < git.SHAFullLength { - return nil, fmt.Errorf(`ReadFile(%s): invalid commit-ID "%s"`, headFile, commitID) - } - cmd := commitID[:git.SHAFullLength] + ".." + pr.BaseBranch // Get the commit from BaseBranch where the pull request got merged - mergeCommit, _, err := git.NewCommand(ctx, "rev-list", "--ancestry-path", "--merges", "--reverse").AddDynamicArguments(cmd). - RunStdString(&git.RunOpts{Dir: "", Env: []string{"GIT_INDEX_FILE=" + indexTmpPath, "GIT_DIR=" + pr.BaseRepo.RepoPath()}}) + mergeCommit, _, err := git.NewCommand(ctx, "rev-list", "--ancestry-path", "--merges", "--reverse"). + AddDynamicArguments(prHeadCommitID + ".." + pr.BaseBranch). + RunStdString(&git.RunOpts{Dir: pr.BaseRepo.RepoPath()}) if err != nil { return nil, fmt.Errorf("git rev-list --ancestry-path --merges --reverse: %w", err) } else if len(mergeCommit) < git.SHAFullLength { // PR was maybe fast-forwarded, so just use last commit of PR - mergeCommit = commitID[:git.SHAFullLength] + mergeCommit = prHeadCommitID } + mergeCommit = strings.TrimSpace(mergeCommit) gitRepo, err := git.OpenRepository(ctx, pr.BaseRepo.RepoPath()) if err != nil { - return nil, fmt.Errorf("OpenRepository: %w", err) + return nil, fmt.Errorf("%-v OpenRepository: %w", pr.BaseRepo, err) } defer gitRepo.Close() - commit, err := gitRepo.GetCommit(mergeCommit[:git.SHAFullLength]) + commit, err := gitRepo.GetCommit(mergeCommit) if err != nil { - return nil, fmt.Errorf("GetMergeCommit[%v]: %w", mergeCommit[:git.SHAFullLength], err) + return nil, fmt.Errorf("GetMergeCommit[%s]: %w", mergeCommit, err) } return commit, nil @@ -233,7 +227,7 @@ func getMergeCommit(ctx context.Context, pr *issues_model.PullRequest) (*git.Com // When a pull request got manually merged mark the pull request as merged func manuallyMerged(ctx context.Context, pr *issues_model.PullRequest) bool { if err := pr.LoadBaseRepoCtx(ctx); err != nil { - log.Error("PullRequest[%d].LoadBaseRepo: %v", pr.ID, err) + log.Error("%-v LoadBaseRepo: %v", pr, err) return false } @@ -243,47 +237,50 @@ func manuallyMerged(ctx context.Context, pr *issues_model.PullRequest) bool { return false } } else { - log.Error("PullRequest[%d].BaseRepo.GetUnit(unit.TypePullRequests): %v", pr.ID, err) + log.Error("%-v BaseRepo.GetUnit(unit.TypePullRequests): %v", pr, err) return false } commit, err := getMergeCommit(ctx, pr) if err != nil { - log.Error("PullRequest[%d].getMergeCommit: %v", pr.ID, err) + log.Error("%-v getMergeCommit: %v", pr, err) return false } - if commit != nil { - pr.MergedCommitID = commit.ID.String() - pr.MergedUnix = timeutil.TimeStamp(commit.Author.When.Unix()) - pr.Status = issues_model.PullRequestStatusManuallyMerged - merger, _ := user_model.GetUserByEmail(commit.Author.Email) - // When the commit author is unknown set the BaseRepo owner as merger - if merger == nil { - if pr.BaseRepo.Owner == nil { - if err = pr.BaseRepo.GetOwner(ctx); err != nil { - log.Error("BaseRepo.GetOwner[%d]: %v", pr.ID, err) - return false - } - } - merger = pr.BaseRepo.Owner - } - pr.Merger = merger - pr.MergerID = merger.ID - - if merged, err := pr.SetMerged(ctx); err != nil { - log.Error("PullRequest[%d].setMerged : %v", pr.ID, err) - return false - } else if !merged { - return false - } - - notification.NotifyMergePullRequest(pr, merger) - - log.Info("manuallyMerged[%d]: Marked as manually merged into %s/%s by commit id: %s", pr.ID, pr.BaseRepo.Name, pr.BaseBranch, commit.ID.String()) - return true + if commit == nil { + // no merge commit found + return false } - return false + + pr.MergedCommitID = commit.ID.String() + pr.MergedUnix = timeutil.TimeStamp(commit.Author.When.Unix()) + pr.Status = issues_model.PullRequestStatusManuallyMerged + merger, _ := user_model.GetUserByEmail(commit.Author.Email) + + // When the commit author is unknown set the BaseRepo owner as merger + if merger == nil { + if pr.BaseRepo.Owner == nil { + if err = pr.BaseRepo.GetOwner(ctx); err != nil { + log.Error("%-v BaseRepo.GetOwner: %v", pr, err) + return false + } + } + merger = pr.BaseRepo.Owner + } + pr.Merger = merger + pr.MergerID = merger.ID + + if merged, err := pr.SetMerged(ctx); err != nil { + log.Error("%-v setMerged : %v", pr, err) + return false + } else if !merged { + return false + } + + notification.NotifyMergePullRequest(pr, merger) + + log.Info("manuallyMerged[%-v]: Marked as manually merged into %s/%s by commit id: %s", pr, pr.BaseRepo.Name, pr.BaseBranch, commit.ID.String()) + return true } // InitializePullRequests checks and tests untested patches of pull requests. @@ -299,10 +296,10 @@ func InitializePullRequests(ctx context.Context) { return default: if err := prPatchCheckerQueue.PushFunc(strconv.FormatInt(prID, 10), func() error { - log.Trace("Adding PR ID: %d to the pull requests patch checking queue", prID) + log.Trace("Adding PR[%d] to the pull requests patch checking queue", prID) return nil }); err != nil { - log.Error("Error adding prID: %s to the pull requests patch checking queue %v", prID, err) + log.Error("Error adding PR[%d] to the pull requests patch checking queue %v", prID, err) } } } @@ -326,23 +323,30 @@ func testPR(id int64) { pr, err := issues_model.GetPullRequestByID(ctx, id) if err != nil { - log.Error("GetPullRequestByID[%d]: %v", id, err) + log.Error("Unable to GetPullRequestByID[%d] for testPR: %v", id, err) return } + log.Trace("Testing %-v", pr) + defer func() { + log.Trace("Done testing %-v (status: %s)", pr, pr.Status) + }() + if pr.HasMerged { + log.Trace("%-v is already merged (status: %s, merge commit: %s)", pr, pr.Status, pr.MergedCommitID) return } if manuallyMerged(ctx, pr) { + log.Trace("%-v is manually merged (status: %s, merge commit: %s)", pr, pr.Status, pr.MergedCommitID) return } if err := TestPatch(pr); err != nil { - log.Error("testPatch[%d]: %v", pr.ID, err) + log.Error("testPatch[%-v]: %v", pr, err) pr.Status = issues_model.PullRequestStatusError if err := pr.UpdateCols("status"); err != nil { - log.Error("update pr [%d] status to PullRequestStatusError failed: %v", pr.ID, err) + log.Error("update pr [%-v] status to PullRequestStatusError failed: %v", pr, err) } return } diff --git a/services/pull/patch.go b/services/pull/patch.go index fdfbf7e072eb..ed16259057e9 100644 --- a/services/pull/patch.go +++ b/services/pull/patch.go @@ -60,7 +60,7 @@ var patchErrorSuffices = []string{ // TestPatch will test whether a simple patch will apply func TestPatch(pr *issues_model.PullRequest) error { - ctx, _, finished := process.GetManager().AddContext(graceful.GetManager().HammerContext(), fmt.Sprintf("TestPatch: Repo[%d]#%d", pr.BaseRepoID, pr.Index)) + ctx, _, finished := process.GetManager().AddContext(graceful.GetManager().HammerContext(), fmt.Sprintf("TestPatch: %s", pr)) defer finished() // Clone base repo.