Improve trace logging for pulls and processes (#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>
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>

1 files changed, 13 insertions, 13 deletions

diff --git a/services/automerge/automerge.go b/services/automerge/automerge.go
index 15d94e7920..74cfb8da8f 100644
--- a/services/automerge/automerge.go
+++ b/services/automerge/automerge.go
@@ -164,7 +164,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)
@@ -176,7 +176,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 {
@@ -188,13 +188,13 @@ func handlePull(pullID int64, sha string) {
 	// did not succeed or was not finished yet.
 
 	if err = pr.LoadHeadRepo(ctx); err != nil {
-		log.Error("pull[%d] LoadHeadRepo: %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()
@@ -202,40 +202,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.GetUserByID(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
 	}
 
@@ -244,13 +244,13 @@ func handlePull(pullID int64, sha string) {
 		baseGitRepo = headGitRepo
 	} else {
 		if err = pr.LoadBaseRepo(ctx); err != nil {
-			log.Error("LoadBaseRepo: %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()