]> source.dussan.org Git - gitea.git/commitdiff
Improve trace logging for pulls and processes (#22633) (#22812)
authorzeripath <art27@cantab.net>
Mon, 13 Feb 2023 03:17:36 +0000 (03:17 +0000)
committerGitHub <noreply@github.com>
Mon, 13 Feb 2023 03:17:36 +0000 (11:17 +0800)
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 <art27@cantab.net>
models/issues/pull.go
modules/log/colors.go
modules/log/log.go
modules/process/manager.go
modules/process/manager_test.go
routers/web/repo/pull.go
services/automerge/automerge.go
services/pull/check.go
services/pull/patch.go

index f03cabc3c828dee54abbd9922ff07a8e5410f578..e772fb1e4369ed91cc90022db1a55943851d3e9f 100644 (file)
@@ -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("<nil>/<nil>"),
+                       log.NewColoredIDValue(0),
+                       log.NewColoredValue("<nil>"),
+                       log.NewColoredValue("<nil>/<nil>"),
+                       log.NewColoredValue("<nil>"),
+               )
+               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
 }
index 15e23a0dac21035a296d6e925049860150a0ac4a..d512202f21b588495e25bdab5ec191bf74de2de0 100644 (file)
@@ -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
index 4303ecf4c03c4237bd50df2deb1bd3d63da2c23b..e0a116e5e6b576e5e3be168f43c26ff92e66a906 100644 (file)
@@ -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 {
index 7f14287de508c99cc568621ee1894e79096b8f4c..cbdc88cc4b9c4c84a649ad18ae71b6d0d0cf92c4 100644 (file)
@@ -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)
        }
 }
 
index 30eabeb37a48601fd58d6a1979d210d033e2d1a7..a6d32d950d801e17c383ff5cd28880e06e388d5c 100644 (file)
@@ -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))
index 98b78645dc00b8a81e4e70e9dc50ec0dcaed366f..387853677c11df3f9cc93de30f2ee081d59a395e 100644 (file)
@@ -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())
index ca008ebfe6c820e753a16ec6df27be41b80aa47b..49bd1d0c029658d42fe1705576ec73fdebdbacac 100644 (file)
@@ -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()
index 1780f1e989b643fb8b02cd2856982c9037a2d480..d828ee8cd7fadc95c8049313576c0a7992f9954a 100644 (file)
@@ -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)
-               }
-       }
-
-       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)
+       if err := pr.LoadBaseRepoCtx(ctx); err != nil {
+               return nil, fmt.Errorf("unable to load base repo for %s: %w", pr, err)
        }
-       defer func() {
-               if err := util.RemoveAll(indexTmpPath); err != nil {
-                       log.Warn("Unable to remove temporary index path: %s: Error: %v", indexTmpPath, err)
-               }
-       }()
 
-       headFile := pr.GetGitRefName()
+       prHeadRef := 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 {
+               // no merge commit found
                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
-                               }
+
+       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
+               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
-               }
+       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)
+       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
-       }
-       return false
+       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
        }
index fdfbf7e072eb921917d84326a053315bbc7aae13..ed16259057e9f394c688dc8864bb2b469bd28943 100644 (file)
@@ -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.