Skip to content

Commit

Permalink
Improve SyncMirrors logging (#19045)
Browse files Browse the repository at this point in the history 
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 <art27@cantab.net>
  • Loading branch information
@zeripath
zeripath authored Mar 10, 2022
1 parent 1314f38 commit 75eb6cc
Show file tree
Hide file tree
Showing 4 changed files with 57 additions and 43 deletions.
5 changes: 3 additions & 2 deletions models/lfs.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)
}
}
}
Expand Down
13 changes: 13 additions & 0 deletions modules/lfs/pointer.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -14,6 +14,8 @@ import (
"regexp"
"strconv"
"strings"

"code.gitea.io/gitea/modules/log"
)

const (
Expand Down Expand Up @@ -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, "<empty>")
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()
Expand Down
40 changes: 20 additions & 20 deletions modules/repository/repo.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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{}{}
Expand All @@ -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)
}
}
}
Expand All @@ -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
Expand All @@ -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{
Expand Down Expand Up @@ -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
}
Expand All @@ -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
}

Expand All @@ -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
}

Expand Down
42 changes: 21 additions & 21 deletions services/mirror/mirror_pull.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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{}
Expand All @@ -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
Expand Down Expand Up @@ -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)
Expand All @@ -267,28 +267,28 @@ 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 {
log.Trace("SyncMirrors [repo: %-v]: syncing LFS objects...", m.Repo)
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() {
Expand All @@ -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
Expand All @@ -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
Expand Down Expand Up @@ -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)
Expand All @@ -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
}

Expand All @@ -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
}

Expand All @@ -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
}

Expand All @@ -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()
Expand All @@ -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{
Expand All @@ -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
}

Expand All @@ -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
}

Expand Down

0 comments on commit 75eb6cc

Please sign in to comment.