seaweedfs/weed/server/filer_subscribe_agg_test.go

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)
}