fix(filer.sync): keep sync_offset fresh while the source is read-only (#9589)

* fix(filer.sync): keep sync_offset fresh while the source is read-only

sync_offset holds the timestamp of the last replicated source event, so
monitoring derives lag from now-sync_offset. A read-only source emits no
metadata events, so the gauge froze at the last write and the derived lag
grew without bound, making thresholds unusable.

The source filer now sends an idle heartbeat carrying its current time
while a subscriber is caught up to the buffer head. filer.sync uses it to
advance the gauge, so now-sync_offset reflects real lag. Heartbeats are
opt-in (client_supports_idle_heartbeat), are never written to the metadata
log, and do not move the resume checkpoint, so a restart still resumes
from the last real event.

* fix(filer.sync): gate idle heartbeat on the read cursor, not SinceNs

In metadata-chunks mode persisted entries replay as log file refs and
never reach eachLogEntryFn, so lastSeenTsNs stays put and a caught-up
subscriber with an old SinceNs would never get a heartbeat. Use the
read cursor (lastReadTime), which advances in that mode too, max'd with
lastSeenTsNs so the in-memory backlog-then-idle case still works while
the cursor returned to the caller has not yet updated.

weed/server/filer_grpc_server_sub_meta.go

@@ -22,6 +22,12 @@ import (
 const (
 	// MaxUnsyncedEvents send empty notification with timestamp when certain amount of events have been filtered
 	MaxUnsyncedEvents = 1e3
+
+	// idleHeartbeatInterval bounds how often a caught-up subscriber that asked
+	// for idle heartbeats is reminded that the source is alive and has nothing
+	// newer. It keeps freshness signals such as filer.sync's sync_offset metric
+	// from looking stuck during read-only periods on the source.
+	idleHeartbeatInterval = 5 * time.Second
 )
 
 // metadataStreamSender is satisfied by both gRPC stream types and pipelinedSender.
@@ -186,7 +192,16 @@ func (fs *FilerServer) SubscribeMetadata(req *filer_pb.SubscribeMetadataRequest,
 
 	eachEventNotificationFn := fs.eachEventNotificationFn(req, sender, clientName)
 
-	eachLogEntryFn := eachLogEntryFn(eachEventNotificationFn)
+	// lastSeenTsNs tracks how far the subscriber has read so idle heartbeats are
+	// only emitted once it is caught up to the buffer head. It is read and
+	// written from this single goroutine, so no synchronization is needed.
+	var lastSeenTsNs int64
+	var lastHeartbeatNs int64
+	baseEachLogEntryFn := eachLogEntryFn(eachEventNotificationFn)
+	eachLogEntryFn := func(logEntry *filer_pb.LogEntry) (bool, error) {
+		lastSeenTsNs = logEntry.TsNs
+		return baseEachLogEntryFn(logEntry)
+	}
 
 	var processedTsNs int64
 	var readPersistedLogErr error
@@ -248,7 +263,11 @@ func (fs *FilerServer) SubscribeMetadata(req *filer_pb.SubscribeMetadataRequest,
 				return false
 			default:
 			}
-			return fs.hasClient(req.ClientId, req.ClientEpoch)
+			if !fs.hasClient(req.ClientId, req.ClientEpoch) {
+				return false
+			}
+			lastHeartbeatNs = fs.maybeSendIdleHeartbeat(req, sender, fs.filer.MetaAggregator.MetaLogBuffer, lastReadTime.Time.UnixNano(), lastSeenTsNs, lastHeartbeatNs)
+			return true
 		}, eachLogEntryFn)
 		if readInMemoryLogErr != nil {
 			if errors.Is(readInMemoryLogErr, log_buffer.ResumeFromDiskError) {
@@ -314,7 +333,16 @@ func (fs *FilerServer) SubscribeLocalMetadata(req *filer_pb.SubscribeMetadataReq
 
 	eachEventNotificationFn := fs.eachEventNotificationFn(req, sender, clientName)
 
-	eachLogEntryFn := eachLogEntryFn(eachEventNotificationFn)
+	// lastSeenTsNs tracks how far the subscriber has read so idle heartbeats are
+	// only emitted once it is caught up to the buffer head. It is read and
+	// written from this single goroutine, so no synchronization is needed.
+	var lastSeenTsNs int64
+	var lastHeartbeatNs int64
+	baseEachLogEntryFn := eachLogEntryFn(eachEventNotificationFn)
+	eachLogEntryFn := func(logEntry *filer_pb.LogEntry) (bool, error) {
+		lastSeenTsNs = logEntry.TsNs
+		return baseEachLogEntryFn(logEntry)
+	}
 
 	var processedTsNs int64
 	var readPersistedLogErr error
@@ -400,7 +428,11 @@ func (fs *FilerServer) SubscribeLocalMetadata(req *filer_pb.SubscribeMetadataReq
 				return false
 			default:
 			}
-			return fs.hasClient(req.ClientId, req.ClientEpoch)
+			if !fs.hasClient(req.ClientId, req.ClientEpoch) {
+				return false
+			}
+			lastHeartbeatNs = fs.maybeSendIdleHeartbeat(req, sender, fs.filer.LocalMetaLogBuffer, lastReadTime.Time.UnixNano(), lastSeenTsNs, lastHeartbeatNs)
+			return true
 		}, eachLogEntryFn)
 		if readInMemoryLogErr != nil {
 			if readInMemoryLogErr == log_buffer.ResumeFromDiskError {
@@ -474,6 +506,45 @@ func eachLogEntryFn(eachEventNotificationFn func(dirPath string, eventNotificati
 	}
 }
 
+// maybeSendIdleHeartbeat emits an empty response carrying the current time when
+// the subscriber has consumed everything up to the buffer head. The client uses
+// it to advance freshness signals (e.g. filer.sync's sync_offset) without moving
+// its resume checkpoint, so a restart still re-reads from the last real event.
+//
+// The catch-up floor is the max of two read-progress markers:
+//   - readPositionTsNs: how far the read cursor has advanced. It starts at
+//     SinceNs and also covers metadata-chunks mode, where persisted entries are
+//     replayed as log file refs rather than through eachLogEntryFn.
+//   - lastSeenTsNs: the timestamp of the most recent entry streamed in this
+//     call. It advances live while reading the in-memory backlog, before the
+//     read cursor returned by LoopProcessLogData has been updated.
+//
+// While the buffer head is past that floor the subscriber is still behind (e.g.
+// replaying a backlog) and no heartbeat is sent. Returns the (possibly advanced)
+// lastHeartbeatNs.
+func (fs *FilerServer) maybeSendIdleHeartbeat(req *filer_pb.SubscribeMetadataRequest, sender metadataStreamSender, logBuffer *log_buffer.LogBuffer, readPositionTsNs, lastSeenTsNs, lastHeartbeatNs int64) int64 {
+	if !req.ClientSupportsIdleHeartbeat {
+		return lastHeartbeatNs
+	}
+	floorTsNs := lastSeenTsNs
+	if readPositionTsNs > floorTsNs {
+		floorTsNs = readPositionTsNs
+	}
+	if logBuffer.LastTsNs.Load() > floorTsNs {
+		// the buffer holds data the subscriber has not reached yet
+		return lastHeartbeatNs
+	}
+	now := time.Now().UnixNano()
+	if now-lastHeartbeatNs < int64(idleHeartbeatInterval) {
+		return lastHeartbeatNs
+	}
+	if err := sender.Send(&filer_pb.SubscribeMetadataResponse{TsNs: now}); err != nil {
+		glog.V(0).Infof("=> idle heartbeat to %s: %v", req.ClientName, err)
+		return lastHeartbeatNs
+	}
+	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.

weed/server/filer_grpc_server_sub_meta_test.go

@@ -10,6 +10,7 @@ import (
 	"github.com/seaweedfs/seaweedfs/weed/filer"
 	"github.com/seaweedfs/seaweedfs/weed/pb"
 	"github.com/seaweedfs/seaweedfs/weed/pb/filer_pb"
+	"github.com/seaweedfs/seaweedfs/weed/util/log_buffer"
 )
 
 // slowStream simulates a gRPC stream with configurable per-Send latency.
@@ -32,9 +33,13 @@ func (s *slowStream) Send(msg *filer_pb.SubscribeMetadataResponse) error {
 
 type collectingStream struct {
 	messages []*filer_pb.SubscribeMetadataResponse
+	err      error
 }
 
 func (s *collectingStream) Send(msg *filer_pb.SubscribeMetadataResponse) error {
+	if s.err != nil {
+		return s.err
+	}
 	s.messages = append(s.messages, msg)
 	return nil
 }
@@ -409,3 +414,85 @@ func TestPipelinedSingleVsParallelStreams(t *testing.T) {
 		t.Logf("Speedup: %.1fx (%d parallel pipelined streams vs 1)", parallelRate/singleRate, numDirs)
 	}
 }
+
+func TestMaybeSendIdleHeartbeat(t *testing.T) {
+	lb := log_buffer.NewLogBuffer("test", time.Minute, nil, nil, nil)
+	defer lb.ShutdownLogBuffer()
+
+	fs := &FilerServer{}
+	const recentEvent = int64(1_000_000)
+
+	t.Run("not opted in", func(t *testing.T) {
+		lb.LastTsNs.Store(recentEvent)
+		s := &collectingStream{}
+		req := &filer_pb.SubscribeMetadataRequest{ClientSupportsIdleHeartbeat: false}
+		got := fs.maybeSendIdleHeartbeat(req, s, lb, recentEvent, recentEvent, 0)
+		if got != 0 || len(s.messages) != 0 {
+			t.Fatalf("expected no heartbeat, got lastHeartbeat=%d msgs=%d", got, len(s.messages))
+		}
+	})
+
+	t.Run("behind buffer head", func(t *testing.T) {
+		lb.LastTsNs.Store(recentEvent)
+		s := &collectingStream{}
+		req := &filer_pb.SubscribeMetadataRequest{ClientSupportsIdleHeartbeat: true}
+		// startTs and lastSeen both below the buffer head: still replaying.
+		got := fs.maybeSendIdleHeartbeat(req, s, lb, 0, recentEvent-1, 0)
+		if got != 0 || len(s.messages) != 0 {
+			t.Fatalf("expected no heartbeat while behind, got lastHeartbeat=%d msgs=%d", got, len(s.messages))
+		}
+	})
+
+	t.Run("caught up via lastSeen", func(t *testing.T) {
+		lb.LastTsNs.Store(recentEvent)
+		s := &collectingStream{}
+		req := &filer_pb.SubscribeMetadataRequest{ClientSupportsIdleHeartbeat: true}
+		got := fs.maybeSendIdleHeartbeat(req, s, lb, 0, recentEvent, 0)
+		if len(s.messages) != 1 {
+			t.Fatalf("expected one heartbeat, got %d", len(s.messages))
+		}
+		hb := s.messages[0]
+		if hb.EventNotification != nil || len(hb.Events) != 0 || hb.TsNs <= 0 {
+			t.Fatalf("heartbeat should be an empty timestamped response, got %+v", hb)
+		}
+		if got != hb.TsNs {
+			t.Fatalf("expected returned lastHeartbeat %d to equal sent ts %d", got, hb.TsNs)
+		}
+	})
+
+	t.Run("caught up via read position floor", func(t *testing.T) {
+		// The read cursor has advanced past the buffer head while lastSeen stayed
+		// 0. This is the idle-source case (subscribed from "now", read nothing) and
+		// also metadata-chunks mode, where persisted entries replay as log file
+		// refs and never reach eachLogEntryFn.
+		lb.LastTsNs.Store(recentEvent)
+		s := &collectingStream{}
+		req := &filer_pb.SubscribeMetadataRequest{ClientSupportsIdleHeartbeat: true}
+		readPosition := time.Now().UnixNano()
+		got := fs.maybeSendIdleHeartbeat(req, s, lb, readPosition, 0, 0)
+		if len(s.messages) != 1 || got <= 0 {
+			t.Fatalf("expected heartbeat for caught-up subscriber, got msgs=%d lastHeartbeat=%d", len(s.messages), got)
+		}
+	})
+
+	t.Run("throttled within interval", func(t *testing.T) {
+		lb.LastTsNs.Store(recentEvent)
+		s := &collectingStream{}
+		req := &filer_pb.SubscribeMetadataRequest{ClientSupportsIdleHeartbeat: true}
+		justSent := time.Now().UnixNano()
+		got := fs.maybeSendIdleHeartbeat(req, s, lb, 0, recentEvent, justSent)
+		if got != justSent || len(s.messages) != 0 {
+			t.Fatalf("expected throttled (no send), got lastHeartbeat=%d msgs=%d", got, len(s.messages))
+		}
+	})
+
+	t.Run("send error keeps prior heartbeat time", func(t *testing.T) {
+		lb.LastTsNs.Store(recentEvent)
+		s := &collectingStream{err: fmt.Errorf("broken stream")}
+		req := &filer_pb.SubscribeMetadataRequest{ClientSupportsIdleHeartbeat: true}
+		got := fs.maybeSendIdleHeartbeat(req, s, lb, 0, recentEvent, 0)
+		if got != 0 {
+			t.Fatalf("expected lastHeartbeat unchanged on send error, got %d", got)
+		}
+	})
+}