finn/forgejo
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity

Improve trace logging for pulls and processes (#22633)

Browse source 
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>
Co-authored-by: Lunny Xiao <xiaolunwen@gmail.com>
Co-authored-by: delvh <dev.lh@web.de>
Co-authored-by: 6543 <6543@obermui.de>
Co-authored-by: techknowlogick <techknowlogick@gitea.io>
This commit is contained in:
zeripath 2023-02-03 23:11:48 +00:00 committed by GitHub
parent 01f082287d
commit 3c5655ce18
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
9 changed files with 233 additions and 149 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

67
models/issues/pull.go
View file

@ -8,6 +8,7 @@ import (
"context" "context"
"fmt" "fmt"
"io" "io"
"strconv"
"strings" "strings"
"code.gitea.io/gitea/models/db" "code.gitea.io/gitea/models/db"
@ -132,6 +133,27 @@ const (
PullRequestStatusAncestor 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 // PullRequestFlow the flow of pull request
type PullRequestFlow int type PullRequestFlow int
@ -202,6 +224,42 @@ func DeletePullsByBaseRepoID(ctx context.Context, repoID int64) error {
return err 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 // MustHeadUserName returns the HeadRepo's username if failed return blank
func (pr *PullRequest) MustHeadUserName(ctx context.Context) string { func (pr *PullRequest) MustHeadUserName(ctx context.Context) string {
if err := pr.LoadHeadRepo(ctx); err != nil { if err := pr.LoadHeadRepo(ctx); err != nil {
@ -234,7 +292,8 @@ func (pr *PullRequest) LoadAttributes(ctx context.Context) (err error) {
return nil return nil
} }
// LoadHeadRepo loads the head repository // LoadHeadRepo loads the head repository, pr.HeadRepo will remain nil if it does not exist
// and thus ErrRepoNotExist will never be returned
func (pr *PullRequest) LoadHeadRepo(ctx context.Context) (err error) { func (pr *PullRequest) LoadHeadRepo(ctx context.Context) (err error) {
if !pr.isHeadRepoLoaded && pr.HeadRepo == nil && pr.HeadRepoID > 0 { if !pr.isHeadRepoLoaded && pr.HeadRepo == nil && pr.HeadRepoID > 0 {
if pr.HeadRepoID == pr.BaseRepoID { if pr.HeadRepoID == pr.BaseRepoID {
@ -249,14 +308,14 @@ func (pr *PullRequest) LoadHeadRepo(ctx context.Context) (err error) {
pr.HeadRepo, err = repo_model.GetRepositoryByID(ctx, pr.HeadRepoID) pr.HeadRepo, err = repo_model.GetRepositoryByID(ctx, pr.HeadRepoID)
if err != nil && !repo_model.IsErrRepoNotExist(err) { // Head repo maybe deleted, but it should still work 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 pr.isHeadRepoLoaded = true
} }
return nil return nil
} }
// LoadBaseRepo loads the target repository // LoadBaseRepo loads the target repository. ErrRepoNotExist may be returned.
func (pr *PullRequest) LoadBaseRepo(ctx context.Context) (err error) { func (pr *PullRequest) LoadBaseRepo(ctx context.Context) (err error) {
if pr.BaseRepo != nil { if pr.BaseRepo != nil {
return nil return nil
@ -274,7 +333,7 @@ func (pr *PullRequest) LoadBaseRepo(ctx context.Context) (err error) {
pr.BaseRepo, err = repo_model.GetRepositoryByID(ctx, pr.BaseRepoID) pr.BaseRepo, err = repo_model.GetRepositoryByID(ctx, pr.BaseRepoID)
if err != nil { 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 return nil
} }

7
modules/log/colors.go
View file

@ -383,6 +383,13 @@ func (cv *ColoredValue) Format(s fmt.State, c rune) {
s.Write(*cv.resetBytes) 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 // SetColorBytes will allow a user to set the colorBytes of a colored value
func (cv *ColoredValue) SetColorBytes(colorBytes []byte) { func (cv *ColoredValue) SetColorBytes(colorBytes []byte) {
cv.colorBytes = &colorBytes cv.colorBytes = &colorBytes

11
modules/log/log.go
View file

@ -9,6 +9,8 @@ import (
"runtime" "runtime"
"strings" "strings"
"sync" "sync"
"code.gitea.io/gitea/modules/process"
) )
type loggerMap struct { type loggerMap struct {
@ -285,6 +287,15 @@ func (l *LoggerAsWriter) Log(msg string) {
} }
func init() { 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) _, filename, _, _ := runtime.Caller(0)
prefix = strings.TrimSuffix(filename, "modules/log/log.go") prefix = strings.TrimSuffix(filename, "modules/log/log.go")
if prefix == filename { if prefix == filename {

22
modules/process/manager.go
View file

@ -6,6 +6,7 @@ package process
import ( import (
"context" "context"
"log"
"runtime/pprof" "runtime/pprof"
"strconv" "strconv"
"sync" "sync"
@ -43,6 +44,18 @@ type IDType string
// - it is simply an alias for context.CancelFunc and is only for documentary purposes // - it is simply an alias for context.CancelFunc and is only for documentary purposes
type FinishedFunc = context.CancelFunc 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. // Manager manages all processes and counts PIDs.
type Manager struct { type Manager struct {
mutex sync.Mutex mutex sync.Mutex
@ -154,6 +167,7 @@ func (pm *Manager) Add(ctx context.Context, description string, cancel context.C
pm.processMap[pid] = process pm.processMap[pid] = process
pm.mutex.Unlock() 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)) pprofCtx := pprof.WithLabels(ctx, pprof.Labels(DescriptionPProfLabel, description, PPIDPProfLabel, string(parentPID), PIDPProfLabel, string(pid), ProcessTypePProfLabel, processType))
if currentlyRunning { if currentlyRunning {
@ -185,18 +199,12 @@ func (pm *Manager) nextPID() (start time.Time, pid IDType) {
return start, pid 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) { func (pm *Manager) remove(process *process) {
pm.mutex.Lock() pm.mutex.Lock()
defer pm.mutex.Unlock() defer pm.mutex.Unlock()
if p := pm.processMap[process.PID]; p == process { if p := pm.processMap[process.PID]; p == process {
delete(pm.processMap, process.PID) delete(pm.processMap, process.PID)
Trace(false, process.PID, process.Description, process.ParentPID, process.Type)
} }
} }

2
modules/process/manager_test.go
View file

@ -82,7 +82,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()) 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)] _, exists := pm.processMap[GetPID(p2Ctx)]
assert.False(t, exists, "PID %d is in the list but shouldn't", GetPID(p2Ctx)) assert.False(t, exists, "PID %d is in the list but shouldn't", GetPID(p2Ctx))

51
routers/web/repo/pull.go
View file

@ -926,59 +926,54 @@ func MergePullRequest(ctx *context.Context) {
pr := issue.PullRequest pr := issue.PullRequest
pr.Issue = issue pr.Issue = issue
pr.Issue.Repo = ctx.Repo.Repository 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 forceMerge := form.ForceMerge != nil && *form.ForceMerge
// start with merging by checking // start with merging by checking
if err := pull_service.CheckPullMergable(ctx, ctx.Doer, &ctx.Repo.Permission, pr, manuallMerge, forceMerge); err != nil { if err := pull_service.CheckPullMergable(ctx, ctx.Doer, &ctx.Repo.Permission, pr, manualMerge, forceMerge); err != nil {
if errors.Is(err, pull_service.ErrIsClosed) { switch {
case errors.Is(err, pull_service.ErrIsClosed):
if issue.IsPull { if issue.IsPull {
ctx.Flash.Error(ctx.Tr("repo.pulls.is_closed")) ctx.Flash.Error(ctx.Tr("repo.pulls.is_closed"))
ctx.Redirect(issue.Link())
} else { } else {
ctx.Flash.Error(ctx.Tr("repo.issues.closed_title")) 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.Flash.Error(ctx.Tr("repo.pulls.update_not_allowed"))
ctx.Redirect(issue.Link()) case errors.Is(err, pull_service.ErrHasMerged):
} else if errors.Is(err, pull_service.ErrHasMerged) {
ctx.Flash.Error(ctx.Tr("repo.pulls.has_merged")) ctx.Flash.Error(ctx.Tr("repo.pulls.has_merged"))
ctx.Redirect(issue.Link()) case errors.Is(err, pull_service.ErrIsWorkInProgress):
} else if errors.Is(err, pull_service.ErrIsWorkInProgress) {
ctx.Flash.Error(ctx.Tr("repo.pulls.no_merge_wip")) ctx.Flash.Error(ctx.Tr("repo.pulls.no_merge_wip"))
ctx.Redirect(issue.Link()) case errors.Is(err, pull_service.ErrNotMergableState):
} else if errors.Is(err, pull_service.ErrNotMergableState) {
ctx.Flash.Error(ctx.Tr("repo.pulls.no_merge_not_ready")) ctx.Flash.Error(ctx.Tr("repo.pulls.no_merge_not_ready"))
ctx.Redirect(issue.Link()) case models.IsErrDisallowedToMerge(err):
} else if models.IsErrDisallowedToMerge(err) {
ctx.Flash.Error(ctx.Tr("repo.pulls.no_merge_not_ready")) ctx.Flash.Error(ctx.Tr("repo.pulls.no_merge_not_ready"))
ctx.Redirect(issue.Link()) case asymkey_service.IsErrWontSign(err):
} else if asymkey_service.IsErrWontSign(err) { ctx.Flash.Error(err.Error()) // has no translation ...
ctx.Flash.Error(err.Error()) // has not translation ... case errors.Is(err, pull_service.ErrDependenciesLeft):
ctx.Redirect(issue.Link())
} else if errors.Is(err, pull_service.ErrDependenciesLeft) {
ctx.Flash.Error(ctx.Tr("repo.issues.dependency.pr_close_blocked")) ctx.Flash.Error(ctx.Tr("repo.issues.dependency.pr_close_blocked"))
ctx.Redirect(issue.Link()) default:
} else {
ctx.ServerError("WebCheck", err) ctx.ServerError("WebCheck", err)
return
} }
ctx.Redirect(issue.Link())
return return
} }
// handle manually-merged mark // handle manually-merged mark
if manuallMerge { if manualMerge {
if err := pull_service.MergedManually(pr, ctx.Doer, ctx.Repo.GitRepo, form.MergeCommitID); err != nil { 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.Flash.Error(ctx.Tr("repo.pulls.invalid_merge_option"))
ctx.Redirect(issue.Link()) case strings.Contains(err.Error(), "Wrong commit ID"):
} else if strings.Contains(err.Error(), "Wrong commit ID") {
ctx.Flash.Error(ctx.Tr("repo.pulls.wrong_commit_id")) ctx.Flash.Error(ctx.Tr("repo.pulls.wrong_commit_id"))
ctx.Redirect(issue.Link()) default:
} else {
ctx.ServerError("MergedManually", err) ctx.ServerError("MergedManually", err)
return
} }
return
} }
ctx.Redirect(issue.Link()) ctx.Redirect(issue.Link())

26
services/automerge/automerge.go
View file

@ -164,7 +164,7 @@ func getPullRequestsByHeadSHA(ctx context.Context, sha string, repo *repo_model.
func handlePull(pullID int64, sha string) { func handlePull(pullID int64, sha string) {
ctx, _, finished := process.GetManager().AddContext(graceful.GetManager().HammerContext(), 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() defer finished()
pr, err := issues_model.GetPullRequestByID(ctx, pullID) pr, err := issues_model.GetPullRequestByID(ctx, pullID)
@ -176,7 +176,7 @@ func handlePull(pullID int64, sha string) {
// Check if there is a scheduled pr in the db // Check if there is a scheduled pr in the db
exists, scheduledPRM, err := pull_model.GetScheduledMergeByPullID(ctx, pr.ID) exists, scheduledPRM, err := pull_model.GetScheduledMergeByPullID(ctx, pr.ID)
if err != nil { if err != nil {
log.Error("pull[%d] GetScheduledMergeByPullID: %v", pr.ID, err) log.Error("%-v GetScheduledMergeByPullID: %v", pr, err)
return return
} }
if !exists { if !exists {
@ -188,13 +188,13 @@ func handlePull(pullID int64, sha string) {
// did not succeed or was not finished yet. // did not succeed or was not finished yet.
if err = pr.LoadHeadRepo(ctx); err != nil { if err = pr.LoadHeadRepo(ctx); err != nil {
log.Error("pull[%d] LoadHeadRepo: %v", pr.ID, err) log.Error("%-v LoadHeadRepo: %v", pr, err)
return return
} }
headGitRepo, err := git.OpenRepository(ctx, pr.HeadRepo.RepoPath()) headGitRepo, err := git.OpenRepository(ctx, pr.HeadRepo.RepoPath())
if err != nil { if err != nil {
log.Error("OpenRepository: %v", err) log.Error("OpenRepository %-v: %v", pr.HeadRepo, err)
return return
} }
defer headGitRepo.Close() defer headGitRepo.Close()
@ -202,40 +202,40 @@ func handlePull(pullID int64, sha string) {
headBranchExist := headGitRepo.IsBranchExist(pr.HeadBranch) headBranchExist := headGitRepo.IsBranchExist(pr.HeadBranch)
if pr.HeadRepo == nil || !headBranchExist { 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 return
} }
// Check if all checks succeeded // Check if all checks succeeded
pass, err := pull_service.IsPullCommitStatusPass(ctx, pr) pass, err := pull_service.IsPullCommitStatusPass(ctx, pr)
if err != nil { if err != nil {
log.Error("IsPullCommitStatusPass: %v", err) log.Error("%-v IsPullCommitStatusPass: %v", pr, err)
return return
} }
if !pass { 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 return
} }
// Merge if all checks succeeded // Merge if all checks succeeded
doer, err := user_model.GetUserByID(ctx, scheduledPRM.DoerID) doer, err := user_model.GetUserByID(ctx, scheduledPRM.DoerID)
if err != nil { if err != nil {
log.Error("GetUserByIDCtx: %v", err) log.Error("Unable to get scheduled User[%d]: %v", scheduledPRM.DoerID, err)
return return
} }
perm, err := access_model.GetUserRepoPermission(ctx, pr.HeadRepo, doer) perm, err := access_model.GetUserRepoPermission(ctx, pr.HeadRepo, doer)
if err != nil { if err != nil {
log.Error("GetUserRepoPermission: %v", err) log.Error("GetUserRepoPermission %-v: %v", pr.HeadRepo, err)
return return
} }
if err := pull_service.CheckPullMergable(ctx, doer, &perm, pr, false, false); err != nil { if err := pull_service.CheckPullMergable(ctx, doer, &perm, pr, false, false); err != nil {
if errors.Is(pull_service.ErrUserNotAllowedToMerge, err) { 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 return
} }
log.Error("pull[%d] CheckPullMergable: %v", pr.ID, err) log.Error("%-v CheckPullMergable: %v", pr, err)
return return
} }
@ -244,13 +244,13 @@ func handlePull(pullID int64, sha string) {
baseGitRepo = headGitRepo baseGitRepo = headGitRepo
} else { } else {
if err = pr.LoadBaseRepo(ctx); err != nil { if err = pr.LoadBaseRepo(ctx); err != nil {
log.Error("LoadBaseRepo: %v", err) log.Error("%-v LoadBaseRepo: %v", pr, err)
return return
} }
baseGitRepo, err = git.OpenRepository(ctx, pr.BaseRepo.RepoPath()) baseGitRepo, err = git.OpenRepository(ctx, pr.BaseRepo.RepoPath())
if err != nil { if err != nil {
log.Error("OpenRepository: %v", err) log.Error("OpenRepository %-v: %v", pr.BaseRepo, err)
return return
} }
defer baseGitRepo.Close() defer baseGitRepo.Close()

194
services/pull/check.go
View file

@ -8,7 +8,6 @@ import (
"context" "context"
"errors" "errors"
"fmt" "fmt"
"os"
"strconv" "strconv"
"strings" "strings"
@ -27,7 +26,6 @@ import (
"code.gitea.io/gitea/modules/process" "code.gitea.io/gitea/modules/process"
"code.gitea.io/gitea/modules/queue" "code.gitea.io/gitea/modules/queue"
"code.gitea.io/gitea/modules/timeutil" "code.gitea.io/gitea/modules/timeutil"
"code.gitea.io/gitea/modules/util"
asymkey_service "code.gitea.io/gitea/services/asymkey" asymkey_service "code.gitea.io/gitea/services/asymkey"
) )
@ -50,14 +48,14 @@ func AddToTaskQueue(pr *issues_model.PullRequest) {
pr.Status = issues_model.PullRequestStatusChecking pr.Status = issues_model.PullRequestStatusChecking
err := pr.UpdateColsIfNotMerged(db.DefaultContext, "status") err := pr.UpdateColsIfNotMerged(db.DefaultContext, "status")
if err != nil { 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 { } 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 return err
}) })
if err != nil && err != queue.ErrAlreadyInQueue { 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.LoadIssue(ctx); err != nil { if err := pr.LoadIssue(ctx); err != nil {
log.Error("Unable to load issue[%d] for %-v: %v", pr.IssueID, pr, err)
return err return err
} else if pr.Issue.IsClosed { } else if pr.Issue.IsClosed {
return ErrIsClosed return ErrIsClosed
} }
if allowedMerge, err := IsUserAllowedToMerge(ctx, pr, *perm, doer); err != nil { 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 return err
} else if !allowedMerge { } else if !allowedMerge {
return ErrUserNotAllowedToMerge 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 err := CheckPullBranchProtections(ctx, pr, false); err != nil {
if models.IsErrDisallowedToMerge(err) { if !models.IsErrDisallowedToMerge(err) {
if force { log.Error("Error whilst checking pull branch protection for %-v: %v", pr, err)
if isRepoAdmin, err2 := access_model.IsUserRepoAdmin(ctx, pr.BaseRepo, doer); err2 != nil { return err
return err2 }
} else if !isRepoAdmin {
return err if !force {
} return err
} }
} else {
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 return err
} }
} }
@ -144,7 +148,7 @@ func isSignedIfRequired(ctx context.Context, pr *issues_model.PullRequest, doer
// checkAndUpdateStatus checks if pull request is possible to leaving checking status, // checkAndUpdateStatus checks if pull request is possible to leaving checking status,
// and set to be either conflict or mergeable. // and set to be either conflict or mergeable.
func checkAndUpdateStatus(ctx context.Context, pr *issues_model.PullRequest) { func checkAndUpdateStatus(ctx context.Context, 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 { if pr.Status == issues_model.PullRequestStatusChecking {
pr.Status = issues_model.PullRequestStatusMergeable pr.Status = issues_model.PullRequestStatusMergeable
} }
@ -152,79 +156,69 @@ func checkAndUpdateStatus(ctx context.Context, pr *issues_model.PullRequest) {
// Make sure there is no waiting test to process before leaving the checking status. // Make sure there is no waiting test to process before leaving the checking status.
has, err := prPatchCheckerQueue.Has(strconv.FormatInt(pr.ID, 10)) has, err := prPatchCheckerQueue.Has(strconv.FormatInt(pr.ID, 10))
if err != nil { 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 has {
if err := pr.UpdateColsIfNotMerged(ctx, "merge_base", "status", "conflicted_files", "changed_protected_files"); err != nil { log.Trace("Not updating status for %-v as it is due to be rechecked", pr)
log.Error("Update[%d]: %v", pr.ID, err) return
} }
if err := pr.UpdateColsIfNotMerged(ctx, "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 // Returns the git.Commit of the pull request if merged
func getMergeCommit(ctx context.Context, pr *issues_model.PullRequest) (*git.Commit, error) { func getMergeCommit(ctx context.Context, pr *issues_model.PullRequest) (*git.Commit, error) {
if pr.BaseRepo == nil { if err := pr.LoadBaseRepo(ctx); err != nil {
var err error return nil, fmt.Errorf("unable to load base repo for %s: %w", pr, err)
pr.BaseRepo, err = repo_model.GetRepositoryByID(ctx, pr.BaseRepoID)
if err != nil {
return nil, fmt.Errorf("GetRepositoryByID: %w", err)
}
} }
indexTmpPath, err := os.MkdirTemp(os.TempDir(), "gitea-"+pr.BaseRepo.Name) prHeadRef := pr.GetGitRefName()
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)
}
}()
headFile := pr.GetGitRefName() // Check if the pull request is merged into BaseBranch
if _, _, err := git.NewCommand(ctx, "merge-base", "--is-ancestor").
// Check if a pull request is merged into BaseBranch AddDynamicArguments(prHeadRef, pr.BaseBranch).
_, _, err = git.NewCommand(ctx, "merge-base", "--is-ancestor").AddDynamicArguments(headFile, pr.BaseBranch). RunStdString(&git.RunOpts{Dir: pr.BaseRepo.RepoPath()}); err != nil {
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
if strings.Contains(err.Error(), "exit status 1") { if strings.Contains(err.Error(), "exit status 1") {
// prHeadRef is not an ancestor of the base branch
return nil, nil 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 { 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 // Get the commit from BaseBranch where the pull request got merged
mergeCommit, _, err := git.NewCommand(ctx, "rev-list", "--ancestry-path", "--merges", "--reverse").AddDynamicArguments(cmd). mergeCommit, _, err := git.NewCommand(ctx, "rev-list", "--ancestry-path", "--merges", "--reverse").
RunStdString(&git.RunOpts{Dir: "", Env: []string{"GIT_INDEX_FILE=" + indexTmpPath, "GIT_DIR=" + pr.BaseRepo.RepoPath()}}) AddDynamicArguments(prHeadCommitID + ".." + pr.BaseBranch).
RunStdString(&git.RunOpts{Dir: pr.BaseRepo.RepoPath()})
if err != nil { if err != nil {
return nil, fmt.Errorf("git rev-list --ancestry-path --merges --reverse: %w", err) return nil, fmt.Errorf("git rev-list --ancestry-path --merges --reverse: %w", err)
} else if len(mergeCommit) < git.SHAFullLength { } else if len(mergeCommit) < git.SHAFullLength {
// PR was maybe fast-forwarded, so just use last commit of PR // 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()) gitRepo, err := git.OpenRepository(ctx, pr.BaseRepo.RepoPath())
if err != nil { if err != nil {
return nil, fmt.Errorf("OpenRepository: %w", err) return nil, fmt.Errorf("%-v OpenRepository: %w", pr.BaseRepo, err)
} }
defer gitRepo.Close() defer gitRepo.Close()
commit, err := gitRepo.GetCommit(mergeCommit[:git.SHAFullLength]) commit, err := gitRepo.GetCommit(mergeCommit)
if err != nil { 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 return commit, nil
@ -234,7 +228,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 // When a pull request got manually merged mark the pull request as merged
func manuallyMerged(ctx context.Context, pr *issues_model.PullRequest) bool { func manuallyMerged(ctx context.Context, pr *issues_model.PullRequest) bool {
if err := pr.LoadBaseRepo(ctx); err != nil { if err := pr.LoadBaseRepo(ctx); err != nil {
log.Error("PullRequest[%d].LoadBaseRepo: %v", pr.ID, err) log.Error("%-v LoadBaseRepo: %v", pr, err)
return false return false
} }
@ -244,47 +238,50 @@ func manuallyMerged(ctx context.Context, pr *issues_model.PullRequest) bool {
return false return false
} }
} else { } 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 return false
} }
commit, err := getMergeCommit(ctx, pr) commit, err := getMergeCommit(ctx, pr)
if err != nil { if err != nil {
log.Error("PullRequest[%d].getMergeCommit: %v", pr.ID, err) log.Error("%-v getMergeCommit: %v", pr, err)
return false 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 commit == nil {
if merger == nil { // no merge commit found
if pr.BaseRepo.Owner == nil { return false
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(ctx, merger, pr)
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
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(ctx, merger, pr)
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. // InitializePullRequests checks and tests untested patches of pull requests.
@ -300,10 +297,10 @@ func InitializePullRequests(ctx context.Context) {
return return
default: default:
if err := prPatchCheckerQueue.PushFunc(strconv.FormatInt(prID, 10), func() error { 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 return nil
}); err != 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)
} }
} }
} }
@ -327,23 +324,30 @@ func testPR(id int64) {
pr, err := issues_model.GetPullRequestByID(ctx, id) pr, err := issues_model.GetPullRequestByID(ctx, id)
if err != nil { if err != nil {
log.Error("GetPullRequestByID[%d]: %v", id, err) log.Error("Unable to GetPullRequestByID[%d] for testPR: %v", id, err)
return return
} }
log.Trace("Testing %-v", pr)
defer func() {
log.Trace("Done testing %-v (status: %s)", pr, pr.Status)
}()
if pr.HasMerged { if pr.HasMerged {
log.Trace("%-v is already merged (status: %s, merge commit: %s)", pr, pr.Status, pr.MergedCommitID)
return return
} }
if manuallyMerged(ctx, pr) { if manuallyMerged(ctx, pr) {
log.Trace("%-v is manually merged (status: %s, merge commit: %s)", pr, pr.Status, pr.MergedCommitID)
return return
} }
if err := TestPatch(pr); err != nil { 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 pr.Status = issues_model.PullRequestStatusError
if err := pr.UpdateCols("status"); err != nil { 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 return
} }

2
services/pull/patch.go
View file

@ -60,7 +60,7 @@ var patchErrorSuffices = []string{
// TestPatch will test whether a simple patch will apply // TestPatch will test whether a simple patch will apply
func TestPatch(pr *issues_model.PullRequest) error { 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() defer finished()
// Clone base repo. // Clone base repo.