fileindex: log compaction can persist a stale NextUID, regressing the folder's UID counter under concurrent load

[0kaba0hub]

Summary

Live evidence (two independent full-load reproduction runs, imaptest+smoketest concurrently, with new DEBUG breadcrumbs from #643) shows a mailbox folder's NextUID counter regressing mid-life — e.g. dropping from 24 back to 1 — while UIDValidity stays completely unchanged. This is a genuine UID-monotonicity violation (RFC 3501), reproducible only on mdbox/sdbox (never maildir) under concurrent load, and is the actual root cause behind the report/imap objectid smoketest failures previously misattributed to the FTS checkpoint issue (#638, correctly fixed but not the cause of this).

Root cause chain (proven, not hypothesized)

1. LMTP delivery is clean. New breadcrumbs (debug: breadcrumbs around LMTP's non-atomic AllocateUID→Save→AppendMessage window #643) confirm AllocateUID/AppendMessage never race or collide — every delivery gets a unique, strictly-increasing UID at allocation time, with a per-call correlation id (call_id) proving no interleaving.

   Live log evidence, u1@d00001.test INBOX:

   23:49:57.420 fileindex: uid allocated folder=INBOX uid=24
   23:49:57.446 lmtp: uid committed folder=INBOX uid=24
   ...
   23:50:05.229 fileindex: uid allocated folder=INBOX uid=1   <- regression, not a race
   23:50:05.240 lmtp: uid committed folder=INBOX uid=1
   23:50:05.317 fileindex: uid allocated folder=INBOX uid=2
   23:50:05.332 lmtp: uid committed folder=INBOX uid=2
   

   Each commit is clean and sequential within its own transaction — the counter itself reset between 23:49:57 and 23:50:05.

2. UIDValidity provably did not change across this window (confirmed via the fts: index run start breadcrumbs from fix(fts): reset the index when a mailbox's UIDVALIDITY changes (#638) #640, which log both stored_uidvalidity and current_uidvalidity on every run):

   stored_uidvalidity=1784418459, current_uidvalidity=1784418459   (before AND after the NextUID reset)
   

   This rules out any UIDVALIDITY-triggered reset path (createFresh, the fix(fts): reset the index when a mailbox's UIDVALIDITY changes (#638) #640 fix's own reset branch, or a folder DELETE+CREATE) — those all touch UIDValidity too, and it never moved.

3. The only code path that overwrites the persisted header mid-life without an explicit UIDVALIDITY change is log compaction:

   • internal/storage/index/file/file.go:339 compactLogIfNeeded(fs), called from AppendMessage after every successful append.
   • When fs.logSize (this session's locally-tracked view of the on-disk .log file) crosses logCompactMinBytes/MaxBytes/age, it calls fs.flush(false) — a full rewrite of the base .index file via mailindex.Recreate, built from fs.file.Header as this session currently holds it in memory.
   • withFolder (the caller of both AppendMessage and compactLogIfNeeded) does call fs.reload() first every time, and reload()'s fast-path correctly compares actual on-disk .log byte size (newLogSize) against fs.logSize, not just mtime — so in principle this session should always see the latest state before compacting.
   • In practice, under concurrent load with many other yarilo-lmtp/yarilo-imap sessions racing the same folder's shared .log file, if this session's reload() ever misses (or races) the most recent state — a filesystem stat() timing edge case, an os.Stat cache artifact, or a narrow window between another process's appendMutLog write completing and its own subsequent os.Stat call — this session's in-memory fs.file.Header.NextUID can be stale relative to reality. compactLogIfNeeded's flush then persists that stale, lower NextUID as the new ground truth, and truncates the shared log to zero (truncateLog), permanently discarding whatever advances other sessions had appended that this session never picked up.

   This uniquely explains every observed property: UIDValidity untouched (compaction doesn't touch it beyond copying it as-is), NextUID regresses to a low, clean value (session's own stale local counter, not corruption/garbage), no collision ever recorded (the compacting session simply didn't know about the higher value — it's not racing to write the SAME uid, it's overwriting with an outdated LOWER ground truth), and mdbox/sdbox-only (their slower Save() — map lookup, refcounting, possible rotation — widens the window during which other sessions can advance the shared log before this session's next reload, making the staleness race far more likely to land than on maildir's near-instant flat-file writes).

Why maildir doesn't reproduce

Not a different code path — maildir uses the identical internal/storage/index/file fileindex package end-to-end (confirmed by code, not assumption). The divergence is purely timing: mdbox/sdbox's storage-layer writes (box.Save()) take measurably longer (map/refcount/rotation overhead vs. a flat file write), which widens the reload-then-compact window during which this staleness can occur under concurrent load. maildir's faster path apparently doesn't stay open long enough between reloads for the race to land in these test runs — not proof it's structurally immune, just far less likely to hit.

Fix — use the same approach real Dovecot 2.4 uses for this exact class of bug

Checked src/lib-index/mail-index-write.c in a local Dovecot 2.4 checkout. Dovecot hits the identical hazard (a full index rewrite trusting an in-memory header that might be stale relative to a concurrently-modified on-disk file) and guards it two ways — implement both, matching Dovecot's pattern, not a narrower yarilo-specific patch:

1. Identity-based staleness check, not mtime+size. mail_index_should_recreate() decides whether the on-disk index has been replaced since last opened by comparing fstat() on the already-open fd against a fresh stat() of the path — inode + device, not mtime/size:

if (st1.st_ino != st2.st_ino ||
    !CMP_DEV_T(st1.st_dev, st2.st_dev)) {
    /* Index has already been recreated since we last read it.
       We can't trust our decisions about whether to recreate it. */
    return FALSE;
}

yarilo's reload() fast-path instead compares newBaseMod == fs.baseMod && newLogSize == fs.logSize — a timestamp and a byte count, both of which can theoretically remain unchanged across specific read/write timing windows in a way inode identity can't (a stat() result served from any layer of caching, or two writes landing within the same mtime-resolution tick). Replace/augment yarilo's staleness check with an inode+device comparison, mirroring mail_index_should_recreate.

2. Explicit re-fetch after any refresh — never trust a header reference captured earlier in the call chain. mail_index_write() asserts the lock is held (i_assert(index->log_sync_locked)), and after triggering log rotation (which can itself refresh the in-memory index), it does not keep using the hdr pointer captured at function entry — it re-fetches it:

if (mail_transaction_log_rotate(index->log, FALSE) == 0) {
    ...
    /* Log rotation refreshes the index, which may cause the
       map to change. Because we're locked, it's not
       supposed to happen and will likely lead to an
       assert-crash below, but we still need to make sure
       we're using the latest map to do the checks. */
    hdr = &index->map->hdr;
    ...
}

Even Dovecot's own authors flag this as "shouldn't happen under our locking model, but we defend against it anyway." Apply the same principle in flush(): treat fs.file.Header as needing an explicit, deliberate re-fetch immediately before it's persisted as ground truth and the log discarded — not just in compactLogIfNeeded, but in every caller of flush() that can race a concurrent writer (SaveFolder, RecomputeVSize, and the reload's own indexid-mismatch recovery path all call it too, and all need the same guard).

Do not settle for a narrower fix (e.g. just adding one more blind reload() call before compaction) — the point of matching Dovecot's approach is that the staleness check itself is currently too weak (mtime+size) to structurally rule out the false-negative this bug depends on, independent of how many reload calls are added around it.

Reproduction

Confirmed on two independent full-load runs (imaptest job + smoketest on all three mailbox types running concurrently against a freshly-wiped sandbox), both showing the identical signature on u1@d00001.test (mdbox) and the sdbox equivalent, never on maildir. Root-caused via the new DEBUG breadcrumbs from #643 (lmtp: uid allocated / uid committed, fileindex: uid allocated / committing pre-allocated uid) cross-referenced with the #640 FTS breadcrumbs' stored_uidvalidity/current_uidvalidity fields.

Supersedes

The report/imap objectid smoketest failures were previously tracked under #627 (closed, superseded by #638) and #638 (closed, fixed a real but different bug — stale FTS checkpoint surviving a genuine UIDVALIDITY change). This issue is the actual remaining cause of the SAME symptom under concurrent load once #638's fix is in place: the UID a new message receives is sometimes lower than one already issued, so any FTS/search logic keyed off UID monotonicity (correctly, per IMAP semantics) treats the new message as already-covered and never indexes/finds it.

[0kaba0hub]

New, most-precise evidence yet (2.1.16, with #653's indexPath/driver breadcrumbs)

Reproduced again under the same imaptest+smoketest concurrent-load battery, on a u1@d00001.test (mdbox) freshly wiped immediately before this run (both mdbox/ and index/ removed). This time the createFresh WARN breadcrumb (#652/#653) fired at the correct, real dbox-layout path — ruling out a wrong-indexDir/driver-mismatch theory for this instance:

08:31:32.543  service=lmtp   fileindex: uid allocated  folder=INBOX uid=14
08:31:32.800  service=imap   fileindex: createFresh resetting NextUID to 1
              index_path=/var/mail/vhosts/d00001.test/u1@d00001.test/index/mailboxes/INBOX/dbox-Mails/yarilo.index
              caller=userIndex.loadOrInit  requested_uidvalidity=1784449766
08:31:38.445  service=lmtp   fileindex: uid allocated  folder=INBOX uid=1   <- regression

257ms between yarilo-lmtp successfully using the folder at uid=14 and yarilo-imap's loadOrInit seeing os.Stat on the exact same, correct path return ErrNotExist.

Revised leading theory: a genuine race at first-ever creation, not a stale read of an established file

Checked for any code path that could directly os.Remove (not .tmp+rename) the base .index file — none found (grep -rn "os.Remove(" internal/storage/index/file/*.go only shows .tmp/backup cleanup). migrateLegacyFilenames only renames a legacy file to the native name and is a no-op once the native file exists.

Given the file was wiped by the test harness moments before this run, both yarilo-lmtp and yarilo-imap are candidates to be the very first process to open u1's INBOX in this run. OpenFolder's dedup check (u.byDir[indexDir]) and the os.Stat+loadOrInit fallback happen before any per-folder lock is taken (the lock only guards withFolder's reload, not OpenFolder's own initial existence check) — so two different processes racing to open a folder that genuinely does not exist yet can both observe ErrNotExist and both call createFresh, each performing their own initial flush(true). Whichever's flush lands last silently overwrites the other's already-progressed state (up to NextUID=14 in this capture) with a fresh NextUID=1 — with no error on either side, since both believe they are legitimately creating a brand-new folder.

This is a distinct failure mode from both:

• fix(fileindex): detect .log replacement by inode identity to stop NextUID regression (#644) #645's fix (stale cached logFD surviving a truncateLog rename) — not applicable, this is about the file's very first creation, not compaction of an established one.
• fileindex: withFolderRO reloads without the cross-process lock — can race a locked compaction and poison shared in-memory header (NextUID regression persists after #645) #647 (unlocked withFolderRO reload racing a locked writer) — not applicable here either; this WARN's caller is loadOrInit, reached via OpenFolder's first-open path (before any folderState/lock exists for this folder at all), not a stale reload of an already-open one.

Suggested fix direction

OpenFolder's existence check + createFresh needs the same cross-process serialization withFolderLock already provides for established folders — currently nothing prevents two processes from concurrently discovering "this folder doesn't exist yet" and both winning. Candidates:

• Take the cross-process lock (u.b.locker, locks.MailboxKey(...)) around the os.Stat+loadOrInit+registration sequence in OpenFolder, not just around withFolder's reload — mirroring Dovecot's own pattern of never trusting an existence/freshness check taken outside the lock that guards the corresponding write.
• Alternatively, make createFresh's initial flush(true) conditional/atomic at the filesystem level (e.g. O_EXCL on the tmp-then-rename, or a check-and-set using the same inode-identity technique from fix(fileindex): detect .log replacement by inode identity to stop NextUID regression (#644) #645) so a second, late createFresh for the same path detects it lost the race and reconciles (reload + replay) instead of blindly overwriting.

Filed as a comment here rather than a new issue since it's the same NextUID-regression symptom on the same tracking issue — but it is a third, distinct trigger from #645's and #647's, found only once #653's breadcrumbs made the exact path and caller visible.