Improve trace logging for pulls and processes (go-gitea#22633)

Backport go-gitea#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 go-gitea#22568 * Adds a lot more logging in to testPR etc. Ref go-gitea#22578 --------- Signed-off-by: Andrew Thornton <art27@cantab.net>
zeripath · Feb 7, 2023 · 05e62a3 · 05e62a3
1 parent ff20146
commit 05e62a3
Show file tree

Hide file tree

Showing 9 changed files with 227 additions and 148 deletions.
diff --git 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("<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,13 +313,9 @@ 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
-	}
-	return nil
 }
-
 // LoadHeadRepo loads the head repository
 func (pr *PullRequest) LoadHeadRepo() error {
 	return pr.LoadHeadRepoCtx(db.DefaultContext)
@@ -290,7 +344,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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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,54 +189,54 @@ 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()
 
 	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()