Skip to content

Commit f173bf2

Browse files
zeripathzeripath
committed
Improve SyncMirrors logging (go-gitea#19045)
Backport go-gitea#19045 Yet another issue has come up where the logging from SyncMirrors does not provide enough context. This PR adds more context to these logging events. Related go-gitea#19038 Signed-off-by: Andrew Thornton <art27@cantab.net>
1 parent 3e5c844 commit f173bf2

File tree

4 files changed

+57
-43
lines changed

4 files changed

+57
-43
lines changed

‎models/lfs.go

+3-2
Original file line numberDiff line numberDiff line change
@@ -193,12 +193,13 @@ func LFSAutoAssociate(metas []*LFSMetaObject, user *user_model.User, repoID int6
193193
// admin can associate any LFS object to any repository, and we do not care about errors (eg: duplicated unique key),
194194
// even if error occurs, it won't hurt users and won't make things worse
195195
for i := range metas {
196+
p := lfs.Pointer{Oid: metas[i].Oid, Size: metas[i].Size}
196197
_, err = sess.Insert(&LFSMetaObject{
197-
Pointer: lfs.Pointer{Oid: metas[i].Oid, Size: metas[i].Size},
198+
Pointer: p,
198199
RepositoryID: repoID,
199200
})
200201
if err != nil {
201-
log.Warn("failed to insert LFS meta object into database, err=%v", err)
202+
log.Warn("failed to insert LFS meta object %-v for repo_id: %d into database, err=%v", p, repoID, err)
202203
}
203204
}
204205
}

‎modules/lfs/pointer.go

+13
Original file line numberDiff line numberDiff line change
@@ -14,6 +14,8 @@ import (
1414
"regexp"
1515
"strconv"
1616
"strings"
17+
18+
"code.gitea.io/gitea/modules/log"
1719
)
1820

1921
const (
@@ -111,6 +113,17 @@ func (p Pointer) RelativePath() string {
111113
return path.Join(p.Oid[0:2], p.Oid[2:4], p.Oid[4:])
112114
}
113115

116+
// ColorFormat provides a basic color format for a Team
117+
func (p Pointer) ColorFormat(s fmt.State) {
118+
if p.Oid == "" && p.Size == 0 {
119+
log.ColorFprintf(s, "<empty>")
120+
return
121+
}
122+
log.ColorFprintf(s, "%s:%d",
123+
log.NewColoredIDValue(p.Oid),
124+
p.Size)
125+
}
126+
114127
// GeneratePointer generates a pointer for arbitrary content
115128
func GeneratePointer(content io.Reader) (Pointer, error) {
116129
h := sha256.New()

‎modules/repository/repo.go

+20-20
Original file line numberDiff line numberDiff line change
@@ -254,7 +254,7 @@ func SyncReleasesWithTags(repo *repo_model.Repository, gitRepo *git.Repository)
254254
opts.Page = page
255255
rels, err := models.GetReleasesByRepoID(repo.ID, opts)
256256
if err != nil {
257-
return fmt.Errorf("GetReleasesByRepoID: %v", err)
257+
return fmt.Errorf("unable to GetReleasesByRepoID in Repo[%d:%s/%s]: %w", repo.ID, repo.OwnerName, repo.Name, err)
258258
}
259259
if len(rels) == 0 {
260260
break
@@ -265,11 +265,11 @@ func SyncReleasesWithTags(repo *repo_model.Repository, gitRepo *git.Repository)
265265
}
266266
commitID, err := gitRepo.GetTagCommitID(rel.TagName)
267267
if err != nil && !git.IsErrNotExist(err) {
268-
return fmt.Errorf("GetTagCommitID: %s: %v", rel.TagName, err)
268+
return fmt.Errorf("unable to GetTagCommitID for %q in Repo[%d:%s/%s]: %w", rel.TagName, repo.ID, repo.OwnerName, repo.Name, err)
269269
}
270270
if git.IsErrNotExist(err) || commitID != rel.Sha1 {
271271
if err := models.PushUpdateDeleteTag(repo, rel.TagName); err != nil {
272-
return fmt.Errorf("PushUpdateDeleteTag: %s: %v", rel.TagName, err)
272+
return fmt.Errorf("unable to PushUpdateDeleteTag: %q in Repo[%d:%s/%s]: %w", rel.TagName, repo.ID, repo.OwnerName, repo.Name, err)
273273
}
274274
} else {
275275
existingRelTags[strings.ToLower(rel.TagName)] = struct{}{}
@@ -278,12 +278,12 @@ func SyncReleasesWithTags(repo *repo_model.Repository, gitRepo *git.Repository)
278278
}
279279
tags, err := gitRepo.GetTags(0, 0)
280280
if err != nil {
281-
return fmt.Errorf("GetTags: %v", err)
281+
return fmt.Errorf("unable to GetTags in Repo[%d:%s/%s]: %w", repo.ID, repo.OwnerName, repo.Name, err)
282282
}
283283
for _, tagName := range tags {
284284
if _, ok := existingRelTags[strings.ToLower(tagName)]; !ok {
285285
if err := PushUpdateAddTag(repo, gitRepo, tagName); err != nil {
286-
return fmt.Errorf("pushUpdateAddTag: %v", err)
286+
return fmt.Errorf("unable to PushUpdateAddTag: %q to Repo[%d:%s/%s]: %w", tagName, repo.ID, repo.OwnerName, repo.Name, err)
287287
}
288288
}
289289
}
@@ -294,11 +294,11 @@ func SyncReleasesWithTags(repo *repo_model.Repository, gitRepo *git.Repository)
294294
func PushUpdateAddTag(repo *repo_model.Repository, gitRepo *git.Repository, tagName string) error {
295295
tag, err := gitRepo.GetTag(tagName)
296296
if err != nil {
297-
return fmt.Errorf("GetTag: %v", err)
297+
return fmt.Errorf("unable to GetTag: %w", err)
298298
}
299299
commit, err := tag.Commit(gitRepo)
300300
if err != nil {
301-
return fmt.Errorf("Commit: %v", err)
301+
return fmt.Errorf("unable to get tag Commit: %w", err)
302302
}
303303

304304
sig := tag.Tagger
@@ -315,14 +315,14 @@ func PushUpdateAddTag(repo *repo_model.Repository, gitRepo *git.Repository, tagN
315315
if sig != nil {
316316
author, err = user_model.GetUserByEmail(sig.Email)
317317
if err != nil && !user_model.IsErrUserNotExist(err) {
318-
return fmt.Errorf("GetUserByEmail: %v", err)
318+
return fmt.Errorf("unable to GetUserByEmail for %q: %w", sig.Email, err)
319319
}
320320
createdAt = sig.When
321321
}
322322

323323
commitsCount, err := commit.CommitsCount()
324324
if err != nil {
325-
return fmt.Errorf("CommitsCount: %v", err)
325+
return fmt.Errorf("unable to get CommitsCount: %w", err)
326326
}
327327

328328
var rel = models.Release{
@@ -359,14 +359,14 @@ func StoreMissingLfsObjectsInRepository(ctx context.Context, repo *repo_model.Re
359359

360360
_, err := models.NewLFSMetaObject(&models.LFSMetaObject{Pointer: p, RepositoryID: repo.ID})
361361
if err != nil {
362-
log.Error("Error creating LFS meta object %v: %v", p, err)
362+
log.Error("Repo[%-v]: Error creating LFS meta object %-v: %v", repo, p, err)
363363
return err
364364
}
365365

366366
if err := contentStore.Put(p, content); err != nil {
367-
log.Error("Error storing content for LFS meta object %v: %v", p, err)
367+
log.Error("Repo[%-v]: Error storing content for LFS meta object %-v: %v", repo, p, err)
368368
if _, err2 := models.RemoveLFSMetaObjectByOid(repo.ID, p.Oid); err2 != nil {
369-
log.Error("Error removing LFS meta object %v: %v", p, err2)
369+
log.Error("Repo[%-v]: Error removing LFS meta object %-v: %v", repo, p, err2)
370370
}
371371
return err
372372
}
@@ -386,32 +386,32 @@ func StoreMissingLfsObjectsInRepository(ctx context.Context, repo *repo_model.Re
386386
for pointerBlob := range pointerChan {
387387
meta, err := models.GetLFSMetaObjectByOid(repo.ID, pointerBlob.Oid)
388388
if err != nil && err != models.ErrLFSObjectNotExist {
389-
log.Error("Error querying LFS meta object %v: %v", pointerBlob.Pointer, err)
389+
log.Error("Repo[%-v]: Error querying LFS meta object %-v: %v", repo, pointerBlob.Pointer, err)
390390
return err
391391
}
392392
if meta != nil {
393-
log.Trace("Skipping unknown LFS meta object %v", pointerBlob.Pointer)
393+
log.Trace("Repo[%-v]: Skipping unknown LFS meta object %-v", repo, pointerBlob.Pointer)
394394
continue
395395
}
396396

397-
log.Trace("LFS object %v not present in repository %s", pointerBlob.Pointer, repo.FullName())
397+
log.Trace("Repo[%-v]: LFS object %-v not present in repository", repo, pointerBlob.Pointer)
398398

399399
exist, err := contentStore.Exists(pointerBlob.Pointer)
400400
if err != nil {
401-
log.Error("Error checking if LFS object %v exists: %v", pointerBlob.Pointer, err)
401+
log.Error("Repo[%-v]: Error checking if LFS object %-v exists: %v", repo, pointerBlob.Pointer, err)
402402
return err
403403
}
404404

405405
if exist {
406-
log.Trace("LFS object %v already present; creating meta object", pointerBlob.Pointer)
406+
log.Trace("Repo[%-v]: LFS object %-v already present; creating meta object", repo, pointerBlob.Pointer)
407407
_, err := models.NewLFSMetaObject(&models.LFSMetaObject{Pointer: pointerBlob.Pointer, RepositoryID: repo.ID})
408408
if err != nil {
409-
log.Error("Error creating LFS meta object %v: %v", pointerBlob.Pointer, err)
409+
log.Error("Repo[%-v]: Error creating LFS meta object %-v: %v", repo, pointerBlob.Pointer, err)
410410
return err
411411
}
412412
} else {
413413
if setting.LFS.MaxFileSize > 0 && pointerBlob.Size > setting.LFS.MaxFileSize {
414-
log.Info("LFS object %v download denied because of LFS_MAX_FILE_SIZE=%d < size %d", pointerBlob.Pointer, setting.LFS.MaxFileSize, pointerBlob.Size)
414+
log.Info("Repo[%-v]: LFS object %-v download denied because of LFS_MAX_FILE_SIZE=%d < size %d", repo, pointerBlob.Pointer, setting.LFS.MaxFileSize, pointerBlob.Size)
415415
continue
416416
}
417417

@@ -432,7 +432,7 @@ func StoreMissingLfsObjectsInRepository(ctx context.Context, repo *repo_model.Re
432432

433433
err, has := <-errChan
434434
if has {
435-
log.Error("Error enumerating LFS objects for repository: %v", err)
435+
log.Error("Repo[%-v]: Error enumerating LFS objects for repository: %v", repo, err)
436436
return err
437437
}
438438

‎services/mirror/mirror_pull.go

+21-21
Original file line numberDiff line numberDiff line change
@@ -196,7 +196,7 @@ func runSync(ctx context.Context, m *repo_model.Mirror) ([]*mirrorSyncResult, bo
196196

197197
remoteAddr, remoteErr := git.GetRemoteAddress(ctx, repoPath, m.GetRemoteName())
198198
if remoteErr != nil {
199-
log.Error("GetRemoteAddress Error %v", remoteErr)
199+
log.Error("SyncMirrors [repo: %-v]: GetRemoteAddress Error %v", m.Repo, remoteErr)
200200
}
201201

202202
stdoutBuilder := strings.Builder{}
@@ -215,7 +215,7 @@ func runSync(ctx context.Context, m *repo_model.Mirror) ([]*mirrorSyncResult, bo
215215

216216
// Now check if the error is a resolve reference due to broken reference
217217
if strings.Contains(stderr, "unable to resolve reference") && strings.Contains(stderr, "reference broken") {
218-
log.Warn("Failed to update mirror repository %-v due to broken references:\nStdout: %s\nStderr: %s\nErr: %v\nAttempting Prune", m.Repo, stdoutMessage, stderrMessage, err)
218+
log.Warn("SyncMirrors [repo: %-v]: failed to update mirror repository due to broken references:\nStdout: %s\nStderr: %s\nErr: %v\nAttempting Prune", m.Repo, stdoutMessage, stderrMessage, err)
219219
err = nil
220220

221221
// Attempt prune
@@ -240,7 +240,7 @@ func runSync(ctx context.Context, m *repo_model.Mirror) ([]*mirrorSyncResult, bo
240240

241241
// If there is still an error (or there always was an error)
242242
if err != nil {
243-
log.Error("Failed to update mirror repository %-v:\nStdout: %s\nStderr: %s\nErr: %v", m.Repo, stdoutMessage, stderrMessage, err)
243+
log.Error("SyncMirrors [repo: %-v]: failed to update mirror repository:\nStdout: %s\nStderr: %s\nErr: %v", m.Repo, stdoutMessage, stderrMessage, err)
244244
desc := fmt.Sprintf("Failed to update mirror repository '%s': %s", repoPath, stderrMessage)
245245
if err = admin_model.CreateRepositoryNotice(desc); err != nil {
246246
log.Error("CreateRepositoryNotice: %v", err)
@@ -252,28 +252,28 @@ func runSync(ctx context.Context, m *repo_model.Mirror) ([]*mirrorSyncResult, bo
252252

253253
gitRepo, err := git.OpenRepository(repoPath)
254254
if err != nil {
255-
log.Error("OpenRepository: %v", err)
255+
log.Error("SyncMirrors [repo: %-v]: failed to OpenRepository: %v", m.Repo, err)
256256
return nil, false
257257
}
258258

259259
log.Trace("SyncMirrors [repo: %-v]: syncing releases with tags...", m.Repo)
260260
if err = repo_module.SyncReleasesWithTags(m.Repo, gitRepo); err != nil {
261-
log.Error("Failed to synchronize tags to releases for repository: %v", err)
261+
log.Error("SyncMirrors [repo: %-v]: failed to synchronize tags to releases: %v", m.Repo, err)
262262
}
263263

264264
if m.LFS && setting.LFS.StartServer {
265265
log.Trace("SyncMirrors [repo: %-v]: syncing LFS objects...", m.Repo)
266266
endpoint := lfs.DetermineEndpoint(remoteAddr.String(), m.LFSEndpoint)
267267
lfsClient := lfs.NewClient(endpoint, nil)
268268
if err = repo_module.StoreMissingLfsObjectsInRepository(ctx, m.Repo, gitRepo, lfsClient); err != nil {
269-
log.Error("Failed to synchronize LFS objects for repository: %v", err)
269+
log.Error("SyncMirrors [repo: %-v]: failed to synchronize LFS objects for repository: %v", m.Repo, err)
270270
}
271271
}
272272
gitRepo.Close()
273273

274274
log.Trace("SyncMirrors [repo: %-v]: updating size of repository", m.Repo)
275275
if err := models.UpdateRepoSize(db.DefaultContext, m.Repo); err != nil {
276-
log.Error("Failed to update size for mirror repository: %v", err)
276+
log.Error("SyncMirrors [repo: %-v]: failed to update size for mirror repository: %v", m.Repo, err)
277277
}
278278

279279
if m.Repo.HasWiki() {
@@ -291,7 +291,7 @@ func runSync(ctx context.Context, m *repo_model.Mirror) ([]*mirrorSyncResult, bo
291291

292292
remoteAddr, remoteErr := git.GetRemoteAddress(ctx, wikiPath, m.GetRemoteName())
293293
if remoteErr != nil {
294-
log.Error("GetRemoteAddress Error %v", remoteErr)
294+
log.Error("SyncMirrors [repo: %-v Wiki]: unable to get GetRemoteAddress Error %v", m.Repo, remoteErr)
295295
}
296296

297297
// sanitize the output, since it may contain the remote address, which may
@@ -302,7 +302,7 @@ func runSync(ctx context.Context, m *repo_model.Mirror) ([]*mirrorSyncResult, bo
302302

303303
// Now check if the error is a resolve reference due to broken reference
304304
if strings.Contains(stderrMessage, "unable to resolve reference") && strings.Contains(stderrMessage, "reference broken") {
305-
log.Warn("Failed to update mirror wiki repository %-v due to broken references:\nStdout: %s\nStderr: %s\nErr: %v\nAttempting Prune", m.Repo, stdoutMessage, stderrMessage, err)
305+
log.Warn("SyncMirrors [repo: %-v Wiki]: failed to update mirror wiki repository due to broken references:\nStdout: %s\nStderr: %s\nErr: %v\nAttempting Prune", m.Repo, stdoutMessage, stderrMessage, err)
306306
err = nil
307307

308308
// Attempt prune
@@ -325,7 +325,7 @@ func runSync(ctx context.Context, m *repo_model.Mirror) ([]*mirrorSyncResult, bo
325325

326326
// If there is still an error (or there always was an error)
327327
if err != nil {
328-
log.Error("Failed to update mirror repository wiki %-v:\nStdout: %s\nStderr: %s\nErr: %v", m.Repo, stdoutMessage, stderrMessage, err)
328+
log.Error("SyncMirrors [repo: %-v Wiki]: failed to update mirror repository wiki:\nStdout: %s\nStderr: %s\nErr: %v", m.Repo, stdoutMessage, stderrMessage, err)
329329
desc := fmt.Sprintf("Failed to update mirror repository wiki '%s': %s", wikiPath, stderrMessage)
330330
if err = admin_model.CreateRepositoryNotice(desc); err != nil {
331331
log.Error("CreateRepositoryNotice: %v", err)
@@ -339,7 +339,7 @@ func runSync(ctx context.Context, m *repo_model.Mirror) ([]*mirrorSyncResult, bo
339339
log.Trace("SyncMirrors [repo: %-v]: invalidating mirror branch caches...", m.Repo)
340340
branches, _, err := git.GetBranchesByPath(m.Repo.RepoPath(), 0, 0)
341341
if err != nil {
342-
log.Error("GetBranches: %v", err)
342+
log.Error("SyncMirrors [repo: %-v]: failed to GetBranches: %v", m.Repo, err)
343343
return nil, false
344344
}
345345

@@ -360,12 +360,12 @@ func SyncPullMirror(ctx context.Context, repoID int64) bool {
360360
return
361361
}
362362
// There was a panic whilst syncMirrors...
363-
log.Error("PANIC whilst syncMirrors[%d] Panic: %v\nStacktrace: %s", repoID, err, log.Stack(2))
363+
log.Error("PANIC whilst SyncMirrors[repo_id: %d] Panic: %v\nStacktrace: %s", repoID, err, log.Stack(2))
364364
}()
365365

366366
m, err := repo_model.GetMirrorByRepoID(repoID)
367367
if err != nil {
368-
log.Error("GetMirrorByRepoID [%d]: %v", repoID, err)
368+
log.Error("SyncMirrors [repo_id: %v]: unable to GetMirrorByRepoID: %v", repoID, err)
369369
return false
370370
}
371371

@@ -381,7 +381,7 @@ func SyncPullMirror(ctx context.Context, repoID int64) bool {
381381
log.Trace("SyncMirrors [repo: %-v]: Scheduling next update", m.Repo)
382382
m.ScheduleNextUpdate()
383383
if err = repo_model.UpdateMirror(m); err != nil {
384-
log.Error("UpdateMirror [%d]: %v", m.RepoID, err)
384+
log.Error("SyncMirrors [repo: %-v]: failed to UpdateMirror with next update date: %v", m.Repo, err)
385385
return false
386386
}
387387

@@ -392,7 +392,7 @@ func SyncPullMirror(ctx context.Context, repoID int64) bool {
392392
log.Trace("SyncMirrors [repo: %-v]: %d branches updated", m.Repo, len(results))
393393
gitRepo, err = git.OpenRepositoryCtx(ctx, m.Repo.RepoPath())
394394
if err != nil {
395-
log.Error("OpenRepository [%d]: %v", m.RepoID, err)
395+
log.Error("SyncMirrors [repo: %-v]: unable to OpenRepository: %v", m.Repo, err)
396396
return false
397397
}
398398
defer gitRepo.Close()
@@ -419,7 +419,7 @@ func SyncPullMirror(ctx context.Context, repoID int64) bool {
419419
}
420420
commitID, err := gitRepo.GetRefCommitID(result.refName)
421421
if err != nil {
422-
log.Error("gitRepo.GetRefCommitID [repo_id: %d, ref_name: %s]: %v", m.RepoID, result.refName, err)
422+
log.Error("SyncMirrors [repo: %-v]: unable to GetRefCommitID [ref_name: %s]: %v", m.Repo, result.refName, err)
423423
continue
424424
}
425425
notification.NotifySyncPushCommits(m.Repo.MustOwner(), m.Repo, &repo_module.PushUpdateOptions{
@@ -440,17 +440,17 @@ func SyncPullMirror(ctx context.Context, repoID int64) bool {
440440
// Push commits
441441
oldCommitID, err := git.GetFullCommitID(gitRepo.Path, result.oldCommitID)
442442
if err != nil {
443-
log.Error("GetFullCommitID [%d]: %v", m.RepoID, err)
443+
log.Error("SyncMirrors [repo: %-v]: unable to get GetFullCommitID[%s]: %v", m.Repo, result.oldCommitID, err)
444444
continue
445445
}
446446
newCommitID, err := git.GetFullCommitID(gitRepo.Path, result.newCommitID)
447447
if err != nil {
448-
log.Error("GetFullCommitID [%d]: %v", m.RepoID, err)
448+
log.Error("SyncMirrors [repo: %-v]: unable to get GetFullCommitID [%s]: %v", m.Repo, result.newCommitID, err)
449449
continue
450450
}
451451
commits, err := gitRepo.CommitsBetweenIDs(newCommitID, oldCommitID)
452452
if err != nil {
453-
log.Error("CommitsBetweenIDs [repo_id: %d, new_commit_id: %s, old_commit_id: %s]: %v", m.RepoID, newCommitID, oldCommitID, err)
453+
log.Error("SyncMirrors [repo: %-v]: unable to get CommitsBetweenIDs [new_commit_id: %s, old_commit_id: %s]: %v", m.Repo, newCommitID, oldCommitID, err)
454454
continue
455455
}
456456

@@ -472,12 +472,12 @@ func SyncPullMirror(ctx context.Context, repoID int64) bool {
472472
// Get latest commit date and update to current repository updated time
473473
commitDate, err := git.GetLatestCommitTime(m.Repo.RepoPath())
474474
if err != nil {
475-
log.Error("GetLatestCommitDate [%d]: %v", m.RepoID, err)
475+
log.Error("SyncMirrors [repo: %-v]: unable to GetLatestCommitDate: %v", m.Repo, err)
476476
return false
477477
}
478478

479479
if err = repo_model.UpdateRepositoryUpdatedTime(m.RepoID, commitDate); err != nil {
480-
log.Error("Update repository 'updated_unix' [%d]: %v", m.RepoID, err)
480+
log.Error("SyncMirrors [repo: %-v]: unable to update repository 'updated_unix': %v", m.Repo, err)
481481
return false
482482
}
483483

0 commit comments

Comments
 (0)