Github-Mirror/seaweedfs
1
0
Fork 0
mirror of https://github.com/seaweedfs/seaweedfs.git synced 2026-09-08 15:41:15 +02:00
Code Issues Packages Projects Releases Wiki Activity

fix(filer): stop skipping recent unflushed events on metadata subscription gaps (#10501)

Browse Source 
* fix(filer): don't skip unflushed events on metadata subscription gaps

A subscriber that falls behind the in-memory log ring during a write
burst could have its read position jumped past events that were evicted
but not yet flushed to disk — silently lost for filer.backup/filer.sync/
mount subscribers. Route all three gap-skip sites through
resolveDiskGapResume: only skip past windows older than a settled
horizon (2*LogFlushInterval); recent gaps wait for the flush and
re-read disk.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>

* fix(filer): harden metadata gap-skip guard

Address review findings on the settled-horizon guard:

- local subscriptions: gate the skip on the buffer's flush watermark
  observed before the disk read (resolveLocalGapResume) — a disk miss
  is then proof the gap is empty, with no wall-clock assumptions
- aggregated subscriptions: cap skips strictly below the horizon
  boundary (persisted reads exclude ts <= cursor) and pace capped
  advances, so the sliding horizon cannot cause disk-probe spinning
- replace unbounded sync.Cond waits with a bounded select on the
  buffer's subscriber channel + retry timer + ctx cancellation,
  eliminating the lost-wakeup stall

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>

* fix(filer): close remaining gap-skip loss paths from re-review

- log_buffer: a sentinel-offset (time-based) read below the earliest
  in-memory entry silently started at earliest, skipping a window that
  may hold evicted-but-unflushed events. Track the ring's eviction
  watermark (lastEvictedTsNs) and keep the inclusive fast path only
  when nothing at/after the position was ever evicted; otherwise
  return ResumeFromDiskError so the subscription gap guard decides.
- capped horizon advances stay on the disk-probe path (never expose a
  mid-gap position to the memory read) and keep pacing
- gap jumps land just below earliest: positions are exclusive, so the
  earliest entry itself is still delivered
- subscriber notification keys include clientId/epoch so a replacement
  stream never inherits a channel the old stream's cleanup closes

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>

* fix(log_buffer): generalize the eviction-watermark read gate

Third-review findings:

- epoch/zero-time reads bypassed the eviction watermark: gate them the
  same way, so a SinceNs=0 subscriber cannot silently start at the
  earliest retained entry after an unflushed window was evicted
- apply the watermark gate regardless of the cursor's batch offset
  (batch offsets carry no meaning for time-based reads); this also
  serves adjacent cursors (earliest == current+1) from memory instead
  of stalling them in the gap loop
- LoopProcessLogData reader names include clientId/epoch, since they
  are registered as subscriber keys internally (same collision as the
  outer notification keys)
- test: pin the gate (below/at watermark, epoch-after-eviction) and
  update the slow-consumer test to the sharper contract — complete
  in-memory history is served from memory; disk only once evicted

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>

* fix(log_buffer): watermark equality is unsafe for inclusive sentinel cursors

Sentinel (Offset <= 0) time-based cursors search from ts-1ns, i.e. they
read inclusively of their own timestamp — and the evicted window may end
exactly at that timestamp. Allow watermark equality only for exclusive
(positive-offset) cursors; sentinel cursors must be strictly above it.
Also shut down the test buffer and pin the equality cases.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>

* fix(filer): wait on an empty aggregated buffer instead of falling through

When a disk read finds nothing for a ResumeFromDiskError gap and the
aggregated buffer has no readable entries (zero earliest time),
resolveDiskGapResume declines to advance and control fell through to the
in-memory read — which returns ResumeFromDiskError again immediately,
spinning through the probe cycle without any wait. Fold the case into
the existing recent-gap branch so it waits (notification, cancellation,
or the retry interval) before re-probing, matching the local
subscription path, which already waits unconditionally.

* fix(filer): serve the exact eviction-boundary entry without another flush wait

When the flush watermark has passed the earliest in-memory entry but that
entry sits exactly one nanosecond above the cursor, the exclusive resume
target collapses onto the cursor and resolveLocalGapResume declines to
advance — while a sentinel cursor at the eviction watermark keeps
deferring the in-memory read to disk. Progress then depends on the next
flush cycle. Re-arm the cursor with a positive (exclusive) offset instead:
ReadFromBuffer explicitly allows positive-offset cursors at the watermark,
so the boundary entry is served from memory immediately.

Also promote the aggregated path's horizon-capped gap skip to a warning:
that skip may pass events a stalled flush lands later (the aggregated
ring has no flush watermark to gate on), so operators should see when a
flush stall outlasts the settled horizon.

* fix(filer): resume a gap skip with an exclusive cursor

The resume position landed one nanosecond below the earliest in-memory
entry but kept the inclusive sentinel offset. When that timestamp is also
the eviction watermark, the read gate answers ResumeFromDiskError for an
inclusive cursor, the disk read finds nothing, and the resume target
collapses onto the cursor, so neither helper can advance: the subscriber
parks on timed waits forever.

A skip is only taken once the gap is proven empty, so nothing remains to
deliver at the resume timestamp. Resume exclusively instead, and let an
inclusive cursor already sitting on the target count as progress.

* fix(filer): gate aggregated gap skips on eviction, not wall clock

Wall-clock age never proved persistence. The aggregated ring has no flush
watermark because peers persist their own local logs, so a horizon of
2 * LogFlushInterval was standing in for one. While the disk stayed empty
the horizon kept sliding forward and walked the cursor past
evicted-but-unflushed events one window at a time - the volume-outage
stall this change set exists to survive.

The ring does carry a real proof: its eviction watermark. If nothing at or
after the cursor was ever dropped, memory still holds every entry after it
and the gap is provably empty. Below the watermark entries were dropped
and only the producing peer's flush can supply them, so wait for that
flush instead of advancing. The skip that remains is the one the ring can
prove, which keeps the infinite-loop guard for a genuinely empty gap.

* perf(filer): stop re-probing disk on every metadata append

A subscriber parked on a gap woke on the log buffer's subscriber channel,
which fires on every append. On the aggregated path each wake re-ran a
full ReadPersistedLogBuffer - a ListDirectoryEntries plus a readahead
goroutine - so one parked subscriber turned every cluster-wide metadata
event into a store query, exactly while the cluster is already struggling
with the flush stall that parked it. An append also cannot settle the gap:
what this waits on is a peer persisting its own log, which nothing local
signals. Wait on the timer alone there.

The local buffer does signal its flush on that channel, so keep it, but
drain the stale token first: otherwise the appends riding the same channel
spin the wait at write rate. The retry interval covers the notification
the drain discards.

* fix(filer): surface a metadata subscriber parked on a gap

Refusing to skip an unresolved gap trades silent loss for a silent stall,
and a stall is no easier to diagnose: filer.sync and mount followers just
stop advancing, with no error on either end. The only trace was a V(3)
line nobody runs with.

Warn on entry and once a minute after, and carry a subscribe_gap_stalled
gauge for the duration, so a flush that never lands shows up as a stalled
subscriber rather than a consumer that mysteriously went quiet.

* refactor(filer): drop the metadata listener cond with no waiters left

Both listenersCond.Wait() sites are gone, so listenersWaits never leaves
zero, the guard in the filer's notify callback never fires, and the two
Broadcast calls around client registration wake nobody. Remove the cond,
its counter and its lock, and pass a nil notify func: the log buffer
already skips a nil one, and the subscriber channels carry these wakeups
now.

* test(log_buffer): drive the eviction watermark through a real seal

Both eviction tests wrote lastEvictedTsNs directly, leaving the one line
that sets it uncovered: copyToFlushInternal has to read slot 0 before
SealBuffer shifts it out, and moving that read one statement later still
passed every test. Append past the ring instead, and check the watermark
appears only on the seal that drops a window, matches that window's stop,
and then advances. The buffer under test never flushes, matching the
aggregated meta ring where the watermark is the only emptiness proof.

* refactor(filer): build the subscriber reader name once per stream

It was rebuilt on every loop iteration from values that cannot change for
the life of the stream. Hoist it next to the notification key it mirrors.

* docs(filer): tighten the gap-handling comments

Several ran to eight lines restating the same reasoning at each site.
Keep the non-obvious why, drop the retelling.

* fix(filer): mark a confirmed disk position as an exclusive cursor

A disk read returns the timestamp of the last entry it handed to the
subscriber, but the cursor built from it stayed inclusive. Land that
cursor exactly on the eviction watermark and the read gate sends it back
to disk for an entry the disk just delivered; the re-read finds nothing,
neither emptiness proof holds for an inclusive cursor there, and the
subscriber parks - until some later flush, or forever while one stays
stalled. Everything after the watermark was sitting in memory the whole
time.

Carry the offset instead, so it also covers the ring evicting onto the
cursor after the read rather than before it. The constant is no longer
gap-specific, so it is now named for what it asserts.

* perf(filer): re-park a gap wait woken by an ordinary append

Draining one stale token did not bound anything: the subscriber channel
carries an append per metadata write, so under continuous writes the next
one satisfies the wait immediately. During the write burst these stalls
come from, each parked subscriber ran the recovery loop at write rate
rather than the intended two-second cadence.

Only a flush can settle a gap, so check the flush watermark on wake-up and
go back to waiting if an append is all that arrived. The retry timer is
created once, so re-parking does not extend the interval.

* fix(filer): keep a disk-derived cursor inclusive

Marking every disk position exclusive assumed the entry at that timestamp
was the only one there. On the aggregated stream it is not: disk can
deliver one filer's persisted event at T while another filer's event at
the same T is still unflushed in the aggregate ring. The exclusive cursor
skipped it, and since the persisted reader also excludes ts <= its start,
nothing would ever bring it back.

Take the weaker guarantee instead. The reason the exclusive cursor was
introduced - an inclusive one landing on the eviction watermark parks
forever - is better answered in the resolvers: at the watermark memory
holds nothing (retained windows start strictly after it) and the persisted
reader cannot return that entry at any later time either, so refusing the
gap buys nothing and never ends. Skip it whatever the cursor's
inclusivity. That proof does not depend on a flush, so the local resolver
takes it as a second, independent disjunct alongside its flush watermark.

* perf(filer): wake a parked gap wait on flushes only

Re-parking on an append bounded the work but not the wake-ups: the
subscriber channel carries one per metadata write, so a parked subscriber
still took a scheduling round-trip per write. Worse, draining it kept the
channel empty, so every writer's non-blocking notify succeeded instead of
falling through - the burst paid for the wake-ups too.

Give the log buffer a flush-only subscriber list, notified from loopFlush,
and park on that. The append channel now fills once and stays full, which
is exactly the state the non-blocking send is designed for.

* fix(filer): stop the gap-stall gauge from leaking a series per connection

clientName is req.ClientName + "@" + peer address, so it carries the
client's ephemeral source port and changes on every reconnect. Labelling
the gauge with it minted a new series per connection, and clearing it only
ever Set(0), so nothing was ever released - a client in a reconnect loop
grows the filer's metric map and /metrics payload without bound. Key it on
the stable client-supplied name, as the neighbouring subscribe gauge
already does, and delete the series on teardown.

Two logging fixes ride along, both in the same reporter: the resume
warning was unpaced while the park warning throttles to one a minute, so a
burst that parks and resumes every couple of seconds warned on every
cycle; and clear() doubled as the teardown path, announcing "resumed
after 14m0s parked" for a client that actually gave up and disconnected
still behind.

* fix(filer): give a parked gap wait the exits the read loop has

A park never re-enters the read loop, so every exit that loop relies on
stopped working while a subscriber was parked. It kept scanning the filer
store every 2s for a client that a higher-epoch reconnect had already
superseded, until the TCP connection finally died - hours, on a half-open
one. It never reached the only code that honors UntilNs, so bounded
callers like `weed shell fs.verify` and `filer.meta.tail -until=` hung
instead of exiting. And a notification channel closed out from under it
turned the bounded wait into a spin, since a receive on a closed channel
returns instantly.

Check all three where the subscriber actually waits. Bound the wait too:
waiting is productive while the window is still queued for flush, but a
peer that never returns, or whose filer store this filer cannot read at
all, makes it permanent - and a subscriber that silently stops delivering
is no better than one that silently skips. Fail the stream after that
instead of hanging, loudly enough to say which gap and for how long.

* fix(log_buffer): keep the eviction gate out of the shared read path

The gate belonged to the filer's subscribe loops but was installed in
ReadFromBuffer, which the message queue shares and which has no gap
handling of its own. Three MQ paths broke on it: GetUnflushedMessages
asks for everything in memory past the flush watermark and got
ResumeFromDiskError instead, so SQL results silently dropped unflushed
rows; a RESET_TO_EARLIEST consumer's epoch cursor was sent to disk, and
the MQ disk reader resets an empty read back to epoch, so the whole
partition replayed on every pass; and a disk cursor landing on the
watermark carried offset -2, which the gate refused and the disk reader's
ts <= start filter also skips, so neither side could ever serve it. The
rewrite also dropped the old Offset <= 0 requirement, letting a stale
positive-offset cursor jump to memory over on-disk history, and refused
any negative-timestamp cursor even with nothing evicted.

Restore the read path exactly as it was and keep only lastEvictedTsNs,
which is the useful primitive. The filer loops now consult the watermark
themselves before reading memory, which is where the gap handling that
makes the refusal actionable already lives - and they check it every pass,
not just when the disk came up empty, since a disk read can leave the
cursor short of the watermark too.

* fix(filer): read the log file whose window spans past its own name

A log file is named for the start of the window it holds, but a window
runs up to a flush interval longer, so "12-30" can hold entries through
12:31:58. File selection compared the cursor's minute against that name
and skipped anything sorting earlier, so a subscriber resuming at 12:31:10
never saw the rest of that file: the read reported nothing on disk while
the entries sat in it.

That was survivable when a miss only meant "wait and retry", but the gap
resolvers now read a miss as proof the range is empty and move the cursor
past it, which turns those entries into silent loss. Start the file scan a
flush interval early; entries are still filtered against the exact cursor,
so this only opens one more file and never re-delivers.

* fix(filer): resume a gap with a cursor the memory read will serve

Reverting the eviction gate put ReadFromBuffer back to refusing every
positive-offset cursor below the in-memory window, but the resolvers still
handed back one - earliest-1 marked exclusive. So the resume bounced
straight to ResumeFromDiskError, the disk had nothing, and the resolver
saw its own cursor as no progress and parked: a subscriber stalled, and
after the new bound failed outright, with the whole gap sitting in the
ring the entire time.

The exclusive marking only existed to dodge a park the gate itself caused,
and the gate is gone. Resume at earliest with the sentinel offset, which
is the position master used and which case 2.1 reads inclusively. That
makes the resume unconditionally ahead of the cursor, so the progress
check it needed goes away with it.

* fix(filer): stop dropping a log file whose window outruns its name

Listing the earlier file was not enough: the iterator then decided whether
to read it by comparing the *following* file's name against the cursor,
which treats that name as an upper bound on this file's contents. It is
not one. A file is named for the start of the window it holds,
minute-truncated, and the window runs up to a flush interval longer, so
"12-30" can hold an event at 12:31:20 while "12-31" sits right after it -
and a cursor at 12:31:10 skipped straight past the event.

Bound the decision on the file itself: skip it only when its name plus the
minute truncation plus a flush interval still lands at or before the
cursor. That also covers the last file in the queue, which the old check
never skipped because it had no successor to compare against.

* fix(filer): stop a chunk-ref read from rewinding the subscriber

CollectLogFileRefs reports the minute-level name of the last file it
shipped, and the caller assigns that straight to the read position. Since
the scan now reaches back a flush interval to catch a spanning file, a
request at 12:31:10 that picks up the 12-30 ref moved the cursor to
12:30:00 - so the memory read that followed replayed events older than the
client's own SinceNs and re-sent what the chunk reader had already been
handed. The same rewind was reachable before, within a minute, whenever
the last file's name sorted behind the request.

Clamp the reported position to the one that was asked for. It still
under-advances by design, since the server never reads the entries it
ships refs for and cannot know where they end.

* fix(filer): resume below earliest so a one-entry window is not skipped

Moving the resume onto earliest itself was wrong for the smallest window
there is. A sealed window holding a single entry has startTime ==
stopTime, and the sealed-buffer lookup only enters a window whose stopTime
is strictly after the cursor, so a cursor sitting exactly on earliest
walks past it and its sole event is never delivered. Low-volume metadata
windows are routinely one entry, which is precisely when losing it is
hardest to notice.

Go back to one nanosecond below, which takes the startTime.After branch
and returns the whole window, and keep the sentinel offset the memory read
requires. The earlier test used an active multi-entry buffer, where both
cursors happen to work; the new one seals single-entry windows and
compares which entry comes back.

* fix(filer): count a persisted read as progress only when it moves

A chunk-ref read reports the minute-level name of the last file it
shipped, now clamped so it never rewinds, so it comes back non-zero even
when it names the position the subscriber already held. The loops read
non-zero as progress: they cleared the stall timer, then found the cursor
still short of the eviction watermark and parked again. Every retry
re-shipped the same refs and reset the timer, so the bound that is
supposed to end an unrecoverable stall was never reached - and a
chunk-capable client buffers those refs waiting for an event that never
comes, so it just accumulates duplicates.

Require the reported position to be strictly ahead of the cursor.

* fix(filer): count the evicted ranges the aggregated stream cannot prove

The eviction watermark belongs to the merged ring, but the disk it gets
checked against is the union of every peer's own log and each peer flushes
on its own schedule. A read that lifts the cursor from below the watermark
to above it may have done so entirely on a peer that is already ahead,
while a lagging peer still holds unflushed events inside the range just
crossed; when it flushes them they sit behind the cursor and are never
delivered. One aggregate maximum is not proof that every peer persisted
the range.

Nothing available locally separates that from the ordinary case where
every peer had in fact persisted it: the aggregator tracks peers by
address while log files carry a random per-filer id, so "has this peer
flushed through T" cannot be answered here at all. Deciding it needs the
source filer's own flush watermark carried on the subscribe stream, which
is a wire change this does not make. Count and log the crossing so the
window is at least measurable instead of invisible.

* fix(filer): send log file refs through the pipelined sender

sendLogFileRefs wrote on the raw gRPC stream while pipelinedSender's
goroutine concurrently calls Send for queued memory events - two senders
on one stream, which gRPC forbids. The window used to open once per
fall-behind; the gap retry loop now reopens it every pass. Routing refs
through the sender also restores ordering: refs used to overtake up to
1024 queued events, and the client treats any non-ref message as the
signal to process buffered refs, so overtaken refs were applied against
the wrong position.

The reason refs bypassed the sender was the batcher: their TsNs of 0
reads as far behind, and the client recognizes refs by the top-level
field alone - a refs envelope would drop its Events tail, and refs inside
Events would be applied as an empty event. Teach the batcher instead:
refs messages always go solo, and one drained mid-batch is sent solo
right after that batch.

* fix(filer): count parked subscribers instead of flagging them by name

The per-client gauge series could not work. Its label was rebuilt from the
peer address at first, which leaks a series per reconnect; keyed on the
client-supplied name instead, it collides - every mount registers as
"mount" - so one stream's teardown deleted a parked sibling's live series,
and the sibling never re-created it because its own park state said the
gauge was already set. Either way the alert this gauge exists to drive
goes dark.

A count needs no identity: Inc on park, Dec on resume or teardown, scope
as the only label. Client details stay in the logs.

Also start warning only once a stall has outlived the warn interval.
park() warned immediately on every first park, so catch-up churn that
parks and resumes every couple of seconds logged a warning pair per cycle
- exactly the flood the pacing was supposed to prevent, burying the
long-stall warnings that matter.

* fix(filer): one gap resolver, and re-arm an unservable adjacent cursor

The two resolvers were the same function - the aggregated one is the
local one with a flush watermark of zero, since its ring never flushes -
duplicated down to the comment justifying the resume target. A fix
applied to one and not the other is how the two streams drift; merge
them.

The merge carries the one behavioral fix both copies needed. Timestamp
collision bumps make adjacent entries exactly 1ns apart, so an entry
ending an evicted window leaves the cursor exactly one below earliest
with a positive batch offset. The resume target then equals the cursor
and both copies refused it as no progress - but that cursor cannot be
served (ReadFromBuffer refuses positive offsets below the window) while
the sentinel resume at the same timestamp is, and both deliver exactly
the entries after it. Refusing parked a subscriber whose data was
entirely in memory: until the next flush locally, and through a
15-minute stall failure on the aggregated path. Advance on equal target
when the held cursor is exclusive; a sentinel there is already served,
so it still refuses.

* fix(filer): a bounded subscription parked exactly on UntilNs is finished

The park's UntilNs check was strict while the bound is inclusive and
cursors are exclusive: a disk read whose last entry sits exactly on
UntilNs leaves the cursor there with everything up to the bound already
delivered. If the next range was an unprovable gap, the completed
subscription parked anyway and eventually failed - fs.verify hanging and
then erroring on a healthy cluster.

* fix(filer): re-derive the subscribe loops as one state machine

The loops had grown three generations of gap handling - a post-disk-read
branch, a post-memory-read branch, and an every-pass guard bolted on in
front of the memory read - each consulting state the others mutated. The
worst interaction wedged the aggregated stream permanently: diskExhausted
compared the disk result against the cursor that result had just updated,
and paired it with a ResumeFromDiskError latch that only a resolver
advance cleared, so one fall-behind sent every later pass into the gap
block and LoopProcessLogData never ran again. Mounts kept a
healthy-looking stream and applied nothing.

Both loops now run the same derived sequence. One disk pass; progress is
the pre-update cursor against the result, freshly each pass. One gap
decision before the memory read: a cursor the ring evicted past either
keeps draining the disk (it just advanced), resolves forward (the gap is
proven empty), or parks - and a cursor memory refused with nothing
evicted after it re-arms onto the retained window. The stale-latch branch
is gone: the error is only consulted on a pass whose own disk read came
up empty. All four parks go through one parkOnGap helper, so the exits
live in one place. The eviction watermark is read after the disk read and
the same value feeds both the guard and the unproven-crossing report,
which previously compared against a snapshot taken before a potentially
minutes-long backlog read and missed evictions landing during it. The
next-day jump now clears the stall reporter - it used to leave a stale
park epoch that could kill the next brief park instantly at the 15-minute
bound - and counts its own watermark crossing.

Chunk-ref reads get two rules the old loops lacked. Refs are sent once
per position: retries re-sent identical batches every two seconds into a
client that only drains them on a non-ref message, growing an unbounded
pending list. And when refs cannot advance the cursor - they report file
start minutes, which sit below the content the client was actually given,
pinning the cursor under the watermark forever during bursts - the pass
falls through to entry reads, which move the cursor by real timestamps
and double as the client's drain signal.

* fix(filer): give up on an unprovable gap instead of failing the stream

Failing after maxGapStall assumed the client could do something better,
but every consumer just reconnects at the same SinceNs and hits the same
wall, so an unprovable gap - a dead peer, or a peer whose filer store
this filer cannot read at all - turned into a permanent 15-minute
fail/reconnect loop delivering nothing. Master handled the same state by
skipping instantly and silently.

Take the middle: wait the full bound, then abandon the gap and resume at
the eviction watermark, where everything retained starts strictly after,
so the loss is exactly the range that could not be proven. The skip
shares the unproven-crossing counter and logs at error level - loss is
bounded, recorded, and the stream keeps working. A stall with nothing
evicted past the cursor loses nothing by waiting, so it restarts the
clock and keeps parking rather than skipping.

* test(filer): pin the file-skip bound through the production predicate

The spanning-file test asserted against its own copy of the arithmetic,
so a regression in the iterator - restoring the next-file-name comparison
or dropping the flush-interval term - would keep CI green while
re-introducing the silent loss the fix closed. Extract the bound into
logFileMayContainAfter, call it from the iterator, and point the test at
it; breaking the production expression now fails the test.

* test(log_buffer): pin the flush-subscriber contract

The registry the filer's gap parks wait on had no test at all. Cover the
observable contract: an append never wakes a flush subscriber, a flush
does with the watermark already stored, unregistering closes the channel
so an abandoned waiter unblocks, and double or unknown unregisters are
harmless.

The store-before-notify ordering in loopFlush is what makes the parks'
wake-up re-check sound, and it is not black-box testable - reordering
leaves a same-goroutine window of nanoseconds that hundreds of tight
round-trips never catch. Mark it load-bearing at the site instead; a
reorder now at least has to argue with the comment it deletes.

* fix(filer): a -1 SinceNs is a position, not the refs-gate sentinel

The once-per-position refs gate used -1 as "never sent", but a client may
legally subscribe with SinceNs=-1, whose cursor timestamp is exactly -1:
the very first pass then believed refs were already sent there and fell
back to streaming the whole persisted history entry by entry - the
bootstrap load chunks mode exists to avoid. Use MinInt64, which no cursor
can carry.

* refactor(filer): drop the aggregator's listener cond with no waiters left

Same shape as the FilerServer cond already removed: nothing increments
ListenersWaits and nothing ever calls Wait, so the three Broadcasts wake
nobody and the notify callback's guard is always false. Aggregated
subscribers wake through the buffer's subscriber channels now.

* fix(filer): make the gap metrics say what they count

The crossing counter's help text described only the aggregated peer case,
but give-ups increment it for local stalls too - a wedged local flush -
which sends an operator chasing peer replication when the problem is the
local store. Label it by scope and say both. The stalled gauge counted
every park, including waits with nothing evicted and nothing at risk,
while its help text promised evicted-but-unpersisted events; describe it
as what it is, a count of subscribers parked on a gap.

* test(filer): make the flush and stall tests assert what they claim

The flush-subscriber rounds were vacuous: the probe entry sat above the
round timestamps, so every round entry was collision-bumped and the
stored watermark exceeded the local value each assertion compared
against - the same bump mistake this test suite already made once. Put
the probe below the rounds and guard each round against bumping, so a
vacuous setup fails instead of passing.

The stall-outcome test wrote the reporter's park epoch directly,
bypassing the gauge Inc that gaveUp() later Decs - leaving the shared
process gauge at -1 for every test that runs after it. Park through the
real path, age the park by hand, release what the test holds, and assert
the gauge lands back where it started.

* fix(filer): finish the stream checks before marking it parked

parkOnGap stamped the reporter before waitOnGap ran its instant done
exits, so a bounded subscription completing inside a gap state was marked
parked for the microsecond before done fired - a phantom gauge blip and a
false "disconnected still behind" warning on every healthy completion.
Fold waitOnGap into parkOnGap so the done exits run first and the park
mark only ever covers a stream that actually waits.

While the park owns its timer, back the retry off as the stall ages -
2s probes growing toward one a minute - since every retry re-reads the
persisted log, and probing the store each 2s for 15 minutes per parked
subscriber during the very outage that parked them makes the bad time
worse. The subtest still named for the old fail-the-stream stall
behavior goes with the merge.

* fix(log_buffer): gate filer cursors against eviction under the read lock

The subscribe loops checked the eviction watermark and then read memory,
but a seal can land between the two: the read then served a sentinel
cursor from the earliest retained window, silently skipping the window
just evicted - the loss class this PR exists to make loud, surviving as
a race.

The only place the check is atomic with the serve decision is inside
ReadFromBuffer, under the lock seals take to evict. Rather than put the
policy back into the shared read path - which broke four message-queue
readers last time - add a new sentinel offset that opts into it:
EvictionGatedOffset reads inclusively exactly like -2, except below the
watermark it is refused to disk. The filer loops stamp it on every
cursor they hand the memory read; a refusal lands in the same gap
machinery the loop-side check feeds, so the race collapses into the
handled path. MQ cursors never carry it and keep master behavior
byte-for-byte.

* fix(filer): gate the aggregated gap on received, not bumped, timestamps

The aggregated ring rewrites an out-of-order arrival to its head plus a
nanosecond, so after any bump-heavy interval - a peer history replay
following a restart is enough - its eviction watermark lives above every
timestamp that exists on any peer's disk. Comparing a disk cursor against
it parked subscribers that had in fact drained every peer's log: a
15-minute delivery freeze ending in a give-up skip and a false loss
alarm, on a healthy cluster where master resumed instantly.

Track a second watermark in the received timestamp space - the highest
pre-bump timestamp among evicted entries - and gate the aggregated loop
on that. Disk cursors and received timestamps are the same space, so the
comparison means what it says: at or past it, every evicted entry's
original was at or below the cursor, and everything flushed of them was
already delivered. The bumped watermark keeps guarding the in-ring read
gate, whose cursors live in ring space. The local buffer is untouched:
it flushes its own bumped timestamps, so there the two spaces are one.

* fix(filer): ship each log chunk once and stop echoing ref'd files inline

Chunk mode duplicated data through two doors. Consecutive ref
collections overlap by design - the scan backs off a flush interval to
catch a spanning file, and a filer appends chunks to its newest file -
so the same file was shipped again on every pass that re-listed it: the
client re-downloaded its chunks, and a duplicated file mid-batch rewinds
timestamps inside the client's per-filer merge, which reads each stream
as sorted - transiently resurrecting deleted entries during catch-up.
Track per subscription how many chunks of each file were shipped and
send only the unsent suffix; state prunes with the scan window, so it
holds a few files per filer.

The second door was the entry fallback: when refs cannot advance the
minute-named cursor, the pass streamed the ref'd file's tail inline, and
the client applies inline events unfiltered - the same tail it already
applied from chunks. Entry passes for chunk clients now advance the
cursor without delivering; everything they skip is covered by the refs
already sent or the deltas the next collection ships.

* refactor(filer): one gap decision shared by both subscribe loops

The post-disk gap tree - guard, drain, resolve, two parks, the re-arm -
existed twice, differing only in buffer, watermark space, flush getter,
park channels, and reason strings. Four rounds of review fixes have shown
the copies drift the moment one is edited alone. gapPass now carries the
five differences and the tree lives once; the loops shrink to a
three-way switch between reading memory, restarting the pass, and ending
the stream.

* docs(filer): trim the gap-machinery comments to the why

Several blocks had grown to ten-plus lines restating what the tests
already pin or retelling one rationale at multiple sites. Keep the
non-obvious why - the load-bearing flush ordering, the two timestamp
spaces, the refusal-at-equality argument - in a few lines each.

* fix(log_buffer): credit an entry's received timestamp to its own window

The received-ts capture ran before the rollover check, so an append that
sealed the previous window stamped its timestamp onto that window and
then lost it in the reset of the new one. The eviction watermark this
feeds broke both ways: the sealed window's value was inflated by an entry
it does not contain - parking aggregated subscribers on gaps that were
drained - and the entry's real window was deflated, proving gaps empty
that still held its event on some peer's unflushed path. Credit the
timestamp only after the entry lands, when its window is known.

* fix(filer): rebase a shipped chunk suffix to logical offset zero

A grown file's delta kept the chunks' original file offsets, but the
client's chunk reader starts at logical zero and a list opening higher
reads as instant EOF - a successfully empty replay, and since chunk
clients no longer receive disk entries inline, the appended events were
silently dropped. Clone the suffix chunks with offsets rebased to zero;
the cut is record-aligned because each append is one uploaded chunk of
whole entries, so the suffix decodes as a file of its own.

* fix(filer): finish every chunk refs batch with a transition the client acts on

Both chunk consumers buffer refs until a non-ref message arrives, so a
source with historical logs and a quiet ring - a mount reconnecting
after a filer restart is the common case - shipped its backlog and then
went silent: the client sat on the refs until the next metadata mutation
anywhere in the cluster. The disk step now ends every batch with the
empty-notification marker the client already treats as a resume-cursor
advance.

The same step closes the inline replay: the cursor used to stay at the
last file's minute name, so the memory read re-delivered the retained
tail of a file the client had just read via chunks - T1..Tn applied
twice. The advance-only entry read now runs on every chunk pass, moving
the cursor to the true disk content end before memory is consulted.

Ordering inside the pass is load-bearing: the entry read can outrun the
shipped refs by a chunk appended between collection and read, and the
transition timestamp becomes the client's refs filter - stamping it past
unshipped content would silently drop that chunk's events on the next
delta. The pass therefore re-ships the delta after the entry read, so
the transition never exceeds shipped content. Bump-displaced aggregated
entries can still arrive inline above the cursor with originals below
it; that duplication is bounded and stays within the documented
at-least-once residual.

* fix(filer): prune ref state at the minute the scan actually stops at

The collector compares file names at minute granularity while the prune
used the exact-nanosecond scan bound, so for a cursor at 12:31:20 the
12-30 file was still collected but its sent state was already deleted -
the next pass reshipped the whole file, re-creating the duplicate-refs
class the state exists to prevent. Truncate the bound to the minute the
file names live in.

* fix(filer): derive the chunk cursor from the shipped refs themselves

The advance-only entry read left the three positions that must agree in
each other's blind spots. Its snapshot could trail the second delta's, so
a chunk appended between them shipped events newer than the cursor and
the memory pass sent them again. And it made the filer decode the tail
range on every pass, serialized ahead of the client's own reads by the
transition marker - re-introducing a slice of the replay work chunk mode
exists to offload.

Compute the cursor from the shipped set instead: the final entry
timestamp of each filer's last shipped chunk, decoded once through the
shared chunk cache. Refs coverage, transition marker, and memory start
are then the same number by construction - nothing is decoded twice,
nothing is dropped, and the per-pass server cost falls to one cached
chunk decode per filer. The second delta and the once-per-position refs
gate existed to patch the entry read's snapshot races, so both go with
it; the range read survives only as a fallback for legacy chunks that do
not decode standalone.

* fix(filer): keep the chunk-cursor probe inside the shipped snapshot

Three holes in the tail probe, all variations of stepping outside what
was shipped. A permanently missing chunk failed the stream before the
transition marker, so the client discarded its pending refs and
reconnected to the same failure forever - blocking all later metadata
behind one dead volume, where every other replay path (including the
client's own reader) skips such chunks; the probe now walks back to the
last readable chunk, and a filer with nothing readable simply contributes
no cursor. The legacy fallback re-listed the logs after the refs were
collected, so a concurrent append could push the range end over an
unshipped chunk and the marker past events the client never received; it
now streams the shipped chunk list itself, so no snapshot other than the
shipped one is ever consulted. And a file selected before UntilNs can
hold entries past it, which the client filters while still adopting the
marker as its checkpoint - a later bounded request then skipped them;
the marker is clamped to the bound.

* fix(filer): make the cursor probe an exact mirror of the client's reader

The probe answered from the server's view of the chunks; the marker's
correctness depends on the client's. Its backward walk found the last
readable chunk, but the client reads forward and stops at the first
unreadable one, never resuming within a file - for readable, missing,
readable the marker claimed the suffix the client never applied, losing
those entries permanently. Keeping only each filer's final file ref
discarded the progress of earlier readable files when that file was
wholly missing, rewinding the marker to the start cursor. And a torn
trailing size prefix - what a crashed writer leaves - failed the probe
where the client reads a clean end, blocking the marker forever on data
the client accepts.

The probe is now shaped like the reader it answers for: per file the
readable prefix, per filer the newest file with content, and no
condition escapes as an error - understating the marker only re-ships,
overstating loses events, and a probe failure must never block the
transition the client is waiting on. Each rule is pinned by a test that
fails against the previous shape.

* fix(filer): judge chunk readability at the volumes, not the decode cache

Two ways the probe's answer could drift from what the client experiences.
A chunk this server decoded earlier stays warm in the shared cache after
its volume dies, so the probe sailed past a chunk the direct-reading
client stops at - marker beyond the unread suffix, entries lost. Every
chunk now passes a volume lookup before the cache is consulted; the
lookup rides the master client's in-memory map, so the probe stays cheap.

And a probe stop was treated as harmless understatement, but the delta
had already marked the whole ref sent: a transient server-side failure
left the cursor stranded behind shipped content for the life of the
connection, parking aggregated streams below the watermark for data the
client already holds. The pass now rolls back the sent state of every
ref above the file that answered the probe, so unreached refs re-ship
and re-probe until the cursor gets there. Re-shipped entries at or below
the client's checkpoint are filtered client-side, and batches are
marker-separated, so a re-shipped file cannot rewind a merge mid-batch.

* test(filer): end-to-end subscribe-loop harness and wire-contract tests

Every escaped bug across this change's review rounds lived in an
interaction the unit tests could not see: the loop state machine, the
disk/memory handoff, or the server/client contract. The harness runs the
real SubscribeLocalMetadata loop against a real leveldb-backed filer,
faking only the volume layer behind the existing test hooks, and asserts
the delivered stream itself.

Eight scenarios, each pinning a class this change was reviewed for: the
headline evicted-unflushed gap parks and then delivers in full; a ring
that evicted nothing serves memory promptly; a backlog-to-live handoff
with 1ms-adjacent timestamps across every boundary delivers exactly
once; a flush-proven gap over vacuumed log files skips to the retained
ring including a single-entry window; a bounded subscription terminates
at its bound; a permanently wedged flush ends in the give-up skip with
the stream still alive; and chunk mode is checked against the real
client code - pb.ReadLogFileRefs applied to the shipped refs must cover
everything the transition marker claims, with and without a dead volume
in the middle.

Validated by re-introducing three fixed bugs: the missing eviction guard
delivers during the unproven gap, a 2ms cursor error at the handoff
drops exactly one event, and resuming at rather than below the earliest
retained window loses a single-entry window's sole event - each caught
by the scenario built for it. The gap timing knobs become vars so parks
run at test speed, a small filer hook swaps the volume-touching read
functions, and a sender test pins the refs wire rules the client
depends on: never batched, never an envelope, everything in order.

* fix(filer): re-ship a partially read answering file, pin the probe's limits

The sent-state rollback stopped at files newer than the one that answered
the probe. When the answering file itself was only prefix-readable - a
dead or transient chunk mid-file - its unread suffix stayed marked sent,
and the next append advanced the cursor past it for good. The probe now
reports whether the answering file was read through to its end, and a
prefix-limited answer re-ships that file too; a torn tail counts as
complete, since the client's read ends there as well. The rollback rules
live in one predicate with a table test - files below a complete answer
stay sent, because the client has moved past them and re-shipping cannot
rewind its filter.

Two test honesty fixes ride along. The loop harness derived its timestamp
base from time.Now() per call, so expectations recomputed across a second
boundary drifted by exactly one second; the base is now fixed per
harness. And the probe's liveness boundary is pinned as a test instead of
a comment: a volume lookup cannot see a dead needle or a stale location
inside a resolvable volume, so a warm cache can answer past a chunk the
client fails on - accepted because metadata log chunks die
volume-at-a-time and the alternative is a real read per probe, which is
what the probe exists to avoid. The test states the boundary so changing
it is a decision, not an accident.

---------

Co-authored-by: Claude Fable 5 <noreply@anthropic.com>
Co-authored-by: Chris Lu <chris.lu@gmail.com>
This commit is contained in:
Jaehoon Kim
2026-08-02 00:06:22 -07:00
committed by GitHub
co-authored by Claude Fable 5 Chris Lu
parent e696c2585e
commit 813a4b0711
13 changed files with 2985 additions and 189 deletions
Download Patch File Download Diff File Expand all files Collapse all files
weed/filer/filer_notify_read.go
+149 -10
View File
@@ -23,13 +23,138 @@ type LogFileEntry struct {
FileEntry *Entry
}
// logFileMayContainAfter reports whether the log file named for fileTsNs can
// hold any entry past startTsNs. The following file's name is not the bound: a
// file is named for the start of the window it holds, minute-truncated, and the
// window runs up to a flush interval longer, so "12-30" can hold 12:31:20 while
// "12-31" exists alongside it. Comparing against the next name dropped exactly
// the spanning file a mid-window cursor needs.
func logFileMayContainAfter(fileTsNs, startTsNs int64) bool {
return fileTsNs+int64(time.Minute)+int64(LogFlushInterval) > startTsNs
}
// persistedLogScanStart backs a read position off by one flush interval before
// choosing which log files to open. A log file is named for the start of the
// window it holds and a window spans up to flushInterval, so a file whose name
// sorts before the cursor's own minute can still hold entries after it -- a
// window sealed at 12:30:59 and ending 12:31:58 lives in "12-30". Entries are
// filtered against the exact cursor afterwards, so widening the file scan only
// costs a little extra reading and never re-delivers.
func persistedLogScanStart(t time.Time) time.Time {
return t.Add(-LogFlushInterval)
}
// LastShippedLogEntryTsNsForFiler mirrors the client's reader across one
// filer's shipped files, in ship order: a file that fails mid-read still
// delivers its readable prefix and later files still deliver after it, so the
// newest file with readable content answers. answeredFileTsNs names that file
// so the caller can roll back the sent state of everything newer - refs the
// cursor did not reach must re-ship, or a transient probe failure leaves the
// cursor behind them for the life of the connection.
// complete reports whether the answering file was read through to its end: a
// prefix-limited answer means the ref's unread suffix must re-ship too, or a
// transient mid-file failure abandons it for the life of the connection.
func (f *Filer) LastShippedLogEntryTsNsForFiler(refs []*filer_pb.LogFileChunkRef) (tsNs int64, answeredFileTsNs int64, ok bool, complete bool) {
for i := len(refs) - 1; i >= 0; i-- {
if tsNs, ok, complete = f.lastShippedLogEntryTsNs(refs[i].Chunks); ok {
return tsNs, refs[i].FileTsNs, ok, complete
}
}
return 0, 0, false, false
}
// lookupLogChunkFn reports whether a chunk still resolves to a live volume.
// Swapped in tests.
var lookupLogChunkFn = func(f *Filer, fileId string) error {
_, err := f.MasterClient.GetLookupFileIdFunction()(context.Background(), fileId)
return err
}
// lastShippedLogEntryTsNs mirrors the client's read of one shipped file: a
// sequential scan of exactly these chunks that ends at the first unreadable
// one, so a marker built from it never claims content the client will not
// apply. Unreadable includes transient failures - understating the marker
// only re-ships, overstating loses events - and no error escapes: a probe
// failure must never block the transition the client is waiting on.
//
// Readability is judged where the client reads - the volumes - not by the
// decoded-chunk cache: a chunk this server decoded an hour ago may sit on a
// volume that has since died, and the direct-reading client stops there no
// matter how well the cache still remembers the bytes.
func (f *Filer) lastShippedLogEntryTsNs(chunks []*filer_pb.FileChunk) (tsNs int64, ok bool, complete bool) {
for _, chunk := range chunks {
if lookupErr := lookupLogChunkFn(f, chunk.GetFileIdString()); lookupErr != nil {
return tsNs, ok, false
}
entries, loadErr := f.persistedLogCache.getOrLoad(chunk.GetFileIdString(), int64(chunk.Size), func() ([]*filer_pb.LogEntry, bool, error) {
return loadLogFileEntriesFn(f.MasterClient, chunk)
})
if errors.Is(loadErr, errLogChunkIncomplete) {
// Records span chunks; the client streams such a file whole.
if streamTsNs, streamOk, streamComplete := f.lastStreamedLogEntryTsNs(chunks); streamOk {
return streamTsNs, true, streamComplete
}
return tsNs, ok, false
}
if loadErr != nil {
return tsNs, ok, false // prefix ends here, like the client's reader
}
if len(entries) > 0 {
tsNs, ok = entries[len(entries)-1].TsNs, true
}
}
return tsNs, ok, true
}
// lastStreamedLogEntryTsNs scans the chunk list as one byte stream, ending
// where the client's reader ends: a clean or torn tail, a missing chunk, or
// undecodable bytes all terminate the scan with the progress made.
func (f *Filer) lastStreamedLogEntryTsNs(chunks []*filer_pb.FileChunk) (tsNs int64, ok bool, complete bool) {
r := newLogFileStreamReader(f.MasterClient, chunks)
if closer, isCloser := r.(io.Closer); isCloser {
defer closer.Close()
}
sizeBuf := make([]byte, 4)
for {
if _, readErr := io.ReadFull(r, sizeBuf); readErr != nil {
// A clean or torn tail is where the client's read ends too; only a
// mid-stream failure leaves an unread remainder worth re-shipping.
ended := readErr == io.EOF || readErr == io.ErrUnexpectedEOF
return tsNs, ok, ended
}
size := util.BytesToUint32(sizeBuf)
if size > maxLogEntrySize {
return tsNs, ok, false
}
data := make([]byte, size)
if _, readErr := io.ReadFull(r, data); readErr != nil {
return tsNs, ok, false
}
logEntry := &filer_pb.LogEntry{}
if unmarshalErr := logEntry.UnmarshalVT(data); unmarshalErr != nil {
return tsNs, ok, false
}
tsNs, ok = logEntry.TsNs, true
}
}
// PersistedLogScanStartTsNs is the oldest file-name timestamp a scan from t
// can still list. File names are minute-truncated, and the collector compares
// names at minute granularity, so the bound must truncate too: an exact-ns
// bound sits inside the boundary file's minute and disowns a file the next
// collection will still return.
func PersistedLogScanStartTsNs(t time.Time) int64 {
return persistedLogScanStart(t).Truncate(time.Minute).UnixNano()
}
func (f *Filer) collectPersistedLogBuffer(startPosition log_buffer.MessagePosition, stopTsNs int64) (v *OrderedLogVisitor, err error) {
if stopTsNs != 0 && startPosition.Time.UnixNano() > stopTsNs {
return nil, io.EOF
}
startDate := fmt.Sprintf("%04d-%02d-%02d", startPosition.Time.Year(), startPosition.Time.Month(), startPosition.Time.Day())
scanFrom := persistedLogScanStart(startPosition.Time)
startDate := fmt.Sprintf("%04d-%02d-%02d", scanFrom.Year(), scanFrom.Month(), scanFrom.Day())
dayEntries, _, listDayErr := f.ListDirectoryEntries(context.Background(), SystemLogDir, startDate, true, math.MaxInt32, "", "", "")
if listDayErr != nil {
@@ -48,8 +173,9 @@ func (f *Filer) CollectLogFileRefs(ctx context.Context, startPosition log_buffer
return nil, 0, nil
}
startDate := fmt.Sprintf("%04d-%02d-%02d", startPosition.Time.Year(), startPosition.Time.Month(), startPosition.Time.Day())
startHourMinute := fmt.Sprintf("%02d-%02d", startPosition.Time.Hour(), startPosition.Time.Minute())
scanFrom := persistedLogScanStart(startPosition.Time)
startDate := fmt.Sprintf("%04d-%02d-%02d", scanFrom.Year(), scanFrom.Month(), scanFrom.Day())
startHourMinute := fmt.Sprintf("%02d-%02d", scanFrom.Hour(), scanFrom.Minute())
var stopDate, stopHourMinute string
if stopTsNs != 0 {
stopTime := time.Unix(0, stopTsNs).UTC()
@@ -105,9 +231,24 @@ func (f *Filer) CollectLogFileRefs(ctx context.Context, startPosition log_buffer
lastTsNs = t.UnixNano()
}
}
lastTsNs = clampLogRefsCursor(lastTsNs, startPosition.Time.UnixNano())
return
}
// clampLogRefsCursor keeps a chunk-ref read from moving the subscriber's cursor
// backwards. Refs are named for the minute their window starts in, so the last
// one routinely sorts before the position that was asked for -- always, now
// that the scan reaches back a flush interval to pick up a spanning file. The
// caller makes this value the new read position, and rewinding it would replay
// memory from before the client's own SinceNs and re-send what the chunk reader
// has already been handed.
func clampLogRefsCursor(lastTsNs, startTsNs int64) int64 {
if lastTsNs < startTsNs {
return startTsNs
}
return lastTsNs
}
func (f *Filer) HasPersistedLogFiles(startPosition log_buffer.MessagePosition) (bool, error) {
startDate := fmt.Sprintf("%04d-%02d-%02d", startPosition.Time.Year(), startPosition.Time.Month(), startPosition.Time.Day())
dayEntries, _, listDayErr := f.ListDirectoryEntries(context.Background(), SystemLogDir, startDate, true, 1, "", "", "")
@@ -234,8 +375,9 @@ func NewLogFileEntryCollector(f *Filer, startPosition log_buffer.MessagePosition
// println("enqueue day entry", dayEntry.Name())
}
startDate := fmt.Sprintf("%04d-%02d-%02d", startPosition.Time.Year(), startPosition.Time.Month(), startPosition.Time.Day())
startHourMinute := fmt.Sprintf("%02d-%02d", startPosition.Time.Hour(), startPosition.Time.Minute())
scanFrom := persistedLogScanStart(startPosition.Time)
startDate := fmt.Sprintf("%04d-%02d-%02d", scanFrom.Year(), scanFrom.Month(), scanFrom.Day())
startHourMinute := fmt.Sprintf("%02d-%02d", scanFrom.Hour(), scanFrom.Minute())
var stopDate, stopHourMinute string
if stopTsNs != 0 {
stopTime := time.Unix(0, stopTsNs+24*60*60*int64(time.Second)).UTC()
@@ -410,15 +552,12 @@ func (iter *LogFileQueueIterator) getNext(v *OrderedLogVisitor) (logEntry *filer
if iter.stopTsNs != 0 && t.TsNs > iter.stopTsNs {
return nil, io.EOF
}
next := iter.q.Peek()
if next == nil {
if iter.q.Peek() == nil {
if collectErr := v.logFileEntryCollector.collectMore(v); collectErr != nil && collectErr != io.EOF {
return nil, collectErr
}
next = iter.q.Peek() // Re-peek after collectMore
}
// skip the file if the next entry is before the startTsNs
if next != nil && next.TsNs <= iter.startTsNs {
if !logFileMayContainAfter(t.TsNs, iter.startTsNs) {
continue
}
iter.currentFileIterator = newLogFileIterator(iter.masterClient, iter.cache, t.FileEntry, iter.startTsNs, iter.stopTsNs)
weed/filer/filer_notify_read_minute_test.go
+270
View File
@@ -0,0 +1,270 @@
package filer
import (
"bytes"
"fmt"
"io"
"testing"
"time"
"github.com/seaweedfs/seaweedfs/weed/pb/filer_pb"
"github.com/seaweedfs/seaweedfs/weed/util"
"github.com/seaweedfs/seaweedfs/weed/wdclient"
)
// TestPersistedLogScanStartCoversSpanningWindow pins the file-selection window.
// A log file is named for the start of the window it holds, and a window spans
// up to LogFlushInterval, so a cursor inside the window's later minutes must
// still open the file named for its earlier one -- otherwise the read reports
// "nothing on disk" for entries that are sitting in it, and the gap resolvers
// take that miss as proof the range is empty.
func TestPersistedLogScanStartCoversSpanningWindow(t *testing.T) {
// A window sealed at 12:30:59 ending 12:31:58 is written to "12-30".
sealed := time.Date(2026, 6, 29, 12, 30, 59, 0, time.UTC)
fileMinute := sealed.Format("15-04")
// A subscriber resuming mid-window must not sort past that file.
for _, cursor := range []time.Time{
sealed.Add(11 * time.Second), // 12:31:10, the reported case
sealed.Add(59 * time.Second), // 12:31:58, the window's last entry
sealed, // exactly the window start
} {
scanMinute := persistedLogScanStart(cursor).Format("15-04")
if scanMinute > fileMinute {
t.Fatalf("cursor %v scans from %q, which sorts past the file %q holding it",
cursor.Format("15:04:05"), scanMinute, fileMinute)
}
}
}
// A cursor just after midnight has to reach back into the previous day.
func TestPersistedLogScanStartCrossesMidnight(t *testing.T) {
cursor := time.Date(2026, 6, 29, 0, 0, 30, 0, time.UTC)
scanFrom := persistedLogScanStart(cursor)
if got, want := scanFrom.Format("2006-01-02"), "2026-06-28"; got != want {
t.Fatalf("scan date = %q, want %q so the previous day's last file is listed", got, want)
}
}
// TestSpanningLogFileIsNotSkipped pins the other half of the minute-boundary
// fix, against the predicate the iterator actually calls. Widening which files
// get listed is useless if the iterator then drops the spanning file, which it
// did by treating the following file's name as an upper bound on this file's
// contents -- it is not.
func TestSpanningLogFileIsNotSkipped(t *testing.T) {
// Window sealed at 12:30:59, ending 12:31:58, written to "12-30".
spanning := time.Date(2026, 6, 29, 12, 30, 0, 0, time.UTC).UnixNano()
// The next window starts at 12:31:59 and is written to "12-31".
following := time.Date(2026, 6, 29, 12, 31, 0, 0, time.UTC).UnixNano()
cursor := time.Date(2026, 6, 29, 12, 31, 10, 0, time.UTC).UnixNano()
if following > cursor {
t.Fatal("precondition: the following file's name sorts at or before the cursor")
}
if !logFileMayContainAfter(spanning, cursor) {
t.Fatal("the spanning file holds entries past the cursor and must be read")
}
// A file that genuinely cannot reach the cursor is still skipped, so the
// widening does not turn into reading the whole day.
old := time.Date(2026, 6, 29, 12, 0, 0, 0, time.UTC).UnixNano()
if logFileMayContainAfter(old, cursor) {
t.Fatal("a file a full interval behind the cursor should still be skipped")
}
}
// TestClampLogRefsCursorNeverRewinds pins that a chunk-ref read cannot move the
// subscriber backwards. The refs carry minute-level names, so the last one
// normally sorts before the requested position, and the caller assigns that
// value straight to the read cursor.
func TestClampLogRefsCursorNeverRewinds(t *testing.T) {
cursor := time.Date(2026, 6, 29, 12, 31, 10, 0, time.UTC).UnixNano()
spanningFile := time.Date(2026, 6, 29, 12, 30, 0, 0, time.UTC).UnixNano()
if got := clampLogRefsCursor(spanningFile, cursor); got != cursor {
t.Fatalf("cursor moved to %v, want it held at %v", time.Unix(0, got), time.Unix(0, cursor))
}
// A ref genuinely ahead of the cursor still advances it.
ahead := time.Date(2026, 6, 29, 12, 32, 0, 0, time.UTC).UnixNano()
if got := clampLogRefsCursor(ahead, cursor); got != ahead {
t.Fatalf("cursor = %v, want it to advance to %v", time.Unix(0, got), time.Unix(0, ahead))
}
}
// TestPersistedLogScanStartTsNsMinuteAligned pins the prune bound against the
// collector's minute-granular file comparison: a cursor at 12:31:20 still
// collects the 12-30 file, so the bound must not sit past 12:30:00 - an
// exact-ns bound disowns the file's sent state and the next pass reships it
// whole, re-creating the duplicate-refs class the state exists to prevent.
func TestPersistedLogScanStartTsNsMinuteAligned(t *testing.T) {
cursor := time.Date(2026, 6, 29, 12, 31, 20, 0, time.UTC)
fileTsNs := time.Date(2026, 6, 29, 12, 30, 0, 0, time.UTC).UnixNano()
bound := PersistedLogScanStartTsNs(cursor)
if fileTsNs < bound {
t.Fatalf("bound %v disowns the 12-30 file the collector still lists", time.Unix(0, bound).UTC())
}
// A file a full interval plus a minute behind is genuinely out of scan range.
old := time.Date(2026, 6, 29, 12, 28, 0, 0, time.UTC).UnixNano()
if old >= bound {
t.Fatalf("bound %v keeps state for files the scan can no longer list", time.Unix(0, bound).UTC())
}
}
// TestLastShippedLogEntryTsNs pins the chunk-mode cursor source against the
// client's reader, which it must mirror: per file the readable prefix - the
// client stops at the first unreadable chunk and never resumes within the file
// - and per filer the newest file with content, because the client keeps
// reading later files after skipping a bad one. A marker past what the client
// applies loses events; one short only re-ships.
func TestLastShippedLogEntryTsNs(t *testing.T) {
f := &Filer{persistedLogCache: newPersistedLogCache(1 << 20)}
entry := func(ts int64) *filer_pb.LogEntry { return &filer_pb.LogEntry{TsNs: ts} }
chunk := func(id string) *filer_pb.FileChunk { return &filer_pb.FileChunk{FileId: id, Size: 10} }
ref := func(fileTsNs int64, chunks ...*filer_pb.FileChunk) *filer_pb.LogFileChunkRef {
return &filer_pb.LogFileChunkRef{FilerId: "a", FileTsNs: fileTsNs, Chunks: chunks}
}
byId := map[string]struct {
entries []*filer_pb.LogEntry
err error
}{
"good-early": {entries: []*filer_pb.LogEntry{entry(100), entry(200)}},
"good-late": {entries: []*filer_pb.LogEntry{entry(300), entry(400)}},
"missing": {err: fmt.Errorf("volume 7 not found")},
"missing2": {err: fmt.Errorf("volume 8 not found")},
"empty": {},
}
origLoad := loadLogFileEntriesFn
loadLogFileEntriesFn = func(masterClient *wdclient.MasterClient, c *filer_pb.FileChunk) ([]*filer_pb.LogEntry, bool, error) {
r := byId[c.FileId]
return r.entries, true, r.err
}
origLookup := lookupLogChunkFn
deadVolumes := map[string]bool{}
lookupLogChunkFn = func(f *Filer, fileId string) error {
if deadVolumes[fileId] {
return fmt.Errorf("volume 9 not found")
}
return nil
}
defer func() { loadLogFileEntriesFn = origLoad; lookupLogChunkFn = origLookup }()
t.Run("a fully readable file answers with its tail, complete", func(t *testing.T) {
ts, ok, complete := f.lastShippedLogEntryTsNs([]*filer_pb.FileChunk{chunk("good-early"), chunk("good-late")})
if !ok || ts != 400 || !complete {
t.Fatalf("ts=%d ok=%v complete=%v, want 400 and complete", ts, ok, complete)
}
})
t.Run("the prefix ends at the first missing chunk", func(t *testing.T) {
// The client's reader stops there and never resumes within the file:
// answering from the readable suffix would put the marker past entries
// the client never applied, losing them permanently.
ts, ok, complete := f.lastShippedLogEntryTsNs([]*filer_pb.FileChunk{chunk("good-early"), chunk("missing"), chunk("good-late")})
if !ok || ts != 200 {
t.Fatalf("ts=%d ok=%v, want the prefix end 200, never the suffix 400", ts, ok)
}
if complete {
t.Fatal("a prefix-limited read must report incomplete, or the unread suffix is never re-shipped")
}
})
t.Run("nothing readable is a clean no-answer", func(t *testing.T) {
if _, ok, _ := f.lastShippedLogEntryTsNs([]*filer_pb.FileChunk{chunk("missing"), chunk("empty")}); ok {
t.Fatal("want no answer")
}
})
t.Run("an entirely missing last file falls back to earlier files", func(t *testing.T) {
// The client skips the bad file but has applied the earlier ones;
// discarding their progress would rewind the marker to the start
// cursor and stall or replay.
ts, answeredFileTsNs, ok, _ := f.LastShippedLogEntryTsNsForFiler([]*filer_pb.LogFileChunkRef{
ref(1000, chunk("good-late")),
ref(2000, chunk("missing"), chunk("missing2")),
})
if !ok || ts != 400 {
t.Fatalf("ts=%d ok=%v, want the previous file's 400", ts, ok)
}
if answeredFileTsNs != 1000 {
t.Fatalf("answered file %d, want 1000: the caller rolls back sent state above it", answeredFileTsNs)
}
})
t.Run("a cached chunk on a dead volume ends the prefix", func(t *testing.T) {
// Warm the cache, then kill the middle chunk's volume. The client
// reads directly and stops there; a probe trusting its own decoded
// cache would sail past to the tail and put the marker beyond entries
// the client never applied.
if ts, ok, _ := f.lastShippedLogEntryTsNs([]*filer_pb.FileChunk{chunk("good-early"), chunk("good-late")}); !ok || ts != 400 {
t.Fatalf("warmup: ts=%d ok=%v, want 400", ts, ok)
}
deadVolumes["good-early"] = true
defer delete(deadVolumes, "good-early")
ts, ok, complete := f.lastShippedLogEntryTsNs([]*filer_pb.FileChunk{chunk("good-early"), chunk("good-late")})
if ok || ts != 0 {
t.Fatalf("ts=%d ok=%v, want no answer: the first chunk's volume is gone however warm the cache", ts, ok)
}
if complete {
t.Fatal("a lookup-limited read must report incomplete so the ref re-ships")
}
})
t.Run("a dead needle behind a warm cache is the accepted residual", func(t *testing.T) {
// Production liveness is a volume lookup: it cannot see a needle 404
// or a stale location inside a resolvable volume, so a warm cache can
// answer past a chunk the client fails to read. Accepted because
// metadata log chunks die volume-at-a-time (TTL'd log volumes) and the
// alternative is a real read per probe, which is what the probe exists
// to avoid; the client logs the skip at V(0). This test pins the
// boundary so a change to it is a decision, not an accident.
if ts, ok, _ := f.lastShippedLogEntryTsNs([]*filer_pb.FileChunk{chunk("good-early"), chunk("good-late")}); !ok || ts != 400 {
t.Fatalf("warmup: ts=%d ok=%v, want 400", ts, ok)
}
// The needle dies: loads fail, but the volume still resolves.
prev := byId["good-early"]
byId["good-early"] = struct {
entries []*filer_pb.LogEntry
err error
}{err: fmt.Errorf("read: 404 Not Found: not found")}
defer func() { byId["good-early"] = prev }()
ts, ok, complete := f.lastShippedLogEntryTsNs([]*filer_pb.FileChunk{chunk("good-early"), chunk("good-late")})
if !ok || ts != 400 || !complete {
t.Fatalf("ts=%d ok=%v complete=%v: the warm cache masks a dead needle - if this now fails, the residual was closed and this test should assert the new behavior", ts, ok, complete)
}
})
t.Run("spanning records stream the shipped list", func(t *testing.T) {
origLoad2 := loadLogFileEntriesFn
loadLogFileEntriesFn = func(masterClient *wdclient.MasterClient, c *filer_pb.FileChunk) ([]*filer_pb.LogEntry, bool, error) {
return nil, false, errLogChunkIncomplete
}
origStream := newLogFileStreamReader
newLogFileStreamReader = func(masterClient *wdclient.MasterClient, chunks []*filer_pb.FileChunk) io.Reader {
var buf bytes.Buffer
for _, ts := range []int64{500, 600} {
data, _ := (&filer_pb.LogEntry{TsNs: ts}).MarshalVT()
var sizeBuf [4]byte
util.Uint32toBytes(sizeBuf[:], uint32(len(data)))
buf.Write(sizeBuf[:])
buf.Write(data)
}
// A torn trailing size prefix, as a crashed writer leaves it: the
// client reads it as a clean end, so the probe must too - failing
// here would block the marker forever on data the client accepts.
buf.Write([]byte{0x01, 0x02})
return &buf
}
defer func() { loadLogFileEntriesFn = origLoad2; newLogFileStreamReader = origStream }()
ts, ok, complete := f.lastShippedLogEntryTsNs([]*filer_pb.FileChunk{chunk("incomplete")})
if !ok || ts != 600 {
t.Fatalf("ts=%d ok=%v, want the streamed tail 600 past the torn prefix", ts, ok)
}
if !complete {
t.Fatal("a torn tail is where the client's read ends too: complete, nothing to re-ship")
}
})
}
weed/filer/filer_notify_read_testing.go
+33
View File
@@ -0,0 +1,33 @@
package filer
import (
"io"
"github.com/seaweedfs/seaweedfs/weed/pb/filer_pb"
"github.com/seaweedfs/seaweedfs/weed/wdclient"
)
// SetLogReadHooksForTesting swaps the volume-touching pieces of persisted log
// reading - chunk decode, byte streaming, volume liveness - for fakes, so loop
// tests can run the real subscribe machinery against an in-memory volume
// layer. Returns a restore func. Test support only.
func SetLogReadHooksForTesting(
load func(chunk *filer_pb.FileChunk) ([]*filer_pb.LogEntry, error),
stream func(chunks []*filer_pb.FileChunk) io.Reader,
lookup func(fileId string) error,
) (restore func()) {
prevLoad, prevStream, prevLookup := loadLogFileEntriesFn, newLogFileStreamReader, lookupLogChunkFn
loadLogFileEntriesFn = func(masterClient *wdclient.MasterClient, chunk *filer_pb.FileChunk) ([]*filer_pb.LogEntry, bool, error) {
entries, err := load(chunk)
return entries, true, err
}
newLogFileStreamReader = func(masterClient *wdclient.MasterClient, chunks []*filer_pb.FileChunk) io.Reader {
return stream(chunks)
}
lookupLogChunkFn = func(f *Filer, fileId string) error {
return lookup(fileId)
}
return func() {
loadLogFileEntriesFn, newLogFileStreamReader, lookupLogChunkFn = prevLoad, prevStream, prevLookup
}
}
weed/filer/meta_aggregator.go
+3 -10
View File
@@ -30,10 +30,6 @@ type MetaAggregator struct {
MetaLogBuffer *log_buffer.LogBuffer
peerChans map[pb.ServerAddress]chan struct{}
peerChansLock sync.Mutex
// notifying clients
ListenersLock sync.Mutex
ListenersWaits int64 // Atomic counter
ListenersCond *sync.Cond
}
// MetaAggregator only aggregates data "on the fly". The logs are not re-persisted to disk.
@@ -45,12 +41,9 @@ func NewMetaAggregator(filer *Filer, self pb.ServerAddress, grpcDialOption grpc.
grpcDialOption: grpcDialOption,
peerChans: make(map[pb.ServerAddress]chan struct{}),
}
t.ListenersCond = sync.NewCond(&t.ListenersLock)
t.MetaLogBuffer = log_buffer.NewLogBuffer("aggr", LogFlushInterval, nil, nil, func() {
if atomic.LoadInt64(&t.ListenersWaits) > 0 {
t.ListenersCond.Broadcast()
}
})
// nil notifyFn: aggregated subscribers wake through the buffer's
// subscriber channels, not a cond.
t.MetaLogBuffer = log_buffer.NewLogBuffer("aggr", LogFlushInterval, nil, nil, nil)
return t
}
weed/server/filer_grpc_server_sub_meta.go
+617 -129
View File
@@ -5,9 +5,10 @@ import (
"errors"
"fmt"
"strings"
"sync/atomic"
"time"
"github.com/prometheus/client_golang/prometheus"
"github.com/seaweedfs/seaweedfs/weed/stats"
"google.golang.org/protobuf/proto"
@@ -19,6 +20,22 @@ import (
"github.com/seaweedfs/seaweedfs/weed/util/log_buffer"
)
// Vars, not consts: the loop tests shrink them to drive parks and give-ups in
// test time.
var (
// unflushedGapRetryInterval caps the wait of a subscriber parked on a recent
// (possibly-unflushed) gap, in case the flush notification is missed.
unflushedGapRetryInterval = 2 * time.Second
// gapStallWarnInterval paces the warning for a subscriber that stays parked.
gapStallWarnInterval = time.Minute
// maxGapStall bounds a gap wait before giving up and skipping it, counted
// and logged: a dead peer makes the wait permanent, and failing the stream
// only moves the loop into a client that reconnects to the same wall.
maxGapStall = 15 * time.Minute
)
const (
// MaxUnsyncedEvents send empty notification with timestamp when certain amount of events have been filtered
MaxUnsyncedEvents = 1e3
@@ -73,7 +90,13 @@ func newPipelinedSender(stream metadataStreamSender, bufSize int, clientSupports
func (s *pipelinedSender) sendLoop(stream metadataStreamSender) {
defer close(s.done)
for msg := range s.sendCh {
shouldBatch := s.canBatch && time.Now().UnixNano()-msg.TsNs > int64(batchBehindThreshold)
// LogFileRefs messages are unbatchable: the client recognizes them by
// the top-level field and skips the rest of the response, so a refs
// envelope would drop its Events tail and refs inside Events would be
// applied as an (empty) event. Their TsNs is 0, which the batch
// heuristic would misread as far behind. Always send them solo.
shouldBatch := s.canBatch && len(msg.LogFileRefs) == 0 &&
time.Now().UnixNano()-msg.TsNs > int64(batchBehindThreshold)
if !shouldBatch {
// Real-time: send immediately for low latency
@@ -89,6 +112,7 @@ func (s *pipelinedSender) sendLoop(stream metadataStreamSender) {
// go in the Events slice. Old clients ignore the Events field.
batch := make([]*filer_pb.SubscribeMetadataResponse, 0, maxBatchSize)
batch = append(batch, msg)
var trailingRefs *filer_pb.SubscribeMetadataResponse
drain:
for len(batch) < maxBatchSize {
select {
@@ -96,6 +120,11 @@ func (s *pipelinedSender) sendLoop(stream metadataStreamSender) {
if !ok {
break drain
}
if len(next.LogFileRefs) > 0 {
// already consumed; send it solo right after the batch
trailingRefs = next
break drain
}
batch = append(batch, next)
default:
break drain
@@ -117,6 +146,12 @@ func (s *pipelinedSender) sendLoop(stream metadataStreamSender) {
if toSend.Events != nil {
toSend.Events = nil
}
if trailingRefs != nil {
if err := stream.Send(trailingRefs); err != nil {
s.reportErr(err)
return
}
}
}
}
@@ -157,6 +192,314 @@ func (s *pipelinedSender) Close() error {
}
}
// reportUnprovenAggregatedCrossing records the residual hole: a disk read that
// crosses the eviction watermark may have advanced on one peer's log while a
// lagging peer still holds unflushed events in the crossed range. Locally
// undecidable (log files carry random filer ids, peers are tracked by address);
// closing it needs each peer's flush watermark on the subscribe stream.
func reportUnprovenAggregatedCrossing(cursorBeforeTsNs, cursorAfterTsNs, evictedTsNs int64, clientName, pathPrefix string) {
if evictedTsNs == 0 || cursorBeforeTsNs >= evictedTsNs || cursorAfterTsNs < evictedTsNs {
return
}
stats.FilerSubscribeUnprovenGapCrossings.WithLabelValues("aggregated").Inc()
glog.Warningf("aggregated subscriber %s %s crossed an evicted range (%v..%v] on peer disk reads; a peer that flushes into it later will not be re-read",
clientName, pathPrefix, time.Unix(0, cursorBeforeTsNs), time.Unix(0, evictedTsNs))
}
// diskReadAdvanced reports whether a persisted read moved the subscriber on.
// A chunk-ref read reports the minute-level name of the last file it shipped,
// clamped so it never rewinds, so it comes back non-zero even when it names the
// position that was already current. Treating that as progress clears the stall
// timer, and a subscriber parked on a gap it re-ships the same refs for would
// reset the timer every retry and never reach the stall bound.
func diskReadAdvanced(processedTsNs int64, cursor log_buffer.MessagePosition) bool {
return processedTsNs != 0 && processedTsNs > cursor.Time.UnixNano()
}
// gapResumeCursorOffset marks every cursor these loops hand to the memory read:
// gated, so a seal racing the loop's watermark check is refused under the
// read's own lock instead of silently served from the earliest window.
const gapResumeCursorOffset = log_buffer.EvictionGatedOffset
// memoryHoldsGap reports whether nothing after the cursor was evicted. Equality
// counts: the evicted window ends on the watermark, retained windows start
// strictly after it, and the persisted reader skips ts <= cursor, so no wait
// can ever produce the boundary entry - refusing there never ends.
func memoryHoldsGap(currentTsNs, lastEvictedTsNs int64) bool {
if lastEvictedTsNs == 0 {
return true // nothing was ever dropped from the ring
}
return currentTsNs >= lastEvictedTsNs
}
// gapStallReporter makes a parked subscriber visible: a flush that never lands
// stalls the stream for good, and filer.sync and mount followers just stop
// advancing with no error on either side.
//
// The gauge counts parked subscribers per scope. It deliberately carries no
// per-client label: clientName embeds the ephemeral source port (a series per
// reconnect), and the client-supplied name is not unique either - every mount
// registers as "mount" - so same-named streams would clobber and delete each
// other's series. A count needs no identity and no cleanup; the logs carry the
// client details.
type gapStallReporter struct {
scope string
clientName string
pathPrefix string
since time.Time
lastWarnAt time.Time
}
func (r *gapStallReporter) gauge() prometheus.Gauge {
return stats.FilerSubscribeGapStalledGauge.WithLabelValues(r.scope)
}
// stalledFor reports how long this subscriber has been parked, zero if it is not.
func (r *gapStallReporter) stalledFor() time.Duration {
if r.since.IsZero() {
return 0
}
return time.Since(r.since)
}
// park records that the subscriber is waiting on a gap. It stays quiet until
// the stall has lasted gapStallWarnInterval: during a catch-up burst a
// subscriber parks and resumes every couple of seconds, and a warning per
// cycle would bury the long-stall warnings this reporter exists to surface.
func (r *gapStallReporter) park(cursor time.Time, detail string) {
now := time.Now()
if r.since.IsZero() {
r.since = now
r.gauge().Inc()
}
if now.Sub(r.since) < gapStallWarnInterval {
return
}
if !r.lastWarnAt.IsZero() && now.Sub(r.lastWarnAt) < gapStallWarnInterval {
return
}
r.lastWarnAt = now
glog.Warningf("%s subscriber %s %s parked %v at %v: %s", r.scope, r.clientName, r.pathPrefix,
now.Sub(r.since).Truncate(time.Second), cursor, detail)
}
// resumed marks the gap cleared. Only a stall park() had already warned about
// is worth announcing.
func (r *gapStallReporter) resumed() {
if r.since.IsZero() {
return
}
if !r.lastWarnAt.IsZero() {
glog.Warningf("%s subscriber %s %s resumed after %v parked", r.scope, r.clientName, r.pathPrefix,
time.Since(r.since).Truncate(time.Second))
}
r.since, r.lastWarnAt = time.Time{}, time.Time{}
r.gauge().Dec()
}
// gaveUp records that the subscriber stopped waiting on an unprovable gap and
// skipped it. This is the loss the whole gap machinery exists to make loud: it
// shares the unproven-crossing counter and logs at error level.
func (r *gapStallReporter) gaveUp(cursor time.Time, skipToTsNs int64, detail string) {
stats.FilerSubscribeUnprovenGapCrossings.WithLabelValues(r.scope).Inc()
glog.Errorf("%s subscriber %s %s skipping the gap (%v..%v] after %v parked: %s; events a peer flushes into that range later will not be delivered",
r.scope, r.clientName, r.pathPrefix, cursor, time.Unix(0, skipToTsNs), r.stalledFor().Truncate(time.Second), detail)
r.since, r.lastWarnAt = time.Time{}, time.Time{}
r.gauge().Dec()
}
// restartStall re-arms the stall clock for a park that outlived maxGapStall
// with nothing to skip to, so the give-up path does not retrigger on every
// retry while still reporting each full cycle.
func (r *gapStallReporter) restartStall(cursor time.Time, detail string) {
glog.Errorf("%s subscriber %s %s still parked after %v at %v with nothing to skip to: %s", r.scope, r.clientName,
r.pathPrefix, r.stalledFor().Truncate(time.Second), cursor, detail)
r.since, r.lastWarnAt = time.Now(), time.Time{}
}
// close releases the gauge on teardown. Unlike resumed() it does not claim
// recovery: a subscriber that disconnects while parked never resumed.
func (r *gapStallReporter) close() {
if r.since.IsZero() {
return
}
glog.Warningf("%s subscriber %s %s disconnected after %v parked, still behind", r.scope, r.clientName,
r.pathPrefix, r.stalledFor().Truncate(time.Second))
r.gauge().Dec()
r.since = time.Time{}
}
// parkOnGap parks the subscriber on a gap it cannot read past and reports how
// to go on. done: the stream is over - the client is gone, a bounded
// subscription is complete, or the context ended. skip: the park outlived
// maxGapStall and the caller must resume at skipToTsNs, abandoning the gap
// (recorded via gaveUp). Otherwise the caller re-probes. notifyChan may be nil,
// which parks on the retry timer alone - right when no local signal
// corresponds to the event being waited for. The park is where a stalled
// subscriber spends all its time, so every exit the read loop relies on has to
// be checked here too.
func (fs *FilerServer) parkOnGap(ctx context.Context, req *filer_pb.SubscribeMetadataRequest, gapStall *gapStallReporter, evictedTsNs func() int64, cursor log_buffer.MessagePosition, notifyChan <-chan struct{}, reason string) (skipToTsNs int64, skip bool, done bool) {
// Done exits run before park(): a finished stream was never parked, and
// marking it so leaves a false "still behind" trace. A cursor at UntilNs is
// finished - the bound is inclusive, cursors are exclusive, and
// LoopProcessLogData (the only place UntilNs ends a stream) is unreachable
// from a park.
if req.UntilNs != 0 && cursor.Time.UnixNano() >= req.UntilNs {
return 0, false, true
}
if !fs.hasClient(req.ClientId, req.ClientEpoch) {
return 0, false, true
}
gapStall.park(cursor.Time, reason)
if gapStall.stalledFor() >= maxGapStall {
// Resume at the eviction watermark: everything retained starts
// strictly after it, so the recorded loss is exactly (cursor, skipTo].
if evicted := evictedTsNs(); evicted > cursor.Time.UnixNano() {
gapStall.gaveUp(cursor.Time, evicted, reason)
return evicted, true, false
}
// Nothing was withheld past the cursor - nothing to skip, nothing being
// lost; keep waiting on a fresh stall cycle.
gapStall.restartStall(cursor.Time, reason)
}
// Re-probes back off as the stall ages: every retry re-reads the persisted
// log, and probing the store each 2s for 15 minutes - per parked subscriber,
// during the outage that parked them - makes the bad time worse.
waitFor := unflushedGapRetryInterval + gapStall.stalledFor()/8
if waitFor > gapStallWarnInterval {
waitFor = gapStallWarnInterval
}
retry := time.After(waitFor)
for {
select {
case _, ok := <-notifyChan:
if !ok {
// Closed out from under us: a receive now returns instantly, so
// stop watching it rather than spinning until the timer fires.
notifyChan = nil
continue
}
case <-ctx.Done():
return 0, false, true
case <-retry:
}
if !fs.hasClient(req.ClientId, req.ClientEpoch) {
return 0, false, true
}
return 0, false, false
}
}
// resolveGapResume decides whether a subscriber may skip a gap its disk read
// found empty. Either proof settles it: nothing after the cursor was evicted,
// so memory still holds the whole gap; or the flush watermark observed before
// the read had already passed the earliest in-memory timestamp, so every event
// in the gap would have been on disk when the read ran and the miss is
// authoritative. The aggregated ring never flushes - peers persist their own
// logs - so it passes flushedTsNs 0 and only the eviction proof can hold.
func resolveGapResume(currentTsNs, currentOffset, earliestMemTsNs, flushedTsNs, lastEvictedTsNs int64) (advanceToTsNs int64, advance bool) {
// No in-memory data (zero time → negative UnixNano), or memory not ahead of us.
if earliestMemTsNs <= 0 || earliestMemTsNs <= currentTsNs {
return 0, false
}
// The gap may still hold unflushed events.
if !memoryHoldsGap(currentTsNs, lastEvictedTsNs) && flushedTsNs < earliestMemTsNs {
return 0, false
}
// Resume just below earliest, not at it. A sealed window holding a single
// entry has startTime == stopTime == earliest, and the sealed-buffer lookup
// only enters a window whose stopTime is strictly after the cursor, so a
// cursor sitting exactly on earliest skips that window entirely and loses
// its sole event. One nanosecond lower takes the startTime.After branch and
// returns the whole window.
target := earliestMemTsNs - 1
if target < currentTsNs {
return 0, false
}
if target == currentTsNs && currentOffset <= 0 {
// The sentinel resume would be the position we already hold.
return 0, false
}
// target > cursor is plainly forward. target == cursor with a positive
// (exclusive) offset is progress too: that cursor cannot be served -
// ReadFromBuffer refuses positive offsets below the window - while the
// sentinel one is, and both deliver exactly the entries after target.
return target, true
}
// gapPass carries what the shared post-disk gap decisions differ by between
// the two subscribe loops; everything else about them must stay identical, and
// this PR's history shows they drift when edited separately.
type gapPass struct {
fs *FilerServer
req *filer_pb.SubscribeMetadataRequest
gapStall *gapStallReporter
earliest func() time.Time
evicted func() int64 // gap-proof watermark; aggregated uses the received-ts space
flushed func() int64 // flush watermark the last disk read observed; aggregated: 0
gapChan <-chan struct{}
dataChan <-chan struct{}
gapReason func(earliest time.Time, evictedTsNs int64) string
}
type gapOutcome int
const (
gapProceed gapOutcome = iota // read memory
gapContinue // restart the pass
gapDone // the stream is over
)
// resolve is the gap decision both loops run between the disk pass and the
// memory read. A cursor the ring evicted past cannot be served from memory
// without skipping what was dropped: keep draining the disk if it just moved,
// skip if a proof says the gap is empty, park otherwise. A cursor memory
// refused with nothing evicted after it re-arms onto the retained window.
func (p *gapPass) resolve(ctx context.Context, cursor *log_buffer.MessagePosition, latch *error, diskAdvanced bool) gapOutcome {
earliest := p.earliest()
evictedTsNs := p.evicted()
cursorTsNs := cursor.Time.UnixNano()
if !memoryHoldsGap(cursorTsNs, evictedTsNs) {
if diskAdvanced {
return gapContinue // the disk may hold more of the gap
}
if advanceToTsNs, advance := resolveGapResume(cursorTsNs, cursor.Offset, earliest.UnixNano(), p.flushed(), evictedTsNs); advance {
p.gapStall.resumed()
glog.V(3).Infof("%s subscriber %s: gap proven empty, skipping from %v to earliest memory %v",
p.gapStall.scope, p.gapStall.clientName, cursor.Time, earliest)
*cursor = log_buffer.NewMessagePosition(advanceToTsNs, gapResumeCursorOffset)
*latch = nil
return gapProceed
}
return p.park(ctx, cursor, latch, p.gapChan, p.gapReason(earliest, evictedTsNs))
}
if !diskAdvanced && errors.Is(*latch, log_buffer.ResumeFromDiskError) {
// Memory refused the cursor though nothing after it was evicted: its
// exclusive offset predates the retained window. Re-arm it onto the
// window; failing even that, wait for data.
if advanceToTsNs, advance := resolveGapResume(cursorTsNs, cursor.Offset, earliest.UnixNano(), p.flushed(), evictedTsNs); advance {
p.gapStall.resumed()
*cursor = log_buffer.NewMessagePosition(advanceToTsNs, gapResumeCursorOffset)
*latch = nil
return gapProceed
}
return p.park(ctx, cursor, latch, p.dataChan, "no readable in-memory entries yet")
}
return gapProceed
}
func (p *gapPass) park(ctx context.Context, cursor *log_buffer.MessagePosition, latch *error, notifyChan <-chan struct{}, reason string) gapOutcome {
skipTo, skip, done := p.fs.parkOnGap(ctx, p.req, p.gapStall, p.evicted, *cursor, notifyChan, reason)
if done {
return gapDone
}
if skip {
*cursor = log_buffer.NewMessagePosition(skipTo, gapResumeCursorOffset)
*latch = nil
}
return gapContinue
}
func (fs *FilerServer) SubscribeMetadata(req *filer_pb.SubscribeMetadataRequest, stream filer_pb.SeaweedFiler_SubscribeMetadataServer) error {
if fs.filer.MetaAggregator == nil || !fs.filer.MetaAggregator.HasRemotePeers() {
return fs.SubscribeLocalMetadata(req, stream)
@@ -167,18 +510,15 @@ func (fs *FilerServer) SubscribeMetadata(req *filer_pb.SubscribeMetadataRequest,
isReplacing, alreadyKnown, clientName := fs.addClient("", req.ClientName, peerAddress, req.PathPrefix, req.ClientId, req.ClientEpoch)
if isReplacing {
fs.filer.MetaAggregator.ListenersCond.Broadcast() // nudges the subscribers that are waiting
} else if alreadyKnown {
fs.filer.MetaAggregator.ListenersCond.Broadcast() // nudges the subscribers that are waiting
return fmt.Errorf("duplicated subscription detected for client %s id %d", clientName, req.ClientId)
}
defer func() {
glog.V(0).Infof("disconnect %v subscriber %s clientId:%d", clientName, req.PathPrefix, req.ClientId)
fs.deleteClient("", clientName, req.ClientId, req.ClientEpoch)
fs.filer.MetaAggregator.ListenersCond.Broadcast() // nudges the subscribers that are waiting
}()
lastReadTime := log_buffer.NewMessagePosition(req.SinceNs, -2)
lastReadTime := log_buffer.NewMessagePosition(req.SinceNs, gapResumeCursorOffset)
glog.V(0).Infof(" %v starts to subscribe %s from %+v", clientName, req.PathPrefix, lastReadTime)
sender := newPipelinedSender(stream, 1024, req.ClientSupportsBatching)
@@ -186,10 +526,19 @@ func (fs *FilerServer) SubscribeMetadata(req *filer_pb.SubscribeMetadataRequest,
// Register for instant notification when new data arrives in the aggregated log buffer.
// Used to replace the 1127ms sleep with event-driven wake-up.
aggNotifyName := "aggSubscribe:" + clientName
// Key includes clientId/epoch: a replacement stream may reuse the same
// clientName (same gRPC conn), and sharing the channel would let the old
// stream's deferred unregister close it under the new stream.
aggNotifyName := fmt.Sprintf("aggSubscribe:%s:%d:%d", clientName, req.ClientId, req.ClientEpoch)
// Same key shape for the reader: LoopProcessLogData registers it as a
// subscriber internally, once per loop iteration.
aggReaderName := fmt.Sprintf("aggMeta:%s:%d:%d", clientName, req.ClientId, req.ClientEpoch)
aggNotifyChan := fs.filer.MetaAggregator.MetaLogBuffer.RegisterSubscriber(aggNotifyName)
defer fs.filer.MetaAggregator.MetaLogBuffer.UnregisterSubscriber(aggNotifyName)
gapStall := &gapStallReporter{scope: "aggregated", clientName: clientName, pathPrefix: req.PathPrefix}
defer gapStall.close()
var unsyncedEvents int64
eachEventNotificationFn := fs.eachEventNotificationFn(req, sender, clientName, &unsyncedEvents)
@@ -208,13 +557,32 @@ func (fs *FilerServer) SubscribeMetadata(req *filer_pb.SubscribeMetadataRequest,
var readPersistedLogErr error
var readInMemoryLogErr error
var isDone bool
sentRefs := make(map[string]sentRefState)
aggBuffer := fs.filer.MetaAggregator.MetaLogBuffer
gaps := &gapPass{
fs: fs,
req: req,
gapStall: gapStall,
earliest: aggBuffer.GetEarliestTime,
evicted: aggBuffer.GetLastEvictedOriginalTsNs,
flushed: func() int64 { return 0 }, // the aggregated ring never flushes
gapChan: nil, // nothing local signals a peer's flush; the timer paces it
dataChan: aggNotifyChan,
gapReason: func(earliest time.Time, evictedTsNs int64) string {
return fmt.Sprintf("gap evicted through %v is not on a peer's disk yet (earliest memory %v)",
time.Unix(0, evictedTsNs), earliest)
},
}
for {
glog.V(4).Infof("read on disk %v aggregated subscribe %s from %+v", clientName, req.PathPrefix, lastReadTime)
cursorBeforeDiskTsNs := lastReadTime.Time.UnixNano()
if req.ClientSupportsMetadataChunks {
processedTsNs, isDone, readPersistedLogErr = fs.sendLogFileRefs(ctx, stream, lastReadTime, req.UntilNs)
processedTsNs, isDone, readPersistedLogErr = fs.chunkDiskPass(ctx, sender, lastReadTime, req.UntilNs, sentRefs)
} else {
processedTsNs, isDone, readPersistedLogErr = fs.filer.ReadPersistedLogBuffer(ctx, lastReadTime, req.UntilNs, eachLogEntryFn)
}
@@ -226,39 +594,42 @@ func (fs *FilerServer) SubscribeMetadata(req *filer_pb.SubscribeMetadataRequest,
}
glog.V(4).Infof("processed to %v: %v", clientName, processedTsNs)
if processedTsNs != 0 {
lastReadTime = log_buffer.NewMessagePosition(processedTsNs, -2)
} else {
// No data found on disk
// Check if we previously got ResumeFromDiskError from memory, meaning we're in a gap
if errors.Is(readInMemoryLogErr, log_buffer.ResumeFromDiskError) {
// We have a gap: requested time < earliest memory time, but no data on disk
// Skip forward to earliest memory time to avoid infinite loop
earliestTime := fs.filer.MetaAggregator.MetaLogBuffer.GetEarliestTime()
if !earliestTime.IsZero() && earliestTime.After(lastReadTime.Time) {
glog.V(3).Infof("gap detected: skipping from %v to earliest memory time %v for %v",
lastReadTime.Time, earliestTime, clientName)
// Position at earliest time; time-based reader will include it
lastReadTime = log_buffer.NewMessagePosition(earliestTime.UnixNano(), -2)
readInMemoryLogErr = nil // Clear the error since we're skipping forward
}
} else {
// First pass or no ResumeFromDiskError yet - check the next day for logs
nextDayTs := util.GetNextDayTsNano(lastReadTime.Time.UnixNano())
position := log_buffer.NewMessagePosition(nextDayTs, -2)
found, err := fs.filer.HasPersistedLogFiles(position)
if err != nil {
return fmt.Errorf("checking persisted log files: %w", err)
}
if found {
lastReadTime = position
}
diskAdvanced := diskReadAdvanced(processedTsNs, lastReadTime)
// Read after the disk read (an eviction landing mid-read must count) and
// in received-ts space: the ring's bumped stopTimes exceed anything on
// any peer's disk, and gating disk cursors on them parks subscribers
// that drained every peer's log.
lastEvictedTsNs := fs.filer.MetaAggregator.MetaLogBuffer.GetLastEvictedOriginalTsNs()
if diskAdvanced {
gapStall.resumed()
reportUnprovenAggregatedCrossing(cursorBeforeDiskTsNs, processedTsNs, lastEvictedTsNs, clientName, req.PathPrefix)
lastReadTime = log_buffer.NewMessagePosition(processedTsNs, gapResumeCursorOffset)
} else if readInMemoryLogErr == nil {
// Nothing on disk and memory never spoke: scan forward for the next
// day that has logs.
nextDayTs := util.GetNextDayTsNano(lastReadTime.Time.UnixNano())
position := log_buffer.NewMessagePosition(nextDayTs, gapResumeCursorOffset)
found, err := fs.filer.HasPersistedLogFiles(position)
if err != nil {
return fmt.Errorf("checking persisted log files: %w", err)
}
if found {
gapStall.resumed()
reportUnprovenAggregatedCrossing(cursorBeforeDiskTsNs, nextDayTs, lastEvictedTsNs, clientName, req.PathPrefix)
lastReadTime = position
}
}
switch gaps.resolve(ctx, &lastReadTime, &readInMemoryLogErr, diskAdvanced) {
case gapDone:
return nil
case gapContinue:
continue
}
glog.V(4).Infof("read in memory %v aggregated subscribe %s from %+v", clientName, req.PathPrefix, lastReadTime)
lastReadTime, isDone, readInMemoryLogErr = fs.filer.MetaAggregator.MetaLogBuffer.LoopProcessLogData("aggMeta:"+clientName, lastReadTime, req.UntilNs, func() bool {
lastReadTime, isDone, readInMemoryLogErr = fs.filer.MetaAggregator.MetaLogBuffer.LoopProcessLogData(aggReaderName, lastReadTime, req.UntilNs, func() bool {
select {
case <-ctx.Done():
return false
@@ -272,8 +643,8 @@ func (fs *FilerServer) SubscribeMetadata(req *filer_pb.SubscribeMetadataRequest,
}, eachLogEntryFn)
if readInMemoryLogErr != nil {
if errors.Is(readInMemoryLogErr, log_buffer.ResumeFromDiskError) {
// Memory says data is too old - will read from disk on next iteration
// But if disk also has no data (gap in history), we'll skip forward
// Fell behind the ring: back to the disk pass, and from there to
// the gap resolution above if the disk has nothing either.
continue
}
glog.Errorf("processed to %v: %v", lastReadTime, readInMemoryLogErr)
@@ -316,22 +687,34 @@ func (fs *FilerServer) SubscribeLocalMetadata(req *filer_pb.SubscribeMetadataReq
isReplacing, alreadyKnown, clientName := fs.addClient("local", req.ClientName, peerAddress, req.PathPrefix, req.ClientId, req.ClientEpoch)
if isReplacing {
fs.listenersCond.Broadcast() // nudges the subscribers that are waiting
} else if alreadyKnown {
return fmt.Errorf("duplicated local subscription detected for client %s clientId:%d", clientName, req.ClientId)
}
defer func() {
glog.V(0).Infof("disconnect %v local subscriber %s clientId:%d", clientName, req.PathPrefix, req.ClientId)
fs.deleteClient("local", clientName, req.ClientId, req.ClientEpoch)
fs.listenersCond.Broadcast() // nudges the subscribers that are waiting
}()
lastReadTime := log_buffer.NewMessagePosition(req.SinceNs, -2)
lastReadTime := log_buffer.NewMessagePosition(req.SinceNs, gapResumeCursorOffset)
glog.V(0).Infof(" + %v local subscribe %s from %+v clientId:%d", clientName, req.PathPrefix, lastReadTime, req.ClientId)
sender := newPipelinedSender(stream, 1024, req.ClientSupportsBatching)
defer sender.Close()
// Bounded gap waits use the buffer's subscriber notification plus a retry
// timer, so a flush landing between the disk read and the wait cannot
// strand the subscriber (no lost-wakeup window). Key includes clientId/
// epoch so a replacement stream never shares (and loses) the channel.
localNotifyName := fmt.Sprintf("localGap:%s:%d:%d", clientName, req.ClientId, req.ClientEpoch)
// Same key shape for the reader: LoopProcessLogData registers it as a
// subscriber internally, once per loop iteration.
localReaderName := fmt.Sprintf("localMeta:%s:%d:%d", clientName, req.ClientId, req.ClientEpoch)
localFlushChan := fs.filer.LocalMetaLogBuffer.RegisterFlushSubscriber(localNotifyName)
defer fs.filer.LocalMetaLogBuffer.UnregisterFlushSubscriber(localNotifyName)
gapStall := &gapStallReporter{scope: "local", clientName: clientName, pathPrefix: req.PathPrefix}
defer gapStall.close()
var unsyncedEvents int64
eachEventNotificationFn := fs.eachEventNotificationFn(req, sender, clientName, &unsyncedEvents)
@@ -352,6 +735,23 @@ func (fs *FilerServer) SubscribeLocalMetadata(req *filer_pb.SubscribeMetadataReq
var isDone bool
var lastCheckedFlushTsNs int64 = -1 // Track the last flushed time we checked
var lastDiskReadTsNs int64 = -1 // Track the last read position we used for disk read
sentRefs := make(map[string]sentRefState)
localBuffer := fs.filer.LocalMetaLogBuffer
gaps := &gapPass{
fs: fs,
req: req,
gapStall: gapStall,
earliest: localBuffer.GetEarliestTime,
evicted: localBuffer.GetLastEvictedTsNs, // local disk carries the ring's own timestamps
flushed: func() int64 { return lastCheckedFlushTsNs },
gapChan: localFlushChan,
dataChan: localFlushChan,
gapReason: func(earliest time.Time, evictedTsNs int64) string {
return fmt.Sprintf("gap is not flushed yet (earliest memory %v, flushed through %v)",
earliest, time.Unix(0, lastCheckedFlushTsNs))
},
}
for {
// Check if new data has been flushed to disk since last check, or if read position advanced
@@ -362,12 +762,13 @@ func (fs *FilerServer) SubscribeLocalMetadata(req *filer_pb.SubscribeMetadataReq
currentFlushTsNs > lastCheckedFlushTsNs ||
currentReadTsNs > lastDiskReadTsNs
diskAdvanced := false
if shouldReadFromDisk {
// Record the position we are about to read from
lastDiskReadTsNs = currentReadTsNs
glog.V(4).Infof("read on disk %v local subscribe %s from %+v (lastFlushed: %v)", clientName, req.PathPrefix, lastReadTime, time.Unix(0, currentFlushTsNs))
if req.ClientSupportsMetadataChunks {
processedTsNs, isDone, readPersistedLogErr = fs.sendLogFileRefs(ctx, stream, lastReadTime, req.UntilNs)
processedTsNs, isDone, readPersistedLogErr = fs.chunkDiskPass(ctx, sender, lastReadTime, req.UntilNs, sentRefs)
} else {
processedTsNs, isDone, readPersistedLogErr = fs.filer.ReadPersistedLogBuffer(ctx, lastReadTime, req.UntilNs, eachLogEntryFn)
}
@@ -382,49 +783,36 @@ func (fs *FilerServer) SubscribeLocalMetadata(req *filer_pb.SubscribeMetadataReq
// Update the last checked flushed time
lastCheckedFlushTsNs = currentFlushTsNs
if processedTsNs != 0 {
lastReadTime = log_buffer.NewMessagePosition(processedTsNs, -2)
} else {
// No data found on disk
// Check if we previously got ResumeFromDiskError from memory, meaning we're in a gap
if readInMemoryLogErr == log_buffer.ResumeFromDiskError {
// We have a gap: requested time < earliest memory time, but no data on disk
// Skip forward to earliest memory time to avoid infinite loop
earliestTime := fs.filer.LocalMetaLogBuffer.GetEarliestTime()
if !earliestTime.IsZero() && earliestTime.After(lastReadTime.Time) {
glog.V(3).Infof("gap detected: skipping from %v to earliest memory time %v for %v",
lastReadTime.Time, earliestTime, clientName)
// Position at earliest time; time-based reader will include it
lastReadTime = log_buffer.NewMessagePosition(earliestTime.UnixNano(), -2)
readInMemoryLogErr = nil // Clear the error since we're skipping forward
} else {
// No memory data yet, wait for new data (event-driven)
fs.listenersLock.Lock()
atomic.AddInt64(&fs.listenersWaits, 1)
fs.listenersCond.Wait()
atomic.AddInt64(&fs.listenersWaits, -1)
fs.listenersLock.Unlock()
continue
}
} else {
// First pass or no ResumeFromDiskError yet
// Check the next day for logs
nextDayTs := util.GetNextDayTsNano(lastReadTime.Time.UnixNano())
position := log_buffer.NewMessagePosition(nextDayTs, -2)
found, err := fs.filer.HasPersistedLogFiles(position)
if err != nil {
return fmt.Errorf("checking persisted log files: %w", err)
}
if found {
lastReadTime = position
}
diskAdvanced = diskReadAdvanced(processedTsNs, lastReadTime)
if diskAdvanced {
gapStall.resumed()
lastReadTime = log_buffer.NewMessagePosition(processedTsNs, gapResumeCursorOffset)
} else if readInMemoryLogErr == nil {
// Nothing on disk and memory never spoke: scan forward for the
// next day that has logs.
nextDayTs := util.GetNextDayTsNano(lastReadTime.Time.UnixNano())
position := log_buffer.NewMessagePosition(nextDayTs, gapResumeCursorOffset)
found, err := fs.filer.HasPersistedLogFiles(position)
if err != nil {
return fmt.Errorf("checking persisted log files: %w", err)
}
if found {
gapStall.resumed()
lastReadTime = position
}
}
}
switch gaps.resolve(ctx, &lastReadTime, &readInMemoryLogErr, diskAdvanced) {
case gapDone:
return nil
case gapContinue:
continue
}
glog.V(3).Infof("read in memory %v local subscribe %s from %+v", clientName, req.PathPrefix, lastReadTime)
lastReadTime, isDone, readInMemoryLogErr = fs.filer.LocalMetaLogBuffer.LoopProcessLogData("localMeta:"+clientName, lastReadTime, req.UntilNs, func() bool {
lastReadTime, isDone, readInMemoryLogErr = fs.filer.LocalMetaLogBuffer.LoopProcessLogData(localReaderName, lastReadTime, req.UntilNs, func() bool {
select {
case <-ctx.Done():
return false
@@ -437,46 +825,14 @@ func (fs *FilerServer) SubscribeLocalMetadata(req *filer_pb.SubscribeMetadataReq
return true
}, eachLogEntryFn)
if readInMemoryLogErr != nil {
if readInMemoryLogErr == log_buffer.ResumeFromDiskError {
// Memory buffer says the requested time is too old
// Retry disk read if: (a) flush advanced, or (b) read position advanced (draining backlog)
currentFlushTsNs := fs.filer.LocalMetaLogBuffer.GetLastFlushTsNs()
currentReadTsNs := lastReadTime.Time.UnixNano()
if currentFlushTsNs > lastCheckedFlushTsNs || currentReadTsNs > lastDiskReadTsNs {
glog.V(0).Infof("retry disk read %v local subscribe %s (lastFlushed: %v -> %v, readTs: %v -> %v)",
clientName, req.PathPrefix,
time.Unix(0, lastCheckedFlushTsNs), time.Unix(0, currentFlushTsNs),
time.Unix(0, lastDiskReadTsNs), time.Unix(0, currentReadTsNs))
continue
}
// No flush or read-position progress — there may be a gap
// between the last persisted data and the earliest in-memory
// data (e.g. a slow consumer that fell behind while writes
// already stopped). Skip forward to the earliest in-memory
// time so the consumer can resume instead of blocking forever.
earliestTime := fs.filer.LocalMetaLogBuffer.GetEarliestTime()
if !earliestTime.IsZero() && earliestTime.After(lastReadTime.Time) {
glog.V(3).Infof("gap detected: skipping from %v to earliest memory time %v for %v",
lastReadTime.Time, earliestTime, clientName)
lastReadTime = log_buffer.NewMessagePosition(earliestTime.UnixNano(), -2)
// Clear the stale ResumeFromDiskError so the next
// iteration's shouldReadFromDisk path (triggered by the
// advanced lastReadTime) doesn't re-enter the gap branch
// at line 360 with earliestTime == lastReadTime.Time and
// stall on listenersCond.Wait().
readInMemoryLogErr = nil
continue
}
// No progress possible, wait for new data to arrive (event-driven, not polling)
fs.listenersLock.Lock()
atomic.AddInt64(&fs.listenersWaits, 1)
fs.listenersCond.Wait()
atomic.AddInt64(&fs.listenersWaits, -1)
fs.listenersLock.Unlock()
if errors.Is(readInMemoryLogErr, log_buffer.ResumeFromDiskError) {
// Fell behind the ring: back to the disk pass (it re-runs when
// the flush or the cursor moved), and from there to the gap
// resolution above if the disk has nothing either.
continue
}
glog.Errorf("processed to %v: %v", lastReadTime, readInMemoryLogErr)
if readInMemoryLogErr != log_buffer.ResumeError {
if !errors.Is(readInMemoryLogErr, log_buffer.ResumeError) {
break
}
}
@@ -578,33 +934,165 @@ func (fs *FilerServer) maybeSendIdleHeartbeat(req *filer_pb.SubscribeMetadataReq
return now
}
// sendLogFileRefs collects persisted log file chunk references and sends them
// to the client so it can read the data directly from volume servers.
// This does zero volume server I/O — it only lists filer store directory entries.
// Sends directly on the gRPC stream (bypasses pipelinedSender) because ref
// messages have TsNs=0 and must not be batched into Events by the sender.
func (fs *FilerServer) sendLogFileRefs(ctx context.Context, stream metadataStreamSender, startPosition log_buffer.MessagePosition, stopTsNs int64) (lastTsNs int64, isDone bool, err error) {
refs, lastTsNs, err := fs.filer.CollectLogFileRefs(ctx, startPosition, stopTsNs)
// chunkDiskPass is the disk step for chunk-capable clients: ship the unsent
// refs, then advance the cursor to the shipped content's own end - the final
// entry timestamp of each filer's last shipped chunk, decoded through the
// shared chunk cache. Deriving the cursor from the shipped set itself keeps
// the three positions that must agree in lockstep: the client's refs cover
// exactly up to the cursor, the transition marker (which becomes the client's
// refs filter) equals it, and the memory pass delivers strictly after it - no
// range is decoded twice and none is dropped. The transition is the
// empty-notification marker: both chunk consumers buffer refs until a non-ref
// message, so an idle source would otherwise strand the backlog in the
// client's pending list until the next mutation.
func (fs *FilerServer) chunkDiskPass(ctx context.Context, sender metadataStreamSender, startPos log_buffer.MessagePosition, untilNs int64, sent map[string]sentRefState) (processedTsNs int64, isDone bool, err error) {
collected, _, err := fs.filer.CollectLogFileRefs(ctx, startPos, untilNs)
if err != nil {
return 0, false, err
}
refs := deltaLogFileRefs(collected, sent, filer.PersistedLogScanStartTsNs(startPos.Time))
if len(refs) == 0 {
return 0, false, nil
return startPos.Time.UnixNano(), false, nil
}
if err := fs.sendRefsBatched(sender, refs); err != nil {
return 0, false, err
}
// Shipped content end, read from the shipped chunks alone - a fresh
// listing here could see a concurrent append and move the cursor past
// unshipped content. The probe mirrors the client's reader exactly (per
// file the readable prefix, per filer the newest file with content), so
// the marker never claims events the client will not apply, and it cannot
// fail: a dead volume must not block the transition the client waits on.
cursorTsNs := startPos.Time.UnixNano()
refsPerFiler := make(map[string][]*filer_pb.LogFileChunkRef, 2)
for _, ref := range refs {
refsPerFiler[ref.FilerId] = append(refsPerFiler[ref.FilerId], ref)
}
for filerId, filerRefs := range refsPerFiler {
tailTsNs, answeredFileTsNs, ok, complete := fs.filer.LastShippedLogEntryTsNsForFiler(filerRefs)
if ok && tailTsNs > cursorTsNs {
cursorTsNs = tailTsNs
}
// Refs the cursor did not reach must re-ship on a later pass: their
// content sits above the marker, and sent-state that outlives a
// transient probe failure would strand the cursor behind them for the
// life of the connection - parking aggregated streams below the
// watermark. A prefix-limited answer re-ships the answering file too,
// or its unread suffix is abandoned the moment a later append advances
// past it. Re-shipped entries at or below the client's checkpoint are
// filtered client-side, and batches are marker-separated, so a
// re-shipped whole file cannot rewind a merge mid-batch.
for _, ref := range filerRefs {
if refNeedsReship(ref.FileTsNs, ok, answeredFileTsNs, complete) {
delete(sent, sentRefKey(filerId, ref.FileTsNs))
}
}
}
// A file selected before the bound can hold entries past it. The client
// filters those but adopts the marker as its checkpoint, so an unclamped
// marker makes a later bounded request skip them.
if untilNs != 0 && cursorTsNs > untilNs {
cursorTsNs = untilNs
}
if err := sender.Send(&filer_pb.SubscribeMetadataResponse{
EventNotification: &filer_pb.EventNotification{},
TsNs: cursorTsNs,
}); err != nil {
return 0, false, err
}
return cursorTsNs, false, nil
}
// sendRefsBatched sends refs through the pipelined sender, which keeps them
// out of Events batches; gRPC allows one sending goroutine per stream and the
// sender's goroutine is it.
func (fs *FilerServer) sendRefsBatched(sender metadataStreamSender, refs []*filer_pb.LogFileChunkRef) error {
const maxRefsPerMessage = 64
for i := 0; i < len(refs); i += maxRefsPerMessage {
end := i + maxRefsPerMessage
if end > len(refs) {
end = len(refs)
}
if err := stream.Send(&filer_pb.SubscribeMetadataResponse{
LogFileRefs: refs[i:end],
}); err != nil {
return lastTsNs, false, err
if err := sender.Send(&filer_pb.SubscribeMetadataResponse{LogFileRefs: refs[i:end]}); err != nil {
return err
}
}
return lastTsNs, false, nil
return nil
}
// sentRefState tracks, per subscription, how many chunks of each log file have
// been shipped as refs. Collection re-lists files up to a flush interval behind
// the cursor (the spanning-file back-off), and a filer appends further chunks
// to its newest file, so consecutive collections overlap; shipping only each
// file's unsent chunk suffix keeps every per-filer ref stream duplicate-free
// and timestamp-sorted - the contract the client's merge reads them under.
type sentRefState struct {
chunks int
fileTsNs int64
}
// refNeedsReship says whether a shipped ref's sent state must be dropped so a
// later pass re-ships it: everything above the file that answered the probe
// (the cursor never reached it), the answering file itself when its read was
// prefix-limited (its unread suffix would otherwise be abandoned the moment a
// later append advances past it), and everything when nothing answered. Files
// below a complete answer stay sent: the client has moved past them, and
// re-shipping cannot rewind its filter.
func refNeedsReship(fileTsNs int64, answered bool, answeredFileTsNs int64, complete bool) bool {
if !answered {
return true
}
if fileTsNs > answeredFileTsNs {
return true
}
return fileTsNs == answeredFileTsNs && !complete
}
func sentRefKey(filerId string, fileTsNs int64) string {
return fmt.Sprintf("%s/%d", filerId, fileTsNs)
}
// deltaLogFileRefs reduces a collection to the chunks not yet shipped, updates
// the sent state, and prunes files the scan window has moved past.
//
// A shipped suffix is rebased to logical offset zero: the client's chunk
// reader starts at zero, and a chunk list opening at a higher offset reads as
// instant EOF - an empty replay that would silently drop the appended events.
// The cut is record-aligned because each append is one chunk of whole entries
// (logFlushFunc appends one uploaded window per flush), so the rebased suffix
// decodes as a file of its own.
func deltaLogFileRefs(refs []*filer_pb.LogFileChunkRef, sent map[string]sentRefState, pruneBeforeTsNs int64) []*filer_pb.LogFileChunkRef {
out := make([]*filer_pb.LogFileChunkRef, 0, len(refs))
for _, ref := range refs {
key := sentRefKey(ref.FilerId, ref.FileTsNs)
prior := sent[key].chunks
if len(ref.Chunks) <= prior {
continue
}
chunks := ref.Chunks[prior:]
if base := chunks[0].Offset; base != 0 {
rebased := make([]*filer_pb.FileChunk, len(chunks))
for i, c := range chunks {
cc := proto.Clone(c).(*filer_pb.FileChunk)
cc.Offset -= base
rebased[i] = cc
}
chunks = rebased
}
out = append(out, &filer_pb.LogFileChunkRef{
Chunks: chunks,
FileTsNs: ref.FileTsNs,
FilerId: ref.FilerId,
})
sent[key] = sentRefState{chunks: len(ref.Chunks), fileTsNs: ref.FileTsNs}
}
for key, st := range sent {
if st.fileTsNs < pruneBeforeTsNs {
delete(sent, key)
}
}
return out
}
func (fs *FilerServer) eachEventNotificationFn(req *filer_pb.SubscribeMetadataRequest, sender metadataStreamSender, clientName string, filtered *int64) func(dirPath string, eventNotification *filer_pb.EventNotification, tsNs int64) error {
weed/server/filer_grpc_server_sub_meta_gap_test.go
+562
View File
@@ -0,0 +1,562 @@
package weed_server
import (
"context"
"testing"
"time"
dto "github.com/prometheus/client_model/go"
"github.com/seaweedfs/seaweedfs/weed/pb/filer_pb"
"github.com/seaweedfs/seaweedfs/weed/stats"
"github.com/seaweedfs/seaweedfs/weed/util/log_buffer"
)
// TestResolveGapResume pins the one decision both subscribe paths share: a gap
// the disk read found empty may be skipped only when it is provably so - the
// ring never evicted past the cursor, or the flush watermark observed before
// the read had already passed the earliest in-memory time. The aggregated ring
// never flushes, so it is the flushedTsNs=0 column of this table.
func TestResolveGapResume(t *testing.T) {
now := time.Date(2026, 6, 29, 12, 0, 0, 0, time.UTC).UnixNano()
ago := func(d time.Duration) int64 { return now - int64(d) }
cases := []struct {
name string
currentTsNs int64
currentOffset int64 // <= 0 is a sentinel (inclusive) cursor
earliestMemTsNs int64
flushedTsNs int64 // 0 also models the never-flushing aggregated ring
lastEvictedTsNs int64 // zero value is a ring that never evicted
wantAdvance bool
}{
{
// The bug this PR fixes: the ring dropped the 30s..25s window
// before it was flushed, so skipping past it loses those events.
name: "gap the ring dropped must NOT skip",
currentTsNs: ago(30 * time.Second),
earliestMemTsNs: ago(25 * time.Second),
lastEvictedTsNs: ago(26 * time.Second),
wantAdvance: false,
},
{
// An ancient cursor is always below the watermark once anything has
// been evicted: wall-clock age is not a licence to skip.
name: "ancient cursor below the watermark must NOT skip",
currentTsNs: time.Unix(0, 0).UnixNano(),
earliestMemTsNs: ago(30 * time.Second),
lastEvictedTsNs: ago(10 * time.Minute),
wantAdvance: false,
},
{
name: "watermark behind earliest must NOT skip (may be unflushed)",
currentTsNs: ago(40 * time.Second),
earliestMemTsNs: ago(30 * time.Second),
flushedTsNs: ago(35 * time.Second),
lastEvictedTsNs: ago(32 * time.Second),
wantAdvance: false,
},
{
// Everything up to earliest was flushed before the read: the miss
// is authoritative even though the ring dropped the gap.
name: "flush watermark at earliest proves the gap and skips",
currentTsNs: ago(40 * time.Second),
earliestMemTsNs: ago(30 * time.Second),
flushedTsNs: ago(30 * time.Second),
lastEvictedTsNs: ago(32 * time.Second),
wantAdvance: true,
},
{
name: "flush watermark past earliest skips",
currentTsNs: ago(10 * time.Minute),
earliestMemTsNs: ago(30 * time.Second),
flushedTsNs: ago(10 * time.Second),
lastEvictedTsNs: ago(32 * time.Second),
wantAdvance: true,
},
{
// Nothing was ever evicted, so memory still holds the gap whatever
// the flush watermark says and however old the cursor is.
name: "nothing evicted skips despite a stale flush watermark",
currentTsNs: ago(40 * time.Second),
earliestMemTsNs: ago(30 * time.Second),
flushedTsNs: 0,
wantAdvance: true,
},
{
// The evicted window ends exactly on the cursor. Memory holds
// nothing at that timestamp and the persisted reader skips
// ts <= its start, so no wait can produce it and the rest of the
// gap is in memory: skipping is the only way forward.
name: "cursor on the eviction watermark skips with a stalled flush",
currentTsNs: ago(30 * time.Second),
earliestMemTsNs: ago(25 * time.Second),
flushedTsNs: 0,
lastEvictedTsNs: ago(30 * time.Second),
wantAdvance: true,
},
{
name: "memory not ahead of current must NOT skip",
currentTsNs: ago(20 * time.Second),
earliestMemTsNs: ago(40 * time.Second),
flushedTsNs: ago(10 * time.Second),
wantAdvance: false,
},
{
// time.Time{}.UnixNano() is a large negative value: no in-memory data.
name: "no in-memory data must NOT skip",
currentTsNs: ago(30 * time.Second),
earliestMemTsNs: time.Time{}.UnixNano(),
flushedTsNs: ago(10 * time.Second),
wantAdvance: false,
},
{
// Timestamp collision bumps make adjacent entries exactly 1ns
// apart, so a delivered entry ending an evicted window leaves the
// cursor exactly one below earliest. The resume target equals the
// cursor, but the exclusive (positive-offset) cursor cannot be
// served - ReadFromBuffer refuses positive offsets below the
// window - while the sentinel resume is, and both deliver exactly
// the entries after it. Refusing here parked a subscriber whose
// data was entirely in memory.
name: "exclusive cursor adjacent to earliest re-arms to a sentinel",
currentTsNs: ago(30 * time.Second),
currentOffset: 7, // a batch offset from a served memory read
earliestMemTsNs: ago(30*time.Second) + 1,
flushedTsNs: 0,
lastEvictedTsNs: ago(30 * time.Second),
wantAdvance: true,
},
{
// The same position already sentinel is served by the memory read,
// so re-issuing it is not progress.
name: "sentinel cursor adjacent to earliest must NOT re-arm",
currentTsNs: ago(30 * time.Second),
currentOffset: -2,
earliestMemTsNs: ago(30*time.Second) + 1,
flushedTsNs: 0,
lastEvictedTsNs: ago(30 * time.Second),
wantAdvance: false,
},
}
for _, tc := range cases {
t.Run(tc.name, func(t *testing.T) {
gotTo, gotAdvance := resolveGapResume(tc.currentTsNs, tc.currentOffset, tc.earliestMemTsNs, tc.flushedTsNs, tc.lastEvictedTsNs)
if gotAdvance != tc.wantAdvance {
t.Fatalf("advance = %v, want %v (current=%v earliest=%v flushed=%v evicted=%v)",
gotAdvance, tc.wantAdvance, time.Unix(0, tc.currentTsNs), time.Unix(0, tc.earliestMemTsNs),
time.Unix(0, tc.flushedTsNs), time.Unix(0, tc.lastEvictedTsNs))
}
if !gotAdvance {
return
}
// The resume lands just below earliest so the earliest entry is
// still delivered, even from a single-entry sealed window.
if gotTo != tc.earliestMemTsNs-1 {
t.Fatalf("advanceTo = %v, want just below earliest %v", time.Unix(0, gotTo), time.Unix(0, tc.earliestMemTsNs))
}
})
}
}
// TestInclusiveDiskCursorOnWatermarkStillAdvances pins the disk-to-memory
// handoff. A cursor built from a disk position stays inclusive, because memory
// above the eviction watermark may hold a different entry sharing that
// timestamp and an exclusive cursor would drop it. That inclusive cursor can
// land exactly on the watermark, where the read gate sends it to disk and the
// persisted reader — which skips ts <= its start — returns nothing. Waiting
// cannot fix that, so the resolver must skip instead of parking.
func TestInclusiveDiskCursorOnWatermarkStillAdvances(t *testing.T) {
now := time.Date(2026, 6, 29, 12, 0, 0, 0, time.UTC).UnixNano()
watermark := now - int64(30*time.Second) // disk delivered exactly this far
earliest := watermark + int64(time.Second)
if !memoryHoldsGap(watermark, watermark) {
t.Fatal("memory holds everything after the watermark, whatever the cursor's inclusivity")
}
// No flush has landed, so only the eviction proof can settle this.
to, advance := resolveGapResume(watermark, -2, earliest, 0, watermark)
if !advance {
t.Fatal("an inclusive cursor on the watermark must still advance")
}
if to != earliest-1 {
t.Fatalf("advanceTo = %v, want just below earliest %v", time.Unix(0, to), time.Unix(0, earliest))
}
// One nanosecond earlier the gap really was dropped unflushed: park.
if _, advance := resolveGapResume(watermark-1, -2, earliest, 0, watermark); advance {
t.Fatal("a cursor below the watermark with no flush proof must wait, not skip")
}
}
// TestParkOnGapExits pins every way a park has to end. The park is where a
// stalled subscriber spends all its time and it never re-enters the read loop,
// so any exit the loop relies on has to be honored here as well - and the done
// exits must run before the reporter marks the stream parked, or a healthy
// completion leaves a phantom "still behind" trace.
func TestParkOnGapExits(t *testing.T) {
fs := &FilerServer{knownListeners: map[int32]int32{7: 3}}
req := &filer_pb.SubscribeMetadataRequest{ClientId: 7, ClientEpoch: 3}
cursorTs := time.Now().UnixNano()
cursor := log_buffer.NewMessagePosition(cursorTs, -2)
noEviction := func() int64 { return 0 }
newStall := func() *gapStallReporter {
return &gapStallReporter{scope: "aggregated", clientName: "c", pathPrefix: "/"}
}
t.Run("retries on the timer with no notification channel", func(t *testing.T) {
gapStall := newStall()
defer gapStall.resumed()
start := time.Now()
_, skip, done := fs.parkOnGap(context.Background(), req, gapStall, noEviction, cursor, nil, "test")
if skip || done {
t.Fatalf("skip=%v done=%v, want a plain retry", skip, done)
}
if elapsed := time.Since(start); elapsed < unflushedGapRetryInterval {
t.Fatalf("returned after %v, want the full %v retry interval", elapsed, unflushedGapRetryInterval)
}
})
t.Run("a replaced client ends the stream without parking", func(t *testing.T) {
// A reconnect at a higher epoch supersedes this stream; without this the
// old one keeps scanning the filer store until its TCP connection dies.
gapStall := newStall()
superseded := &filer_pb.SubscribeMetadataRequest{ClientId: 7, ClientEpoch: 2}
if _, _, done := fs.parkOnGap(context.Background(), superseded, gapStall, noEviction, cursor, nil, "test"); !done {
t.Fatal("want done")
}
if !gapStall.since.IsZero() {
t.Fatal("a finished stream must not be marked parked")
}
})
t.Run("a bounded subscription past its window ends without parking", func(t *testing.T) {
gapStall := newStall()
bounded := &filer_pb.SubscribeMetadataRequest{ClientId: 7, ClientEpoch: 3, UntilNs: cursorTs - 1}
if _, _, done := fs.parkOnGap(context.Background(), bounded, gapStall, noEviction, cursor, nil, "test"); !done {
t.Fatal("want done")
}
if !gapStall.since.IsZero() {
t.Fatal("a finished stream must not be marked parked")
}
})
t.Run("a bounded subscription exactly at its window ends without parking", func(t *testing.T) {
// The bound is inclusive and cursors are exclusive: a disk read whose
// last entry sits exactly on UntilNs leaves the cursor there with
// everything <= UntilNs delivered. Parking would make fs.verify hang.
gapStall := newStall()
bounded := &filer_pb.SubscribeMetadataRequest{ClientId: 7, ClientEpoch: 3, UntilNs: cursorTs}
if _, _, done := fs.parkOnGap(context.Background(), bounded, gapStall, noEviction, cursor, nil, "test"); !done {
t.Fatal("want done")
}
if !gapStall.since.IsZero() {
t.Fatal("a finished stream must not be marked parked")
}
})
t.Run("a cancelled stream ends promptly", func(t *testing.T) {
gapStall := newStall()
defer gapStall.resumed()
ctx, cancel := context.WithCancel(context.Background())
cancel()
start := time.Now()
if _, _, done := fs.parkOnGap(ctx, req, gapStall, noEviction, cursor, nil, "test"); !done {
t.Fatal("want done")
}
if elapsed := time.Since(start); elapsed >= unflushedGapRetryInterval {
t.Fatalf("took %v, want well under the %v retry interval", elapsed, unflushedGapRetryInterval)
}
})
t.Run("a closed notification channel does not spin", func(t *testing.T) {
// A receive on a closed channel returns instantly forever; selecting on
// it without checking would burn a core until the retry timer fires.
gapStall := newStall()
defer gapStall.resumed()
closed := make(chan struct{})
close(closed)
start := time.Now()
_, skip, done := fs.parkOnGap(context.Background(), req, gapStall, noEviction, cursor, closed, "test")
if skip || done {
t.Fatalf("skip=%v done=%v, want a plain retry", skip, done)
}
if elapsed := time.Since(start); elapsed < unflushedGapRetryInterval {
t.Fatalf("returned after %v, want the timer to pace it to %v", elapsed, unflushedGapRetryInterval)
}
})
t.Run("a notification wakes it early", func(t *testing.T) {
gapStall := newStall()
defer gapStall.resumed()
notify := make(chan struct{}, 1)
notify <- struct{}{}
start := time.Now()
_, skip, done := fs.parkOnGap(context.Background(), req, gapStall, noEviction, cursor, notify, "test")
if skip || done {
t.Fatalf("skip=%v done=%v, want a plain retry", skip, done)
}
if elapsed := time.Since(start); elapsed >= unflushedGapRetryInterval {
t.Fatalf("took %v, want well under the %v retry interval", elapsed, unflushedGapRetryInterval)
}
})
}
// TestGapResumeCursorOffsetIsSentinel ties the resolvers' resume cursor to what
// ReadFromBuffer will serve. That read falls through to memory for a cursor
// below the in-memory window only when the offset is a sentinel; a positive one
// comes back as ResumeFromDiskError, so the resume would bounce to the resolver,
// which sees no progress and parks a subscriber whose data is in the ring.
func TestGapResumeCursorOffsetIsSentinel(t *testing.T) {
if gapResumeCursorOffset > 0 {
t.Fatalf("gapResumeCursorOffset = %d, want a sentinel (<= 0) or the memory read refuses every gap resume",
gapResumeCursorOffset)
}
}
// TestDiskReadAdvancedRequiresForwardProgress pins that a persisted read only
// counts as progress when it actually moves the cursor. A chunk-ref read
// reports the minute-level name of the last file it shipped, clamped so it
// never rewinds, so it comes back non-zero while naming the position that was
// already current -- and a subscriber parked on a gap it keeps re-shipping the
// same refs for would clear its stall timer on every retry and never reach the
// bound that is supposed to end it.
func TestDiskReadAdvancedRequiresForwardProgress(t *testing.T) {
cursorTsNs := time.Date(2026, 6, 29, 12, 31, 10, 0, time.UTC).UnixNano()
cursor := log_buffer.NewMessagePosition(cursorTsNs, gapResumeCursorOffset)
if diskReadAdvanced(0, cursor) {
t.Fatal("an empty disk read is not progress")
}
if diskReadAdvanced(cursorTsNs, cursor) {
t.Fatal("a read reporting the position already held is not progress")
}
if diskReadAdvanced(cursorTsNs-1, cursor) {
t.Fatal("a read reporting an earlier position is not progress")
}
if !diskReadAdvanced(cursorTsNs+1, cursor) {
t.Fatal("a read that moves the cursor forward is progress")
}
}
// TestReportUnprovenAggregatedCrossing pins which advances are flagged. The
// eviction watermark belongs to the merged ring while the disk behind it is the
// union of each peer's own log, so a read that lifts the cursor from below the
// watermark to above it may have done so entirely on a peer that is ahead --
// leaving a lagging peer's unflushed events inside the range just crossed.
func TestReportUnprovenAggregatedCrossing(t *testing.T) {
const (
before = 10
evicted = 20
after = 25
)
crossings := func() float64 {
var m dto.Metric
if err := stats.FilerSubscribeUnprovenGapCrossings.WithLabelValues("aggregated").Write(&m); err != nil {
t.Fatalf("read counter: %v", err)
}
return m.GetCounter().GetValue()
}
start := crossings()
// Nothing evicted: no range to cross.
reportUnprovenAggregatedCrossing(before, after, 0, "c", "/")
// Cursor already past the watermark: the evicted range was behind it.
reportUnprovenAggregatedCrossing(evicted, after, evicted, "c", "/")
// Cursor still short of the watermark: the gap is open, not crossed.
reportUnprovenAggregatedCrossing(before, evicted-1, evicted, "c", "/")
if got := crossings(); got != start {
t.Fatalf("counter moved by %v on advances that cross nothing", got-start)
}
// From below the watermark to above it: unproven.
reportUnprovenAggregatedCrossing(before, after, evicted, "c", "/")
if got := crossings(); got != start+1 {
t.Fatalf("counter = %v, want %v after one unproven crossing", got, start+1)
}
}
// TestParkOnGapStallOutcomes pins what a park that outlived maxGapStall does.
// Failing the stream would just move the loop into the client, which
// reconnects at the same position and hits the same wall delivering nothing;
// instead the subscriber abandons the gap, loudly: the skip lands exactly on
// the eviction watermark (everything retained starts strictly after it) and
// the unproven-crossing counter records the loss. A stall with nothing evicted
// past the cursor has nothing to skip and keeps waiting on a fresh cycle.
func TestParkOnGapStallOutcomes(t *testing.T) {
fs := &FilerServer{knownListeners: map[int32]int32{7: 3}}
req := &filer_pb.SubscribeMetadataRequest{ClientId: 7, ClientEpoch: 3}
lb := log_buffer.NewLogBuffer("park-stall", time.Minute, nil, nil, nil)
defer lb.ShutdownLogBuffer()
// Entries far enough apart that every append seals the window before it;
// the ring evicts once it wraps, moving the watermark for real.
base := time.Now().Add(-time.Hour).Truncate(time.Second)
for i := 0; i < log_buffer.PreviousBufferCount+2; i++ {
if err := lb.AddLogEntryToBuffer(&filer_pb.LogEntry{
TsNs: base.Add(time.Duration(i) * 2 * time.Minute).UnixNano(), Data: []byte("x"), Key: []byte("k"),
}); err != nil {
t.Fatalf("add %d: %v", i, err)
}
}
evicted := lb.GetLastEvictedTsNs()
if evicted == 0 {
t.Fatal("precondition: the ring evicted nothing")
}
crossings := func() float64 {
var m dto.Metric
if err := stats.FilerSubscribeUnprovenGapCrossings.WithLabelValues("aggregated").Write(&m); err != nil {
t.Fatalf("read counter: %v", err)
}
return m.GetCounter().GetValue()
}
var g0 dto.Metric
if err := stats.FilerSubscribeGapStalledGauge.WithLabelValues("aggregated").Write(&g0); err != nil {
t.Fatalf("read gauge: %v", err)
}
gaugeBefore := g0.GetGauge().GetValue()
t.Run("a stalled park below the watermark skips to it", func(t *testing.T) {
gapStall := &gapStallReporter{scope: "aggregated", clientName: "c", pathPrefix: "/"}
cursor := log_buffer.NewMessagePosition(evicted-int64(time.Minute), -2)
// Park through the real path so the gauge Inc that gaveUp() will Dec
// exists, then age the park to the give-up bound.
gapStall.park(cursor.Time, "test")
gapStall.since = time.Now().Add(-maxGapStall)
before := crossings()
skipTo, skip, done := fs.parkOnGap(context.Background(), req, gapStall, lb.GetLastEvictedTsNs, cursor, nil, "test")
if done || !skip {
t.Fatalf("skip=%v done=%v, want a forced skip", skip, done)
}
if skipTo != evicted {
t.Fatalf("skipTo = %v, want the eviction watermark %v", time.Unix(0, skipTo), time.Unix(0, evicted))
}
if got := crossings(); got != before+1 {
t.Fatalf("crossing counter moved by %v, want 1: the loss must be recorded", got-before)
}
if !gapStall.since.IsZero() {
t.Fatal("the stall must be cleared after giving up")
}
})
t.Run("a stalled park with nothing to skip to keeps waiting", func(t *testing.T) {
gapStall := &gapStallReporter{scope: "aggregated", clientName: "c", pathPrefix: "/"}
cursor := log_buffer.NewMessagePosition(evicted, -2) // at the watermark: nothing withheld
gapStall.park(cursor.Time, "test")
gapStall.since = time.Now().Add(-maxGapStall)
defer gapStall.close() // release the gauge this test's park holds
before := crossings()
_, skip, done := fs.parkOnGap(context.Background(), req, gapStall, lb.GetLastEvictedTsNs, cursor, nil, "test")
if skip || done {
t.Fatalf("skip=%v done=%v, want neither: nothing is being lost", skip, done)
}
if got := crossings(); got != before {
t.Fatal("no loss happened, the counter must not move")
}
if gapStall.stalledFor() >= maxGapStall {
t.Fatal("the stall clock must restart, or this branch retriggers every retry")
}
})
// The shared gauge must come back to its starting value: a test leaving it
// skewed corrupts every later assertion on it in this package.
var g dto.Metric
if err := stats.FilerSubscribeGapStalledGauge.WithLabelValues("aggregated").Write(&g); err != nil {
t.Fatalf("read gauge: %v", err)
}
if got := g.GetGauge().GetValue(); got != gaugeBefore {
t.Fatalf("stalled gauge = %v, want %v: parks and releases must balance", got, gaugeBefore)
}
}
// TestDeltaLogFileRefs pins the per-stream ref dedup. Collections overlap by
// design - the scan backs off a flush interval to catch a spanning file, and a
// filer appends chunks to its newest file - so without the delta a subscriber
// receives the same file twice: re-downloaded chunks at best, and a mid-stream
// timestamp rewind inside the client's sorted per-filer merge at worst.
func TestDeltaLogFileRefs(t *testing.T) {
chunk := func(id string, offset, size int64) *filer_pb.FileChunk {
return &filer_pb.FileChunk{FileId: id, Offset: offset, Size: uint64(size)}
}
ref := func(filerId string, fileTsNs int64, chunks ...*filer_pb.FileChunk) *filer_pb.LogFileChunkRef {
return &filer_pb.LogFileChunkRef{FilerId: filerId, FileTsNs: fileTsNs, Chunks: chunks}
}
sent := make(map[string]sentRefState)
// First collection ships everything.
out := deltaLogFileRefs([]*filer_pb.LogFileChunkRef{ref("a", 100, chunk("c1", 0, 10), chunk("c2", 10, 10))}, sent, 0)
if len(out) != 1 || len(out[0].Chunks) != 2 {
t.Fatalf("first collection: got %d refs, want the whole file", len(out))
}
// Re-collection of the identical file ships nothing.
out = deltaLogFileRefs([]*filer_pb.LogFileChunkRef{ref("a", 100, chunk("c1", 0, 10), chunk("c2", 10, 10))}, sent, 0)
if len(out) != 0 {
t.Fatalf("unchanged re-collection: got %d refs, want none", len(out))
}
// A grown file ships only its new chunks; a new file ships whole.
out = deltaLogFileRefs([]*filer_pb.LogFileChunkRef{
ref("a", 100, chunk("c1", 0, 10), chunk("c2", 10, 10), chunk("c3", 20, 10)),
ref("a", 200, chunk("d1", 0, 10)),
}, sent, 0)
if len(out) != 2 {
t.Fatalf("growth pass: got %d refs, want 2", len(out))
}
if len(out[0].Chunks) != 1 || out[0].Chunks[0].FileId != "c3" {
t.Fatalf("grown file must ship only the appended suffix, got %+v", out[0].Chunks)
}
// The suffix must read from logical zero: the client's chunk reader starts
// there, and a list opening at a higher offset is an instant EOF - a
// silently empty replay of the appended events.
if out[0].Chunks[0].Offset != 0 {
t.Fatalf("suffix chunk keeps file offset %d; it must be rebased to 0", out[0].Chunks[0].Offset)
}
if len(out[1].Chunks) != 1 || out[1].Chunks[0].FileId != "d1" {
t.Fatalf("new file must ship whole, got %+v", out[1].Chunks)
}
// Files behind the scan window are pruned; one that somehow reappears ships
// again rather than leaking state forever.
deltaLogFileRefs(nil, sent, 150)
if _, kept := sent["a/100"]; kept {
t.Fatal("file behind the scan window must be pruned")
}
if _, kept := sent["a/200"]; !kept {
t.Fatal("file inside the scan window must be kept")
}
}
// TestRefNeedsReship pins the sent-state rollback rules. Sent state that
// outlives what the probe could not verify strands the cursor behind shipped
// content for the life of the connection; sent state dropped for files the
// client has moved past only re-ships noise it will filter.
func TestRefNeedsReship(t *testing.T) {
const answered = 2000
cases := []struct {
name string
fileTsNs int64
ok bool
complete bool
want bool
}{
{"file above the answer re-ships", 3000, true, true, true},
{"complete answering file stays sent", answered, true, true, false},
{"prefix-limited answering file re-ships its suffix", answered, true, false, true},
{"file below a complete answer stays sent", 1000, true, true, false},
{"file below an incomplete answer stays sent (client moved past)", 1000, true, false, false},
{"everything re-ships when nothing answered", 1000, false, false, true},
}
for _, tc := range cases {
t.Run(tc.name, func(t *testing.T) {
if got := refNeedsReship(tc.fileTsNs, tc.ok, answered, tc.complete); got != tc.want {
t.Fatalf("refNeedsReship(%d, %v, %d, %v) = %v, want %v",
tc.fileTsNs, tc.ok, answered, tc.complete, got, tc.want)
}
})
}
}
weed/server/filer_pipelined_sender_test.go
+104
View File
@@ -0,0 +1,104 @@
package weed_server
import (
"fmt"
"sync"
"testing"
"time"
"github.com/seaweedfs/seaweedfs/weed/pb/filer_pb"
)
type recordingStream struct {
mu sync.Mutex
slow time.Duration
msgs []*filer_pb.SubscribeMetadataResponse
}
func (s *recordingStream) Send(m *filer_pb.SubscribeMetadataResponse) error {
if s.slow > 0 {
time.Sleep(s.slow)
}
s.mu.Lock()
defer s.mu.Unlock()
// Clone-ish: the sender clears Events after sending, so keep our own view.
copied := &filer_pb.SubscribeMetadataResponse{
TsNs: m.TsNs,
Directory: m.Directory,
EventNotification: m.EventNotification,
LogFileRefs: m.LogFileRefs,
Events: append([]*filer_pb.SubscribeMetadataResponse(nil), m.Events...),
}
s.msgs = append(s.msgs, copied)
return nil
}
func (s *recordingStream) snapshot() []*filer_pb.SubscribeMetadataResponse {
s.mu.Lock()
defer s.mu.Unlock()
return append([]*filer_pb.SubscribeMetadataResponse(nil), s.msgs...)
}
// TestPipelinedSenderRefsNeverBatched pins the wire rules the client depends
// on: a refs message must arrive solo - the client recognizes refs by the
// top-level field and skips the rest of the response, so a refs envelope would
// drop its Events tail, and refs inside Events would be applied as an empty
// event. Everything must arrive, in order, whatever the batcher does.
func TestPipelinedSenderRefsNeverBatched(t *testing.T) {
stream := &recordingStream{slow: 2 * time.Millisecond} // let the queue back up so batching engages
sender := newPipelinedSender(stream, 64, true)
oldTs := time.Now().Add(-time.Hour).UnixNano() // far behind: the batch heuristic fires
var wantOrder []string
send := func(kind string, m *filer_pb.SubscribeMetadataResponse) {
wantOrder = append(wantOrder, kind)
if err := sender.Send(m); err != nil {
t.Fatalf("send %s: %v", kind, err)
}
}
event := func(i int) *filer_pb.SubscribeMetadataResponse {
return &filer_pb.SubscribeMetadataResponse{
TsNs: oldTs + int64(i),
EventNotification: &filer_pb.EventNotification{NewEntry: &filer_pb.Entry{Name: fmt.Sprintf("e%d", i)}},
}
}
refs := func() *filer_pb.SubscribeMetadataResponse {
return &filer_pb.SubscribeMetadataResponse{LogFileRefs: []*filer_pb.LogFileChunkRef{{FilerId: "a"}}}
}
// Interleave backlog events with refs so refs land both between batches
// and mid-drain.
for i := 0; i < 30; i++ {
send("event", event(i))
if i%7 == 3 {
send("refs", refs())
}
}
if err := sender.Close(); err != nil {
t.Fatalf("close: %v", err)
}
var gotOrder []string
for _, m := range stream.snapshot() {
if len(m.LogFileRefs) > 0 {
if len(m.Events) > 0 {
t.Fatal("a refs envelope carried an Events tail; the client drops that tail")
}
if m.EventNotification != nil {
t.Fatal("a refs message doubled as an event envelope")
}
gotOrder = append(gotOrder, "refs")
continue
}
gotOrder = append(gotOrder, "event")
for _, e := range m.Events {
if len(e.LogFileRefs) > 0 {
t.Fatal("refs packed inside Events; the client applies that as an empty event")
}
gotOrder = append(gotOrder, "event")
}
}
if fmt.Sprint(gotOrder) != fmt.Sprint(wantOrder) {
t.Fatalf("delivery order/count changed:\n got %v\nwant %v", gotOrder, wantOrder)
}
}
weed/server/filer_server.go
+1 -11
View File
@@ -91,11 +91,6 @@ type FilerOption struct {
type FilerServer struct {
inFlightDataSize int64
inFlightUploads int64
listenersWaits int64
// notifying clients
listenersLock sync.Mutex
listenersCond *sync.Cond
inFlightDataLimitCond *sync.Cond
@@ -196,7 +191,6 @@ func NewFilerServer(defaultMux, readonlyMux *http.ServeMux, option *FilerOption)
fs.startPosixLockSweeper()
fs.mountPeerRegistry = filer.NewMountPeerRegistry()
go fs.runMountPeerRegistrySweeper()
fs.listenersCond = sync.NewCond(&fs.listenersLock)
option.Masters.RefreshBySrvIfAvailable()
if len(option.Masters.GetInstances()) == 0 {
@@ -219,11 +213,7 @@ func NewFilerServer(defaultMux, readonlyMux *http.ServeMux, option *FilerOption)
v.SetDefault("filer.options.max_file_name_length", 255)
maxFilenameLength := v.GetUint32("filer.options.max_file_name_length")
glog.V(0).Infof("max_file_name_length %d", maxFilenameLength)
fs.filer = filer.NewFiler(*option.Masters, fs.grpcDialOption, option.Host, option.FilerGroup, option.Collection, option.DefaultReplication, option.DataCenter, maxFilenameLength, func() {
if atomic.LoadInt64(&fs.listenersWaits) > 0 {
fs.listenersCond.Broadcast()
}
})
fs.filer = filer.NewFiler(*option.Masters, fs.grpcDialOption, option.Host, option.FilerGroup, option.Collection, option.DefaultReplication, option.DataCenter, maxFilenameLength, nil)
fs.filer.Cipher = option.Cipher
fs.filer.DefaultDiskType = option.DiskType
// we do not support IP whitelist right now https://github.com/seaweedfs/seaweedfs/issues/7094
weed/server/filer_subscribe_loop_test.go
+735
View File
@@ -0,0 +1,735 @@
package weed_server
// End-to-end tests for the metadata subscribe loops. The unit tests in this
// package pin individual helpers; every escaped bug across this PR's review
// rounds lived in the interactions - the loop state machine, the disk/memory
// handoff, and the server/client contract. These tests run the real
// SubscribeLocalMetadata loop against a real filer store, with only the volume
// layer faked, and assert the delivered stream itself: exactly the written
// events, in order, no duplicates from the entry path, and the chunk-mode
// marker never claiming more than the real client code applies.
import (
"context"
"fmt"
"io"
"sort"
"strings"
"sync"
"testing"
"time"
"google.golang.org/grpc/metadata"
"google.golang.org/protobuf/proto"
"github.com/seaweedfs/seaweedfs/weed/filer"
"github.com/seaweedfs/seaweedfs/weed/filer/leveldb"
"github.com/seaweedfs/seaweedfs/weed/pb"
"github.com/seaweedfs/seaweedfs/weed/pb/filer_pb"
"github.com/seaweedfs/seaweedfs/weed/util"
"github.com/seaweedfs/seaweedfs/weed/util/log_buffer"
)
// ---- store configuration ----
type testConfig map[string]string
func (c testConfig) GetString(key string) string { return c[key] }
func (c testConfig) GetBool(key string) bool { return false }
func (c testConfig) GetInt(key string) int { return 0 }
func (c testConfig) GetStringSlice(key string) []string { return nil }
func (c testConfig) SetDefault(key string, v interface{}) {}
// ---- fake gRPC stream ----
type fakeSubscribeStream struct {
ctx context.Context
mu sync.Mutex
msgs []*filer_pb.SubscribeMetadataResponse
}
func (s *fakeSubscribeStream) Send(resp *filer_pb.SubscribeMetadataResponse) error {
select {
case <-s.ctx.Done():
return s.ctx.Err()
default:
}
s.mu.Lock()
defer s.mu.Unlock()
s.msgs = append(s.msgs, resp)
return nil
}
func (s *fakeSubscribeStream) snapshot() []*filer_pb.SubscribeMetadataResponse {
s.mu.Lock()
defer s.mu.Unlock()
return append([]*filer_pb.SubscribeMetadataResponse(nil), s.msgs...)
}
func (s *fakeSubscribeStream) Context() context.Context { return s.ctx }
func (s *fakeSubscribeStream) SetHeader(metadata.MD) error { return nil }
func (s *fakeSubscribeStream) SendHeader(metadata.MD) error { return nil }
func (s *fakeSubscribeStream) SetTrailer(metadata.MD) {}
func (s *fakeSubscribeStream) SendMsg(m interface{}) error { return nil }
func (s *fakeSubscribeStream) RecvMsg(m interface{}) error { return nil }
// ---- fake volume layer ----
type fakeLogVolumes struct {
mu sync.Mutex
bytes map[string][]byte // chunk fileId -> raw log bytes (size-prefixed entries)
dead map[string]bool
nextId int
}
func newFakeLogVolumes() *fakeLogVolumes {
return &fakeLogVolumes{bytes: make(map[string][]byte), dead: make(map[string]bool)}
}
func (v *fakeLogVolumes) put(data []byte) string {
v.mu.Lock()
defer v.mu.Unlock()
v.nextId++
id := fmt.Sprintf("t,%d", v.nextId)
v.bytes[id] = data
return id
}
func (v *fakeLogVolumes) kill(fileId string) {
v.mu.Lock()
defer v.mu.Unlock()
v.dead[fileId] = true
}
// notFoundErr matches both the server's and the client's missing-chunk
// predicates, like a real dead log volume does.
func notFoundErr(fileId string) error { return fmt.Errorf("read %s: volume 42 not found", fileId) }
func (v *fakeLogVolumes) get(fileId string) ([]byte, error) {
v.mu.Lock()
defer v.mu.Unlock()
if v.dead[fileId] {
return nil, notFoundErr(fileId)
}
data, found := v.bytes[fileId]
if !found {
return nil, notFoundErr(fileId)
}
return data, nil
}
func decodeLogBytes(data []byte) ([]*filer_pb.LogEntry, error) {
var entries []*filer_pb.LogEntry
for pos := 0; pos+4 <= len(data); {
size := int(util.BytesToUint32(data[pos : pos+4]))
if pos+4+size > len(data) {
break // torn tail
}
entry := &filer_pb.LogEntry{}
if err := entry.UnmarshalVT(data[pos+4 : pos+4+size]); err != nil {
return nil, err
}
entries = append(entries, entry)
pos += 4 + size
}
return entries, nil
}
// chunkStreamReader mimics the client's whole-file byte stream: sequential,
// erroring at the first dead chunk.
type chunkStreamReader struct {
vol *fakeLogVolumes
chunks []*filer_pb.FileChunk
buf []byte
idx int
}
func (r *chunkStreamReader) Read(p []byte) (int, error) {
for len(r.buf) == 0 {
if r.idx >= len(r.chunks) {
return 0, io.EOF
}
data, err := r.vol.get(r.chunks[r.idx].GetFileIdString())
if err != nil {
return 0, err
}
r.buf = data
r.idx++
}
n := copy(p, r.buf)
r.buf = r.buf[n:]
return n, nil
}
func (r *chunkStreamReader) Close() error { return nil }
// ---- the harness ----
type subscribeHarness struct {
t *testing.T
f *filer.Filer
fs *FilerServer
vol *fakeLogVolumes
base int64 // fixed timestamp origin; a per-call time.Now() shifts across second boundaries mid-test
// flushGate, when non-nil, blocks the flush function - the "volume outage
// stalls the metadata log flush" state the whole PR exists to handle.
gateMu sync.Mutex
flushGate chan struct{}
}
const testFilerIdSuffix = "0000abcd"
func newSubscribeHarness(t *testing.T) *subscribeHarness {
// Shrink the timing knobs so parks and retries run at test speed.
prevRetry, prevWarn, prevStall := unflushedGapRetryInterval, gapStallWarnInterval, maxGapStall
unflushedGapRetryInterval, gapStallWarnInterval, maxGapStall = 30*time.Millisecond, 200*time.Millisecond, time.Hour
t.Cleanup(func() {
unflushedGapRetryInterval, gapStallWarnInterval, maxGapStall = prevRetry, prevWarn, prevStall
})
f := filer.NewFiler(pb.ServerDiscovery{}, nil, "", "", "", "", "", 255, nil)
store := &leveldb.LevelDBStore{}
if err := store.Initialize(testConfig{"test.dir": t.TempDir()}, "test."); err != nil {
t.Fatalf("init store: %v", err)
}
f.SetStore(store)
vol := newFakeLogVolumes()
restore := filer.SetLogReadHooksForTesting(
func(chunk *filer_pb.FileChunk) ([]*filer_pb.LogEntry, error) {
data, err := vol.get(chunk.GetFileIdString())
if err != nil {
return nil, err
}
return decodeLogBytes(data)
},
func(chunks []*filer_pb.FileChunk) io.Reader {
return &chunkStreamReader{vol: vol, chunks: chunks}
},
func(fileId string) error {
_, err := vol.get(fileId)
return err
},
)
t.Cleanup(restore)
h := &subscribeHarness{t: t, f: f, vol: vol,
base: time.Now().Add(-time.Hour).Truncate(time.Second).UnixNano()}
// The real buffer, with the flush function writing through the fake volume
// layer the way logFlushFunc writes through real volumes.
f.LocalMetaLogBuffer.ShutdownLogBuffer()
f.LocalMetaLogBuffer = log_buffer.NewLogBuffer("local", time.Minute, h.flushToStore, nil, nil)
t.Cleanup(f.LocalMetaLogBuffer.ShutdownLogBuffer)
h.fs = &FilerServer{
filer: f,
option: &FilerOption{Host: pb.ServerAddress("test:8888")},
knownListeners: make(map[int32]int32),
}
return h
}
func (h *subscribeHarness) blockFlushes() {
h.gateMu.Lock()
defer h.gateMu.Unlock()
if h.flushGate == nil {
h.flushGate = make(chan struct{})
}
}
func (h *subscribeHarness) releaseFlushes() {
h.gateMu.Lock()
defer h.gateMu.Unlock()
if h.flushGate != nil {
close(h.flushGate)
h.flushGate = nil
}
}
func (h *subscribeHarness) flushToStore(lb *log_buffer.LogBuffer, startTime, stopTime time.Time, buf []byte, minOffset, maxOffset int64) {
h.gateMu.Lock()
gate := h.flushGate
h.gateMu.Unlock()
if gate != nil {
<-gate
}
// The same file naming and append shape as logFlushFunc, against the fake
// volumes: one chunk per flushed window, named for the window start minute.
startTime, stopTime = startTime.UTC(), stopTime.UTC()
targetFile := fmt.Sprintf("%s/%04d-%02d-%02d/%02d-%02d.%s", filer.SystemLogDir,
startTime.Year(), startTime.Month(), startTime.Day(), startTime.Hour(), startTime.Minute(), testFilerIdSuffix)
data := append([]byte(nil), buf...)
fileId := h.vol.put(data)
ctx := context.Background()
fullpath := util.FullPath(targetFile)
entry, err := h.f.FindEntry(ctx, fullpath)
var offset int64
if err == filer_pb.ErrNotFound {
entry = &filer.Entry{
FullPath: fullpath,
Attr: filer.Attr{Crtime: time.Now(), Mtime: time.Now(), Mode: 0644},
}
} else if err != nil {
h.t.Errorf("find %s: %v", targetFile, err)
return
} else {
offset = int64(filer.TotalSize(entry.GetChunks()))
}
entry.Chunks = append(entry.GetChunks(), &filer_pb.FileChunk{
FileId: fileId,
Offset: offset,
Size: uint64(len(data)),
ModifiedTsNs: time.Now().UnixNano(),
})
if err := h.f.CreateEntry(ctx, entry, nil, false, false, nil, false, 255); err != nil {
h.t.Errorf("write log file %s: %v", targetFile, err)
}
}
// event builds a metadata event log entry the way the filer's notification
// path does, so the loop's real decode and filter code runs.
func testEvent(tsNs int64, name string) *filer_pb.LogEntry {
data, err := proto.Marshal(&filer_pb.SubscribeMetadataResponse{
Directory: "/t",
EventNotification: &filer_pb.EventNotification{NewEntry: &filer_pb.Entry{Name: name}},
TsNs: tsNs,
})
if err != nil {
panic(err)
}
return &filer_pb.LogEntry{TsNs: tsNs, Data: data, Key: []byte("/t/" + name)}
}
func (h *subscribeHarness) append(tsNs int64) {
if err := h.f.LocalMetaLogBuffer.AddLogEntryToBuffer(testEvent(tsNs, fmt.Sprintf("f-%d", tsNs))); err != nil {
h.t.Fatalf("append: %v", err)
}
}
type runningSubscribe struct {
stream *fakeSubscribeStream
cancel context.CancelFunc
done chan error
finished chan struct{} // closed after done is populated; safe to wait repeatedly
}
func (h *subscribeHarness) subscribe(sinceNs int64, mutate func(*filer_pb.SubscribeMetadataRequest)) *runningSubscribe {
ctx, cancel := context.WithCancel(context.Background())
stream := &fakeSubscribeStream{ctx: ctx}
req := &filer_pb.SubscribeMetadataRequest{
ClientName: "loop-test",
ClientId: 7,
ClientEpoch: 1,
SinceNs: sinceNs,
}
if mutate != nil {
mutate(req)
}
r := &runningSubscribe{stream: stream, cancel: cancel, done: make(chan error, 1), finished: make(chan struct{})}
go func() {
r.done <- h.fs.SubscribeLocalMetadata(req, stream)
close(r.finished)
}()
h.t.Cleanup(func() {
cancel()
select {
case <-r.finished:
case <-time.After(5 * time.Second):
h.t.Error("subscribe loop did not exit on cancel")
}
})
return r
}
// eventTimestamps extracts delivered metadata events (markers, heartbeats and
// refs excluded).
func eventTimestamps(msgs []*filer_pb.SubscribeMetadataResponse) []int64 {
var out []int64
for _, m := range msgs {
if len(m.LogFileRefs) > 0 || m.EventNotification == nil || m.EventNotification.NewEntry == nil {
continue
}
out = append(out, m.TsNs)
}
return out
}
func waitForEvents(t *testing.T, r *runningSubscribe, want []int64, timeout time.Duration) []int64 {
t.Helper()
deadline := time.Now().Add(timeout)
var got []int64
for time.Now().Before(deadline) {
got = eventTimestamps(r.stream.snapshot())
if len(got) >= len(want) {
break
}
time.Sleep(10 * time.Millisecond)
}
if fmt.Sprint(got) != fmt.Sprint(want) {
t.Fatalf("delivered %v, want %v", got, want)
}
return got
}
func assertNoEventsFor(t *testing.T, r *runningSubscribe, d time.Duration) {
t.Helper()
time.Sleep(d)
if got := eventTimestamps(r.stream.snapshot()); len(got) > 0 {
t.Fatalf("delivered %v while the gap was unproven; these events must wait", got)
}
}
// tsAt returns test timestamps from the harness's fixed base: old enough that
// windows seal on the jump between them, entries 1ms apart within a window.
func (h *subscribeHarness) tsAt(window, i int) int64 {
return h.base + int64(window)*int64(2*time.Minute) + int64(i)*int64(time.Millisecond)
}
// ---- scenarios ----
// The headline behavior of the whole PR: events evicted from the ring before
// their flush landed must not be skipped. The subscriber parks while the gap
// is unproven and delivers everything once the stalled flush lands.
func TestSubscribeLoop_EvictedUnflushedGapWaitsThenDelivers(t *testing.T) {
h := newSubscribeHarness(t)
h.blockFlushes()
var want []int64
for w := 0; w < log_buffer.PreviousBufferCount+3; w++ {
ts := h.tsAt(w, 0)
want = append(want, ts)
h.append(ts)
}
if h.f.LocalMetaLogBuffer.GetLastEvictedTsNs() == 0 {
t.Fatal("precondition: the ring evicted nothing")
}
r := h.subscribe(0, nil)
// The evicted windows are nowhere: not in memory, not on disk. Master
// silently skipped them here; the loop must park instead.
assertNoEventsFor(t, r, 300*time.Millisecond)
h.releaseFlushes()
waitForEvents(t, r, want, 5*time.Second)
}
// A gap that never existed is proven empty and served from memory promptly -
// the guard must not park subscribers on rings that evicted nothing.
func TestSubscribeLoop_NothingEvictedServesFromMemory(t *testing.T) {
h := newSubscribeHarness(t)
h.blockFlushes() // no disk at all; memory alone must serve
want := []int64{h.tsAt(0, 0), h.tsAt(0, 1), h.tsAt(0, 2)}
for _, ts := range want {
h.append(ts)
}
r := h.subscribe(0, nil)
waitForEvents(t, r, want, 3*time.Second)
}
// Disk backlog then live tail: the handoff must deliver every event exactly
// once, in order. Timestamps are 1ms-adjacent ACROSS every boundary - window
// to window on disk, and disk to retained memory - so a cursor error of even
// one entry at any handoff shows up as a hole or a duplicate. Flushed windows
// exist on disk AND in the retained ring, which is exactly where
// inclusive/exclusive mistakes on either side used to hide.
func TestSubscribeLoop_BacklogThenLiveExactlyOnce(t *testing.T) {
h := newSubscribeHarness(t)
ts := func(i int) int64 { return h.base + int64(i)*int64(time.Millisecond) }
var want []int64
n := 0
for w := 0; w < 3; w++ {
for i := 0; i < 3; i++ {
want = append(want, ts(n))
h.append(ts(n))
n++
}
h.f.LocalMetaLogBuffer.ForceFlush() // adjacent-timestamp window boundary on disk
}
// A retained, unflushed tail starting 1ms after the flushed content ends.
for i := 0; i < 3; i++ {
want = append(want, ts(n))
h.append(ts(n))
n++
}
r := h.subscribe(0, nil)
waitForEvents(t, r, want, 5*time.Second)
// Live tail on top.
live := []int64{ts(n), ts(n + 1)}
for _, l := range live {
h.append(l)
}
waitForEvents(t, r, append(append([]int64(nil), want...), live...), 5*time.Second)
}
// A bounded subscription delivers through its bound and terminates - it must
// not park forever on the gap machinery with its window already served.
func TestSubscribeLoop_BoundedSubscriptionTerminates(t *testing.T) {
h := newSubscribeHarness(t)
all := []int64{h.tsAt(0, 0), h.tsAt(0, 1), h.tsAt(1, 0), h.tsAt(1, 1)}
for _, ts := range all {
h.append(ts)
}
h.f.LocalMetaLogBuffer.ForceFlush()
until := all[1]
r := h.subscribe(0, func(req *filer_pb.SubscribeMetadataRequest) { req.UntilNs = until })
select {
case err := <-r.done:
if err != nil {
t.Fatalf("bounded subscription failed: %v", err)
}
case <-time.After(5 * time.Second):
t.Fatal("bounded subscription did not terminate")
}
for _, ts := range eventTimestamps(r.stream.snapshot()) {
if ts > until {
t.Fatalf("delivered %d past the bound %d", ts, until)
}
}
}
// Vacuumed logs: the flush watermark proves a gap empty even though the files
// are gone - the resolver must skip to the retained ring and deliver its
// earliest window intact, including a single-entry window whose start and stop
// coincide. This is the one path where resolveGapResume itself advances the
// stream, and the resume-below-earliest arithmetic is load-bearing.
func TestSubscribeLoop_FlushProvenGapSkipsToRetained(t *testing.T) {
h := newSubscribeHarness(t)
for w := 0; w < log_buffer.PreviousBufferCount+2; w++ {
h.append(h.tsAt(w, 0))
}
waitForFlushedFiles(t, h)
if h.f.LocalMetaLogBuffer.GetLastEvictedTsNs() == 0 {
t.Fatal("precondition: nothing evicted")
}
deleteAllLogFiles(t, h)
earliest := h.f.LocalMetaLogBuffer.GetEarliestTime().UnixNano()
var retained []int64
for w := 0; w < log_buffer.PreviousBufferCount+2; w++ {
if ts := h.tsAt(w, 0); ts >= earliest {
retained = append(retained, ts)
}
}
r := h.subscribe(0, nil)
waitForEvents(t, r, retained, 5*time.Second)
}
func waitForFlushedFiles(t *testing.T, h *subscribeHarness) {
t.Helper()
deadline := time.Now().Add(3 * time.Second)
for time.Now().Before(deadline) {
if h.f.LocalMetaLogBuffer.GetLastFlushTsNs() >= h.f.LocalMetaLogBuffer.GetLastEvictedTsNs() {
return
}
time.Sleep(10 * time.Millisecond)
}
t.Fatal("flushes did not land")
}
func deleteAllLogFiles(t *testing.T, h *subscribeHarness) {
t.Helper()
ctx := context.Background()
days, _, err := h.f.ListDirectoryEntries(ctx, filer.SystemLogDir, "", true, 1000, "", "", "")
if err != nil {
t.Fatalf("list log days: %v", err)
}
store := h.f.GetStore()
for _, day := range days {
if err := store.DeleteFolderChildren(ctx, day.FullPath); err != nil {
t.Fatalf("delete %s children: %v", day.FullPath, err)
}
if err := store.DeleteEntry(ctx, day.FullPath); err != nil {
t.Fatalf("delete %s: %v", day.FullPath, err)
}
}
}
// A permanently wedged flush ends in the loud give-up skip: the loss is
// bounded to the unprovable range, counted, and the stream keeps delivering
// what memory still holds - it must not stay silent forever and must not fail.
func TestSubscribeLoop_GiveUpSkipsAndKeepsStreaming(t *testing.T) {
h := newSubscribeHarness(t)
prevStall := maxGapStall
maxGapStall = 250 * time.Millisecond
t.Cleanup(func() { maxGapStall = prevStall })
h.blockFlushes()
var retained []int64
for w := 0; w < log_buffer.PreviousBufferCount+3; w++ {
h.append(h.tsAt(w, 0))
}
// What the ring still holds after eviction is what must arrive post-skip.
earliest := h.f.LocalMetaLogBuffer.GetEarliestTime().UnixNano()
for w := 0; w < log_buffer.PreviousBufferCount+3; w++ {
if ts := h.tsAt(w, 0); ts >= earliest {
retained = append(retained, ts)
}
}
r := h.subscribe(0, nil)
waitForEvents(t, r, retained, 5*time.Second)
select {
case err := <-r.done:
t.Fatalf("stream ended (%v); the give-up must keep it alive", err)
default:
}
}
// Chunk mode, checked against the real client code: everything the marker
// claims must be applied by pb.ReadLogFileRefs over the shipped refs, and the
// inline stream must start strictly after the marker - the contract whose two
// sides drifted in round after round of review.
func TestSubscribeLoop_ChunkModeMarkerMatchesClientReplay(t *testing.T) {
h := newSubscribeHarness(t)
var want []int64
for w := 0; w < 3; w++ {
for i := 0; i < 3; i++ {
ts := h.tsAt(w, i)
want = append(want, ts)
h.append(ts)
}
}
h.f.LocalMetaLogBuffer.ForceFlush()
r := h.subscribe(0, func(req *filer_pb.SubscribeMetadataRequest) { req.ClientSupportsMetadataChunks = true })
// Wait for refs plus their transition marker.
var refs []*filer_pb.LogFileChunkRef
var markerTsNs int64
deadline := time.Now().Add(5 * time.Second)
for time.Now().Before(deadline) {
refs = refs[:0]
markerTsNs = 0
for _, m := range r.stream.snapshot() {
if len(m.LogFileRefs) > 0 {
refs = append(refs, m.LogFileRefs...)
if markerTsNs != 0 {
t.Fatal("refs arrived after their batch's marker")
}
continue
}
if m.EventNotification != nil && m.EventNotification.NewEntry == nil && m.TsNs > 0 && markerTsNs == 0 {
markerTsNs = m.TsNs
}
}
if markerTsNs != 0 {
break
}
time.Sleep(10 * time.Millisecond)
}
if markerTsNs == 0 {
t.Fatal("no transition marker followed the refs; the client would buffer them forever")
}
// Apply the refs exactly the way the real client does.
var applied []int64
clientLastTs, err := pb.ReadLogFileRefs(refs,
func(chunks []*filer_pb.FileChunk) (io.ReadCloser, error) {
return &chunkStreamReader{vol: h.vol, chunks: chunks}, nil
},
0, 0, pb.PathFilter{},
func(resp *filer_pb.SubscribeMetadataResponse) error {
applied = append(applied, resp.TsNs)
return nil
})
if err != nil {
t.Fatalf("client replay: %v", err)
}
if markerTsNs > clientLastTs {
t.Fatalf("marker %d claims more than the client applied through %d; the difference is silently lost", markerTsNs, clientLastTs)
}
if fmt.Sprint(applied) != fmt.Sprint(want) {
t.Fatalf("client applied %v, want %v", applied, want)
}
// The inline stream must not re-deliver ref-covered content.
for _, ts := range eventTimestamps(r.stream.snapshot()) {
if ts <= markerTsNs {
t.Fatalf("inline event %d at or below the marker %d duplicates the client's chunk replay", ts, markerTsNs)
}
}
// And a live tail still arrives inline, after the marker.
live := h.tsAt(4, 0)
h.append(live)
waitForEvents(t, r, []int64{live}, 5*time.Second)
}
// Chunk mode with a dead volume mid-file: the marker must stop where the
// client's read stops, the stream must keep working, and the events after the
// dead chunk's file must still arrive.
func TestSubscribeLoop_ChunkModeDeadVolumeAgreesWithClient(t *testing.T) {
h := newSubscribeHarness(t)
// Three flushed windows -> three files; kill the middle file's chunk.
var written []int64
for w := 0; w < 3; w++ {
ts := h.tsAt(w, 0)
written = append(written, ts)
h.append(ts)
}
h.f.LocalMetaLogBuffer.ForceFlush()
h.vol.kill("t,2")
r := h.subscribe(0, func(req *filer_pb.SubscribeMetadataRequest) { req.ClientSupportsMetadataChunks = true })
var refs []*filer_pb.LogFileChunkRef
var markerTsNs int64
deadline := time.Now().Add(5 * time.Second)
for time.Now().Before(deadline) {
refs = refs[:0]
markerTsNs = 0
for _, m := range r.stream.snapshot() {
if len(m.LogFileRefs) > 0 {
refs = append(refs, m.LogFileRefs...)
} else if m.EventNotification != nil && m.EventNotification.NewEntry == nil && m.TsNs > markerTsNs {
markerTsNs = m.TsNs
}
}
if markerTsNs != 0 {
break
}
time.Sleep(10 * time.Millisecond)
}
if markerTsNs == 0 {
t.Fatal("no transition marker; a dead volume must not block it")
}
var applied []int64
clientLastTs, err := pb.ReadLogFileRefs(refs,
func(chunks []*filer_pb.FileChunk) (io.ReadCloser, error) {
return &chunkStreamReader{vol: h.vol, chunks: chunks}, nil
},
0, 0, pb.PathFilter{},
func(resp *filer_pb.SubscribeMetadataResponse) error {
applied = append(applied, resp.TsNs)
return nil
})
if err != nil {
t.Fatalf("client replay: %v", err)
}
if markerTsNs > clientLastTs {
t.Fatalf("marker %d ahead of the client's %d with a dead chunk in between; the suffix is silently lost", markerTsNs, clientLastTs)
}
// The client skips the dead file but applies the later one.
sort.Slice(applied, func(i, j int) bool { return applied[i] < applied[j] })
appliedStr := fmt.Sprint(applied)
if !strings.Contains(appliedStr, fmt.Sprint(written[2])) || strings.Contains(appliedStr, fmt.Sprint(written[1])) {
t.Fatalf("client applied %v; want the dead file %d skipped and the later file %d applied", applied, written[1], written[2])
}
}
weed/stats/metrics.go
+18
View File
@@ -234,6 +234,22 @@ var (
Help: "The last send timestamp of the filer subscription.",
}, []string{"sourceFiler", "clientName", "path"})
FilerSubscribeUnprovenGapCrossings = prometheus.NewCounterVec(
prometheus.CounterOpts{
Namespace: Namespace,
Subsystem: subsystemFiler,
Name: "subscribe_unproven_gap_crossings",
Help: "Times a metadata subscriber moved past a log range without proof it was persisted: scope=aggregated means a peer may not have flushed it, scope=local means this filer's own log flush was wedged past the give-up bound.",
}, []string{"scope"})
FilerSubscribeGapStalledGauge = prometheus.NewGaugeVec(
prometheus.GaugeOpts{
Namespace: Namespace,
Subsystem: subsystemFiler,
Name: "subscribe_gap_stalled",
Help: "Number of metadata subscribers currently parked waiting to read past a gap in the metadata log.",
}, []string{"scope"})
// Sampled only on first creation, so counts track distinct objects.
FilerObjectSizeBytesHistogram = prometheus.NewHistogram(
prometheus.HistogramOpts{
@@ -881,6 +897,8 @@ func init() {
Gather.MustRegister(FilerStoreHistogram)
Gather.MustRegister(FilerSyncOffsetGauge)
Gather.MustRegister(FilerServerLastSendTsOfSubscribeGauge)
Gather.MustRegister(FilerSubscribeGapStalledGauge)
Gather.MustRegister(FilerSubscribeUnprovenGapCrossings)
Gather.MustRegister(FilerObjectSizeBytesHistogram)
Gather.MustRegister(collectors.NewGoCollector())
Gather.MustRegister(collectors.NewProcessCollector(collectors.ProcessCollectorOpts{}))
weed/util/log_buffer/log_buffer.go
+139 -29
View File
@@ -19,6 +19,14 @@ import (
const BufferSize = 8 * 1024 * 1024
const PreviousBufferCount = 4
// EvictionGatedOffset is a sentinel cursor offset (-2..-6 are taken by other
// sentinels) that reads like the plain -2 sentinel except below the eviction
// watermark: there ReadFromBuffer refuses with ResumeFromDiskError instead of
// silently serving from the earliest retained window. The check runs under the
// read lock, atomically with the serve decision, which callers cannot do from
// outside - an eviction can land between any caller-side check and the read.
const EvictionGatedOffset = -7
// flushQueueDepth bounds queued flush copies (BufferSize each); a full queue
// blocks producers, so a stalled flush backpressures writers instead of
// pinning hundreds of buffer copies.
@@ -156,13 +164,18 @@ type LogBuffer struct {
LastTsNs atomic.Int64
lastFlushTsNs atomic.Int64
lastFlushedOffset atomic.Int64 // Highest offset that has been flushed to disk (-1 = nothing flushed yet)
offset int64
bufferStartOffset int64
minOffset int64
maxOffset int64
flushInterval time.Duration
startTime time.Time
stopTime time.Time
lastEvictedTsNs atomic.Int64 // Latest stopTime evicted from the sealed ring (0 = nothing evicted yet)
// lastEvictedTsNs in pre-bump timestamps: gap proofs compare disk cursors,
// which never see the bumped values out-of-order arrivals get.
lastEvictedOriginalTsNs atomic.Int64
curWindowMaxOriginalTsNs int64 // max pre-bump ts in the open window, under the write lock
offset int64
bufferStartOffset int64
minOffset int64
maxOffset int64
flushInterval time.Duration
startTime time.Time
stopTime time.Time
// Other fields
name string
@@ -177,12 +190,14 @@ type LogBuffer struct {
// Per-subscriber notification channels for instant wake-up
subscribersMu sync.RWMutex
subscribers map[string]chan struct{} // subscriberID -> notification channel
isStopping *atomic.Bool
shutdownCh chan struct{} // closed by ShutdownLogBuffer to wake blocked subscribers
isAllFlushed bool
flushChan chan *dataToFlush
flushBudget *flushBudget
flushSeq uint64 // seal counter, assigned under the write lock
// Notified only when a flush lands, for readers that cannot act on an append
flushSubscribers map[string]chan struct{}
isStopping *atomic.Bool
shutdownCh chan struct{} // closed by ShutdownLogBuffer to wake blocked subscribers
isAllFlushed bool
flushChan chan *dataToFlush
flushBudget *flushBudget
flushSeq uint64 // seal counter, assigned under the write lock
// Offset range tracking for Kafka integration
hasOffsets bool
// Disk chunk cache for historical data reads
@@ -199,20 +214,21 @@ type LogBuffer struct {
func NewLogBuffer(name string, flushInterval time.Duration, flushFn LogFlushFuncType,
readFromDiskFn LogReadFromDiskFuncType, notifyFn func()) *LogBuffer {
lb := &LogBuffer{
name: name,
prevBuffers: newSealedBuffers(PreviousBufferCount),
buf: make([]byte, BufferSize),
sizeBuf: make([]byte, 4),
flushInterval: flushInterval,
flushFn: flushFn,
ReadFromDiskFn: readFromDiskFn,
notifyFn: notifyFn,
subscribers: make(map[string]chan struct{}),
flushChan: make(chan *dataToFlush, flushQueueDepth),
flushBudget: newFlushBudget(flushQueueBudget),
isStopping: new(atomic.Bool),
shutdownCh: make(chan struct{}),
offset: 0, // Will be initialized from existing data if available
name: name,
prevBuffers: newSealedBuffers(PreviousBufferCount),
buf: make([]byte, BufferSize),
sizeBuf: make([]byte, 4),
flushInterval: flushInterval,
flushFn: flushFn,
ReadFromDiskFn: readFromDiskFn,
notifyFn: notifyFn,
subscribers: make(map[string]chan struct{}),
flushSubscribers: make(map[string]chan struct{}),
flushChan: make(chan *dataToFlush, flushQueueDepth),
isStopping: new(atomic.Bool),
shutdownCh: make(chan struct{}),
offset: 0, // Will be initialized from existing data if available
flushBudget: newFlushBudget(flushQueueBudget),
diskChunkCache: &DiskChunkCache{
chunks: make(map[int64]*CachedDiskChunk),
maxChunks: 16, // Cache up to 16 chunks (configurable)
@@ -252,6 +268,34 @@ func (logBuffer *LogBuffer) UnregisterSubscriber(subscriberID string) {
}
}
// RegisterFlushSubscriber registers a subscriber woken only when a flush lands.
// A reader waiting for data it can only get from disk has nothing to do with an
// append, and taking those wake-ups off the shared channel would cost it one
// scheduling round-trip per write - and keep that channel drained, so every
// writer's non-blocking send succeeds instead of falling through.
func (logBuffer *LogBuffer) RegisterFlushSubscriber(subscriberID string) chan struct{} {
logBuffer.subscribersMu.Lock()
defer logBuffer.subscribersMu.Unlock()
if existingChan, exists := logBuffer.flushSubscribers[subscriberID]; exists {
return existingChan
}
notifyChan := make(chan struct{}, 1)
logBuffer.flushSubscribers[subscriberID] = notifyChan
return notifyChan
}
// UnregisterFlushSubscriber removes a flush subscriber and closes its channel
func (logBuffer *LogBuffer) UnregisterFlushSubscriber(subscriberID string) {
logBuffer.subscribersMu.Lock()
defer logBuffer.subscribersMu.Unlock()
if ch, exists := logBuffer.flushSubscribers[subscriberID]; exists {
close(ch)
delete(logBuffer.flushSubscribers, subscriberID)
}
}
// IsOffsetInMemory checks if the given offset is available in the in-memory buffer
// Returns true if:
// 1. Offset is newer than what's been flushed to disk (must be in memory)
@@ -322,6 +366,19 @@ func (logBuffer *LogBuffer) notifySubscribers() {
}
}
// notifyFlushSubscribers wakes the readers that only care about a flush landing
func (logBuffer *LogBuffer) notifyFlushSubscribers() {
logBuffer.subscribersMu.RLock()
defer logBuffer.subscribersMu.RUnlock()
for _, notifyChan := range logBuffer.flushSubscribers {
select {
case notifyChan <- struct{}{}:
default:
}
}
}
// InitializeOffsetFromExistingData initializes the offset counter from existing data on disk
// This should be called after LogBuffer creation to ensure offset continuity on restart
func (logBuffer *LogBuffer) InitializeOffsetFromExistingData(getHighestOffsetFn func() (int64, error)) error {
@@ -384,6 +441,7 @@ func (logBuffer *LogBuffer) AddLogEntryToBuffer(logEntry *filer_pb.LogEntry) err
processingTsNs := logEntry.TsNs
ts := time.Unix(0, processingTsNs)
originalTsNs := processingTsNs
// Handle timestamp collision inside lock (rare case)
if logBuffer.LastTsNs.Load() >= processingTsNs {
@@ -454,6 +512,13 @@ func (logBuffer *LogBuffer) AddLogEntryToBuffer(logEntry *filer_pb.LogEntry) err
util.Uint32toBytes(logBuffer.sizeBuf, uint32(size))
copy(logBuffer.buf[logBuffer.pos:logBuffer.pos+4], logBuffer.sizeBuf)
logBuffer.pos += size + 4
// Only now is the entry's window known: a rollover above seals the previous
// window first, and crediting this timestamp before that hands it to the
// sealed window and loses it from the new one - corrupting the received-ts
// eviction watermark in both directions.
if originalTsNs > logBuffer.curWindowMaxOriginalTsNs {
logBuffer.curWindowMaxOriginalTsNs = originalTsNs
}
logBuffer.offset++
return nil
@@ -501,6 +566,7 @@ func (logBuffer *LogBuffer) AddDataToBuffer(partitionKey, data []byte, processin
}
}()
originalTsNs := processingTsNs
// Handle timestamp collision inside lock (rare case)
if logBuffer.LastTsNs.Load() >= processingTsNs {
processingTsNs = logBuffer.LastTsNs.Add(1)
@@ -572,6 +638,13 @@ func (logBuffer *LogBuffer) AddDataToBuffer(partitionKey, data []byte, processin
util.Uint32toBytes(logBuffer.sizeBuf, uint32(size))
copy(logBuffer.buf[logBuffer.pos:logBuffer.pos+4], logBuffer.sizeBuf)
logBuffer.pos += size + 4
// Only now is the entry's window known: a rollover above seals the previous
// window first, and crediting this timestamp before that hands it to the
// sealed window and loses it from the new one - corrupting the received-ts
// eviction watermark in both directions.
if originalTsNs > logBuffer.curWindowMaxOriginalTsNs {
logBuffer.curWindowMaxOriginalTsNs = originalTsNs
}
logBuffer.offset++
return nil
@@ -683,10 +756,17 @@ func (logBuffer *LogBuffer) loopFlush() {
}
// Wake readers that may be waiting to retry disk reads after the flush lands.
// LOAD-BEARING ORDER: the watermark store above must precede these
// notifications. A parked filer subscriber re-checks GetLastFlushTsNs on
// wake-up and goes back to sleep if it has not moved; notifying first
// opens a window where the wake-up looks spurious and the flush that
// caused it is only picked up by the retry timer. Not testable from
// outside (the window is nanoseconds on this goroutine) - keep the order.
if logBuffer.notifyFn != nil {
logBuffer.notifyFn()
}
logBuffer.notifySubscribers()
logBuffer.notifyFlushSubscribers()
// Signal completion if there's a callback channel
if d.done != nil {
@@ -744,7 +824,19 @@ func (logBuffer *LogBuffer) copyToFlushInternal(withCallback bool) *dataToFlush
}
// CRITICAL: logBuffer.offset is the "next offset to assign", so last offset in buffer is offset-1
lastOffsetInBuffer := logBuffer.offset - 1
// Slot 0 falls out of the ring in SealBuffer below, so record how far
// eviction has reached before it goes - in both timestamp spaces.
if evicted := logBuffer.prevBuffers.buffers[0]; evicted.size > 0 && !evicted.stopTime.IsZero() {
if ts := evicted.stopTime.UnixNano(); ts > logBuffer.lastEvictedTsNs.Load() {
logBuffer.lastEvictedTsNs.Store(ts)
}
if ts := evicted.maxOriginalTsNs; ts > logBuffer.lastEvictedOriginalTsNs.Load() {
logBuffer.lastEvictedOriginalTsNs.Store(ts)
}
}
logBuffer.buf = logBuffer.prevBuffers.SealBuffer(logBuffer.startTime, logBuffer.stopTime, logBuffer.buf, logBuffer.pos, logBuffer.bufferStartOffset, lastOffsetInBuffer)
logBuffer.prevBuffers.buffers[len(logBuffer.prevBuffers.buffers)-1].maxOriginalTsNs = logBuffer.curWindowMaxOriginalTsNs
logBuffer.curWindowMaxOriginalTsNs = 0
// SealBuffer hands back the oldest window array to reuse. An entry larger
// than BufferSize grew one of these arrays to fit it, and buffers cycle
// forever, so without this a single oversized entry leaves every later
@@ -800,8 +892,7 @@ func (logBuffer *LogBuffer) invalidateAllDiskCacheChunks() {
// because ReadFromBuffer's tsMemory (and therefore ResumeFromDiskError) is
// computed from the min across both. Returning only the active startTime
// would cause gap-detection callers to skip past data still living in prev
// buffers, and can also silently equal the consumer's lastReadTime and
// stall on listenersCond.Wait().
// buffers, and can also silently equal the consumer's lastReadTime.
func (logBuffer *LogBuffer) GetEarliestTime() time.Time {
logBuffer.RLock()
defer logBuffer.RUnlock()
@@ -846,6 +937,20 @@ func (logBuffer *LogBuffer) GetLastFlushTsNs() int64 {
return logBuffer.lastFlushTsNs.Load()
}
// GetLastEvictedOriginalTsNs is GetLastEvictedTsNs in pre-bump timestamps -
// the space disk cursors live in.
func (logBuffer *LogBuffer) GetLastEvictedOriginalTsNs() int64 {
return logBuffer.lastEvictedOriginalTsNs.Load()
}
// GetLastEvictedTsNs returns the stopTime of the newest window dropped from the
// sealed ring, or 0 if nothing has been evicted. A reader positioned past it
// knows the retained buffers still hold every entry after its position, which is
// the only emptiness proof available to a buffer that never flushes.
func (logBuffer *LogBuffer) GetLastEvictedTsNs() int64 {
return logBuffer.lastEvictedTsNs.Load()
}
func (logBuffer *LogBuffer) SetLastFlushTsNs(ts int64) {
logBuffer.lastFlushTsNs.Store(ts)
}
@@ -966,6 +1071,11 @@ func (logBuffer *LogBuffer) ReadFromBuffer(lastReadPosition MessagePosition) (bu
// For time-based reads, only check timestamp for disk reads
// Don't use offset comparisons as they're not meaningful for time-based subscriptions
// A gated cursor below the eviction watermark must go to disk: serving it
// from the earliest retained window would silently skip the evicted span.
if lastReadPosition.Offset == EvictionGatedOffset && lastReadPosition.Time.UnixNano() < logBuffer.lastEvictedTsNs.Load() {
return nil, -2, false, ResumeFromDiskError
}
// Special case: If requested time is zero (Unix epoch), treat as "start from beginning"
// This handles queries that want to read all data without knowing the exact start time
if lastReadPosition.Time.IsZero() || lastReadPosition.Time.Unix() == 0 {
weed/util/log_buffer/log_buffer_eviction_gate_test.go
+350
View File
@@ -0,0 +1,350 @@
package log_buffer
import (
"testing"
"time"
"github.com/seaweedfs/seaweedfs/weed/pb/filer_pb"
)
// TestEvictionWatermarkTracksSealedRing drives the watermark through the real
// eviction path instead of writing the field: only copyToFlushInternal sees the
// window about to be dropped, and it reads it one statement before SealBuffer
// shifts it out of slot 0. The buffer here never flushes, matching the
// aggregated meta ring, so the watermark is its only emptiness proof.
func TestEvictionWatermarkTracksSealedRing(t *testing.T) {
lb := NewLogBuffer("evict-watermark", time.Minute, nil, nil, nil)
defer lb.ShutdownLogBuffer()
// Each timestamp is further past the previous window's start than the flush
// interval, so every append seals the window before it.
base := time.Now().Add(-30 * time.Minute).Truncate(time.Second)
step := 2 * time.Minute
at := func(i int) time.Time { return base.Add(time.Duration(i) * step) }
if got := lb.GetLastEvictedTsNs(); got != 0 {
t.Fatalf("fresh buffer evicted through %v, want 0", time.Unix(0, got))
}
// PreviousBufferCount seals only fill the ring; the next one drops window 0.
for i := 0; i <= PreviousBufferCount; i++ {
if err := lb.AddLogEntryToBuffer(&filer_pb.LogEntry{TsNs: at(i).UnixNano(), Data: []byte("x"), Key: []byte("k")}); err != nil {
t.Fatalf("add %d: %v", i, err)
}
if got := lb.GetLastEvictedTsNs(); got != 0 {
t.Fatalf("after %d appends evicted through %v, want nothing evicted yet", i+1, time.Unix(0, got))
}
}
if err := lb.AddLogEntryToBuffer(&filer_pb.LogEntry{TsNs: at(PreviousBufferCount + 1).UnixNano(), Data: []byte("x"), Key: []byte("k")}); err != nil {
t.Fatalf("add evicting entry: %v", err)
}
// Window 0 held only the first entry, so its stopTime is that entry's ts.
if got, want := lb.GetLastEvictedTsNs(), at(0).UnixNano(); got != want {
t.Fatalf("evicted through %v, want the dropped window's stop %v", time.Unix(0, got), time.Unix(0, want))
}
// One more eviction advances the watermark; it never regresses.
if err := lb.AddLogEntryToBuffer(&filer_pb.LogEntry{TsNs: at(PreviousBufferCount + 2).UnixNano(), Data: []byte("x"), Key: []byte("k")}); err != nil {
t.Fatalf("add second evicting entry: %v", err)
}
if got, want := lb.GetLastEvictedTsNs(), at(1).UnixNano(); got != want {
t.Fatalf("evicted through %v, want %v", time.Unix(0, got), time.Unix(0, want))
}
}
// TestGapResumeCursorReadsSingleEntrySealedWindow pins the resume cursor
// against the shape that actually breaks: a sealed window holding one entry,
// where startTime == stopTime. The sealed-buffer lookup only enters a window
// whose stopTime is strictly after the cursor, so a cursor sitting exactly on
// earliest walks straight past such a window and its sole event is never
// delivered. Low-volume metadata windows are routinely one entry.
func TestGapResumeCursorReadsSingleEntrySealedWindow(t *testing.T) {
lb := NewLogBuffer("gap-resume-sealed", time.Minute, nil, nil, nil)
defer lb.ShutdownLogBuffer()
// Timestamps far enough apart that every append seals the window before it,
// so each sealed window holds exactly one entry.
base := time.Now().Add(-time.Hour).Truncate(time.Second)
for i := 0; i < 3; i++ {
if err := lb.AddLogEntryToBuffer(&filer_pb.LogEntry{
TsNs: base.Add(time.Duration(i) * 2 * time.Minute).UnixNano(), Data: []byte("x"), Key: []byte("k"),
}); err != nil {
t.Fatalf("add %d: %v", i, err)
}
}
earliest := lb.GetEarliestTime()
if earliest.IsZero() {
t.Fatal("expected in-memory data")
}
// firstTsFrom reports the timestamp of the first entry a read hands back.
firstTsFrom := func(cursorTsNs int64) int64 {
buf, _, pooled, err := lb.ReadFromBuffer(NewMessagePosition(cursorTsNs, gapResumeTestOffset))
if err != nil {
t.Fatalf("read at %v: %v", time.Unix(0, cursorTsNs), err)
}
if buf == nil {
t.Fatalf("read at %v returned no data", time.Unix(0, cursorTsNs))
}
if pooled {
defer lb.ReleaseMemory(buf)
}
_, ts, readErr := readTs(buf.Bytes(), 0)
if readErr != nil {
t.Fatalf("decode first entry: %v", readErr)
}
return ts
}
// The resume the resolvers issue must deliver the earliest entry itself.
if got := firstTsFrom(earliest.UnixNano() - 1); got != earliest.UnixNano() {
t.Fatalf("resume just below earliest starts at %v, want the earliest entry %v",
time.Unix(0, got), earliest)
}
// Resuming exactly on earliest is the shape that loses it.
if got := firstTsFrom(earliest.UnixNano()); got == earliest.UnixNano() {
t.Fatal("expected a cursor exactly on earliest to skip the single-entry window (precondition)")
}
}
// gapResumeTestOffset mirrors the sentinel the filer's gap resume carries.
const gapResumeTestOffset = -2
// TestGapResumeCursorReadsFromMemory pins the contract the filer's gap resolver
// depends on: the cursor it resumes with must be one this read actually serves.
// ReadFromBuffer only falls through to memory for a cursor below the in-memory
// window when the offset is a sentinel, and answers ResumeFromDiskError for
// every positive one -- a resume carrying a positive offset would bounce
// straight back to the resolver, which sees no progress and parks a subscriber
// whose data is sitting in the ring.
func TestGapResumeCursorReadsFromMemory(t *testing.T) {
lb := NewLogBuffer("gap-resume", time.Minute, nil, nil, nil)
defer lb.ShutdownLogBuffer()
base := time.Now().Add(-time.Hour).Truncate(time.Second)
for i := 0; i < 3; i++ {
if err := lb.AddLogEntryToBuffer(&filer_pb.LogEntry{
TsNs: base.Add(time.Duration(i) * time.Second).UnixNano(), Data: []byte("x"), Key: []byte("k"),
}); err != nil {
t.Fatalf("add %d: %v", i, err)
}
}
earliest := lb.GetEarliestTime()
if earliest.IsZero() {
t.Fatal("expected in-memory data")
}
// The resolver resumes at earliest itself, read inclusively.
if buf, _, _, err := lb.ReadFromBuffer(NewMessagePosition(earliest.UnixNano(), -2)); err != nil || buf == nil {
t.Fatalf("resume at earliest: buf=%v err=%v", buf != nil, err)
}
// A sentinel just below it is served too, so the exact boundary is not load-bearing.
if buf, _, _, err := lb.ReadFromBuffer(NewMessagePosition(earliest.UnixNano()-1, -2)); err != nil || buf == nil {
t.Fatalf("resume just below earliest: buf=%v err=%v", buf != nil, err)
}
// A positive offset below the window is refused: this is the shape a gap
// resume must never take.
if _, _, _, err := lb.ReadFromBuffer(NewMessagePosition(earliest.UnixNano()-1, 1)); err != ResumeFromDiskError {
t.Fatalf("positive-offset cursor below the window: want ResumeFromDiskError, got %v", err)
}
}
// TestFlushSubscriberContract pins what the filer's gap parks rest on: a flush
// subscriber is woken when a flush lands and the flush watermark is already
// visible at that moment - loopFlush stores lastFlushTsNs before notifying, so
// a waiter that re-checks the watermark on wake-up cannot miss the flush that
// woke it. Appends alone never signal this channel, and unregistering closes
// it so an abandoned waiter is not stranded.
func TestFlushSubscriberContract(t *testing.T) {
flushed := make(chan struct{}, 16)
// A flush interval far longer than the test, so appends never auto-seal a
// window and ForceFlush is the only source of flushes: each round then has
// exactly one flush, and the token received is known to belong to it.
lb := NewLogBuffer("flush-sub", time.Hour,
func(logBuffer *LogBuffer, startTime, stopTime time.Time, buf []byte, minOffset, maxOffset int64) {
flushed <- struct{}{}
}, nil, nil)
defer lb.ShutdownLogBuffer()
ch := lb.RegisterFlushSubscriber("s")
// An append is not a flush: nothing may arrive on the channel. The probe
// sits just below the first round timestamp: below, so no round entry gets
// collision-bumped and its stored stopTime stays comparable to the local
// value each round asserts against; just below, because a gap wider than
// the flush interval would make round 0's own append auto-seal the probe
// window - a second flush whose token throws every round off by one.
if err := lb.AddLogEntryToBuffer(&filer_pb.LogEntry{TsNs: time.Now().Add(-time.Hour - time.Millisecond).UnixNano(), Data: []byte("x"), Key: []byte("k")}); err != nil {
t.Fatalf("add: %v", err)
}
select {
case <-ch:
t.Fatal("an append must not wake a flush subscriber")
case <-time.After(100 * time.Millisecond):
}
// A flush wakes it with the watermark already stored - the contract the gap
// parks re-check on. The store-before-notify ordering itself is pinned by a
// load-bearing comment at the loopFlush site (a reorder's window is
// nanoseconds on that goroutine, untestable from here); these round-trips
// verify the observable contract and catch a notify with no store at all.
base := time.Now().Add(-time.Hour)
for i := 0; i < 8; i++ {
ts := base.Add(time.Duration(i) * time.Millisecond).UnixNano()
// The round entry must be above the buffer head: a bumped timestamp
// flushes a stopTime far above the local ts compared below, making the
// round's assertion vacuously true.
if last := lb.LastTsNs.Load(); last >= ts {
t.Fatalf("round %d: ts not above buffer head; the assertion would be vacuous", i)
}
if err := lb.AddLogEntryToBuffer(&filer_pb.LogEntry{TsNs: ts, Data: []byte("x"), Key: []byte("k")}); err != nil {
t.Fatalf("add round %d: %v", i, err)
}
go lb.ForceFlush()
select {
case <-ch:
if got := lb.GetLastFlushTsNs(); got < ts {
t.Fatalf("round %d: woken with watermark %v short of the flushed entry %v; a waiter re-checking it on wake-up misses the flush that woke it",
i, time.Unix(0, got), time.Unix(0, ts))
}
case <-time.After(5 * time.Second):
t.Fatalf("round %d: a flush must wake the flush subscriber", i)
}
select {
case <-flushed:
case <-time.After(5 * time.Second):
t.Fatalf("round %d: flushFn did not run", i)
}
}
// Unregistering closes the channel so an abandoned waiter unblocks.
lb.UnregisterFlushSubscriber("s")
select {
case _, ok := <-ch:
if ok {
t.Fatal("unregister must close the channel, not send on it")
}
case <-time.After(time.Second):
t.Fatal("unregister must close the channel")
}
// Unknown ids and double unregisters are harmless.
lb.UnregisterFlushSubscriber("s")
lb.UnregisterFlushSubscriber("never-registered")
}
// TestEvictionGatedCursor pins the gated sentinel: below the eviction watermark
// it is refused to disk under the read's own lock - the only place the check is
// atomic with the serve decision - while the plain -2 sentinel keeps master's
// serve-from-earliest behavior for the message queue's readers.
func TestEvictionGatedCursor(t *testing.T) {
lb := NewLogBuffer("gated-cursor", time.Minute, nil, nil, nil)
defer lb.ShutdownLogBuffer()
// Entries far enough apart that every append seals the window before it;
// wrapping the ring moves the watermark for real.
base := time.Now().Add(-time.Hour).Truncate(time.Second)
for i := 0; i < PreviousBufferCount+2; i++ {
if err := lb.AddLogEntryToBuffer(&filer_pb.LogEntry{
TsNs: base.Add(time.Duration(i) * 2 * time.Minute).UnixNano(), Data: []byte("x"), Key: []byte("k"),
}); err != nil {
t.Fatalf("add %d: %v", i, err)
}
}
evicted := lb.GetLastEvictedTsNs()
if evicted == 0 {
t.Fatal("precondition: the ring evicted nothing")
}
// Below the watermark: gated goes to disk, -2 keeps serving (MQ contract).
if _, _, _, err := lb.ReadFromBuffer(NewMessagePosition(evicted-1, EvictionGatedOffset)); err != ResumeFromDiskError {
t.Fatalf("gated below watermark: want ResumeFromDiskError, got %v", err)
}
if buf, _, _, err := lb.ReadFromBuffer(NewMessagePosition(evicted-1, -2)); err != nil || buf == nil {
t.Fatalf("plain sentinel below watermark: buf=%v err=%v, master behavior must hold", buf != nil, err)
}
// At and above the watermark the gated cursor serves normally.
if buf, _, _, err := lb.ReadFromBuffer(NewMessagePosition(evicted, EvictionGatedOffset)); err != nil || buf == nil {
t.Fatalf("gated at watermark: buf=%v err=%v", buf != nil, err)
}
if buf, _, _, err := lb.ReadFromBuffer(NewMessagePosition(evicted+1, EvictionGatedOffset)); err != nil || buf == nil {
t.Fatalf("gated above watermark: buf=%v err=%v", buf != nil, err)
}
}
// TestEvictionOriginalWatermark pins the second timestamp space. The ring bumps
// an out-of-order arrival past its head, so a bump-heavy interval (peer history
// replay) leaves stopTimes above anything on any peer's disk; a gap gate
// comparing disk cursors against those would park a subscriber that drained
// every peer's log. The original watermark tracks what was actually received.
func TestEvictionOriginalWatermark(t *testing.T) {
lb := NewLogBuffer("orig-watermark", time.Minute, nil, nil, nil)
defer lb.ShutdownLogBuffer()
// Newest original first: it sets the ring head, so every later arrival is
// bumped. Seals go by bumped time, which advances by nanoseconds, so each
// window is sealed explicitly; wrapping the ring evicts.
newest := time.Now().Add(-time.Hour).Truncate(time.Second).UnixNano()
for i := 0; i < PreviousBufferCount+2; i++ {
orig := newest - int64(i)*int64(time.Minute)
if err := lb.AddLogEntryToBuffer(&filer_pb.LogEntry{TsNs: orig, Data: []byte("x"), Key: []byte("k")}); err != nil {
t.Fatalf("add %d: %v", i, err)
}
lb.ForceFlush()
}
bumped := lb.GetLastEvictedTsNs()
original := lb.GetLastEvictedOriginalTsNs()
if bumped == 0 || original == 0 {
t.Fatalf("precondition: nothing evicted (bumped=%d original=%d)", bumped, original)
}
if original > newest {
t.Fatalf("original watermark %v exceeds the highest received timestamp %v", time.Unix(0, original), time.Unix(0, newest))
}
if bumped <= newest {
t.Fatalf("bumped watermark %v not past the ring head %v: the spaces did not diverge", time.Unix(0, bumped), time.Unix(0, newest))
}
// The punchline: a disk cursor that drained every peer's log sits at the
// highest received timestamp - clearing the original watermark while still
// below the bumped one, which no disk timestamp can ever reach.
diskHead := newest
if diskHead < original {
t.Fatalf("disk head %v short of the original watermark %v", time.Unix(0, diskHead), time.Unix(0, original))
}
if diskHead >= bumped {
t.Fatal("disk head reached the bumped watermark; the gate would not have parked and this test proves nothing")
}
}
// TestOriginalWatermarkWindowAttribution pins which window an entry's received
// timestamp is credited to. An append that rolls the window over seals the
// previous one first; crediting the incoming timestamp before that hands it to
// the sealed window (inflating its watermark: spurious parks) and loses it
// from the new one (deflating: gaps proven empty that are not).
func TestOriginalWatermarkWindowAttribution(t *testing.T) {
lb := NewLogBuffer("orig-attribution", time.Minute, nil, nil, nil)
defer lb.ShutdownLogBuffer()
base := time.Now().Add(-time.Hour).Truncate(time.Second)
t1 := base.UnixNano()
t2 := base.Add(2 * time.Minute).UnixNano() // past the flush interval: seals window A
if err := lb.AddLogEntryToBuffer(&filer_pb.LogEntry{TsNs: t1, Data: []byte("x"), Key: []byte("k")}); err != nil {
t.Fatalf("add t1: %v", err)
}
if err := lb.AddLogEntryToBuffer(&filer_pb.LogEntry{TsNs: t2, Data: []byte("x"), Key: []byte("k")}); err != nil {
t.Fatalf("add t2: %v", err)
}
sealed := lb.prevBuffers.buffers[len(lb.prevBuffers.buffers)-1]
if sealed.size == 0 {
t.Fatal("precondition: the second append did not seal the first window")
}
if got := sealed.maxOriginalTsNs; got != t1 {
t.Fatalf("sealed window credited with %v, want its own entry %v (t2 belongs to the open window)", time.Unix(0, got), time.Unix(0, t1))
}
if got := lb.curWindowMaxOriginalTsNs; got != t2 {
t.Fatalf("open window holds %v, want the entry that rolled it over %v", time.Unix(0, got), time.Unix(0, t2))
}
}
weed/util/log_buffer/sealed_buffer.go
+4
View File
@@ -13,6 +13,8 @@ type MemBuffer struct {
stopTime time.Time
startOffset int64 // First offset in this buffer
offset int64 // Last offset in this buffer (endOffset)
// max pre-bump entry timestamp; stamped by the sealer after SealBuffer
maxOriginalTsNs int64
// snapshot is a GC-owned copy of buf[:size] shared by all readers of this
// sealed window, so N subscribers reading the same window cost one copy
@@ -62,6 +64,7 @@ func (sbs *SealedBuffers) SealBuffer(startTime, stopTime time.Time, buf []byte,
sbs.buffers[i].startOffset = sbs.buffers[i+1].startOffset
sbs.buffers[i].offset = sbs.buffers[i+1].offset
sbs.buffers[i].snapshot = sbs.buffers[i+1].snapshot // snapshot follows its window
sbs.buffers[i].maxOriginalTsNs = sbs.buffers[i+1].maxOriginalTsNs
}
sbs.buffers[size-1].buf = buf
sbs.buffers[size-1].size = pos
@@ -70,6 +73,7 @@ func (sbs *SealedBuffers) SealBuffer(startTime, stopTime time.Time, buf []byte,
sbs.buffers[size-1].startOffset = startOffset
sbs.buffers[size-1].offset = endOffset
sbs.buffers[size-1].snapshot = nil
sbs.buffers[size-1].maxOriginalTsNs = 0
return oldBuf
}