Files
seaweedfs/weed/server/filer_grpc_server_sub_meta.go
T
Chris LuandDevin 14fdd61aea filer: stop the aggregated metadata subscribe loop rescanning an exhausted persisted log (#11644)
* fix(filer): gate the aggregated metadata disk pass on real change

A subscriber whose start position is past the end of the local persisted
log re-ran the whole persisted-log pass - store listings, file opens,
readahead - on every loop iteration. Each iteration is paced only by the
shortest wake (the 20ms hold floor on a busy watermark), so one parked
subscriber kept a full CPU core busy for the life of the stream.

The aggregated loop now mirrors the local loop's gate: the disk pass
runs on the first pass and afterwards only when something it cannot
miss changed - a local flush landed, the peers' flush low-watermark
advanced (more content admitted, or new files in a shared store), the
cursor moved, or a disk hold is pending (the ring read that follows an
empty pass parks internally, so skipping there would strand a held
entry).

Regression test: a subscriber parked past the persisted-log tail holds
the listing rate near zero and still delivers once peers report
progress.

Generated with [Devin](https://devin.ai)

Co-Authored-By: Devin <158243242+devin-ai-integration[bot]@users.noreply.github.com>

* filer: re-arm the aggregated disk pass on unobserved change

Review found three staleness classes the gate could not see: the flush
low-watermark only catching rises (a joining peer lowers the minimum and
invalidates an earlier pass's proof), a peer past the minimum landing a
file without moving it, and a chunk subscriber's refs-stop bound
advancing with wall time. Re-read when the low-watermark moves in either
direction, when the chunk listing bound admits more files, and on a slow
re-probe cadence for files no watermark can signal.

Generated with [Devin](https://devin.ai)

Co-Authored-By: Devin <158243242+devin-ai-integration[bot]@users.noreply.github.com>

* filer: unwind the parked ring read so the disk re-probe runs, and re-read on cursor rewinds

A caught-up subscriber parks inside LoopProcessLogData's wait loop, so
the re-probe interval in the outer disk gate could never elapse there;
the callback now unwinds the read once the cadence is due so the gate
re-evaluates. The cursor trigger also needs to notice rewinds, not just
advances, since ResumeFromDiskError moves the cursor backward.

---------

Co-authored-by: Devin <158243242+devin-ai-integration[bot]@users.noreply.github.com>
2026-10-08 22:03:31 +08:00

1646 lines
67 KiB
Go

package weed_server
import (
"context"
"errors"
"fmt"
"strings"
"time"
"github.com/prometheus/client_golang/prometheus"
"github.com/seaweedfs/seaweedfs/weed/stats"
"google.golang.org/protobuf/proto"
"github.com/seaweedfs/seaweedfs/weed/filer"
"github.com/seaweedfs/seaweedfs/weed/glog"
"github.com/seaweedfs/seaweedfs/weed/pb/filer_pb"
"github.com/seaweedfs/seaweedfs/weed/util"
"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
// aggDiskReprobeInterval paces the aggregated persisted-log re-listing for
// files no watermark signals: a peer past the flush low-watermark can land
// a file without moving the minimum.
aggDiskReprobeInterval = 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
// metadataGapSettledHorizon is the liveness escape for the peer-watermark
// holds: a watermark stalled further than this stops holding reads back.
// Twice the flush interval so a healthy peer's flush always lands within.
metadataGapSettledHorizon = 2 * filer.LogFlushInterval
)
// errAggregationUpgrade ends a delegated local stream when remote peers
// appear, so the client reconnects to the aggregated stream. It is an
// error, not a clean end: RetryUntil-driven followers treat a clean end as
// "following finished" and stop reconnecting. It wraps StopReadingError so
// LoopProcessLogData does not log it.
var errAggregationUpgrade = fmt.Errorf("remote filer peers discovered after subscription started; reconnect for aggregated metadata: %w", log_buffer.StopReadingError)
const (
// MaxUnsyncedEvents send empty notification with timestamp when certain amount of events have been filtered
MaxUnsyncedEvents = 1e3
// idleHeartbeatInterval bounds how often a caught-up subscriber that asked
// for idle heartbeats is reminded that the source is alive and has nothing
// newer. It keeps freshness signals such as filer.sync's sync_offset metric
// from looking stuck during read-only periods on the source.
idleHeartbeatInterval = 5 * time.Second
// peerDeliveryClaimInterval paces that heartbeat on the local stream of a
// filer with peers, where it is not a keepalive but a delivery claim: the
// peer aggregator turns it into its delivery low-watermark, and every
// aggregated subscriber in the cluster holds at the minimum across peers.
// So this, not idleHeartbeatInterval, is how far behind live writes a
// quiet filer leaves them. Rounded up to the reader's own poll interval.
peerDeliveryClaimInterval = 200 * time.Millisecond
// heldWakeFloor coalesces hold releases. Peers advance their watermarks
// per event they stream, and each release costs a whole pass - a log file
// listing included - so releasing on every advance turns a busy cluster
// into a listing storm. It is added to delivery latency, so it stays well
// under the claim interval that already bounds it.
heldWakeFloor = 20 * time.Millisecond
)
// metadataStreamSender is satisfied by both gRPC stream types and pipelinedSender.
type metadataStreamSender interface {
Send(*filer_pb.SubscribeMetadataResponse) error
}
// metadataLocalStream is the subset of the local-subscribe gRPC server stream
// the local loop uses, so the aggregated stream type can delegate to it.
type metadataLocalStream interface {
Send(*filer_pb.SubscribeMetadataResponse) error
Context() context.Context
}
const (
// batchBehindThreshold: when an event's timestamp is older than this
// relative to wall clock, the sender switches to batch mode for throughput.
// When events are closer to current time, they are sent one-by-one for
// low latency.
batchBehindThreshold = 2 * time.Minute
maxBatchSize = 256
)
// pipelinedSender decouples event reading from gRPC delivery by buffering
// messages in a channel. A dedicated goroutine handles stream.Send(), allowing
// the reader to continue reading ahead without waiting for the client to
// acknowledge each event.
//
// When the client declares support for batching AND events are far behind
// current time (backlog catch-up), multiple events are packed into a single
// stream.Send() using the Events field. Otherwise events are sent one-by-one.
type pipelinedSender struct {
sendCh chan *filer_pb.SubscribeMetadataResponse
errCh chan error
done chan struct{}
canBatch bool // true only if client set ClientSupportsBatching
}
func newPipelinedSender(stream metadataStreamSender, bufSize int, clientSupportsBatching bool) *pipelinedSender {
s := &pipelinedSender{
sendCh: make(chan *filer_pb.SubscribeMetadataResponse, bufSize),
errCh: make(chan error, 1),
done: make(chan struct{}),
canBatch: clientSupportsBatching,
}
go s.sendLoop(stream)
return s
}
func (s *pipelinedSender) sendLoop(stream metadataStreamSender) {
defer close(s.done)
for msg := range s.sendCh {
// 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.
// Control messages (nil EventNotification: heartbeats, flush reports)
// are unbatchable too - nested in an Events tail their watermark
// state is invisible to receivers.
shouldBatch := s.canBatch && len(msg.LogFileRefs) == 0 && msg.EventNotification != nil &&
time.Now().UnixNano()-msg.TsNs > int64(batchBehindThreshold)
if !shouldBatch {
// Real-time: send immediately for low latency
if err := stream.Send(msg); err != nil {
s.reportErr(err)
return
}
continue
}
// Backlog: batch multiple events into one Send for throughput.
// The first event goes in the top-level fields; additional events
// go in the Events slice. Old clients ignore the Events field.
batch := make([]*filer_pb.SubscribeMetadataResponse, 0, maxBatchSize)
batch = append(batch, msg)
var trailingSolo *filer_pb.SubscribeMetadataResponse
drain:
for len(batch) < maxBatchSize {
select {
case next, ok := <-s.sendCh:
if !ok {
break drain
}
if len(next.LogFileRefs) > 0 || next.EventNotification == nil {
// already consumed; send it solo right after the batch
trailingSolo = next
break drain
}
batch = append(batch, next)
default:
break drain
}
}
var toSend *filer_pb.SubscribeMetadataResponse
if len(batch) == 1 {
toSend = batch[0]
} else {
// Pack batch: first event is the envelope, rest go in Events
toSend = batch[0]
toSend.Events = batch[1:]
}
if err := stream.Send(toSend); err != nil {
s.reportErr(err)
return
}
if toSend.Events != nil {
toSend.Events = nil
}
if trailingSolo != nil {
if err := stream.Send(trailingSolo); err != nil {
s.reportErr(err)
return
}
}
}
}
func (s *pipelinedSender) reportErr(err error) {
select {
case s.errCh <- err:
default:
}
// Don't drain sendCh here — Send() detects the exit via <-s.done
// and the deferred close(s.done) in sendLoop will fire after this returns.
}
func (s *pipelinedSender) Send(msg *filer_pb.SubscribeMetadataResponse) error {
select {
case s.sendCh <- msg:
return nil
case err := <-s.errCh:
return err
case <-s.done:
// Sender goroutine exited (stream error or shutdown).
select {
case err := <-s.errCh:
return err
default:
return fmt.Errorf("pipelined sender closed")
}
}
}
func (s *pipelinedSender) Close() error {
close(s.sendCh)
<-s.done
select {
case err := <-s.errCh:
return err
default:
return nil
}
}
// reportUnprovenAggregatedCrossing counts a disk read crossing the eviction
// watermark without proof. A crossing at or below provenThroughTsNs (the
// flush low-watermark frozen before the pass listed files) is proven and not
// reported, so what remains is exactly what the settled-horizon escape
// allowed past a stalled peer.
func reportUnprovenAggregatedCrossing(cursorBeforeTsNs, cursorAfterTsNs, evictedTsNs, provenThroughTsNs int64, clientName, pathPrefix string) {
if evictedTsNs == 0 || cursorBeforeTsNs >= evictedTsNs || cursorAfterTsNs < evictedTsNs {
return
}
if provenThroughTsNs >= 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
}
// errHeldByPeerWatermark aborts a read at an entry beyond the hold point; the
// caller rewinds to the last delivered entry, waits, and re-reads (the
// re-listing is what picks up a late-landing log file). Holding is the normal
// state on a cluster that keeps writing, hence the quiet stop.
var errHeldByPeerWatermark = fmt.Errorf("held by aggregated peer watermark: %w", log_buffer.StopReadingError)
// resolveAggReadHoldTsNs bounds how far an aggregated subscriber may read: a
// cursor that passes T before every source has provably made T visible loses
// whatever arrives late. The hold is the peers' low-watermark (delivery for
// memory reads, flush for persisted reads), relaxed by the settled horizon so
// a stalled peer delays subscribers by at most the horizon.
func resolveAggReadHoldTsNs(peerLowWatermarkTsNs, nowTsNs int64, settledHorizon time.Duration) int64 {
horizonTsNs := nowTsNs - int64(settledHorizon)
if peerLowWatermarkTsNs > horizonTsNs {
return peerLowWatermarkTsNs
}
return horizonTsNs
}
// previousMinuteEndTsNs returns the last nanosecond of the minute before
// tsNs: log files are named per minute, so a ref listing bounded here cannot
// include a file whose window crosses tsNs.
func previousMinuteEndTsNs(tsNs int64) int64 {
return tsNs - tsNs%int64(time.Minute) - 1
}
// chunkRefsStopTsNs bounds the ref listing so no shipped file holds an entry
// past the hold: clients apply shipped files whole and may checkpoint from a
// tail. A file's window starts in its name's minute and spans up to a flush
// interval, hence the double back-off; a frozen peer's freeze-spanning window
// can still overshoot by its freeze.
func chunkRefsStopTsNs(holdTsNs, untilNs int64) int64 {
stopTsNs := previousMinuteEndTsNs(holdTsNs - int64(filer.LogFlushInterval))
if untilNs != 0 && untilNs < stopTsNs {
stopTsNs = untilNs
}
return stopTsNs
}
// 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, upgradeOnRemotePeer <-chan struct{}) (skipToTsNs int64, skip bool, done bool, upgrade 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, false
}
if !fs.hasClient(req.ClientId, req.ClientEpoch) {
return 0, false, true, false
}
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, 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, false
case <-upgradeOnRemotePeer:
return 0, false, false, true
case <-retry:
}
if !fs.hasClient(req.ClientId, req.ClientEpoch) {
return 0, false, true, false
}
return 0, false, 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 loop passes its peers' proven-covered
// watermark as flushedTsNs (everything at or below it was flushed and inside
// the pass's listing), the local loop its own flush watermark.
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 // what the last disk read proved covered: flushed AND inside its listing
gapChan <-chan struct{}
dataChan <-chan struct{}
gapReason func(earliest time.Time, evictedTsNs int64) string
upgradeOnRemotePeer <-chan struct{}
}
type gapOutcome int
const (
gapProceed gapOutcome = iota // read memory
gapContinue // restart the pass
gapDone // the stream is over
gapUpgrade // remote peer arrived; end for reconnect
)
// 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
}
// The last empty disk read proved coverage through the eviction
// watermark itself: the rest of the gap holds nothing - cross without
// parking or counting. The ring's pre-subscription mark is never
// proven by rotation, so this is its only exit.
if p.flushed() >= evictedTsNs {
p.gapStall.resumed()
*cursor = log_buffer.NewMessagePosition(evictedTsNs, gapResumeCursorOffset)
*latch = nil
return gapContinue
}
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, upgrade := p.fs.parkOnGap(ctx, p.req, p.gapStall, p.evicted, *cursor, notifyChan, reason, p.upgradeOnRemotePeer)
if done {
return gapDone
}
if upgrade {
return gapUpgrade
}
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 {
// A filer that has not learned remote peers yet serves the local log and
// upgrades when the first one appears. RemotePeerArrivedChan takes the
// arrival channel under the same lock as the peer check, so a peer
// learned in between returns nil and the stream goes straight to the
// aggregated path.
if fs.filer.MetaAggregator != nil {
if arrival := fs.filer.MetaAggregator.RemotePeerArrivedChan(); arrival != nil {
return fs.subscribeLocalMetadata(req, stream, arrival)
}
} else {
return fs.subscribeLocalMetadata(req, stream, nil)
}
ctx := stream.Context()
peerAddress := findClientAddress(ctx, 0)
isReplacing, alreadyKnown, clientName := fs.addClient("", req.ClientName, peerAddress, req.PathPrefix, req.ClientId, req.ClientEpoch)
if isReplacing {
} else if alreadyKnown {
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)
}()
lastReadTime := log_buffer.NewMessagePosition(req.SinceNs, gapResumeCursorOffset)
glog.V(0).Infof(" %v starts to subscribe %s from %+v", clientName, req.PathPrefix, lastReadTime)
// diskAnchorTsNs is the newest ORIGINAL-timestamp position this stream is
// proven complete through. Memory reads advance the cursor in the ring's
// bumped (arrival) space while persisted logs keep original timestamps,
// so a reader that falls off the ring must resume the disk pass here, not
// at its bumped cursor - that would skip original-space entries memory
// never delivered. Disk passes advance the anchor directly; contiguous
// memory reads advance it to the delivery low-watermark observed before
// the read (per-peer streams are ordered, so everything at or below it
// had already arrived and been delivered).
diskAnchorTsNs := req.SinceNs
sender := newPipelinedSender(stream, 1024, req.ClientSupportsBatching)
defer sender.Close()
// Register for instant notification when new data arrives in the aggregated log buffer.
// Used to replace the 1127ms sleep with event-driven wake-up.
// 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)
// lastSeenTsNs tracks how far the subscriber has read so idle heartbeats are
// only emitted once it is caught up to the buffer head. It is read and
// written from this single goroutine, so no synchronization is needed.
var lastSeenTsNs int64
var lastHeartbeatNs int64
baseEachLogEntryFn := eachLogEntryFn(req, sender, eachEventNotificationFn, &unsyncedEvents)
// heldAtTsNs remembers the entry a read was held at (for the log line);
// diskHeldAtTsNs is the same marker for the disk pass alone: a pending
// disk hold keeps the pass re-reading until the entry is served.
var heldAtTsNs, diskHeldAtTsNs int64
// Each read path holds at its own watermark: persisted logs are complete
// only up to every peer's flush watermark, the ring only up to every
// peer's delivery watermark.
holdMemTsNs := func() int64 {
return resolveAggReadHoldTsNs(fs.filer.MetaAggregator.PeerLowWatermarkTsNs(), time.Now().UnixNano(), metadataGapSettledHorizon)
}
// deliveredUpToTsNs tracks the newest position actually handed to the
// sender (or intentionally skipped by the gap machinery), so a held read
// can rewind to a position that skips nothing.
var deliveredUpToTsNs int64
guardedEachLogEntryFn := func(holdFn func() int64) log_buffer.EachLogEntryFuncType {
return func(logEntry *filer_pb.LogEntry) (bool, error) {
if logEntry.TsNs > holdFn() {
heldAtTsNs = logEntry.TsNs
return false, errHeldByPeerWatermark
}
lastSeenTsNs = logEntry.TsNs
deliveredUpToTsNs = logEntry.TsNs
return baseEachLogEntryFn(logEntry)
}
}
// Frozen BEFORE each pass lists the log files: per-source flushes are
// ts-ordered, so everything at or below the frozen value is in the
// listing; a live value could rise mid-pass and admit entries past files
// this pass cannot see.
var diskPassFlushLowTsNs int64
var diskPassHoldTsNs int64
// What the last disk pass proved covered: flushed on every peer AND inside
// the pass's listing, so an empty pass proves (cursor, proven] empty.
var diskPassProvenTsNs int64
diskBaseEachLogEntryFn := guardedEachLogEntryFn(func() int64 { return diskPassHoldTsNs })
diskEachLogEntryFn := func(logEntry *filer_pb.LogEntry) (bool, error) {
isDone, err := diskBaseEachLogEntryFn(logEntry)
if errors.Is(err, errHeldByPeerWatermark) {
diskHeldAtTsNs = logEntry.TsNs
}
return isDone, err
}
memEachLogEntryFn := guardedEachLogEntryFn(holdMemTsNs)
// waitHeld pauses a held read until a peer reports further progress, or
// the retry interval elapses (a peer dropped past its grace, or a log file
// landing that no watermark covers). Arriving data is deliberately not a
// wake-up: on a cluster that keeps writing there is always an entry past
// the hold, so waking on it spins the loop without ever releasing the
// hold. The channel is the one for this read's own watermark - a delivery
// advance cannot release a flush-held read - and was taken before the pass
// sampled it, so a rise in between wakes us here instead of being missed.
// False: context ended.
waitHeld := func(scope string, watermarkChan <-chan struct{}) bool {
stats.FilerSubscribeWatermarkHolds.WithLabelValues(scope).Inc()
glog.V(3).Infof("held at %v (deliveredUpTo %v, flushLow %v, deliveryLow %v) for %v",
time.Unix(0, heldAtTsNs), time.Unix(0, deliveredUpToTsNs),
time.Unix(0, fs.filer.MetaAggregator.PeerLowFlushWatermarkTsNs()),
time.Unix(0, fs.filer.MetaAggregator.PeerLowWatermarkTsNs()), clientName)
select {
case <-ctx.Done():
return false
case <-time.After(heldWakeFloor):
}
select {
case <-watermarkChan:
case <-ctx.Done():
return false
case <-time.After(unflushedGapRetryInterval):
}
return true
}
var processedTsNs int64
var readPersistedLogErr error
var readInMemoryLogErr error
var isDone bool
var lastCheckedFlushTsNs int64 = -1 // Track the last local flush we read the disk under
var lastCheckedFlushLowTsNs int64 = -1 // Track the last peer flush low-watermark we read the disk under
var lastDiskReadTsNs int64 = -1 // Track the last read position we used for disk read
var lastDiskRefsStopTsNs int64 = -1 // Track the last chunk listing bound we read the disk under
var lastDiskPassAt time.Time // Paces re-probes for files no watermark signals
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 diskPassProvenTsNs },
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)
// Taken before either read samples its watermark, so a rise mid-pass
// cannot land between the sample and the park below.
flushChan := fs.filer.MetaAggregator.FlushWatermarkAdvancedChan()
deliveryChan := fs.filer.MetaAggregator.DeliveryWatermarkAdvancedChan()
cursorBeforeDiskTsNs := lastReadTime.Time.UnixNano()
// Observe the flush low-watermark before the pass lists files (see
// diskPassHoldTsNs above).
diskPassFlushLowTsNs = fs.filer.MetaAggregator.PeerLowFlushWatermarkTsNs()
diskPassHoldTsNs = resolveAggReadHoldTsNs(diskPassFlushLowTsNs, time.Now().UnixNano(), metadataGapSettledHorizon)
// Re-read the disk only when something changed it cannot miss: a local
// flush landed, the peers' flush low-watermark moved in either
// direction (a joining peer invalidates what an earlier pass proved),
// the cursor moved, or a disk hold is pending (the ring read after an
// empty pass parks internally, so skipping would strand the held
// entry). A peer past the low-watermark can still land a file without
// moving it, so the listing is also re-probed at a slow cadence;
// chunk listings re-arm as soon as their read bound admits more files.
currentFlushTsNs := fs.filer.LocalMetaLogBuffer.GetLastFlushTsNs()
currentReadTsNs := lastReadTime.Time.UnixNano()
var currentRefsStopTsNs int64
if req.ClientSupportsMetadataChunks {
currentRefsStopTsNs = chunkRefsStopTsNs(diskPassHoldTsNs, req.UntilNs)
}
shouldReadFromDisk := lastCheckedFlushTsNs == -1 ||
currentFlushTsNs > lastCheckedFlushTsNs ||
diskPassFlushLowTsNs != lastCheckedFlushLowTsNs ||
currentReadTsNs != lastDiskReadTsNs ||
currentRefsStopTsNs > lastDiskRefsStopTsNs ||
diskHeldAtTsNs != 0 ||
time.Since(lastDiskPassAt) >= aggDiskReprobeInterval
diskAdvanced := false
if shouldReadFromDisk {
lastCheckedFlushTsNs = currentFlushTsNs
lastCheckedFlushLowTsNs = diskPassFlushLowTsNs
lastDiskReadTsNs = currentReadTsNs
lastDiskRefsStopTsNs = currentRefsStopTsNs
lastDiskPassAt = time.Now()
diskHeldAtTsNs = 0
diskPassProvenTsNs = diskPassFlushLowTsNs
if req.ClientSupportsMetadataChunks {
refsStopTsNs := currentRefsStopTsNs
// Nothing above the listing bound is proven by this pass.
if refsStopTsNs < diskPassProvenTsNs {
diskPassProvenTsNs = refsStopTsNs
}
if refsStopTsNs > lastReadTime.Time.UnixNano() {
processedTsNs, isDone, readPersistedLogErr = fs.chunkDiskPass(ctx, sender, lastReadTime, refsStopTsNs, sentRefs, nil)
} else {
processedTsNs, isDone, readPersistedLogErr = 0, false, nil
}
} else {
processedTsNs, isDone, readPersistedLogErr = fs.filer.ReadPersistedLogBuffer(ctx, lastReadTime, req.UntilNs, diskEachLogEntryFn)
}
if errors.Is(readPersistedLogErr, errHeldByPeerWatermark) {
// Stay at the last delivered entry; the held entry is re-read (and
// re-checked) by the next pass.
if processedTsNs > 0 {
lastReadTime = log_buffer.NewMessagePosition(processedTsNs, gapResumeCursorOffset)
if processedTsNs > diskAnchorTsNs {
diskAnchorTsNs = processedTsNs
}
}
// A hold is not a gap: clear any stale ResumeFromDiskError so the
// next pass's disk-miss handling cannot skip past the held entry.
readInMemoryLogErr = nil
if !waitHeld("disk", flushChan) {
return nil
}
continue
}
if readPersistedLogErr != nil {
return fmt.Errorf("reading from persisted logs: %w", readPersistedLogErr)
}
if isDone {
return nil
}
glog.V(4).Infof("processed to %v: %v", clientName, processedTsNs)
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, diskPassFlushLowTsNs, clientName, req.PathPrefix)
lastReadTime = log_buffer.NewMessagePosition(processedTsNs, gapResumeCursorOffset)
if processedTsNs > diskAnchorTsNs {
diskAnchorTsNs = processedTsNs
}
} 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())
// The day jump delivers nothing; stay put until the hold point
// covers the skipped range.
if nextDayTs <= diskPassHoldTsNs {
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, diskPassFlushLowTsNs, clientName, req.PathPrefix)
lastReadTime = position
if nextDayTs > diskAnchorTsNs {
diskAnchorTsNs = nextDayTs
}
}
}
}
}
cursorBeforeResolveTsNs := lastReadTime.Time.UnixNano()
switch gaps.resolve(ctx, &lastReadTime, &readInMemoryLogErr, diskAdvanced) {
case gapDone:
return nil
case gapContinue:
// A cursor move here is a give-up or proven-empty skip (original space);
// anchor it so a later eviction rewind cannot undo the decision.
if ts := lastReadTime.Time.UnixNano(); ts != cursorBeforeResolveTsNs && ts > diskAnchorTsNs {
diskAnchorTsNs = ts
}
continue
}
// A held rewind must not re-park below the gap machinery's
// intentional skips.
if lastReadTime.Time.UnixNano() > deliveredUpToTsNs {
deliveredUpToTsNs = lastReadTime.Time.UnixNano()
}
glog.V(4).Infof("read in memory %v aggregated subscribe %s from %+v", clientName, req.PathPrefix, lastReadTime)
// Sampled before the read: a contiguous (unrefused) read delivers
// every event whose original timestamp is at or below this.
preMemDeliveryLowTsNs := fs.filer.MetaAggregator.PeerLowWatermarkTsNs()
diskReprobeDue := false
lastReadTime, isDone, readInMemoryLogErr = fs.filer.MetaAggregator.MetaLogBuffer.LoopProcessLogData(aggReaderName, lastReadTime, req.UntilNs, func() bool {
select {
case <-ctx.Done():
return false
default:
}
if !fs.hasClient(req.ClientId, req.ClientEpoch) {
return false
}
// Caught-up readers park in the inner wait loop; the outer disk
// gate never runs again unless this read returns, so unwind to
// re-probe the persisted logs on the slow cadence.
if time.Since(lastDiskPassAt) >= aggDiskReprobeInterval {
diskReprobeDue = true
return false
}
// Contiguous and caught up: advance the anchor to the delivery
// low-watermark so long live tails keep eviction rewinds short.
// Only once the run is connected to the ring - the empty-ring
// wait lands here too, with disk files still unshipped below the
// cursor.
if memoryHoldsGap(lastReadTime.Time.UnixNano(), aggBuffer.GetLastEvictedOriginalTsNs()) {
if dl := fs.filer.MetaAggregator.PeerLowWatermarkTsNs(); dl > diskAnchorTsNs {
diskAnchorTsNs = dl
}
}
lastHeartbeatNs = fs.maybeSendIdleHeartbeat(req, sender, fs.filer.MetaAggregator.MetaLogBuffer, lastReadTime.Time.UnixNano(), lastSeenTsNs, lastHeartbeatNs)
return true
}, memEachLogEntryFn)
if readInMemoryLogErr != nil {
if errors.Is(readInMemoryLogErr, errHeldByPeerWatermark) {
// The read was contiguous up to the hold: credit the anchor.
if preMemDeliveryLowTsNs > diskAnchorTsNs {
diskAnchorTsNs = preMemDeliveryLowTsNs
}
// The cursor already advanced onto the held entry; rewind to
// the last delivered entry so nothing in between is skipped.
lastReadTime = log_buffer.NewMessagePosition(deliveredUpToTsNs, gapResumeCursorOffset)
readInMemoryLogErr = nil
if !waitHeld("memory", deliveryChan) {
return nil
}
continue
}
if errors.Is(readInMemoryLogErr, log_buffer.ResumeFromDiskError) {
// Fell off the ring: resume the disk pass from the anchor, not
// the (possibly bumped) cursor - redelivery is within the
// at-least-once contract, skipping is not. For an anchored
// cursor this is a no-op, so the gap machinery's re-arm onto
// the retained window stays reachable.
lastReadTime = log_buffer.NewMessagePosition(diskAnchorTsNs, gapResumeCursorOffset)
continue
}
glog.Errorf("processed to %v: %v", lastReadTime, readInMemoryLogErr)
if !errors.Is(readInMemoryLogErr, log_buffer.ResumeError) {
break
}
}
if isDone {
if diskReprobeDue {
continue
}
return nil
}
if !fs.hasClient(req.ClientId, req.ClientEpoch) {
glog.V(0).Infof("client %v is closed", clientName)
return nil
}
// Wait for new data (event-driven instead of 1127ms polling).
// Drain any stale notification first to avoid a spurious wake-up.
select {
case <-aggNotifyChan:
default:
}
select {
case <-aggNotifyChan:
case <-ctx.Done():
return nil
}
}
return readInMemoryLogErr
}
func (fs *FilerServer) SubscribeLocalMetadata(req *filer_pb.SubscribeMetadataRequest, stream filer_pb.SeaweedFiler_SubscribeLocalMetadataServer) error {
return fs.subscribeLocalMetadata(req, stream, nil)
}
// subscribeLocalMetadata serves the filer's own log to the stream. Peer
// aggregation streams pass upgradeOnRemotePeer == nil; the SubscribeMetadata
// delegation passes the aggregator's arrival channel so the stream ends
// when a remote peer appears and the client reconnects to the aggregated path.
func (fs *FilerServer) subscribeLocalMetadata(req *filer_pb.SubscribeMetadataRequest, stream metadataLocalStream, upgradeOnRemotePeer <-chan struct{}) error {
ctx := stream.Context()
peerAddress := findClientAddress(ctx, 0)
// use negative client id to differentiate from addClient()/deleteClient() used in SubscribeMetadata()
req.ClientId = -req.ClientId
isReplacing, alreadyKnown, clientName := fs.addClient("local", req.ClientName, peerAddress, req.PathPrefix, req.ClientId, req.ClientEpoch)
if isReplacing {
} 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)
}()
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)
// lastSeenTsNs tracks how far the subscriber has read so idle heartbeats are
// only emitted once it is caught up to the buffer head. It is read and
// written from this single goroutine, so no synchronization is needed.
var lastSeenTsNs int64
var lastHeartbeatNs int64
var lastFlushReportNs int64
baseEachLogEntryFn := eachLogEntryFn(req, sender, eachEventNotificationFn, &unsyncedEvents)
eachLogEntryFn := func(logEntry *filer_pb.LogEntry) (bool, error) {
if upgradeOnRemotePeer != nil {
select {
case <-upgradeOnRemotePeer:
return false, errAggregationUpgrade
default:
}
}
lastSeenTsNs = logEntry.TsNs
return baseEachLogEntryFn(logEntry)
}
var processedTsNs int64
var readPersistedLogErr error
var readInMemoryLogErr error
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)
var upgradedToAggregation bool
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,
upgradeOnRemotePeer: upgradeOnRemotePeer,
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 {
if upgradeOnRemotePeer != nil {
select {
case <-upgradeOnRemotePeer:
glog.V(0).Infof("remote peer discovered after local subscribe %s started: ending stream so the client reconnects to the aggregated stream", clientName)
return errAggregationUpgrade
default:
}
}
// Check if new data has been flushed to disk since last check, or if read position advanced
currentFlushTsNs := fs.filer.LocalMetaLogBuffer.GetLastFlushTsNs()
currentReadTsNs := lastReadTime.Time.UnixNano()
// Read from disk if: first time, new flush observed, or read position advanced (draining backlog)
shouldReadFromDisk := lastCheckedFlushTsNs == -1 ||
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.chunkDiskPass(ctx, sender, lastReadTime, req.UntilNs, sentRefs, upgradeOnRemotePeer)
} else {
processedTsNs, isDone, readPersistedLogErr = fs.filer.ReadPersistedLogBuffer(ctx, lastReadTime, req.UntilNs, eachLogEntryFn)
}
if readPersistedLogErr != nil {
if errors.Is(readPersistedLogErr, errAggregationUpgrade) {
return errAggregationUpgrade
}
glog.V(0).Infof("read on disk %v local subscribe %s from %+v: %v", clientName, req.PathPrefix, lastReadTime, readPersistedLogErr)
return fmt.Errorf("reading from persisted logs: %w", readPersistedLogErr)
}
if isDone {
return nil
}
// Update the last checked flushed time
lastCheckedFlushTsNs = currentFlushTsNs
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 gapUpgrade:
return errAggregationUpgrade
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(localReaderName, lastReadTime, req.UntilNs, func() bool {
select {
case <-ctx.Done():
return false
default:
}
if upgradeOnRemotePeer != nil {
select {
case <-upgradeOnRemotePeer:
upgradedToAggregation = true
return false
default:
}
}
if !fs.hasClient(req.ClientId, req.ClientEpoch) {
return false
}
lastHeartbeatNs = fs.maybeSendIdleHeartbeat(req, sender, fs.filer.LocalMetaLogBuffer, lastReadTime.Time.UnixNano(), lastSeenTsNs, lastHeartbeatNs)
lastFlushReportNs = fs.maybeSendFlushReport(req, sender, lastFlushReportNs)
return true
}, eachLogEntryFn)
if upgradedToAggregation {
glog.V(0).Infof("remote peer discovered after local subscribe %s started: ending stream so the client reconnects to the aggregated stream", clientName)
return errAggregationUpgrade
}
if readInMemoryLogErr != nil {
if errors.Is(readInMemoryLogErr, errAggregationUpgrade) {
return errAggregationUpgrade
}
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 !errors.Is(readInMemoryLogErr, log_buffer.ResumeError) {
break
}
}
if isDone {
return nil
}
if !fs.hasClient(req.ClientId, req.ClientEpoch) {
return nil
}
}
return readInMemoryLogErr
}
func eachLogEntryFn(req *filer_pb.SubscribeMetadataRequest, sender metadataStreamSender, eachEventNotificationFn func(dirPath string, eventNotification *filer_pb.EventNotification, tsNs int64) error, filtered *int64) log_buffer.EachLogEntryFuncType {
// A shallow scan of the path fields skips unmarshaling chunk-heavy events
// this subscriber would filter out anyway; scan surprises fall back to the
// full decode. Only a delivery resets the shared unsynced-events counter.
prefilter := req.PathPrefix != "" || len(req.PathPrefixes) > 0 || len(req.Directories) > 0
return func(logEntry *filer_pb.LogEntry) (bool, error) {
if prefilter {
if skeleton, ok := filer_pb.ScanMetadataEventSkeleton(logEntry.Data); ok &&
!filer_pb.MetadataEventMatchesSubscription(skeleton, req.PathPrefix, req.PathPrefixes, req.Directories) {
*filtered++
if *filtered > MaxUnsyncedEvents {
if err := sender.Send(&filer_pb.SubscribeMetadataResponse{
EventNotification: &filer_pb.EventNotification{},
TsNs: skeleton.TsNs,
}); err != nil {
return false, err
}
*filtered = 0
}
return false, nil
}
}
event := &filer_pb.SubscribeMetadataResponse{}
// proto.Unmarshal (not UnmarshalVT) validates UTF-8 in string fields, so
// malformed metadata is rejected here instead of reaching path filtering
// and subscribers.
if err := proto.Unmarshal(logEntry.Data, event); err != nil {
glog.Errorf("unexpected unmarshal filer_pb.SubscribeMetadataResponse: %v", err)
return false, fmt.Errorf("unexpected unmarshal filer_pb.SubscribeMetadataResponse: %w", err)
}
if err := eachEventNotificationFn(event.Directory, event.EventNotification, event.TsNs); err != nil {
return false, err
}
return false, nil
}
}
// maybeSendFlushReport reports the local flush watermark to a subscriber that
// opted into idle heartbeats (peer aggregators). Unlike heartbeats it is sent
// regardless of catch-up state, and its TsNs stays zero so it never advances
// delivery freshness.
func (fs *FilerServer) maybeSendFlushReport(req *filer_pb.SubscribeMetadataRequest, sender metadataStreamSender, lastFlushReportNs int64) int64 {
if !req.ClientSupportsIdleHeartbeat || fs.filer == nil {
return lastFlushReportNs
}
now := time.Now().UnixNano()
if now-lastFlushReportNs < int64(idleHeartbeatInterval) {
return lastFlushReportNs
}
if err := sender.Send(&filer_pb.SubscribeMetadataResponse{FlushedTsNs: fs.filer.LocalFlushedThroughTsNs(now)}); err != nil {
glog.V(0).Infof("=> flush report to %s: %v", req.ClientName, err)
return lastFlushReportNs
}
return now
}
// maybeSendIdleHeartbeat emits an empty response carrying the current time when
// the subscriber has consumed everything up to the buffer head. The client uses
// it to advance freshness signals (e.g. filer.sync's sync_offset) without moving
// its resume checkpoint, so a restart still re-reads from the last real event.
//
// The catch-up floor is the max of two read-progress markers:
// - readPositionTsNs: how far the read cursor has advanced. It starts at
// SinceNs and also covers metadata-chunks mode, where persisted entries are
// replayed as log file refs rather than through eachLogEntryFn.
// - lastSeenTsNs: the timestamp of the most recent entry streamed in this
// call. It advances live while reading the in-memory backlog, before the
// read cursor returned by LoopProcessLogData has been updated.
//
// While the buffer head is past that floor the subscriber is still behind (e.g.
// replaying a backlog) and no heartbeat is sent. Returns the (possibly advanced)
// lastHeartbeatNs.
func (fs *FilerServer) maybeSendIdleHeartbeat(req *filer_pb.SubscribeMetadataRequest, sender metadataStreamSender, logBuffer *log_buffer.LogBuffer, readPositionTsNs, lastSeenTsNs, lastHeartbeatNs int64) int64 {
if !req.ClientSupportsIdleHeartbeat {
return lastHeartbeatNs
}
floorTsNs := lastSeenTsNs
if readPositionTsNs > floorTsNs {
floorTsNs = readPositionTsNs
}
if logBuffer.LastTsNs.Load() > floorTsNs {
// the buffer holds data the subscriber has not reached yet
return lastHeartbeatNs
}
isLocalStream := fs.filer != nil && logBuffer == fs.filer.LocalMetaLogBuffer
interval := idleHeartbeatInterval
if isLocalStream && fs.filer.MetaAggregator != nil && fs.filer.MetaAggregator.HasRemotePeers() {
interval = peerDeliveryClaimInterval
}
now := time.Now().UnixNano()
if now-lastHeartbeatNs < int64(interval) {
return lastHeartbeatNs
}
// On the local stream the heartbeat is a delivery claim to a peer
// aggregator and piggybacks the flush watermark; the aggregated ring
// never flushes, so its heartbeats carry neither. The claims are capped
// by the in-flight floor and fence later stamps above themselves, so
// re-checking the buffer head afterwards closes the append race: an
// event at or below the claim was in flight (capping it), stamped later
// (fenced above it), or already appended here - and then the head check
// proves this stream has sent it before the heartbeat.
heartbeat := &filer_pb.SubscribeMetadataResponse{TsNs: now}
if isLocalStream {
heartbeat.TsNs = fs.filer.LocalDeliveredThroughTsNs(now)
heartbeat.FlushedTsNs = fs.filer.LocalFlushedThroughTsNs(now)
if logBuffer.LastTsNs.Load() > floorTsNs {
return lastHeartbeatNs
}
}
if err := sender.Send(heartbeat); err != nil {
glog.V(0).Infof("=> idle heartbeat to %s: %v", req.ClientName, err)
return lastHeartbeatNs
}
// A heartbeat is a send too: advance the freshness gauge so an idle but
// healthy subscriber doesn't look stale. The gauge otherwise only moves on
// real matching events, which never arrive on a quiet path.
var sourceFiler string
if fs.option != nil {
sourceFiler = fs.option.Host.String()
}
stats.FilerServerLastSendTsOfSubscribeGauge.WithLabelValues(sourceFiler, req.ClientName, req.PathPrefix).Set(float64(now))
return now
}
// 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, upgradeOnRemotePeer <-chan struct{}) (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 startPos.Time.UnixNano(), false, nil
}
if err := fs.sendRefsBatched(sender, refs, upgradeOnRemotePeer); err != nil {
return 0, false, err
}
if upgradeOnRemotePeer != nil {
select {
case <-upgradeOnRemotePeer:
return 0, false, errAggregationUpgrade
default:
}
}
// 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, upgradeOnRemotePeer <-chan struct{}) error {
const maxRefsPerMessage = 64
for i := 0; i < len(refs); i += maxRefsPerMessage {
if upgradeOnRemotePeer != nil {
select {
case <-upgradeOnRemotePeer:
return errAggregationUpgrade
default:
}
}
end := i + maxRefsPerMessage
if end > len(refs) {
end = len(refs)
}
if err := sender.Send(&filer_pb.SubscribeMetadataResponse{LogFileRefs: refs[i:end]}); err != nil {
return err
}
}
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 {
return func(dirPath string, eventNotification *filer_pb.EventNotification, tsNs int64) error {
defer func() {
if *filtered > MaxUnsyncedEvents {
if err := sender.Send(&filer_pb.SubscribeMetadataResponse{
EventNotification: &filer_pb.EventNotification{},
TsNs: tsNs,
}); err == nil {
*filtered = 0
}
}
}()
*filtered++
foundSelf := false
for _, sig := range eventNotification.Signatures {
if sig == req.Signature && req.Signature != 0 {
return nil
}
if sig == fs.filer.Signature {
foundSelf = true
}
}
if !foundSelf {
eventNotification.Signatures = append(eventNotification.Signatures, fs.filer.Signature)
}
// get complete path to the file or directory
var entryName string
if eventNotification.OldEntry != nil {
entryName = eventNotification.OldEntry.Name
} else if eventNotification.NewEntry != nil {
entryName = eventNotification.NewEntry.Name
}
fullpath := util.Join(dirPath, entryName)
// skip on filer internal meta logs
if strings.HasPrefix(fullpath, filer.SystemLogDir) {
return nil
}
message := &filer_pb.SubscribeMetadataResponse{
Directory: dirPath,
EventNotification: eventNotification,
TsNs: tsNs,
}
if !filer_pb.MetadataEventMatchesSubscription(message, req.PathPrefix, req.PathPrefixes, req.Directories) {
return nil
}
// collect timestamps for path
stats.FilerServerLastSendTsOfSubscribeGauge.WithLabelValues(fs.option.Host.String(), req.ClientName, req.PathPrefix).Set(float64(tsNs))
// println("sending", dirPath, entryName)
if err := sender.Send(message); err != nil {
glog.V(0).Infof("=> client %v: %+v", clientName, err)
return err
}
*filtered = 0
return nil
}
}
func (fs *FilerServer) addClient(scope string, clientType string, clientAddress string, pathPrefix string, clientId int32, clientEpoch int32) (isReplacing, alreadyKnown bool, clientName string) {
clientName = clientType + "@" + clientAddress
glog.V(0).Infof("+ %v listener %v clientId %v clientEpoch %v", scope, clientName, clientId, clientEpoch)
if clientId != 0 {
fs.knownListenersLock.Lock()
defer fs.knownListenersLock.Unlock()
epoch, found := fs.knownListeners[clientId]
if !found || epoch < clientEpoch {
fs.knownListeners[clientId] = clientEpoch
isReplacing = true
if fs.subscribers == nil {
fs.subscribers = make(map[int32]*metadataSubscriber)
}
fs.subscribers[clientId] = &metadataSubscriber{
clientName: clientName,
clientType: clientType,
address: clientAddress,
pathPrefix: pathPrefix,
clientId: clientId,
clientEpoch: clientEpoch,
connectedAtNs: time.Now().UnixNano(),
}
} else {
alreadyKnown = true
}
}
return
}
func (fs *FilerServer) deleteClient(scope string, clientName string, clientId int32, clientEpoch int32) {
glog.V(0).Infof("- %v listener %v clientId %v clientEpoch %v", scope, clientName, clientId, clientEpoch)
if clientId != 0 {
fs.knownListenersLock.Lock()
defer fs.knownListenersLock.Unlock()
epoch, found := fs.knownListeners[clientId]
if found && epoch <= clientEpoch {
delete(fs.knownListeners, clientId)
delete(fs.subscribers, clientId)
}
}
}
func (fs *FilerServer) hasClient(clientId int32, clientEpoch int32) bool {
if clientId != 0 {
fs.knownListenersLock.Lock()
defer fs.knownListenersLock.Unlock()
epoch, found := fs.knownListeners[clientId]
if found && epoch <= clientEpoch {
return true
}
}
return false
}