Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Improve SyncMirrors logging #19045

Merged
merged 3 commits into from
Mar 10, 2022
Merged

Improve SyncMirrors logging #19045

Show file tree
Hide file tree
Changes from 1 commit
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
1a6f4f0
Improve SyncMirrors logging
zeripath Mar 9, 2022
cb7d012
Merge branch 'main' into more-sync-mirror-logging-improvements
zeripath Mar 10, 2022
9953ca2
make the pushupdateaddtag and deletetag error messages the same format
zeripath Mar 10, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
5 changes: 3 additions & 2 deletions models/lfs.go
View file
Open in desktop
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
Open in desktop
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
Open in desktop
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 for %q in Repo[%d:%s/%s]: %w", rel.TagName, repo.ID, repo.OwnerName, repo.Name, err)
zeripath marked this conversation as resolved.
Show resolved Hide resolved
}
} 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)
zeripath marked this conversation as resolved.
Show resolved Hide resolved
}
}
}
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
Open in desktop
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