seaweedfs/weed/pb/filer_pb_tail_test.go

package pb

import (
	"bytes"
	"context"
	"errors"
	"fmt"
	"io"
	"sync"
	"sync/atomic"
	"testing"
	"time"

	"github.com/seaweedfs/seaweedfs/weed/pb/filer_pb"
	"github.com/seaweedfs/seaweedfs/weed/util"
	"google.golang.org/grpc"
	"google.golang.org/protobuf/proto"
)

// fakeSubscribeStream plays back a scripted sequence of responses, one per Recv.
type fakeSubscribeStream struct {
	grpc.ClientStream
	responses []*filer_pb.SubscribeMetadataResponse
	delay     time.Duration
	idx       int
}

func (s *fakeSubscribeStream) Recv() (*filer_pb.SubscribeMetadataResponse, error) {
	if s.idx >= len(s.responses) {
		return nil, io.EOF
	}
	if s.idx > 0 && s.delay > 0 {
		// advance the wall clock so AddOffsetFunc's interval gate opens
		time.Sleep(s.delay)
	}
	r := s.responses[s.idx]
	s.idx++
	return r, nil
}

// fakeFilerClient only needs SubscribeMetadata; the embedded nil interface
// covers the rest, which makeSubscribeMetadataFunc never calls.
type fakeFilerClient struct {
	filer_pb.SeaweedFilerClient
	stream *fakeSubscribeStream
}

func (c *fakeFilerClient) SubscribeMetadata(ctx context.Context, in *filer_pb.SubscribeMetadataRequest, opts ...grpc.CallOption) (grpc.ServerStreamingClient[filer_pb.SubscribeMetadataResponse], error) {
	return c.stream, nil
}

// TestFilerSyncOffsetStaysFreshOnFilteredMarker: on a read-only watched path with
// a busy source, the MaxUnsyncedEvents marker (empty EventNotification, fresh
// timestamp) must be treated as a freshness signal, not fed to the offset path
// where it would pin the gauge to the stale watermark. Wiring mirrors filer.sync.
func TestFilerSyncOffsetStaysFreshOnFilteredMarker(t *testing.T) {
	const oldEventTs = int64(1_000_000_000) // t0: last real synced event (stale)
	nowTs := time.Now().UnixNano()          // current source time
	markerTs := nowTs + int64(time.Second)

	var watermark = oldEventTs // MetadataProcessor.processedTsWatermark

	type gaugeWrite struct {
		src string
		ts  int64
	}
	var timeline []gaugeWrite
	var heartbeatCalls, markerToProcessFn int

	// This consumer sets no resume callback, so markers keep moving StartTsNs
	// and never reach processEventFn; the callback path is checked in
	// TestFilerSyncMarkerReachesCallbackConsumer.
	realProcessFn := func(resp *filer_pb.SubscribeMetadataResponse) error {
		if filer_pb.IsEmpty(resp) {
			markerToProcessFn++
			return nil
		}
		watermark = resp.TsNs
		return nil
	}
	// offsetFunc publishes the watermark to the gauge (filer_sync.go).
	processEventFn := AddOffsetFunc(realProcessFn, 0, func(counter, lastTsNs int64) error {
		timeline = append(timeline, gaugeWrite{"offset", watermark})
		return nil
	})

	option := &MetadataFollowOption{
		ClientName:     "syncFrom_A_To_B",
		StartTsNs:      oldEventTs,
		EventErrorType: DontLogError,
		OnIdleHeartbeat: func(tsNs int64) {
			heartbeatCalls++
			timeline = append(timeline, gaugeWrite{"heartbeat", tsNs})
		},
	}

	stream := &fakeSubscribeStream{
		delay: 2 * time.Millisecond,
		responses: []*filer_pb.SubscribeMetadataResponse{
			// real create on the watched path, long ago -> watermark = t0
			{Directory: "/watched", TsNs: oldEventTs, EventNotification: &filer_pb.EventNotification{
				NewEntry: &filer_pb.Entry{Name: "file"},
			}},
			// genuine idle heartbeat
			{TsNs: nowTs},
			// MaxUnsyncedEvents marker: empty EventNotification, fresh timestamp
			{TsNs: markerTs, EventNotification: &filer_pb.EventNotification{}},
		},
	}

	if err := makeSubscribeMetadataFunc(option, processEventFn)(&fakeFilerClient{stream: stream}); err != nil {
		t.Fatalf("follow: %v", err)
	}

	t.Logf("gauge timeline: %+v", timeline)

	// the marker fires OnIdleHeartbeat instead of reaching processEventFn
	if markerToProcessFn != 0 {
		t.Errorf("empty marker must not reach processEventFn, got %d calls", markerToProcessFn)
	}
	if heartbeatCalls != 2 {
		t.Errorf("expected OnIdleHeartbeat for both the heartbeat and the marker (2), got %d", heartbeatCalls)
	}
	if option.StartTsNs != markerTs {
		t.Errorf("marker should advance StartTsNs to %d, got %d", markerTs, option.StartTsNs)
	}

	// gauge stays fresh: last write is the marker's timestamp, not the stale watermark
	last := timeline[len(timeline)-1]
	if last.src != "heartbeat" || last.ts != markerTs {
		t.Fatalf("expected final gauge write fresh at %d, got %+v (spike is back if stale %d)", markerTs, last, oldEventTs)
	}
}

// TestFilerSyncBatchedFreshnessSignalDoesNotCrash: while catching up after a
// peer outage the server folds a backlog into one batched response: the first
// event in the top-level fields, the rest in resp.Events. The drain can pull an
// idle heartbeat (nil EventNotification) into that tail. The batched tail must
// get the same freshness-signal handling as the envelope, else processEventFn
// (filer.sync's AddSyncJob) nil-derefs in IsEmpty. The processEventFn here
// mirrors that first call.
func TestFilerSyncBatchedFreshnessSignalDoesNotCrash(t *testing.T) {
	const ts1 = int64(1_000_000_000)      // envelope: real create
	const ts2 = int64(1_000_000_001)      // batched: real create
	const markerTs = int64(1_000_000_002) // batched: MaxUnsyncedEvents marker (empty entry)
	hbTs := time.Now().UnixNano()         // batched: idle heartbeat (nil EventNotification), fresh

	var realEvents []int64
	var heartbeatTs []int64

	// Mirrors AddSyncJob: IsEmpty nil-derefs on a nil EventNotification.
	processEventFn := func(resp *filer_pb.SubscribeMetadataResponse) error {
		if filer_pb.IsEmpty(resp) {
			return nil
		}
		realEvents = append(realEvents, resp.TsNs)
		return nil
	}

	option := &MetadataFollowOption{
		ClientName:     "syncFrom_A_To_B",
		StartTsNs:      ts1,
		EventErrorType: DontLogError,
		OnIdleHeartbeat: func(tsNs int64) {
			heartbeatTs = append(heartbeatTs, tsNs)
		},
	}

	// One batched response: envelope plus a tail mixing a real event, a marker,
	// and a fresh heartbeat, as the server emits while draining a backlog. The
	// heartbeat is last and carries the largest timestamp on purpose.
	stream := &fakeSubscribeStream{
		responses: []*filer_pb.SubscribeMetadataResponse{{
			Directory:         "/watched",
			TsNs:              ts1,
			EventNotification: &filer_pb.EventNotification{NewEntry: &filer_pb.Entry{Name: "a"}},
			Events: []*filer_pb.SubscribeMetadataResponse{
				{Directory: "/watched", TsNs: ts2, EventNotification: &filer_pb.EventNotification{NewEntry: &filer_pb.Entry{Name: "b"}}},
				{TsNs: markerTs, EventNotification: &filer_pb.EventNotification{}}, // marker: empty entry
				{TsNs: hbTs}, // idle heartbeat: nil EventNotification
			},
		}},
	}

	if err := makeSubscribeMetadataFunc(option, processEventFn)(&fakeFilerClient{stream: stream}); err != nil {
		t.Fatalf("follow: %v", err)
	}

	// Both real events reached processEventFn; neither freshness signal did.
	if len(realEvents) != 2 || realEvents[0] != ts1 || realEvents[1] != ts2 {
		t.Errorf("expected real events [%d %d], got %v", ts1, ts2, realEvents)
	}
	// The batched marker and heartbeat both fired OnIdleHeartbeat.
	if len(heartbeatTs) != 2 || heartbeatTs[0] != markerTs || heartbeatTs[1] != hbTs {
		t.Errorf("expected heartbeats [%d %d], got %v", markerTs, hbTs, heartbeatTs)
	}
	// The marker advances the resume cursor; the heartbeat does not, even though
	// it is last and carries the largest timestamp. StartTsNs ends at the marker.
	if option.StartTsNs != markerTs {
		t.Errorf("expected StartTsNs %d (marker), got %d (heartbeat must not advance the cursor)", markerTs, option.StartTsNs)
	}
}

// TestFilerSyncResumeFromProcessedWatermarkOnReconnect verifies that when GetResumeTsNs is
// configured, reconnection uses the processed watermark instead of skipping ahead to the
// latest received timestamp.
func TestFilerSyncResumeFromProcessedWatermarkOnReconnect(t *testing.T) {
	const initialTs = int64(100)
	const watermarkTs = int64(200)
	const latestStreamTs = int64(500)

	var capturedSinceNs int64
	recordingClient := &recordingFilerClient{
		onSubscribe: func(req *filer_pb.SubscribeMetadataRequest) {
			capturedSinceNs = req.SinceNs
		},
		stream: &fakeSubscribeStream{
			responses: []*filer_pb.SubscribeMetadataResponse{
				{
					Directory:         "/watched",
					TsNs:              latestStreamTs,
					EventNotification: &filer_pb.EventNotification{NewEntry: &filer_pb.Entry{Name: "file"}},
				},
			},
		},
	}

	option := &MetadataFollowOption{
		ClientName: "syncFrom_A_To_B",
		StartTsNs:  initialTs,
		GetResumeTsNs: func() int64 {
			return watermarkTs
		},
	}

	processFn := func(resp *filer_pb.SubscribeMetadataResponse) error {
		return nil
	}

	fn := makeSubscribeMetadataFunc(option, processFn)
	if err := fn(recordingClient); err != nil {
		t.Fatalf("unexpected error: %v", err)
	}

	if capturedSinceNs != watermarkTs {
		t.Fatalf("expected subscribe SinceNs to be watermark %d, got %d", watermarkTs, capturedSinceNs)
	}
	// StartTsNs must not be mutated when GetResumeTsNs is set
	if option.StartTsNs != initialTs {
		t.Fatalf("expected option.StartTsNs to remain %d, got %d", initialTs, option.StartTsNs)
	}
}

// TestFilerSyncDoesNotAdvanceStartTsNsOnProcessError verifies that a failing synchronous
// processEventFn does not advance option.StartTsNs past the failed event.
func TestFilerSyncDoesNotAdvanceStartTsNsOnProcessError(t *testing.T) {
	const initialTs = int64(100)
	const failedTs = int64(200)

	option := &MetadataFollowOption{
		ClientName:     "syncFrom_A_To_B",
		StartTsNs:      initialTs,
		EventErrorType: TrivialOnError,
	}

	stream := &fakeSubscribeStream{
		responses: []*filer_pb.SubscribeMetadataResponse{
			{
				Directory:         "/watched",
				TsNs:              failedTs,
				EventNotification: &filer_pb.EventNotification{NewEntry: &filer_pb.Entry{Name: "bad"}},
			},
		},
	}

	processFn := func(resp *filer_pb.SubscribeMetadataResponse) error {
		return io.ErrUnexpectedEOF
	}

	fn := makeSubscribeMetadataFunc(option, processFn)
	_ = fn(&fakeFilerClient{stream: stream})

	if option.StartTsNs != initialTs {
		t.Fatalf("expected StartTsNs to stay at %d on error, got %d", initialTs, option.StartTsNs)
	}
}

type recordingFilerClient struct {
	filer_pb.SeaweedFilerClient
	onSubscribe func(req *filer_pb.SubscribeMetadataRequest)
	stream      *fakeSubscribeStream
}

func (c *recordingFilerClient) SubscribeMetadata(ctx context.Context, in *filer_pb.SubscribeMetadataRequest, opts ...grpc.CallOption) (grpc.ServerStreamingClient[filer_pb.SubscribeMetadataResponse], error) {
	if c.onSubscribe != nil {
		c.onSubscribe(in)
	}
	return c.stream, nil
}

// RetryForeverOnError resolves a failure inside handleErr, so the cursor must
// still move past the recovered event instead of replaying it on reconnect.
func TestFilerSyncRecoveredEventAdvancesCursor(t *testing.T) {
	var calls int
	processFn := func(resp *filer_pb.SubscribeMetadataResponse) error {
		calls++
		if calls == 1 {
			return io.ErrUnexpectedEOF
		}
		return nil
	}
	option := &MetadataFollowOption{
		ClientName:     "syncFrom_A_To_B",
		StartTsNs:      100,
		EventErrorType: RetryForeverOnError,
	}
	stream := &fakeSubscribeStream{
		responses: []*filer_pb.SubscribeMetadataResponse{
			{Directory: "/watched", TsNs: 300, EventNotification: &filer_pb.EventNotification{
				NewEntry: &filer_pb.Entry{Name: "file"},
			}},
		},
	}
	if err := makeSubscribeMetadataFunc(option, processFn)(&fakeFilerClient{stream: stream}); err != nil {
		t.Fatalf("follow: %v", err)
	}
	if calls != 2 {
		t.Fatalf("expected the event retried once (2 calls), got %d", calls)
	}
	if option.StartTsNs != 300 {
		t.Fatalf("expected StartTsNs 300 after the retry succeeded, got %d", option.StartTsNs)
	}
}

// A consumer with a resume callback keeps its cursor in its processed
// watermark, so a filtered-progress marker is handed to processEventFn (which
// can count it as processed) instead of mutating StartTsNs.
func TestFilerSyncMarkerReachesCallbackConsumer(t *testing.T) {
	var markers, events int
	option := &MetadataFollowOption{
		ClientName: "syncFrom_A_To_B",
		StartTsNs:  100,
		GetResumeTsNs: func() int64 {
			return 100
		},
	}
	stream := &fakeSubscribeStream{
		responses: []*filer_pb.SubscribeMetadataResponse{
			{Directory: "/watched", TsNs: 300, EventNotification: &filer_pb.EventNotification{
				NewEntry: &filer_pb.Entry{Name: "file"},
			}},
			{TsNs: 500, EventNotification: &filer_pb.EventNotification{}},
		},
	}
	fn := makeSubscribeMetadataFunc(option, func(resp *filer_pb.SubscribeMetadataResponse) error {
		if filer_pb.IsEmpty(resp) {
			markers++
		} else {
			events++
		}
		return nil
	})
	if err := fn(&fakeFilerClient{stream: stream}); err != nil {
		t.Fatalf("follow: %v", err)
	}
	if markers != 1 || events != 1 {
		t.Fatalf("expected 1 marker and 1 event at processEventFn, got %d and %d", markers, events)
	}
	if option.StartTsNs != 100 {
		t.Fatalf("callback consumer must not mutate StartTsNs, got %d", option.StartTsNs)
	}
}

func TestFilerSyncMarkerCallbackRetries(t *testing.T) {
	var calls int
	option := &MetadataFollowOption{
		StartTsNs:      100,
		EventErrorType: RetryForeverOnError,
		GetResumeTsNs:  func() int64 { return 100 },
	}
	stream := &fakeSubscribeStream{responses: []*filer_pb.SubscribeMetadataResponse{
		{TsNs: 500, EventNotification: &filer_pb.EventNotification{}},
	}}
	fn := makeSubscribeMetadataFunc(option, func(resp *filer_pb.SubscribeMetadataResponse) error {
		calls++
		if calls == 1 {
			return io.ErrUnexpectedEOF
		}
		return nil
	})
	if err := fn(&fakeFilerClient{stream: stream}); err != nil {
		t.Fatalf("follow: %v", err)
	}
	if calls != 2 || option.StartTsNs != 100 {
		t.Fatalf("calls = %d, cursor = %d; want 2 calls and unchanged cursor 100", calls, option.StartTsNs)
	}
}

// Each subscribe call re-reads the callback, so a reconnect after the consumer
// made progress resumes from the newer watermark.
func TestFilerSyncReconnectReadsWatermarkEachSubscribe(t *testing.T) {
	var watermark atomic.Int64
	watermark.Store(100)
	var sinceNs []int64
	var mu sync.Mutex
	stream := &fakeSubscribeStream{
		responses: []*filer_pb.SubscribeMetadataResponse{
			{Directory: "/watched", TsNs: 300, EventNotification: &filer_pb.EventNotification{
				NewEntry: &filer_pb.Entry{Name: "file"},
			}},
		},
	}
	client := &recordingFilerClient{
		onSubscribe: func(req *filer_pb.SubscribeMetadataRequest) {
			mu.Lock()
			sinceNs = append(sinceNs, req.SinceNs)
			mu.Unlock()
		},
		stream: stream,
	}
	option := &MetadataFollowOption{
		ClientName: "syncFrom_A_To_B",
		StartTsNs:  100,
		GetResumeTsNs: func() int64 {
			return watermark.Load()
		},
	}
	fn := makeSubscribeMetadataFunc(option, func(resp *filer_pb.SubscribeMetadataResponse) error {
		watermark.Store(resp.TsNs)
		return nil
	})
	if err := fn(client); err != nil {
		t.Fatalf("first subscribe: %v", err)
	}
	client.stream = &fakeSubscribeStream{}
	if err := fn(client); err != nil {
		t.Fatalf("resubscribe: %v", err)
	}
	mu.Lock()
	defer mu.Unlock()
	if len(sinceNs) != 2 || sinceNs[0] != 100 || sinceNs[1] != 300 {
		t.Fatalf("expected subscribes at 100 then 300, got %v", sinceNs)
	}
}

// A drained ref batch must leave StartTsNs at the settled checkpoint even when
// the last entry's own timestamp lags its log position, so the next drain does
// not re-read the settled prefix.
func TestChunkDrainCursorKeepsProgressCheckpoint(t *testing.T) {
	event := &filer_pb.SubscribeMetadataResponse{
		Directory: "/watched",
		TsNs:      100,
		EventNotification: &filer_pb.EventNotification{
			NewEntry: &filer_pb.Entry{Name: "file"},
		},
	}
	eventData, err := proto.Marshal(event)
	if err != nil {
		t.Fatalf("marshal event: %v", err)
	}
	entryData, err := (&filer_pb.LogEntry{TsNs: 300, Data: eventData}).MarshalVT()
	if err != nil {
		t.Fatalf("marshal log entry: %v", err)
	}
	var buf bytes.Buffer
	var sizeBuf [4]byte
	util.Uint32toBytes(sizeBuf[:], uint32(len(entryData)))
	buf.Write(sizeBuf[:])
	buf.Write(entryData)

	option := &MetadataFollowOption{
		ClientName: "mount",
		StartTsNs:  0,
		PathPrefix: "/",
		LogFileReaderFn: func(chunks []*filer_pb.FileChunk) (io.ReadCloser, error) {
			return io.NopCloser(bytes.NewReader(buf.Bytes())), nil
		},
	}
	stream := &fakeSubscribeStream{responses: []*filer_pb.SubscribeMetadataResponse{
		{LogFileRefs: []*filer_pb.LogFileChunkRef{
			{FilerId: "f0", Chunks: []*filer_pb.FileChunk{{FileId: "1,01"}}},
		}},
	}}
	if err := makeSubscribeMetadataFunc(option, func(*filer_pb.SubscribeMetadataResponse) error {
		return nil
	})(&fakeFilerClient{stream: stream}); err != nil {
		t.Fatalf("follow: %v", err)
	}
	if option.StartTsNs != 300 {
		t.Fatalf("expected StartTsNs at the settled checkpoint 300, got %d", option.StartTsNs)
	}
}

// blockingFilerClient returns a stream whose Recv parks until the subscribe
// context ends, standing in for a quiet source stream during a sink outage.
type blockingFilerClient struct {
	filer_pb.SeaweedFilerClient
}

func (c *blockingFilerClient) SubscribeMetadata(ctx context.Context, in *filer_pb.SubscribeMetadataRequest, opts ...grpc.CallOption) (grpc.ServerStreamingClient[filer_pb.SubscribeMetadataResponse], error) {
	return &blockingSubscribeStream{ctx: ctx}, nil
}

type blockingSubscribeStream struct {
	grpc.ClientStream
	ctx context.Context
}

func (s *blockingSubscribeStream) Recv() (*filer_pb.SubscribeMetadataResponse, error) {
	<-s.ctx.Done()
	return nil, s.ctx.Err()
}

// A consumer that pins an event asks for the stream to drop so the reconnect
// replays it; the follower must end with ErrResubscribe, not sit on Recv.
func TestFilerSyncResubscribeSignalEndsStream(t *testing.T) {
	resubscribe := make(chan struct{})
	option := &MetadataFollowOption{
		ClientName:     "syncFrom_A_To_B",
		EventErrorType: DontLogError,
		Resubscribe:    resubscribe,
	}
	fn := makeSubscribeMetadataFunc(option, func(resp *filer_pb.SubscribeMetadataResponse) error {
		return nil
	})
	done := make(chan error, 1)
	go func() {
		done <- fn(&blockingFilerClient{})
	}()

	close(resubscribe)

	select {
	case err := <-done:
		if !errors.Is(err, ErrResubscribe) {
			t.Fatalf("expected ErrResubscribe, got %v", err)
		}
	case <-time.After(5 * time.Second):
		t.Fatal("follower did not end after the resubscribe signal")
	}
}

// A dropped stream mid-replay must keep the checkpoints the drain already
// settled: the resubscribe's SinceNs resumes at the last settled entry
// instead of re-reading the whole ref set.
func TestChunkReplayCheckpointSurvivesReconnect(t *testing.T) {
	var events []*filer_pb.SubscribeMetadataResponse
	for i, ts := range []int64{101, 102, 103, 104} {
		events = append(events, makeSubEvent("/watched", fmt.Sprintf("f%d", i), ts))
	}
	logData := buildLogFileData(events)
	refsResp := &filer_pb.SubscribeMetadataResponse{
		LogFileRefs: []*filer_pb.LogFileChunkRef{{
			FilerId: "f0",
			Chunks:  []*filer_pb.FileChunk{{FileId: "log-1"}},
		}},
	}
	markerResp := &filer_pb.SubscribeMetadataResponse{
		EventNotification: &filer_pb.EventNotification{},
		TsNs:              200,
	}
	option := &MetadataFollowOption{
		ClientName: "mount",
		StartTsNs:  100,
		PathPrefix: "/watched/",
		LogFileReaderFn: func(chunks []*filer_pb.FileChunk) (io.ReadCloser, error) {
			return io.NopCloser(bytes.NewReader(logData)), nil
		},
	}

	var sinceNs []int64
	client := &recordingFilerClient{
		onSubscribe: func(req *filer_pb.SubscribeMetadataRequest) {
			sinceNs = append(sinceNs, req.SinceNs)
		},
		stream: &fakeSubscribeStream{responses: []*filer_pb.SubscribeMetadataResponse{refsResp, markerResp}},
	}

	count := 0
	wantErr := fmt.Errorf("apply boom")
	err := makeSubscribeMetadataFunc(option, func(resp *filer_pb.SubscribeMetadataResponse) error {
		count++
		if count == 3 {
			return wantErr
		}
		return nil
	})(client)
	if !errors.Is(err, ErrLogFileRead) {
		t.Fatalf("expected ErrLogFileRead, got %v", err)
	}
	// Entries 101 and 102 settled; 102's checkpoint emits when 103 pops, but
	// 103 failed first, so the last checkpoint is 101.
	if option.StartTsNs != 101 {
		t.Fatalf("StartTsNs = %d, want 101", option.StartTsNs)
	}

	client.stream = &fakeSubscribeStream{}
	if err := makeSubscribeMetadataFunc(option, func(*filer_pb.SubscribeMetadataResponse) error {
		return nil
	})(client); err != nil {
		t.Fatalf("resubscribe: %v", err)
	}
	if len(sinceNs) != 2 || sinceNs[0] != 100 || sinceNs[1] != 101 {
		t.Fatalf("expected subscribes at 100 then 101, got %v", sinceNs)
	}
}