From 75eb6cc9c1efde75d2b34d85d4a3e4f8484e6ab4 Mon Sep 17 00:00:00 2001 From: zeripath Date: Thu, 10 Mar 2022 10:09:48 +0000 Subject: [PATCH] Improve SyncMirrors logging (#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 #19038 Signed-off-by: Andrew Thornton --- models/lfs.go | 5 ++-- modules/lfs/pointer.go | 13 +++++++++++ modules/repository/repo.go | 40 ++++++++++++++++---------------- services/mirror/mirror_pull.go | 42 +++++++++++++++++----------------- 4 files changed, 57 insertions(+), 43 deletions(-) diff --git a/models/lfs.go b/models/lfs.go index e0c16767f..037ed8556 100644 --- a/models/lfs.go +++ b/models/lfs.go @@ -193,12 +193,13 @@ func LFSAutoAssociate(metas []*LFSMetaObject, user *user_model.User, repoID int6 // admin can associate any LFS object to any repository, and we do not care about errors (eg: duplicated unique key), // even if error occurs, it won't hurt users and won't make things worse for i := range metas { + p := lfs.Pointer{Oid: metas[i].Oid, Size: metas[i].Size} _, err = sess.Insert(&LFSMetaObject{ - Pointer: lfs.Pointer{Oid: metas[i].Oid, Size: metas[i].Size}, + Pointer: p, RepositoryID: repoID, }) if err != nil { - log.Warn("failed to insert LFS meta object into database, err=%v", err) + log.Warn("failed to insert LFS meta object %-v for repo_id: %d into database, err=%v", p, repoID, err) } } } diff --git a/modules/lfs/pointer.go b/modules/lfs/pointer.go index 975b5e7dc..2a3a2116b 100644 --- a/modules/lfs/pointer.go +++ b/modules/lfs/pointer.go @@ -14,6 +14,8 @@ import ( "regexp" "strconv" "strings" + + "code.gitea.io/gitea/modules/log" ) const ( @@ -111,6 +113,17 @@ func (p Pointer) RelativePath() string { return path.Join(p.Oid[0:2], p.Oid[2:4], p.Oid[4:]) } +// ColorFormat provides a basic color format for a Team +func (p Pointer) ColorFormat(s fmt.State) { + if p.Oid == "" && p.Size == 0 { + log.ColorFprintf(s, "") + return + } + log.ColorFprintf(s, "%s:%d", + log.NewColoredIDValue(p.Oid), + p.Size) +} + // GeneratePointer generates a pointer for arbitrary content func GeneratePointer(content io.Reader) (Pointer, error) { h := sha256.New() diff --git a/modules/repository/repo.go b/modules/repository/repo.go index ff022f0ae..ed9ed508b 100644 --- a/modules/repository/repo.go +++ b/modules/repository/repo.go @@ -254,7 +254,7 @@ func SyncReleasesWithTags(repo *repo_model.Repository, gitRepo *git.Repository) opts.Page = page rels, err := models.GetReleasesByRepoID(repo.ID, opts) if err != nil { - return fmt.Errorf("GetReleasesByRepoID: %v", err) + return fmt.Errorf("unable to GetReleasesByRepoID in Repo[%d:%s/%s]: %w", repo.ID, repo.OwnerName, repo.Name, err) } if len(rels) == 0 { break @@ -265,11 +265,11 @@ func SyncReleasesWithTags(repo *repo_model.Repository, gitRepo *git.Repository) } commitID, err := gitRepo.GetTagCommitID(rel.TagName) if err != nil && !git.IsErrNotExist(err) { - return fmt.Errorf("GetTagCommitID: %s: %v", rel.TagName, err) + return fmt.Errorf("unable to GetTagCommitID for %q in Repo[%d:%s/%s]: %w", rel.TagName, repo.ID, repo.OwnerName, repo.Name, err) } if git.IsErrNotExist(err) || commitID != rel.Sha1 { if err := models.PushUpdateDeleteTag(repo, rel.TagName); err != nil { - return fmt.Errorf("PushUpdateDeleteTag: %s: %v", rel.TagName, err) + return fmt.Errorf("unable to PushUpdateDeleteTag: %q in Repo[%d:%s/%s]: %w", rel.TagName, repo.ID, repo.OwnerName, repo.Name, err) } } else { existingRelTags[strings.ToLower(rel.TagName)] = struct{}{} @@ -278,12 +278,12 @@ func SyncReleasesWithTags(repo *repo_model.Repository, gitRepo *git.Repository) } tags, err := gitRepo.GetTags(0, 0) if err != nil { - return fmt.Errorf("GetTags: %v", err) + return fmt.Errorf("unable to GetTags in Repo[%d:%s/%s]: %w", repo.ID, repo.OwnerName, repo.Name, err) } for _, tagName := range tags { if _, ok := existingRelTags[strings.ToLower(tagName)]; !ok { if err := PushUpdateAddTag(repo, gitRepo, tagName); err != nil { - return fmt.Errorf("pushUpdateAddTag: %v", err) + return fmt.Errorf("unable to PushUpdateAddTag: %q to Repo[%d:%s/%s]: %w", tagName, repo.ID, repo.OwnerName, repo.Name, err) } } } @@ -294,11 +294,11 @@ func SyncReleasesWithTags(repo *repo_model.Repository, gitRepo *git.Repository) func PushUpdateAddTag(repo *repo_model.Repository, gitRepo *git.Repository, tagName string) error { tag, err := gitRepo.GetTag(tagName) if err != nil { - return fmt.Errorf("GetTag: %v", err) + return fmt.Errorf("unable to GetTag: %w", err) } commit, err := tag.Commit(gitRepo) if err != nil { - return fmt.Errorf("Commit: %v", err) + return fmt.Errorf("unable to get tag Commit: %w", err) } sig := tag.Tagger @@ -315,14 +315,14 @@ func PushUpdateAddTag(repo *repo_model.Repository, gitRepo *git.Repository, tagN if sig != nil { author, err = user_model.GetUserByEmail(sig.Email) if err != nil && !user_model.IsErrUserNotExist(err) { - return fmt.Errorf("GetUserByEmail: %v", err) + return fmt.Errorf("unable to GetUserByEmail for %q: %w", sig.Email, err) } createdAt = sig.When } commitsCount, err := commit.CommitsCount() if err != nil { - return fmt.Errorf("CommitsCount: %v", err) + return fmt.Errorf("unable to get CommitsCount: %w", err) } rel := models.Release{ @@ -359,14 +359,14 @@ func StoreMissingLfsObjectsInRepository(ctx context.Context, repo *repo_model.Re _, err := models.NewLFSMetaObject(&models.LFSMetaObject{Pointer: p, RepositoryID: repo.ID}) if err != nil { - log.Error("Error creating LFS meta object %v: %v", p, err) + log.Error("Repo[%-v]: Error creating LFS meta object %-v: %v", repo, p, err) return err } if err := contentStore.Put(p, content); err != nil { - log.Error("Error storing content for LFS meta object %v: %v", p, err) + log.Error("Repo[%-v]: Error storing content for LFS meta object %-v: %v", repo, p, err) if _, err2 := models.RemoveLFSMetaObjectByOid(repo.ID, p.Oid); err2 != nil { - log.Error("Error removing LFS meta object %v: %v", p, err2) + log.Error("Repo[%-v]: Error removing LFS meta object %-v: %v", repo, p, err2) } return err } @@ -386,32 +386,32 @@ func StoreMissingLfsObjectsInRepository(ctx context.Context, repo *repo_model.Re for pointerBlob := range pointerChan { meta, err := models.GetLFSMetaObjectByOid(repo.ID, pointerBlob.Oid) if err != nil && err != models.ErrLFSObjectNotExist { - log.Error("Error querying LFS meta object %v: %v", pointerBlob.Pointer, err) + log.Error("Repo[%-v]: Error querying LFS meta object %-v: %v", repo, pointerBlob.Pointer, err) return err } if meta != nil { - log.Trace("Skipping unknown LFS meta object %v", pointerBlob.Pointer) + log.Trace("Repo[%-v]: Skipping unknown LFS meta object %-v", repo, pointerBlob.Pointer) continue } - log.Trace("LFS object %v not present in repository %s", pointerBlob.Pointer, repo.FullName()) + log.Trace("Repo[%-v]: LFS object %-v not present in repository", repo, pointerBlob.Pointer) exist, err := contentStore.Exists(pointerBlob.Pointer) if err != nil { - log.Error("Error checking if LFS object %v exists: %v", pointerBlob.Pointer, err) + log.Error("Repo[%-v]: Error checking if LFS object %-v exists: %v", repo, pointerBlob.Pointer, err) return err } if exist { - log.Trace("LFS object %v already present; creating meta object", pointerBlob.Pointer) + log.Trace("Repo[%-v]: LFS object %-v already present; creating meta object", repo, pointerBlob.Pointer) _, err := models.NewLFSMetaObject(&models.LFSMetaObject{Pointer: pointerBlob.Pointer, RepositoryID: repo.ID}) if err != nil { - log.Error("Error creating LFS meta object %v: %v", pointerBlob.Pointer, err) + log.Error("Repo[%-v]: Error creating LFS meta object %-v: %v", repo, pointerBlob.Pointer, err) return err } } else { if setting.LFS.MaxFileSize > 0 && pointerBlob.Size > setting.LFS.MaxFileSize { - log.Info("LFS object %v download denied because of LFS_MAX_FILE_SIZE=%d < size %d", pointerBlob.Pointer, setting.LFS.MaxFileSize, pointerBlob.Size) + 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) continue } @@ -432,7 +432,7 @@ func StoreMissingLfsObjectsInRepository(ctx context.Context, repo *repo_model.Re err, has := <-errChan if has { - log.Error("Error enumerating LFS objects for repository: %v", err) + log.Error("Repo[%-v]: Error enumerating LFS objects for repository: %v", repo, err) return err } diff --git a/services/mirror/mirror_pull.go b/services/mirror/mirror_pull.go index c86f15efc..6c9c4a048 100644 --- a/services/mirror/mirror_pull.go +++ b/services/mirror/mirror_pull.go @@ -201,7 +201,7 @@ func runSync(ctx context.Context, m *repo_model.Mirror) ([]*mirrorSyncResult, bo remoteAddr, remoteErr := git.GetRemoteAddress(ctx, repoPath, m.GetRemoteName()) if remoteErr != nil { - log.Error("GetRemoteAddress Error %v", remoteErr) + log.Error("SyncMirrors [repo: %-v]: GetRemoteAddress Error %v", m.Repo, remoteErr) } stdoutBuilder := strings.Builder{} @@ -225,7 +225,7 @@ func runSync(ctx context.Context, m *repo_model.Mirror) ([]*mirrorSyncResult, bo // Now check if the error is a resolve reference due to broken reference if strings.Contains(stderr, "unable to resolve reference") && strings.Contains(stderr, "reference broken") { - 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) + 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) err = nil // Attempt prune @@ -255,7 +255,7 @@ func runSync(ctx context.Context, m *repo_model.Mirror) ([]*mirrorSyncResult, bo // If there is still an error (or there always was an error) if err != nil { - log.Error("Failed to update mirror repository %-v:\nStdout: %s\nStderr: %s\nErr: %v", m.Repo, stdoutMessage, stderrMessage, err) + log.Error("SyncMirrors [repo: %-v]: failed to update mirror repository:\nStdout: %s\nStderr: %s\nErr: %v", m.Repo, stdoutMessage, stderrMessage, err) desc := fmt.Sprintf("Failed to update mirror repository '%s': %s", repoPath, stderrMessage) if err = admin_model.CreateRepositoryNotice(desc); err != nil { log.Error("CreateRepositoryNotice: %v", err) @@ -267,13 +267,13 @@ func runSync(ctx context.Context, m *repo_model.Mirror) ([]*mirrorSyncResult, bo gitRepo, err := git.OpenRepositoryCtx(ctx, repoPath) if err != nil { - log.Error("OpenRepository: %v", err) + log.Error("SyncMirrors [repo: %-v]: failed to OpenRepository: %v", m.Repo, err) return nil, false } log.Trace("SyncMirrors [repo: %-v]: syncing releases with tags...", m.Repo) if err = repo_module.SyncReleasesWithTags(m.Repo, gitRepo); err != nil { - log.Error("Failed to synchronize tags to releases for repository: %v", err) + log.Error("SyncMirrors [repo: %-v]: failed to synchronize tags to releases: %v", m.Repo, err) } if m.LFS && setting.LFS.StartServer { @@ -281,14 +281,14 @@ func runSync(ctx context.Context, m *repo_model.Mirror) ([]*mirrorSyncResult, bo endpoint := lfs.DetermineEndpoint(remoteAddr.String(), m.LFSEndpoint) lfsClient := lfs.NewClient(endpoint, nil) if err = repo_module.StoreMissingLfsObjectsInRepository(ctx, m.Repo, gitRepo, lfsClient); err != nil { - log.Error("Failed to synchronize LFS objects for repository: %v", err) + log.Error("SyncMirrors [repo: %-v]: failed to synchronize LFS objects for repository: %v", m.Repo, err) } } gitRepo.Close() log.Trace("SyncMirrors [repo: %-v]: updating size of repository", m.Repo) if err := models.UpdateRepoSize(db.DefaultContext, m.Repo); err != nil { - log.Error("Failed to update size for mirror repository: %v", err) + log.Error("SyncMirrors [repo: %-v]: failed to update size for mirror repository: %v", m.Repo, err) } if m.Repo.HasWiki() { @@ -311,7 +311,7 @@ func runSync(ctx context.Context, m *repo_model.Mirror) ([]*mirrorSyncResult, bo remoteAddr, remoteErr := git.GetRemoteAddress(ctx, wikiPath, m.GetRemoteName()) if remoteErr != nil { - log.Error("GetRemoteAddress Error %v", remoteErr) + log.Error("SyncMirrors [repo: %-v Wiki]: unable to get GetRemoteAddress Error %v", m.Repo, remoteErr) } // sanitize the output, since it may contain the remote address, which may @@ -322,7 +322,7 @@ func runSync(ctx context.Context, m *repo_model.Mirror) ([]*mirrorSyncResult, bo // Now check if the error is a resolve reference due to broken reference if strings.Contains(stderrMessage, "unable to resolve reference") && strings.Contains(stderrMessage, "reference broken") { - 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) + 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) err = nil // Attempt prune @@ -350,7 +350,7 @@ func runSync(ctx context.Context, m *repo_model.Mirror) ([]*mirrorSyncResult, bo // If there is still an error (or there always was an error) if err != nil { - log.Error("Failed to update mirror repository wiki %-v:\nStdout: %s\nStderr: %s\nErr: %v", m.Repo, stdoutMessage, stderrMessage, err) + log.Error("SyncMirrors [repo: %-v Wiki]: failed to update mirror repository wiki:\nStdout: %s\nStderr: %s\nErr: %v", m.Repo, stdoutMessage, stderrMessage, err) desc := fmt.Sprintf("Failed to update mirror repository wiki '%s': %s", wikiPath, stderrMessage) if err = admin_model.CreateRepositoryNotice(desc); err != nil { log.Error("CreateRepositoryNotice: %v", err) @@ -364,7 +364,7 @@ func runSync(ctx context.Context, m *repo_model.Mirror) ([]*mirrorSyncResult, bo log.Trace("SyncMirrors [repo: %-v]: invalidating mirror branch caches...", m.Repo) branches, _, err := git.GetBranchesByPath(ctx, m.Repo.RepoPath(), 0, 0) if err != nil { - log.Error("GetBranches: %v", err) + log.Error("SyncMirrors [repo: %-v]: failed to GetBranches: %v", m.Repo, err) return nil, false } @@ -385,12 +385,12 @@ func SyncPullMirror(ctx context.Context, repoID int64) bool { return } // There was a panic whilst syncMirrors... - log.Error("PANIC whilst syncMirrors[%d] Panic: %v\nStacktrace: %s", repoID, err, log.Stack(2)) + log.Error("PANIC whilst SyncMirrors[repo_id: %d] Panic: %v\nStacktrace: %s", repoID, err, log.Stack(2)) }() m, err := repo_model.GetMirrorByRepoID(repoID) if err != nil { - log.Error("GetMirrorByRepoID [%d]: %v", repoID, err) + log.Error("SyncMirrors [repo_id: %v]: unable to GetMirrorByRepoID: %v", repoID, err) return false } @@ -406,7 +406,7 @@ func SyncPullMirror(ctx context.Context, repoID int64) bool { log.Trace("SyncMirrors [repo: %-v]: Scheduling next update", m.Repo) m.ScheduleNextUpdate() if err = repo_model.UpdateMirror(m); err != nil { - log.Error("UpdateMirror [%d]: %v", m.RepoID, err) + log.Error("SyncMirrors [repo: %-v]: failed to UpdateMirror with next update date: %v", m.Repo, err) return false } @@ -417,7 +417,7 @@ func SyncPullMirror(ctx context.Context, repoID int64) bool { log.Trace("SyncMirrors [repo: %-v]: %d branches updated", m.Repo, len(results)) gitRepo, err = git.OpenRepositoryCtx(ctx, m.Repo.RepoPath()) if err != nil { - log.Error("OpenRepository [%d]: %v", m.RepoID, err) + log.Error("SyncMirrors [repo: %-v]: unable to OpenRepository: %v", m.Repo, err) return false } defer gitRepo.Close() @@ -444,7 +444,7 @@ func SyncPullMirror(ctx context.Context, repoID int64) bool { } commitID, err := gitRepo.GetRefCommitID(result.refName) if err != nil { - log.Error("gitRepo.GetRefCommitID [repo_id: %d, ref_name: %s]: %v", m.RepoID, result.refName, err) + log.Error("SyncMirrors [repo: %-v]: unable to GetRefCommitID [ref_name: %s]: %v", m.Repo, result.refName, err) continue } notification.NotifySyncPushCommits(m.Repo.MustOwner(), m.Repo, &repo_module.PushUpdateOptions{ @@ -465,17 +465,17 @@ func SyncPullMirror(ctx context.Context, repoID int64) bool { // Push commits oldCommitID, err := git.GetFullCommitID(gitRepo.Ctx, gitRepo.Path, result.oldCommitID) if err != nil { - log.Error("GetFullCommitID [%d]: %v", m.RepoID, err) + log.Error("SyncMirrors [repo: %-v]: unable to get GetFullCommitID[%s]: %v", m.Repo, result.oldCommitID, err) continue } newCommitID, err := git.GetFullCommitID(gitRepo.Ctx, gitRepo.Path, result.newCommitID) if err != nil { - log.Error("GetFullCommitID [%d]: %v", m.RepoID, err) + log.Error("SyncMirrors [repo: %-v]: unable to get GetFullCommitID [%s]: %v", m.Repo, result.newCommitID, err) continue } commits, err := gitRepo.CommitsBetweenIDs(newCommitID, oldCommitID) if err != nil { - log.Error("CommitsBetweenIDs [repo_id: %d, new_commit_id: %s, old_commit_id: %s]: %v", m.RepoID, newCommitID, oldCommitID, err) + log.Error("SyncMirrors [repo: %-v]: unable to get CommitsBetweenIDs [new_commit_id: %s, old_commit_id: %s]: %v", m.Repo, newCommitID, oldCommitID, err) continue } @@ -497,12 +497,12 @@ func SyncPullMirror(ctx context.Context, repoID int64) bool { // Get latest commit date and update to current repository updated time commitDate, err := git.GetLatestCommitTime(ctx, m.Repo.RepoPath()) if err != nil { - log.Error("GetLatestCommitDate [%d]: %v", m.RepoID, err) + log.Error("SyncMirrors [repo: %-v]: unable to GetLatestCommitDate: %v", m.Repo, err) return false } if err = repo_model.UpdateRepositoryUpdatedTime(m.RepoID, commitDate); err != nil { - log.Error("Update repository 'updated_unix' [%d]: %v", m.RepoID, err) + log.Error("SyncMirrors [repo: %-v]: unable to update repository 'updated_unix': %v", m.Repo, err) return false }