From 8dda1acf998d426f7b3232ae49c2ae2af91d2998 Mon Sep 17 00:00:00 2001 From: Ihor Rusyn <0kaba0@gmail.com> Date: Sun, 19 Jul 2026 03:34:24 +0200 Subject: [PATCH] debug: tag reload() breadcrumbs with lock state and NextUID (#647) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit #645 fixed one trigger of the #644 NextUID-regression class (stale logFD surviving a rename), but the same symptom reproduced again on 2.1.11 under concurrent load with #645's ".log replaced" detector never firing — a second, distinct trigger. withFolderRO (the read path — most importantly OpenFolder's dedup snapshot, hit on every internal/lmtp/deliver.go delivery) calls reload() under only the in-process fs.mu, never acquiring the cross-process distributed lock (u.b.locker) that withFolderLock (the write path) always takes first. An unlocked read can interleave with another process's locked compaction and load a torn view into the shared in-memory folderState, which every subsequent correctly-locked write then trusts as a baseline. reload() now takes a locked bool (true from withFolder/withFolderLock, false from withFolderRO) and logs it plus NextUID before/after on every "fileindex: reload fast-path"/"reload full"/"reload applied" breadcrumb, so the next live reproduction can show an unlocked reload's NextUID diverging from a concurrent locked writer's instead of inferring the race indirectly. Purely additive logging behind LOG_LEVEL=debug — no behavior change. --- helm/Chart.yaml | 4 ++-- internal/storage/index/file/file.go | 10 +++++++- internal/storage/index/file/folder.go | 23 +++++++++++++++++-- .../storage/index/file/log_replace_test.go | 2 +- 4 files changed, 33 insertions(+), 6 deletions(-) diff --git a/helm/Chart.yaml b/helm/Chart.yaml index 01a04819..b213408b 100644 --- a/helm/Chart.yaml +++ b/helm/Chart.yaml @@ -2,8 +2,8 @@ apiVersion: v2 name: yarilo description: Production-grade IMAP/POP3/Submission mail server type: application -version: 2.0.18 -appVersion: "2.1.12" +version: 2.0.19 +appVersion: "2.1.13" keywords: - imap - submission diff --git a/internal/storage/index/file/file.go b/internal/storage/index/file/file.go index 76a690d0..9cb9a31b 100644 --- a/internal/storage/index/file/file.go +++ b/internal/storage/index/file/file.go @@ -457,8 +457,16 @@ func (u *userIndex) withFolderRO(folderID uint64, fn func(*folderState) error) e } // Brief exclusive lock to reload on-disk state (another process may // have written since our last flush). Held only for the disk read. + // + // NOTE (#647): this reload is NOT serialized against u.b.locker, the + // cross-process distributed lock every write path (withFolderLock) takes + // before its own reload. A concurrent, lock-holding compaction on another + // process can interleave with this unlocked read and load a torn view into + // the shared in-memory folderState — which every subsequent, correctly + // locked write then trusts as a baseline. Passing locked=false so the + // reload debug breadcrumbs make this window visible in a live repro. fs.mu.Lock() - err := fs.reload() + err := fs.reload(false) fs.mu.Unlock() if err != nil && !errors.Is(err, os.ErrNotExist) { return err diff --git a/internal/storage/index/file/folder.go b/internal/storage/index/file/folder.go index eb4939b1..2733ece1 100644 --- a/internal/storage/index/file/folder.go +++ b/internal/storage/index/file/folder.go @@ -435,7 +435,7 @@ func (u *userIndex) withFolder(folderID uint64, fn func(*folderState) error) err return fmt.Errorf("fileindex: folder %d not open", folderID) } return u.withFolderLock(fs, func() error { - if err := fs.reload(); err != nil && !errors.Is(err, os.ErrNotExist) { + if err := fs.reload(true); err != nil && !errors.Is(err, os.ErrNotExist) { return err } return fn(fs) @@ -456,8 +456,20 @@ func (u *userIndex) withFolder(folderID uint64, fn func(*folderState) error) err // // 3. If the base file changed (after OptimizeIndex), do a full // re-read of base + remaining log. -func (fs *folderState) reload() error { +// reload re-syncs fs from disk. locked reports whether the caller holds the +// cross-process distributed lock (u.b.locker) for this folder — withFolder +// (writes) always passes true; withFolderRO (reads) passes false, since it +// only takes the in-process fs.mu (#647: this makes withFolderRO's reload +// unserialized against another process's locked compaction, a suspected +// second trigger for the #644 NextUID-regression class of bug alongside the +// #645 stale-logFD fix). Logged on every reload so a live repro can show an +// unlocked reload's NextUID diverging from a concurrent locked writer's. +func (fs *folderState) reload(locked bool) error { t0 := time.Now() + nextUIDBefore := uint32(0) + if fs.file != nil { + nextUIDBefore = fs.file.Header.NextUID + } baseStat, baseErr := os.Stat(fs.indexPath) // Stat the .log by PATH so a replacement is detected by file IDENTITY, not @@ -496,8 +508,10 @@ func (fs *folderState) reload() error { if !logReplaced && newBaseMod == fs.baseMod && newLogSize == fs.logSize { slog.Debug("fileindex: reload fast-path", "folder", fs.folder, + "locked", locked, "log_size", fs.logSize, "base_mod", fs.baseMod.UnixNano(), + "next_uid", nextUIDBefore, "dur_ms", time.Since(t0).Milliseconds()) return nil } @@ -507,10 +521,12 @@ func (fs *folderState) reload() error { } slog.Debug("fileindex: reload full", "folder", fs.folder, + "locked", locked, "new_log_size", newLogSize, "old_log_size", fs.logSize, "new_base_mod", newBaseMod.UnixNano(), "old_base_mod", fs.baseMod.UnixNano(), + "next_uid_before", nextUIDBefore, "dur_ms", time.Since(t0).Milliseconds()) // Base file changed (or first open, or the log was replaced by a concurrent @@ -559,8 +575,11 @@ func (fs *folderState) reload() error { // just-written record was picked up (records_after > records_before) or not. slog.Debug("fileindex: reload applied", "folder", fs.folder, + "locked", locked, "records_before", recordsBefore, "records_after", len(fs.file.Records), + "next_uid_before", nextUIDBefore, + "next_uid_after", fs.file.Header.NextUID, "log_size", fs.logSize, "dur_ms", time.Since(t0).Milliseconds()) return nil diff --git a/internal/storage/index/file/log_replace_test.go b/internal/storage/index/file/log_replace_test.go index 3c67e8cd..7e70d129 100644 --- a/internal/storage/index/file/log_replace_test.go +++ b/internal/storage/index/file/log_replace_test.go @@ -66,7 +66,7 @@ func TestConcurrentCompactionNoUIDRegression(t *testing.T) { // Pod A reloads. The stale logFD (I1) must be recognised as replaced, // dropped, and the advanced NextUID picked up from the rewritten base. fsA.mu.Lock() - if err := fsA.reload(); err != nil { + if err := fsA.reload(true); err != nil { fsA.mu.Unlock() t.Fatalf("podA reload: %v", err) }