diff --git a/weed/filer/filer_notify_read.go b/weed/filer/filer_notify_read.go index c2e8ceeb4..3d3d4f006 100644 --- a/weed/filer/filer_notify_read.go +++ b/weed/filer/filer_notify_read.go @@ -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) diff --git a/weed/filer/filer_notify_read_minute_test.go b/weed/filer/filer_notify_read_minute_test.go new file mode 100644 index 000000000..c9c525b37 --- /dev/null +++ b/weed/filer/filer_notify_read_minute_test.go @@ -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") + } + }) +} diff --git a/weed/filer/filer_notify_read_testing.go b/weed/filer/filer_notify_read_testing.go new file mode 100644 index 000000000..4e3942858 --- /dev/null +++ b/weed/filer/filer_notify_read_testing.go @@ -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 + } +} diff --git a/weed/filer/meta_aggregator.go b/weed/filer/meta_aggregator.go index ca03c1eb1..1e62a130a 100644 --- a/weed/filer/meta_aggregator.go +++ b/weed/filer/meta_aggregator.go @@ -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 } diff --git a/weed/server/filer_grpc_server_sub_meta.go b/weed/server/filer_grpc_server_sub_meta.go index 6a373a36a..f57b3dba6 100644 --- a/weed/server/filer_grpc_server_sub_meta.go +++ b/weed/server/filer_grpc_server_sub_meta.go @@ -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 { diff --git a/weed/server/filer_grpc_server_sub_meta_gap_test.go b/weed/server/filer_grpc_server_sub_meta_gap_test.go new file mode 100644 index 000000000..8d5d1286d --- /dev/null +++ b/weed/server/filer_grpc_server_sub_meta_gap_test.go @@ -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) + } + }) + } +} diff --git a/weed/server/filer_pipelined_sender_test.go b/weed/server/filer_pipelined_sender_test.go new file mode 100644 index 000000000..b50455501 --- /dev/null +++ b/weed/server/filer_pipelined_sender_test.go @@ -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) + } +} diff --git a/weed/server/filer_server.go b/weed/server/filer_server.go index 09567fe6b..9ea143228 100644 --- a/weed/server/filer_server.go +++ b/weed/server/filer_server.go @@ -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 diff --git a/weed/server/filer_subscribe_loop_test.go b/weed/server/filer_subscribe_loop_test.go new file mode 100644 index 000000000..522cc3bab --- /dev/null +++ b/weed/server/filer_subscribe_loop_test.go @@ -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]) + } +} diff --git a/weed/stats/metrics.go b/weed/stats/metrics.go index 37e75590f..b6161709e 100644 --- a/weed/stats/metrics.go +++ b/weed/stats/metrics.go @@ -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{})) diff --git a/weed/util/log_buffer/log_buffer.go b/weed/util/log_buffer/log_buffer.go index 15430b0ed..0bc6f8e96 100644 --- a/weed/util/log_buffer/log_buffer.go +++ b/weed/util/log_buffer/log_buffer.go @@ -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 { diff --git a/weed/util/log_buffer/log_buffer_eviction_gate_test.go b/weed/util/log_buffer/log_buffer_eviction_gate_test.go new file mode 100644 index 000000000..927f13952 --- /dev/null +++ b/weed/util/log_buffer/log_buffer_eviction_gate_test.go @@ -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)) + } +} diff --git a/weed/util/log_buffer/sealed_buffer.go b/weed/util/log_buffer/sealed_buffer.go index a637b23f8..61b87a568 100644 --- a/weed/util/log_buffer/sealed_buffer.go +++ b/weed/util/log_buffer/sealed_buffer.go @@ -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 }