package weed_server // End-to-end tests for the aggregated (SubscribeMetadata) loop's peer // watermark holds. Peers report their progress at their own pace, so on a // cluster that keeps writing there is almost always an entry newer than the // low-watermark: a hold is the normal state, and has to be quiet and paced // rather than logged and retried per arriving event. import ( "context" "fmt" "net" "testing" "time" "github.com/prometheus/client_golang/prometheus/testutil" "google.golang.org/grpc/peer" "github.com/seaweedfs/seaweedfs/weed/filer" "github.com/seaweedfs/seaweedfs/weed/glog" "github.com/seaweedfs/seaweedfs/weed/pb" "github.com/seaweedfs/seaweedfs/weed/pb/filer_pb" "github.com/seaweedfs/seaweedfs/weed/stats" ) const ( testSelfAddress = pb.ServerAddress("self:8888") testPeerAddress = pb.ServerAddress("peer:8888") ) // startAggregator gives the harness a meta aggregator with one remote peer, so // SubscribeMetadata takes the aggregated path instead of delegating to // SubscribeLocalMetadata. func (h *subscribeHarness) startAggregator() *filer.MetaAggregator { ma := filer.NewMetaAggregator(h.f, testSelfAddress, nil) ma.TrackPeerForTesting(testSelfAddress) ma.TrackPeerForTesting(testPeerAddress) h.f.MetaAggregator = ma h.t.Cleanup(ma.MetaLogBuffer.ShutdownLogBuffer) return ma } // reportPeers stands in for both peers' streams reporting through tsNs. func reportPeers(ma *filer.MetaAggregator, tsNs int64) { reportPeersAt(ma, tsNs, tsNs) } // reportPeersAt is reportPeers with the two watermarks apart: a peer streams // an event well before it flushes it, so they advance independently. func reportPeersAt(ma *filer.MetaAggregator, deliveredTsNs, flushedTsNs int64) { ma.ReportPeerWatermarksForTesting(testSelfAddress, deliveredTsNs, flushedTsNs) ma.ReportPeerWatermarksForTesting(testPeerAddress, deliveredTsNs, flushedTsNs) } func (h *subscribeHarness) appendAggregated(tsNs int64) { if err := h.f.MetaAggregator.MetaLogBuffer.AddLogEntryToBuffer(testEvent(tsNs, fmt.Sprintf("a-%d", tsNs))); err != nil { h.t.Fatalf("append aggregated: %v", err) } } func (h *subscribeHarness) subscribeAggregated(sinceNs int64) *runningSubscribe { // A peer in the context keeps findClientAddress quiet, so an ERROR count // across the run sees only what the subscribe loop itself writes. ctx, cancel := context.WithCancel(peer.NewContext(context.Background(), &peer.Peer{Addr: &net.TCPAddr{IP: net.IPv4(127, 0, 0, 1), Port: 12345}})) stream := &fakeSubscribeStream{ctx: ctx} req := &filer_pb.SubscribeMetadataRequest{ ClientName: "agg-loop-test", ClientId: 11, ClientEpoch: 1, SinceNs: sinceNs, } r := &runningSubscribe{stream: stream, cancel: cancel, done: make(chan error, 1), finished: make(chan struct{})} go func() { r.done <- h.fs.SubscribeMetadata(req, stream) close(r.finished) }() h.t.Cleanup(func() { cancel() select { case <-r.finished: case <-time.After(5 * time.Second): h.t.Error("aggregated subscribe loop did not exit on cancel") } }) return r } // heldSubscriber starts a subscriber whose peers reported a moment ago and // then went quiet - the hold sits just behind live writes, exactly where a // quiet peer's idle heartbeat leaves it - and returns it with the write // timestamp the peers last reported. func (h *subscribeHarness) heldSubscriber() (*filer.MetaAggregator, *runningSubscribe, int64) { ma := h.startAggregator() frozen := time.Now().Add(-500 * time.Millisecond).UnixNano() reportPeers(ma, frozen) return ma, h.subscribeAggregated(frozen), frozen } // writeFor appends an entry every 2ms for d, reporting the peers through the // PREVIOUS entry each time when report is set: the live-cluster shape, where // the low-watermark keeps moving but always trails the newest entry, so every // read ends held. func (h *subscribeHarness) writeFor(ma *filer.MetaAggregator, d time.Duration, report bool) (written []int64, elapsed time.Duration) { start := time.Now() for stop := time.After(d); ; { select { case <-stop: if report && len(written) > 0 { reportPeers(ma, written[len(written)-1]) } return written, time.Since(start) default: } ts := time.Now().UnixNano() h.appendAggregated(ts) if report && len(written) > 0 { reportPeers(ma, written[len(written)-1]) } written = append(written, ts) time.Sleep(2 * time.Millisecond) } } // heldReads reads back the hold counter the loop keeps in place of the log // line, which is also how an operator sees a held subscriber now. func heldReads(scopes ...string) int { if len(scopes) == 0 { scopes = []string{"memory", "disk"} } var total int for _, scope := range scopes { total += int(testutil.ToFloat64(stats.FilerSubscribeWatermarkHolds.WithLabelValues(scope))) } return total } // waitForEventsAtLeastOnce asserts every want arrives, in order. The cursor a // hold rewinds to is inclusive of the last delivered entry, so each cycle // repeats it - at-least-once, which is the contract; a skip is not. func waitForEventsAtLeastOnce(t *testing.T, r *runningSubscribe, want []int64, timeout time.Duration) { t.Helper() last := want[len(want)-1] deadline := time.Now().Add(timeout) var got []int64 for time.Now().Before(deadline) { got = eventTimestamps(r.stream.snapshot()) if len(got) > 0 && got[len(got)-1] >= last { break } time.Sleep(10 * time.Millisecond) } seen := make(map[int64]bool, len(got)) var prev int64 for _, ts := range got { if ts < prev { t.Fatalf("delivered %v after %v: out of order", time.Unix(0, ts), time.Unix(0, prev)) } prev, seen[ts] = ts, true } for i, ts := range want { if !seen[ts] { t.Fatalf("event %d of %d (%v) never delivered", i+1, len(want), time.Unix(0, ts)) } } } // TestSubscribeLoop_AggregatedHoldIsQuiet: every held read used to log an // ERROR, so a busy cluster wrote one line per arriving event. func TestSubscribeLoop_AggregatedHoldIsQuiet(t *testing.T) { h := newSubscribeHarness(t) ma, r, _ := h.heldSubscriber() errorsBefore := glog.Stats.Error.Lines() written, elapsed := h.writeFor(ma, time.Second, false) errorLines := glog.Stats.Error.Lines() - errorsBefore t.Logf("%d writes over %v produced %d ERROR lines", len(written), elapsed, errorLines) if errorLines > 0 { t.Fatalf("a held read logged %d ERROR lines over %d writes; holds are control flow", errorLines, len(written)) } if got := eventTimestamps(r.stream.snapshot()); len(got) > 0 { t.Fatalf("delivered %d events past the peers' watermark", len(got)) } } // TestSubscribeLoop_AggregatedHoldIsPaced is the other half: a held read used // to wait on the buffer's data channel, which the very next write signalled, // so the loop re-ran a whole pass - a log file listing in it - per event. // Arriving data cannot release a hold; only peer progress can. func TestSubscribeLoop_AggregatedHoldIsPaced(t *testing.T) { h := newSubscribeHarness(t) // Long enough that a hold paced by the retry interval alone is far below // one hold per write, short enough to keep the test quick. prevRetry := unflushedGapRetryInterval unflushedGapRetryInterval = 200 * time.Millisecond t.Cleanup(func() { unflushedGapRetryInterval = prevRetry }) ma, _, _ := h.heldSubscriber() holdsBefore := heldReads() written, elapsed := h.writeFor(ma, time.Second, false) holds := heldReads() - holdsBefore t.Logf("%d writes over %v produced %d holds", len(written), elapsed, holds) // The watermarks never moved, so the retry interval alone paces the holds. if maxHolds := int(elapsed/unflushedGapRetryInterval) + 2; holds > maxHolds { t.Fatalf("held %d times in %v, want at most %d: a hold must wait for peer progress, not for the next write", holds, elapsed, maxHolds) } } // TestSubscribeLoop_AggregatedHoldReleasesOnPeerProgress pins what pacing the // hold may not cost: once the peers report through the held entry it must be // delivered, without waiting out the retry interval. func TestSubscribeLoop_AggregatedHoldReleasesOnPeerProgress(t *testing.T) { h := newSubscribeHarness(t) // Far longer than this test runs: only the watermark signal can deliver. prevRetry := unflushedGapRetryInterval unflushedGapRetryInterval = 30 * time.Second t.Cleanup(func() { unflushedGapRetryInterval = prevRetry }) ma, r, _ := h.heldSubscriber() ts := time.Now().UnixNano() h.appendAggregated(ts) assertNoEventsFor(t, r, 200*time.Millisecond) reportPeers(ma, ts) waitForEvents(t, r, []int64{ts}, 3*time.Second) } // TestSubscribeLoop_AggregatedHoldCoalescesPeerProgress covers the rest of the // cost: peers advance their watermark on every event they stream, so releasing // a hold per advance is the same pass-per-event storm as releasing per write, // just without the log lines. func TestSubscribeLoop_AggregatedHoldCoalescesPeerProgress(t *testing.T) { h := newSubscribeHarness(t) ma, r, _ := h.heldSubscriber() holdsBefore := heldReads() written, elapsed := h.writeFor(ma, time.Second, true) holds := heldReads() - holdsBefore t.Logf("%d writes over %v produced %d holds", len(written), elapsed, holds) if maxHolds := int(elapsed/heldWakeFloor) + 2; holds > maxHolds { t.Fatalf("held %d times in %v, want at most %d: releases must coalesce", holds, elapsed, maxHolds) } // Coalescing may not lose anything the peers reported through. waitForEventsAtLeastOnce(t, r, written, 3*time.Second) } // TestPeerDeliveryClaimPacing pins what a filer with peers owes them: the idle // heartbeat on its local stream is a delivery claim every aggregated // subscriber in the cluster holds at, so it refreshes at the claim interval, // not at the keepalive interval that used to park them ~5s behind live writes. func TestPeerDeliveryClaimPacing(t *testing.T) { h := newSubscribeHarness(t) req := &filer_pb.SubscribeMetadataRequest{ClientSupportsIdleHeartbeat: true} lb := h.f.LocalMetaLogBuffer // Claimed a second ago: stale for a delivery claim, fresh for a keepalive. claimedAtNs := time.Now().Add(-time.Second).UnixNano() s := &collectingStream{} if got := h.fs.maybeSendIdleHeartbeat(req, s, lb, 0, 0, claimedAtNs); got != claimedAtNs || len(s.messages) != 0 { t.Fatalf("standalone filer sent %d heartbeats early", len(s.messages)) } h.startAggregator() s = &collectingStream{} if got := h.fs.maybeSendIdleHeartbeat(req, s, lb, 0, 0, claimedAtNs); got == claimedAtNs || len(s.messages) != 1 { t.Fatalf("filer with peers sent %d delivery claims, want 1", len(s.messages)) } if s.messages[0].TsNs <= claimedAtNs { t.Fatalf("claim ts %d did not advance past %d", s.messages[0].TsNs, claimedAtNs) } } // TestSubscribeLoop_AggregatedDiskHoldIgnoresDeliveryProgress pins that each // hold parks on its own watermark. A persisted-log read is held by what the // peers have FLUSHED, and peers advance their DELIVERY watermark on every // event they stream, so waking it on delivery progress would re-list a day of // log files per event and re-park on the same entry. func TestSubscribeLoop_AggregatedDiskHoldIgnoresDeliveryProgress(t *testing.T) { h := newSubscribeHarness(t) prevRetry := unflushedGapRetryInterval unflushedGapRetryInterval = 500 * time.Millisecond t.Cleanup(func() { unflushedGapRetryInterval = prevRetry }) // Recent enough that the settled horizon does not take the hold over. onDisk := time.Now().Add(-30 * time.Second).UnixNano() h.append(onDisk) h.f.LocalMetaLogBuffer.ForceFlush() waitForFlushedFiles(t, h, onDisk) ma := h.startAggregator() // Flushed below the entry on disk, delivered well past it: only the disk // pass is held. reportPeersAt(ma, time.Now().UnixNano(), onDisk-int64(time.Second)) r := h.subscribeAggregated(onDisk - int64(5*time.Second)) assertNoEventsFor(t, r, 200*time.Millisecond) holdsBefore := heldReads("disk") start := time.Now() for deadline := start.Add(time.Second); time.Now().Before(deadline); { reportPeersAt(ma, time.Now().UnixNano(), 0) time.Sleep(2 * time.Millisecond) } holds, elapsed := heldReads("disk")-holdsBefore, time.Since(start) t.Logf("%v of delivery-only progress produced %d disk holds", elapsed, holds) if maxHolds := int(elapsed/unflushedGapRetryInterval) + 2; holds > maxHolds { t.Fatalf("held on disk %d times in %v, want at most %d: delivery progress cannot release a flush hold", holds, elapsed, maxHolds) } // The flush watermark reaching the entry is what delivers it. reportPeersAt(ma, 0, onDisk) waitForEvents(t, r, []int64{onDisk}, 3*time.Second) }