Skip to content

fix: stale refs after snapshot restore and server restart #180

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

Merged
inez merged 1 commit into from
Mar 12, 2026
Merged

fix: stale refs after snapshot restore and server restart #180

Changes from all commits
Commits
Show all changes
1 commit
Select commit
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
102 changes: 94 additions & 8 deletions internal/strategy/git/git.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -123,6 +123,43 @@ func New(
slog.String("error", err.Error()))
}
for _, repo := range existing {
logger.InfoContext(ctx, "Running startup fetch for existing repo",
Copy link
Copy Markdown
Contributor

@jrobotham-square jrobotham-square Mar 12, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

any idea what impact this'll have on startup times for cachew?
(they already seem to be really long from what I can see)

Copy link
Copy Markdown
Contributor Author

@inez inez Mar 12, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Frankly I don't know, but I think it's critical to have this functionality (open to different implementation) as currently we would be (or actually are) just serving a stale content.

slog.String("upstream", repo.UpstreamURL()))

preRefs, err := repo.GetLocalRefs(ctx)
if err != nil {
logger.WarnContext(ctx, "Failed to get pre-fetch refs for existing repo",
slog.String("upstream", repo.UpstreamURL()),
slog.String("error", err.Error()))
} else {
logger.InfoContext(ctx, "Pre-fetch refs for existing repo",
slog.String("upstream", repo.UpstreamURL()),
slog.Any("refs", preRefs))
}

start := time.Now()
if err := repo.Fetch(ctx); err != nil {
logger.ErrorContext(ctx, "Startup fetch failed for existing repo",
slog.String("upstream", repo.UpstreamURL()),
slog.String("error", err.Error()),
slog.Duration("duration", time.Since(start)))
} else {
logger.InfoContext(ctx, "Startup fetch completed for existing repo",
Copy link
Copy Markdown
Contributor

@jrobotham-square jrobotham-square Mar 12, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm wondering if the Info logging will be a bit too verbose for the happy case paths.

Copy link
Copy Markdown
Contributor Author

@inez inez Mar 12, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Having it was actually very helpful in discovering that there are two different code paths here. Given that this is not used much, and this logging was and might be very helpful I'm inclined to keep it till it becomes too annoying (once cachew is stable and widely adopted).

slog.String("upstream", repo.UpstreamURL()),
slog.Duration("duration", time.Since(start)))
}

postRefs, err := repo.GetLocalRefs(ctx)
if err != nil {
logger.WarnContext(ctx, "Failed to get post-fetch refs for existing repo",
slog.String("upstream", repo.UpstreamURL()),
slog.String("error", err.Error()))
} else {
logger.InfoContext(ctx, "Post-fetch refs for existing repo",
Copy link
Copy Markdown
Collaborator

@alecthomas alecthomas Mar 12, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This definitely shouldn't be at info

slog.String("upstream", repo.UpstreamURL()),
slog.Any("refs", postRefs))
}

if s.config.SnapshotInterval > 0 {
s.scheduleSnapshotJobs(repo)
}
Expand Down Expand Up @@ -438,20 +475,53 @@ func (s *Strategy) startClone(ctx context.Context, repo *gitclone.Repository) {
logger := logging.FromContext(ctx)
upstream := repo.UpstreamURL()

logger.InfoContext(ctx, "Attempting snapshot restore",
slog.String("upstream", upstream))

if err := s.tryRestoreSnapshot(ctx, repo); err != nil {
logger.InfoContext(ctx, "Snapshot restore failed, falling back to clone",
slog.String("upstream", upstream),
slog.String("error", err.Error()))
} else {
s.cleanupSpools(upstream)

logger.InfoContext(ctx, "Snapshot restore completed, scheduling catch-up fetch",
slog.String("upstream", upstream))
logger.InfoContext(ctx, "Snapshot restored, running synchronous catch-up fetch",
slog.String("upstream", upstream),
slog.String("state", repo.State().String()))

preRefs, err := repo.GetLocalRefs(ctx)
if err != nil {
logger.WarnContext(ctx, "Failed to get pre-fetch refs",
slog.String("upstream", upstream),
slog.String("error", err.Error()))
} else {
logger.InfoContext(ctx, "Pre-fetch refs",
slog.String("upstream", upstream),
slog.Any("refs", preRefs))
}

start := time.Now()
if err := repo.Fetch(ctx); err != nil {
logger.ErrorContext(ctx, "Catch-up fetch after snapshot restore failed",
slog.String("upstream", upstream),
slog.String("error", err.Error()),
slog.Duration("duration", time.Since(start)))
} else {
logger.InfoContext(ctx, "Catch-up fetch after snapshot restore completed",
slog.String("upstream", upstream),
slog.Duration("duration", time.Since(start)))
}

s.scheduler.Submit(upstream, "fetch", func(ctx context.Context) error {
s.backgroundFetch(ctx, repo)
return nil
})
postRefs, err := repo.GetLocalRefs(ctx)
if err != nil {
logger.WarnContext(ctx, "Failed to get post-fetch refs",
slog.String("upstream", upstream),
slog.String("error", err.Error()))
} else {
logger.InfoContext(ctx, "Post-fetch refs",
slog.String("upstream", upstream),
slog.Any("refs", postRefs))
}

if s.config.SnapshotInterval > 0 {
s.scheduleSnapshotJobs(repo)
Expand Down Expand Up @@ -505,20 +575,30 @@ func (s *Strategy) tryRestoreSnapshot(ctx context.Context, repo *gitclone.Reposi
return errors.Wrap(err, "create parent directory for restore")
}

logger := logging.FromContext(ctx)

if err := snapshot.Restore(ctx, s.cache, cacheKey, repo.Path(), s.config.ZstdThreads); err != nil {
_ = os.RemoveAll(repo.Path())
return errors.Wrap(err, "restore snapshot")
}
logger.InfoContext(ctx, "Snapshot archive extracted",
slog.String("upstream", repo.UpstreamURL()),
slog.String("path", repo.Path()))

if err := convertSnapshotToMirror(ctx, repo.Path(), repo.UpstreamURL()); err != nil {
_ = os.RemoveAll(repo.Path())
return errors.Wrap(err, "convert snapshot to mirror")
}
logger.InfoContext(ctx, "Snapshot converted to bare mirror",
slog.String("upstream", repo.UpstreamURL()))

if err := repo.MarkRestored(ctx); err != nil {
_ = os.RemoveAll(repo.Path())
return errors.Wrap(err, "mark restored")
}
logger.InfoContext(ctx, "Repository marked as restored",
slog.String("upstream", repo.UpstreamURL()),
slog.String("state", repo.State().String()))

return nil
}
Expand Down Expand Up @@ -603,13 +683,19 @@ func (s *Strategy) backgroundFetch(ctx context.Context, repo *gitclone.Repositor
return
}

logger.DebugContext(ctx, "Fetching updates",
logger.InfoContext(ctx, "Fetching updates",
slog.String("upstream", repo.UpstreamURL()),
slog.String("path", repo.Path()))

start := time.Now()
if err := repo.Fetch(ctx); err != nil {
logger.ErrorContext(ctx, "Fetch failed",
slog.String("upstream", repo.UpstreamURL()),
slog.String("error", err.Error()))
slog.String("error", err.Error()),
slog.Duration("duration", time.Since(start)))
return
}
logger.InfoContext(ctx, "Fetch completed",
slog.String("upstream", repo.UpstreamURL()),
slog.Duration("duration", time.Since(start)))
}