Skip to content

Commit 3c5655c

Browse files
zeripathlunnydelvh6543techknowlogick
authored
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 parent 01f0822 commit 3c5655c

File tree

9 files changed

+230
-146
lines changed

9 files changed

+230
-146
lines changed

Diff for: ‎models/issues/pull.go

+63-4
Original file line numberDiff line numberDiff line change
@@ -8,6 +8,7 @@ import (
88
"context"
99
"fmt"
1010
"io"
11+
"strconv"
1112
"strings"
1213

1314
"code.gitea.io/gitea/models/db"
@@ -132,6 +133,27 @@ const (
132133
PullRequestStatusAncestor
133134
)
134135

136+
func (status PullRequestStatus) String() string {
137+
switch status {
138+
case PullRequestStatusConflict:
139+
return "CONFLICT"
140+
case PullRequestStatusChecking:
141+
return "CHECKING"
142+
case PullRequestStatusMergeable:
143+
return "MERGEABLE"
144+
case PullRequestStatusManuallyMerged:
145+
return "MANUALLY_MERGED"
146+
case PullRequestStatusError:
147+
return "ERROR"
148+
case PullRequestStatusEmpty:
149+
return "EMPTY"
150+
case PullRequestStatusAncestor:
151+
return "ANCESTOR"
152+
default:
153+
return strconv.Itoa(int(status))
154+
}
155+
}
156+
135157
// PullRequestFlow the flow of pull request
136158
type PullRequestFlow int
137159

@@ -202,6 +224,42 @@ func DeletePullsByBaseRepoID(ctx context.Context, repoID int64) error {
202224
return err
203225
}
204226

227+
// ColorFormat writes a colored string to identify this struct
228+
func (pr *PullRequest) ColorFormat(s fmt.State) {
229+
if pr == nil {
230+
log.ColorFprintf(s, "PR[%d]%s#%d[%s...%s:%s]",
231+
log.NewColoredIDValue(0),
232+
log.NewColoredValue("<nil>/<nil>"),
233+
log.NewColoredIDValue(0),
234+
log.NewColoredValue("<nil>"),
235+
log.NewColoredValue("<nil>/<nil>"),
236+
log.NewColoredValue("<nil>"),
237+
)
238+
return
239+
}
240+
241+
log.ColorFprintf(s, "PR[%d]", log.NewColoredIDValue(pr.ID))
242+
if pr.BaseRepo != nil {
243+
log.ColorFprintf(s, "%s#%d[%s...", log.NewColoredValue(pr.BaseRepo.FullName()),
244+
log.NewColoredIDValue(pr.Index), log.NewColoredValue(pr.BaseBranch))
245+
} else {
246+
log.ColorFprintf(s, "Repo[%d]#%d[%s...", log.NewColoredIDValue(pr.BaseRepoID),
247+
log.NewColoredIDValue(pr.Index), log.NewColoredValue(pr.BaseBranch))
248+
}
249+
if pr.HeadRepoID == pr.BaseRepoID {
250+
log.ColorFprintf(s, "%s]", log.NewColoredValue(pr.HeadBranch))
251+
} else if pr.HeadRepo != nil {
252+
log.ColorFprintf(s, "%s:%s]", log.NewColoredValue(pr.HeadRepo.FullName()), log.NewColoredValue(pr.HeadBranch))
253+
} else {
254+
log.ColorFprintf(s, "Repo[%d]:%s]", log.NewColoredIDValue(pr.HeadRepoID), log.NewColoredValue(pr.HeadBranch))
255+
}
256+
}
257+
258+
// String represents the pr as a simple string
259+
func (pr *PullRequest) String() string {
260+
return log.ColorFormatAsString(pr)
261+
}
262+
205263
// MustHeadUserName returns the HeadRepo's username if failed return blank
206264
func (pr *PullRequest) MustHeadUserName(ctx context.Context) string {
207265
if err := pr.LoadHeadRepo(ctx); err != nil {
@@ -234,7 +292,8 @@ func (pr *PullRequest) LoadAttributes(ctx context.Context) (err error) {
234292
return nil
235293
}
236294

237-
// LoadHeadRepo loads the head repository
295+
// LoadHeadRepo loads the head repository, pr.HeadRepo will remain nil if it does not exist
296+
// and thus ErrRepoNotExist will never be returned
238297
func (pr *PullRequest) LoadHeadRepo(ctx context.Context) (err error) {
239298
if !pr.isHeadRepoLoaded && pr.HeadRepo == nil && pr.HeadRepoID > 0 {
240299
if pr.HeadRepoID == pr.BaseRepoID {
@@ -249,14 +308,14 @@ func (pr *PullRequest) LoadHeadRepo(ctx context.Context) (err error) {
249308

250309
pr.HeadRepo, err = repo_model.GetRepositoryByID(ctx, pr.HeadRepoID)
251310
if err != nil && !repo_model.IsErrRepoNotExist(err) { // Head repo maybe deleted, but it should still work
252-
return fmt.Errorf("GetRepositoryByID(head): %w", err)
311+
return fmt.Errorf("pr[%d].LoadHeadRepo[%d]: %w", pr.ID, pr.HeadRepoID, err)
253312
}
254313
pr.isHeadRepoLoaded = true
255314
}
256315
return nil
257316
}
258317

259-
// LoadBaseRepo loads the target repository
318+
// LoadBaseRepo loads the target repository. ErrRepoNotExist may be returned.
260319
func (pr *PullRequest) LoadBaseRepo(ctx context.Context) (err error) {
261320
if pr.BaseRepo != nil {
262321
return nil
@@ -274,7 +333,7 @@ func (pr *PullRequest) LoadBaseRepo(ctx context.Context) (err error) {
274333

275334
pr.BaseRepo, err = repo_model.GetRepositoryByID(ctx, pr.BaseRepoID)
276335
if err != nil {
277-
return fmt.Errorf("repo_model.GetRepositoryByID(base): %w", err)
336+
return fmt.Errorf("pr[%d].LoadBaseRepo[%d]: %w", pr.ID, pr.BaseRepoID, err)
278337
}
279338
return nil
280339
}

Diff for: ‎modules/log/colors.go

+7
Original file line numberDiff line numberDiff line change
@@ -383,6 +383,13 @@ func (cv *ColoredValue) Format(s fmt.State, c rune) {
383383
s.Write(*cv.resetBytes)
384384
}
385385

386+
// ColorFormatAsString returns the result of the ColorFormat without the color
387+
func ColorFormatAsString(colorVal ColorFormatted) string {
388+
s := new(strings.Builder)
389+
_, _ = ColorFprintf(&protectedANSIWriter{w: s, mode: removeColor}, "%-v", colorVal)
390+
return s.String()
391+
}
392+
386393
// SetColorBytes will allow a user to set the colorBytes of a colored value
387394
func (cv *ColoredValue) SetColorBytes(colorBytes []byte) {
388395
cv.colorBytes = &colorBytes

Diff for: ‎modules/log/log.go

+11
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,8 @@ import (
99
"runtime"
1010
"strings"
1111
"sync"
12+
13+
"code.gitea.io/gitea/modules/process"
1214
)
1315

1416
type loggerMap struct {
@@ -285,6 +287,15 @@ func (l *LoggerAsWriter) Log(msg string) {
285287
}
286288

287289
func init() {
290+
process.Trace = func(start bool, pid process.IDType, description string, parentPID process.IDType, typ string) {
291+
if start && parentPID != "" {
292+
Log(1, TRACE, "Start %s: %s (from %s) (%s)", NewColoredValue(pid, FgHiYellow), description, NewColoredValue(parentPID, FgYellow), NewColoredValue(typ, Reset))
293+
} else if start {
294+
Log(1, TRACE, "Start %s: %s (%s)", NewColoredValue(pid, FgHiYellow), description, NewColoredValue(typ, Reset))
295+
} else {
296+
Log(1, TRACE, "Done %s: %s", NewColoredValue(pid, FgHiYellow), NewColoredValue(description, Reset))
297+
}
298+
}
288299
_, filename, _, _ := runtime.Caller(0)
289300
prefix = strings.TrimSuffix(filename, "modules/log/log.go")
290301
if prefix == filename {

Diff for: ‎modules/process/manager.go

+15-7
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,7 @@ package process
66

77
import (
88
"context"
9+
"log"
910
"runtime/pprof"
1011
"strconv"
1112
"sync"
@@ -43,6 +44,18 @@ type IDType string
4344
// - it is simply an alias for context.CancelFunc and is only for documentary purposes
4445
type FinishedFunc = context.CancelFunc
4546

47+
var Trace = defaultTrace // this global can be overridden by particular logging packages - thus avoiding import cycles
48+
49+
func defaultTrace(start bool, pid IDType, description string, parentPID IDType, typ string) {
50+
if start && parentPID != "" {
51+
log.Printf("start process %s: %s (from %s) (%s)", pid, description, parentPID, typ)
52+
} else if start {
53+
log.Printf("start process %s: %s (%s)", pid, description, typ)
54+
} else {
55+
log.Printf("end process %s: %s", pid, description)
56+
}
57+
}
58+
4659
// Manager manages all processes and counts PIDs.
4760
type Manager struct {
4861
mutex sync.Mutex
@@ -154,6 +167,7 @@ func (pm *Manager) Add(ctx context.Context, description string, cancel context.C
154167

155168
pm.processMap[pid] = process
156169
pm.mutex.Unlock()
170+
Trace(true, pid, description, parentPID, processType)
157171

158172
pprofCtx := pprof.WithLabels(ctx, pprof.Labels(DescriptionPProfLabel, description, PPIDPProfLabel, string(parentPID), PIDPProfLabel, string(pid), ProcessTypePProfLabel, processType))
159173
if currentlyRunning {
@@ -185,18 +199,12 @@ func (pm *Manager) nextPID() (start time.Time, pid IDType) {
185199
return start, pid
186200
}
187201

188-
// Remove a process from the ProcessManager.
189-
func (pm *Manager) Remove(pid IDType) {
190-
pm.mutex.Lock()
191-
delete(pm.processMap, pid)
192-
pm.mutex.Unlock()
193-
}
194-
195202
func (pm *Manager) remove(process *process) {
196203
pm.mutex.Lock()
197204
defer pm.mutex.Unlock()
198205
if p := pm.processMap[process.PID]; p == process {
199206
delete(pm.processMap, process.PID)
207+
Trace(false, process.PID, process.Description, process.ParentPID, process.Type)
200208
}
201209
}
202210

Diff for: ‎modules/process/manager_test.go

+1-1
Original file line numberDiff line numberDiff line change
@@ -82,7 +82,7 @@ func TestManager_Remove(t *testing.T) {
8282

8383
assert.NotEqual(t, GetContext(p1Ctx).GetPID(), GetContext(p2Ctx).GetPID(), "expected to get different pids got %s == %s", GetContext(p2Ctx).GetPID(), GetContext(p1Ctx).GetPID())
8484

85-
pm.Remove(GetPID(p2Ctx))
85+
finished()
8686

8787
_, exists := pm.processMap[GetPID(p2Ctx)]
8888
assert.False(t, exists, "PID %d is in the list but shouldn't", GetPID(p2Ctx))

Diff for: ‎routers/web/repo/pull.go

+23-28
Original file line numberDiff line numberDiff line change
@@ -926,59 +926,54 @@ func MergePullRequest(ctx *context.Context) {
926926
pr := issue.PullRequest
927927
pr.Issue = issue
928928
pr.Issue.Repo = ctx.Repo.Repository
929-
manuallMerge := repo_model.MergeStyle(form.Do) == repo_model.MergeStyleManuallyMerged
929+
manualMerge := repo_model.MergeStyle(form.Do) == repo_model.MergeStyleManuallyMerged
930930
forceMerge := form.ForceMerge != nil && *form.ForceMerge
931931

932932
// start with merging by checking
933-
if err := pull_service.CheckPullMergable(ctx, ctx.Doer, &ctx.Repo.Permission, pr, manuallMerge, forceMerge); err != nil {
934-
if errors.Is(err, pull_service.ErrIsClosed) {
933+
if err := pull_service.CheckPullMergable(ctx, ctx.Doer, &ctx.Repo.Permission, pr, manualMerge, forceMerge); err != nil {
934+
switch {
935+
case errors.Is(err, pull_service.ErrIsClosed):
935936
if issue.IsPull {
936937
ctx.Flash.Error(ctx.Tr("repo.pulls.is_closed"))
937-
ctx.Redirect(issue.Link())
938938
} else {
939939
ctx.Flash.Error(ctx.Tr("repo.issues.closed_title"))
940-
ctx.Redirect(issue.Link())
941940
}
942-
} else if errors.Is(err, pull_service.ErrUserNotAllowedToMerge) {
941+
case errors.Is(err, pull_service.ErrUserNotAllowedToMerge):
943942
ctx.Flash.Error(ctx.Tr("repo.pulls.update_not_allowed"))
944-
ctx.Redirect(issue.Link())
945-
} else if errors.Is(err, pull_service.ErrHasMerged) {
943+
case errors.Is(err, pull_service.ErrHasMerged):
946944
ctx.Flash.Error(ctx.Tr("repo.pulls.has_merged"))
947-
ctx.Redirect(issue.Link())
948-
} else if errors.Is(err, pull_service.ErrIsWorkInProgress) {
945+
case errors.Is(err, pull_service.ErrIsWorkInProgress):
949946
ctx.Flash.Error(ctx.Tr("repo.pulls.no_merge_wip"))
950-
ctx.Redirect(issue.Link())
951-
} else if errors.Is(err, pull_service.ErrNotMergableState) {
947+
case errors.Is(err, pull_service.ErrNotMergableState):
952948
ctx.Flash.Error(ctx.Tr("repo.pulls.no_merge_not_ready"))
953-
ctx.Redirect(issue.Link())
954-
} else if models.IsErrDisallowedToMerge(err) {
949+
case models.IsErrDisallowedToMerge(err):
955950
ctx.Flash.Error(ctx.Tr("repo.pulls.no_merge_not_ready"))
956-
ctx.Redirect(issue.Link())
957-
} else if asymkey_service.IsErrWontSign(err) {
958-
ctx.Flash.Error(err.Error()) // has not translation ...
959-
ctx.Redirect(issue.Link())
960-
} else if errors.Is(err, pull_service.ErrDependenciesLeft) {
951+
case asymkey_service.IsErrWontSign(err):
952+
ctx.Flash.Error(err.Error()) // has no translation ...
953+
case errors.Is(err, pull_service.ErrDependenciesLeft):
961954
ctx.Flash.Error(ctx.Tr("repo.issues.dependency.pr_close_blocked"))
962-
ctx.Redirect(issue.Link())
963-
} else {
955+
default:
964956
ctx.ServerError("WebCheck", err)
957+
return
965958
}
959+
960+
ctx.Redirect(issue.Link())
966961
return
967962
}
968963

969964
// handle manually-merged mark
970-
if manuallMerge {
965+
if manualMerge {
971966
if err := pull_service.MergedManually(pr, ctx.Doer, ctx.Repo.GitRepo, form.MergeCommitID); err != nil {
972-
if models.IsErrInvalidMergeStyle(err) {
967+
switch {
968+
969+
case models.IsErrInvalidMergeStyle(err):
973970
ctx.Flash.Error(ctx.Tr("repo.pulls.invalid_merge_option"))
974-
ctx.Redirect(issue.Link())
975-
} else if strings.Contains(err.Error(), "Wrong commit ID") {
971+
case strings.Contains(err.Error(), "Wrong commit ID"):
976972
ctx.Flash.Error(ctx.Tr("repo.pulls.wrong_commit_id"))
977-
ctx.Redirect(issue.Link())
978-
} else {
973+
default:
979974
ctx.ServerError("MergedManually", err)
975+
return
980976
}
981-
return
982977
}
983978

984979
ctx.Redirect(issue.Link())

Diff for: ‎services/automerge/automerge.go

+13-13
Original file line numberDiff line numberDiff line change
@@ -164,7 +164,7 @@ func getPullRequestsByHeadSHA(ctx context.Context, sha string, repo *repo_model.
164164

165165
func handlePull(pullID int64, sha string) {
166166
ctx, _, finished := process.GetManager().AddContext(graceful.GetManager().HammerContext(),
167-
fmt.Sprintf("Handle AutoMerge of pull[%d] with sha[%s]", pullID, sha))
167+
fmt.Sprintf("Handle AutoMerge of PR[%d] with sha[%s]", pullID, sha))
168168
defer finished()
169169

170170
pr, err := issues_model.GetPullRequestByID(ctx, pullID)
@@ -176,7 +176,7 @@ func handlePull(pullID int64, sha string) {
176176
// Check if there is a scheduled pr in the db
177177
exists, scheduledPRM, err := pull_model.GetScheduledMergeByPullID(ctx, pr.ID)
178178
if err != nil {
179-
log.Error("pull[%d] GetScheduledMergeByPullID: %v", pr.ID, err)
179+
log.Error("%-v GetScheduledMergeByPullID: %v", pr, err)
180180
return
181181
}
182182
if !exists {
@@ -188,54 +188,54 @@ func handlePull(pullID int64, sha string) {
188188
// did not succeed or was not finished yet.
189189

190190
if err = pr.LoadHeadRepo(ctx); err != nil {
191-
log.Error("pull[%d] LoadHeadRepo: %v", pr.ID, err)
191+
log.Error("%-v LoadHeadRepo: %v", pr, err)
192192
return
193193
}
194194

195195
headGitRepo, err := git.OpenRepository(ctx, pr.HeadRepo.RepoPath())
196196
if err != nil {
197-
log.Error("OpenRepository: %v", err)
197+
log.Error("OpenRepository %-v: %v", pr.HeadRepo, err)
198198
return
199199
}
200200
defer headGitRepo.Close()
201201

202202
headBranchExist := headGitRepo.IsBranchExist(pr.HeadBranch)
203203

204204
if pr.HeadRepo == nil || !headBranchExist {
205-
log.Warn("Head branch of auto merge pr does not exist [HeadRepoID: %d, Branch: %s, PR ID: %d]", pr.HeadRepoID, pr.HeadBranch, pr.ID)
205+
log.Warn("Head branch of auto merge %-v does not exist [HeadRepoID: %d, Branch: %s]", pr, pr.HeadRepoID, pr.HeadBranch)
206206
return
207207
}
208208

209209
// Check if all checks succeeded
210210
pass, err := pull_service.IsPullCommitStatusPass(ctx, pr)
211211
if err != nil {
212-
log.Error("IsPullCommitStatusPass: %v", err)
212+
log.Error("%-v IsPullCommitStatusPass: %v", pr, err)
213213
return
214214
}
215215
if !pass {
216-
log.Info("Scheduled auto merge pr has unsuccessful status checks [PullID: %d]", pr.ID)
216+
log.Info("Scheduled auto merge %-v has unsuccessful status checks", pr)
217217
return
218218
}
219219

220220
// Merge if all checks succeeded
221221
doer, err := user_model.GetUserByID(ctx, scheduledPRM.DoerID)
222222
if err != nil {
223-
log.Error("GetUserByIDCtx: %v", err)
223+
log.Error("Unable to get scheduled User[%d]: %v", scheduledPRM.DoerID, err)
224224
return
225225
}
226226

227227
perm, err := access_model.GetUserRepoPermission(ctx, pr.HeadRepo, doer)
228228
if err != nil {
229-
log.Error("GetUserRepoPermission: %v", err)
229+
log.Error("GetUserRepoPermission %-v: %v", pr.HeadRepo, err)
230230
return
231231
}
232232

233233
if err := pull_service.CheckPullMergable(ctx, doer, &perm, pr, false, false); err != nil {
234234
if errors.Is(pull_service.ErrUserNotAllowedToMerge, err) {
235-
log.Info("PR %d was scheduled to automerge by an unauthorized user", pr.ID)
235+
log.Info("%-v was scheduled to automerge by an unauthorized user", pr)
236236
return
237237
}
238-
log.Error("pull[%d] CheckPullMergable: %v", pr.ID, err)
238+
log.Error("%-v CheckPullMergable: %v", pr, err)
239239
return
240240
}
241241

@@ -244,13 +244,13 @@ func handlePull(pullID int64, sha string) {
244244
baseGitRepo = headGitRepo
245245
} else {
246246
if err = pr.LoadBaseRepo(ctx); err != nil {
247-
log.Error("LoadBaseRepo: %v", err)
247+
log.Error("%-v LoadBaseRepo: %v", pr, err)
248248
return
249249
}
250250

251251
baseGitRepo, err = git.OpenRepository(ctx, pr.BaseRepo.RepoPath())
252252
if err != nil {
253-
log.Error("OpenRepository: %v", err)
253+
log.Error("OpenRepository %-v: %v", pr.BaseRepo, err)
254254
return
255255
}
256256
defer baseGitRepo.Close()

0 commit comments

Comments
 (0)