Add some more trace and debug logging to process and testpatch

Given the repeated issues here I've just added some plain trace logging
which should allow for easier tracing of when processes are created.

Signed-off-by: Andrew Thornton <[email protected]>

Author: zeripath

modules/process/manager.go

@@ -15,6 +15,8 @@ import (
 	"strconv"
 	"sync"
 	"time"
+
+	"code.gitea.io/gitea/modules/log"
 )
 
 // TODO: This packages still uses a singleton for the Manager.
@@ -103,6 +105,7 @@ func (pm *Manager) AddContextTimeout(parent context.Context, timeout time.Durati
 func (pm *Manager) Add(parentPID IDType, description string, cancel context.CancelFunc) (IDType, FinishedFunc) {
 	pm.mutex.Lock()
 	start, pid := pm.nextPID()
+	log.Trace("Adding Process[%s:%s] %s", parentPID, pid, description)
 
 	parent := pm.processes[parentPID]
 	if parent == nil {
@@ -120,6 +123,7 @@ func (pm *Manager) Add(parentPID IDType, description string, cancel context.Canc
 	finished := func() {
 		cancel()
 		pm.remove(process)
+		log.Trace("Finished Process[%d:%d] %s", parentPID, pid, description)
 	}
 
 	if parent != nil {

modules/queue/workerpool.go

@@ -484,7 +484,7 @@ func (p *WorkerPool) doWork(ctx context.Context) {
 		case <-paused:
 			log.Trace("Worker for Queue %d Pausing", p.qid)
 			if len(data) > 0 {
-				log.Trace("Handling: %d data, %v", len(data), data)
+				log.Trace("Queue[%d] Handling: %d data, %v", p.qid, len(data), data)
 				if unhandled := p.handle(data...); unhandled != nil {
 					log.Error("Unhandled Data in queue %d", p.qid)
 				}
@@ -507,7 +507,7 @@ func (p *WorkerPool) doWork(ctx context.Context) {
 			// go back around
 		case <-ctx.Done():
 			if len(data) > 0 {
-				log.Trace("Handling: %d data, %v", len(data), data)
+				log.Trace("Queue[%d] Handling: %d data, %v", p.qid, len(data), data)
 				if unhandled := p.handle(data...); unhandled != nil {
 					log.Error("Unhandled Data in queue %d", p.qid)
 				}
@@ -519,7 +519,7 @@ func (p *WorkerPool) doWork(ctx context.Context) {
 			if !ok {
 				// the dataChan has been closed - we should finish up:
 				if len(data) > 0 {
-					log.Trace("Handling: %d data, %v", len(data), data)
+					log.Trace("Queue[%d] Handling: %d data, %v", p.qid, len(data), data)
 					if unhandled := p.handle(data...); unhandled != nil {
 						log.Error("Unhandled Data in queue %d", p.qid)
 					}
@@ -532,7 +532,7 @@ func (p *WorkerPool) doWork(ctx context.Context) {
 			util.StopTimer(timer)
 
 			if len(data) >= p.batchLength {
-				log.Trace("Handling: %d data, %v", len(data), data)
+				log.Trace("Queue[%d] Handling: %d data, %v", p.qid, len(data), data)
 				if unhandled := p.handle(data...); unhandled != nil {
 					log.Error("Unhandled Data in queue %d", p.qid)
 				}
@@ -544,7 +544,7 @@ func (p *WorkerPool) doWork(ctx context.Context) {
 		case <-timer.C:
 			delay = time.Millisecond * 100
 			if len(data) > 0 {
-				log.Trace("Handling: %d data, %v", len(data), data)
+				log.Trace("Queue[%d] Handling: %d data, %v", p.qid, len(data), data)
 				if unhandled := p.handle(data...); unhandled != nil {
 					log.Error("Unhandled Data in queue %d", p.qid)
 				}

services/pull/check.go

@@ -62,9 +62,12 @@ func checkAndUpdateStatus(pr *models.PullRequest) {
 	}
 
 	if !has {
+		log.Trace("Updating PR[%d] in %d: Status:%d Conflicts:%s Protected:%s", pr.ID, pr.BaseRepoID, pr.Status, pr.ConflictedFiles, pr.ChangedProtectedFiles)
 		if err := pr.UpdateColsIfNotMerged("merge_base", "status", "conflicted_files", "changed_protected_files"); err != nil {
 			log.Error("Update[%d]: %v", pr.ID, err)
 		}
+	} else {
+		log.Trace("Not updating PR[%d] in %d as still in the queue", pr.ID, pr.BaseRepoID)
 	}
 }
 
@@ -234,12 +237,15 @@ func testPR(id int64) {
 		log.Error("GetPullRequestByID[%d]: %v", id, err)
 		return
 	}
+	log.Trace("Testing PR[%d] in %d", pr.ID, pr.BaseRepoID)
 
 	if pr.HasMerged {
+		log.Trace("PR[%d] in %d: already merged", pr.ID, pr.BaseRepoID)
 		return
 	}
 
 	if manuallyMerged(ctx, pr) {
+		log.Trace("PR[%d] in %d: manually merged", pr.ID, pr.BaseRepoID)
 		return
 	}
 
@@ -251,6 +257,8 @@ func testPR(id int64) {
 		}
 		return
 	}
+	log.Trace("PR[%d] in %d: patch tested new Status:%d ConflictedFiles:%s ChangedProtectedFiles:%s", pr.ID, pr.BaseRepoID, pr.Status, pr.ConflictedFiles, pr.ChangedProtectedFiles)
+
 	checkAndUpdateStatus(pr)
 }
 

services/pull/patch.go

@@ -280,11 +280,13 @@ func checkConflicts(ctx context.Context, pr *models.PullRequest, gitRepo *git.Re
 	if !conflict {
 		treeHash, err := git.NewCommand(ctx, "write-tree").RunInDir(tmpBasePath)
 		if err != nil {
+			log.Debug("Unable to write unconflicted tree for PR[%d] %s/%s#%d. Error: %v", pr.ID, pr.BaseRepo.OwnerName, pr.BaseRepo.Name, pr.Index, err)
 			return false, err
 		}
 		treeHash = strings.TrimSpace(treeHash)
 		baseTree, err := gitRepo.GetTree("base")
 		if err != nil {
+			log.Debug("Unable to get base tree for PR[%d] %s/%s#%d. Error: %v", pr.ID, pr.BaseRepo.OwnerName, pr.BaseRepo.Name, pr.Index, err)
 			return false, err
 		}
 		pr.Status = models.PullRequestStatusMergeable