fix: harden multi-pod delivery and load verification

This commit is contained in:
richjohnrambo
2026-09-27 03:37:32 +08:00
parent a2de100f2b
commit ce3250be64
33 changed files with 1340 additions and 94 deletions
+167 -34
View File
@@ -4,6 +4,7 @@ import (
"encoding/gob"
"encoding/json"
"errors"
"hash/fnv"
"net"
"net/rpc"
"sort"
@@ -14,6 +15,7 @@ import (
"github.com/tinode/chat/server/auth"
"github.com/tinode/chat/server/concurrency"
"github.com/tinode/chat/server/logs"
immetrics "github.com/tinode/chat/server/metrics"
"github.com/tinode/chat/server/push"
rh "github.com/tinode/chat/server/ringhash"
"github.com/tinode/chat/server/store/types"
@@ -25,18 +27,21 @@ const (
// Default timeout before attempting to reconnect to a node.
clusterDefaultReconnectTime = 200 * time.Millisecond
// Number of replicas in ringhash.
clusterHashReplicas = 20
// Buffer size for sending requests from proxy to master.
clusterProxyToMasterBuffer = 64
// Expand buffer size by this value for nodes over the basic 3-node setup.
clusterProxyToMasterBufferPerNode = 16
// Timeout for attempting to enqueue a proxy-to-master request when the buffer is full.
clusterP2MTimeout = 20 * time.Millisecond
clusterHashReplicas = 20
clusterDefaultP2MBuffer = 4096
clusterDefaultP2MWorkers = 16
clusterDefaultP2MTimeout = 300 * time.Millisecond
clusterDefaultRouteRetries = 3
clusterDefaultRouteRetryBackoff = 25 * time.Millisecond
// Buffer size for receiving responses from other nodes, per node.
clusterRpcCompletionBuffer = 64
)
var errClusterTopicOwnerUnavailable = errors.New("cluster topic owner unavailable")
var (
errClusterTopicOwnerUnavailable = errors.New("cluster topic owner unavailable")
errClusterOverloaded = errors.New("cluster overloaded")
errClusterLoadExceeded = errors.New("cluster load exceeded")
)
// ProxyReqType is the type of proxy requests.
type ProxyReqType int
@@ -64,7 +69,12 @@ type clusterConfig struct {
// Name of this cluster node
ThisName string `json:"self"`
// Deprecated: this field is no longer used.
NumProxyEventGoRoutines int `json:"-"`
NumProxyEventGoRoutines int `json:"-"`
ProxyToMasterBuffer int `json:"proxy_to_master_buffer"`
ProxyToMasterWorkers int `json:"proxy_to_master_workers"`
ProxyToMasterEnqueueTimeoutMS int `json:"proxy_to_master_enqueue_timeout_ms"`
RouteRetries int `json:"route_retries"`
RouteRetryBackoffMS int `json:"route_retry_backoff_ms"`
// Failover configuration
Failover *clusterFailoverConfig
}
@@ -99,8 +109,13 @@ type ClusterNode struct {
// Buffered, clusterRpcCompletionBuffer * number_of_nodes.
rpcDone chan *rpc.Call
// Channel for sending proxy to master requests; buffered, clusterProxyToMasterBuffer.
p2mSender chan *ClusterReq
// Sharded queues preserve ordering for the same tenant and topic while allowing parallel RPCs.
p2mSenders []chan *ClusterReq
p2mEnqueueTimeout time.Duration
routeRetries int
routeRetryBackoff time.Duration
overloadLogAt atomic.Int64
overloadSuppressed atomic.Int64
}
func (n *ClusterNode) asyncRpcLoop() {
@@ -109,19 +124,51 @@ func (n *ClusterNode) asyncRpcLoop() {
}
}
func (n *ClusterNode) p2mSenderLoop() {
for req := range n.p2mSender {
func (n *ClusterNode) p2mSenderLoop(sender <-chan *ClusterReq) {
for req := range sender {
if req == nil {
// Stop
return
}
if err := n.proxyToMaster(req); err != nil {
logs.Warn.Println("p2mSenderLoop: call failed", n.name, err)
if errors.Is(err, errClusterOverloaded) {
n.logOverload("proxy_to_master", req.TenantID, req.RcptTo, 0)
} else {
logs.Warn.Println("p2mSenderLoop: call failed", n.name, err)
}
}
n.updateP2MQueueMetric()
}
}
func (n *ClusterNode) logOverload(path string, tenantID types.TenantID, topic string, seq int64) {
now := time.Now().Unix()
previous := n.overloadLogAt.Load()
if previous == now || !n.overloadLogAt.CompareAndSwap(previous, now) {
n.overloadSuppressed.Add(1)
return
}
suppressed := n.overloadSuppressed.Swap(0)
logs.Warn.Printf("cluster overload: path=%s tenant=%d topic=%s seq=%d peer=%s suppressed=%d",
path, tenantID, topic, seq, n.name, suppressed)
}
func (n *ClusterNode) updateP2MQueueMetric() {
depth := 0
for _, sender := range n.p2mSenders {
depth += len(sender)
}
immetrics.ClusterP2MQueueLength.WithLabelValues(clusterPodName(), n.name).Set(float64(depth))
}
func clusterPodName() string {
if globals.cluster != nil && globals.cluster.thisNodeName != "" {
return globals.cluster.thisNodeName
}
return "standalone"
}
// ClusterSess is a basic info on a remote session where the message was created.
type ClusterSess struct {
TenantID types.TenantID
@@ -318,7 +365,12 @@ func (n *ClusterNode) call(proc string, req, resp any) error {
return errors.New("cluster: node '" + n.name + "' not connected")
}
method := proc
started := time.Now()
immetrics.ClusterRPCInflight.WithLabelValues(clusterPodName(), n.name, method).Inc()
defer immetrics.ClusterRPCInflight.WithLabelValues(clusterPodName(), n.name, method).Dec()
if err := n.endpoint.Call(proc, req, resp); err != nil {
immetrics.ClusterRPCDuration.WithLabelValues(clusterPodName(), n.name, method, "error").Observe(time.Since(started).Seconds())
logs.Warn.Println("cluster: call failed", n.name, err)
n.lock.Lock()
@@ -331,6 +383,7 @@ func (n *ClusterNode) call(proc string, req, resp any) error {
n.lock.Unlock()
return err
}
immetrics.ClusterRPCDuration.WithLabelValues(clusterPodName(), n.name, method, "ok").Observe(time.Since(started).Seconds())
return nil
}
@@ -395,29 +448,47 @@ func (n *ClusterNode) proxyToMaster(msg *ClusterReq) error {
var rejected bool
err := n.call("Cluster.TopicMaster", msg, &rejected)
if err == nil && rejected {
err = errors.New("cluster: topic master node out of sync")
err = errClusterOverloaded
}
return err
}
// proxyToMaster forwards request from topic proxy to topic master.
func (n *ClusterNode) proxyToMasterAsync(msg *ClusterReq) error {
if len(n.p2mSenders) == 0 {
return errClusterTopicOwnerUnavailable
}
sender := n.p2mSenders[clusterReqShard(msg, len(n.p2mSenders))]
select {
case n.p2mSender <- msg:
case sender <- msg:
n.updateP2MQueueMetric()
immetrics.ClusterP2MEnqueueTotal.WithLabelValues(clusterPodName(), n.name, "ok").Inc()
return nil
default:
}
// Buffer is full. Wait briefly before giving up.
timer := time.NewTimer(clusterP2MTimeout)
timer := time.NewTimer(n.p2mEnqueueTimeout)
defer timer.Stop()
select {
case n.p2mSender <- msg:
case sender <- msg:
n.updateP2MQueueMetric()
immetrics.ClusterP2MEnqueueTotal.WithLabelValues(clusterPodName(), n.name, "ok").Inc()
return nil
case <-timer.C:
return errors.New("cluster: load exceeded")
immetrics.ClusterP2MEnqueueTotal.WithLabelValues(clusterPodName(), n.name, "timeout").Inc()
return errClusterLoadExceeded
}
}
func clusterReqShard(msg *ClusterReq, count int) int {
if count <= 1 || msg == nil {
return 0
}
h := fnv.New32a()
_, _ = h.Write([]byte(types.TopicKey{TenantID: msg.TenantID, Topic: msg.RcptTo}.RoutingKey()))
return int(h.Sum32() % uint32(count))
}
// masterToProxyAsync forwards response from topic master to topic proxy
// in a fire-and-forget manner.
func (n *ClusterNode) masterToProxyAsync(msg *ClusterResp) error {
@@ -430,8 +501,32 @@ func (n *ClusterNode) masterToProxyAsync(msg *ClusterResp) error {
// route routes server message within the cluster.
func (n *ClusterNode) route(msg *ClusterRoute) error {
var unused bool
return n.call("Cluster.Route", msg, &unused)
for attempt := 0; attempt <= n.routeRetries; attempt++ {
var rejected bool
err := n.call("Cluster.Route", msg, &rejected)
if err != nil {
immetrics.ClusterRouteTotal.WithLabelValues(clusterPodName(), n.name, "disconnected").Inc()
return err
}
if !rejected {
immetrics.ClusterRouteTotal.WithLabelValues(clusterPodName(), n.name, "ok").Inc()
return nil
}
immetrics.ClusterRouteTotal.WithLabelValues(clusterPodName(), n.name, "peer_rejected").Inc()
if attempt < n.routeRetries {
time.Sleep(n.routeRetryBackoff * time.Duration(1<<attempt))
}
}
seq := int64(0)
topic := ""
if msg != nil && msg.SrvMsg != nil && msg.SrvMsg.Data != nil {
seq = msg.SrvMsg.Data.SeqId
}
if msg != nil && msg.SrvMsg != nil {
topic = msg.SrvMsg.RcptTo
}
n.logOverload("route", msg.TenantID, topic, seq)
return errClusterOverloaded
}
// Cluster is the representation of the cluster.
@@ -460,6 +555,8 @@ type Cluster struct {
// running a separate event processing goroutine for each proxy session
// leads to a rather large memory usage and excessive scheduling overhead.
proxyEventQueue *concurrency.GoRoutinePool
p2mBuffer int
p2mWorkers int
}
func (n *ClusterNode) stopMultiplexingSession(msess *Session) {
@@ -600,7 +697,13 @@ func (c *Cluster) TopicMaster(msg *ClusterReq, rejected *bool) error {
select {
case globals.hub.routeCli <- msg.CliMsg:
default:
logs.Err.Println("cluster: route req failed - hub.route queue full")
*rejected = true
if sess != nil {
reply := ErrServiceUnavailableReply(msg.CliMsg, msg.CliMsg.Timestamp)
reply.Ctrl.Text = "cluster overloaded"
sess.queueOut(reply)
}
node.logOverload("topic_master", msg.TenantID, msg.RcptTo, 0)
}
case ProxyReqBgSession, ProxyReqMeUserAgent:
@@ -681,7 +784,9 @@ func (c *Cluster) Route(msg *ClusterRoute, rejected *bool) error {
select {
case globals.hub.routeSrv <- msg.SrvMsg:
immetrics.ClusterRouteTotal.WithLabelValues(clusterPodName(), msg.Node, "ok").Inc()
default:
immetrics.ClusterRouteTotal.WithLabelValues(clusterPodName(), msg.Node, "hub_full").Inc()
logError("cluster Route: server busy")
}
return nil
@@ -1016,6 +1121,26 @@ func clusterInit(configString json.RawMessage, self *string) int {
if err := json.Unmarshal(configString, &config); err != nil {
logs.Err.Fatal(err)
}
if config.ProxyToMasterBuffer <= 0 {
config.ProxyToMasterBuffer = clusterDefaultP2MBuffer
}
if config.ProxyToMasterWorkers <= 0 {
config.ProxyToMasterWorkers = clusterDefaultP2MWorkers
}
if config.ProxyToMasterWorkers > config.ProxyToMasterBuffer {
config.ProxyToMasterWorkers = config.ProxyToMasterBuffer
}
if config.ProxyToMasterEnqueueTimeoutMS <= 0 {
config.ProxyToMasterEnqueueTimeoutMS = int(clusterDefaultP2MTimeout / time.Millisecond)
}
if config.RouteRetries < 0 {
config.RouteRetries = 0
} else if config.RouteRetries == 0 {
config.RouteRetries = clusterDefaultRouteRetries
}
if config.RouteRetryBackoffMS <= 0 {
config.RouteRetryBackoffMS = int(clusterDefaultRouteRetryBackoff / time.Millisecond)
}
thisName := *self
if thisName == "" {
@@ -1039,6 +1164,8 @@ func clusterInit(configString json.RawMessage, self *string) int {
fingerprint: time.Now().Unix(),
nodes: make(map[string]*ClusterNode),
proxyEventQueue: concurrency.NewGoRoutinePool(len(config.Nodes) * 5),
p2mBuffer: config.ProxyToMasterBuffer,
p2mWorkers: config.ProxyToMasterWorkers,
}
var nodeNames []string
@@ -1052,10 +1179,13 @@ func clusterInit(configString json.RawMessage, self *string) int {
}
globals.cluster.nodes[host.Name] = &ClusterNode{
address: host.Addr,
name: host.Name,
done: make(chan bool, 1),
msess: make(map[string]struct{}),
address: host.Addr,
name: host.Name,
done: make(chan bool, 1),
msess: make(map[string]struct{}),
p2mEnqueueTimeout: time.Duration(config.ProxyToMasterEnqueueTimeoutMS) * time.Millisecond,
routeRetries: config.RouteRetries,
routeRetryBackoff: time.Duration(config.RouteRetryBackoffMS) * time.Millisecond,
}
}
@@ -1113,17 +1243,18 @@ func (c *Cluster) start() {
logs.Err.Fatal(err)
}
var bufferSize = clusterProxyToMasterBuffer
if len(c.nodes) > 2 {
// Expand the buffer for larger (>3 node) clusters.
bufferSize += clusterProxyToMasterBufferPerNode * (len(c.nodes) - 2)
}
for _, n := range c.nodes {
go n.reconnect()
n.rpcDone = make(chan *rpc.Call, len(c.nodes)*clusterRpcCompletionBuffer)
n.p2mSender = make(chan *ClusterReq, bufferSize)
workers := c.p2mWorkers
perWorker := (c.p2mBuffer + workers - 1) / workers
n.p2mSenders = make([]chan *ClusterReq, workers)
go n.asyncRpcLoop()
go n.p2mSenderLoop()
for i := range n.p2mSenders {
n.p2mSenders[i] = make(chan *ClusterReq, perWorker)
go n.p2mSenderLoop(n.p2mSenders[i])
}
immetrics.ClusterP2MQueueCapacity.WithLabelValues(clusterPodName(), n.name).Set(float64(perWorker * workers))
}
if c.fo != nil {
@@ -1147,7 +1278,9 @@ func (c *Cluster) shutdown() {
}
for _, n := range c.nodes {
close(n.rpcDone)
close(n.p2mSender)
for _, sender := range n.p2mSenders {
close(sender)
}
}
globals.cluster.proxyEventQueue.Stop()
+35
View File
@@ -0,0 +1,35 @@
package main
import (
"errors"
"net/http"
"testing"
"time"
"github.com/tinode/chat/server/store/types"
)
func TestClusterReqShardIsStablePerTenantTopic(t *testing.T) {
req := &ClusterReq{TenantID: types.TenantID(6), RcptTo: "p2p-topic"}
want := clusterReqShard(req, 16)
for i := 0; i < 100; i++ {
if got := clusterReqShard(req, 16); got != want {
t.Fatalf("unstable shard: got=%d want=%d", got, want)
}
}
if got := clusterReqShard(req, 1); got != 0 {
t.Fatalf("single worker shard=%d", got)
}
}
func TestClusterRouteErrorReplySeparatesOverloadFromDisconnect(t *testing.T) {
msg := &ClientComMessage{Id: "test", Timestamp: time.Now()}
overload := clusterRouteErrorReply(msg, errClusterLoadExceeded)
if overload.Ctrl == nil || overload.Ctrl.Code != http.StatusServiceUnavailable || overload.Ctrl.Text != "cluster overloaded" {
t.Fatalf("unexpected overload reply: %+v", overload.Ctrl)
}
disconnected := clusterRouteErrorReply(msg, errors.New("disconnected"))
if disconnected.Ctrl == nil || disconnected.Ctrl.Code != http.StatusBadGateway {
t.Fatalf("unexpected disconnected reply: %+v", disconnected.Ctrl)
}
}
+5
View File
@@ -265,6 +265,11 @@ type TenantMessageBatchAdapter interface {
TenantGroupMessageSaveBatch(t.TenantID, []*t.Message) error
}
// TenantMessageSchemaAdapter validates storage contracts required by asynchronous persistence.
type TenantMessageSchemaAdapter interface {
TenantMessageSchemaValidate([]t.TenantID) error
}
// TenantHTTPInfrastructureAdapter is the optional durable infrastructure used
// by Kafka dead-letter handling.
type TenantHTTPInfrastructureAdapter interface {
+57
View File
@@ -8,7 +8,9 @@ import (
"crypto/sha256"
"database/sql"
"encoding/json"
"errors"
"fmt"
"regexp"
"sort"
"strconv"
"strings"
@@ -2249,6 +2251,61 @@ func (a *adapter) TenantMessageSave(id t.TenantID, msg *t.Message) error {
return err
}
func (a *adapter) TenantMessageSchemaValidate(tenantIDs []t.TenantID) error {
if len(tenantIDs) == 0 {
return errors.New("mysql: no active tenants available for message schema validation")
}
validated := make(map[*adapter]map[string]struct{})
for _, tenantID := range tenantIDs {
tenantAdp, err := a.routedTenantAdapter(tenantID)
if err != nil {
return fmt.Errorf("mysql: resolve tenant %d for message schema validation: %w", tenantID, err)
}
table := tenantMessagesTable(tenantID)
if tenantAdp.tenantScopedDB {
table = "im_messages"
}
if validated[tenantAdp] == nil {
validated[tenantAdp] = make(map[string]struct{})
}
if _, ok := validated[tenantAdp][table]; ok {
continue
}
if err = tenantAdp.validateMessageIDColumn(table); err != nil {
return err
}
validated[tenantAdp][table] = struct{}{}
}
if !a.tenantScopedDB {
if err := a.validateMessageIDColumn("im_messages"); err != nil {
return err
}
}
return nil
}
func (a *adapter) validateMessageIDColumn(table string) error {
if !regexp.MustCompile(`^im_(?:[0-9]+_)?messages$`).MatchString(table) {
return fmt.Errorf("mysql: unsafe message table name %q", table)
}
var dataType, nullable, extra string
err := a.db.QueryRow(`SELECT DATA_TYPE,IS_NULLABLE,EXTRA FROM information_schema.COLUMNS
WHERE TABLE_SCHEMA=DATABASE() AND TABLE_NAME=? AND COLUMN_NAME='id'`, table).
Scan(&dataType, &nullable, &extra)
if err == sql.ErrNoRows {
return fmt.Errorf("mysql: required message table %s is missing", table)
}
if err != nil {
return fmt.Errorf("mysql: inspect %s.id: %w", table, err)
}
if !strings.EqualFold(dataType, "bigint") || !strings.EqualFold(nullable, "NO") ||
!strings.Contains(strings.ToLower(extra), "auto_increment") {
return fmt.Errorf("mysql: incompatible %s.id schema: type=%s nullable=%s extra=%s; want BIGINT NOT NULL AUTO_INCREMENT",
table, dataType, nullable, extra)
}
return nil
}
func (a *adapter) TenantMessageSaveBatch(id t.TenantID, messages []*t.Message) error {
tenantAdp, err := a.routedTenantAdapter(id)
if err != nil {
+27 -2
View File
@@ -10,6 +10,7 @@ import (
"github.com/segmentio/kafka-go"
"github.com/tinode/chat/server/logs"
immetrics "github.com/tinode/chat/server/metrics"
"github.com/tinode/chat/server/store"
"github.com/tinode/chat/server/store/types"
)
@@ -160,11 +161,18 @@ func handleKafkaMessagePersistBatch(ctx context.Context, messages []kafka.Messag
groups[key] = append(groups[key], item)
}
for _, items := range groups {
kind := items[0].payload.MessageKind
if kind == "" {
kind = "p2p"
}
started := time.Now()
batch := make([]store.PreparedMessageBatchItem, 0, len(items))
for _, item := range items {
batch = append(batch, store.PreparedMessageBatchItem{Message: &item.payload.Message, ReadBySender: item.payload.ReadBySender})
}
if err := store.PersistPreparedMessageBatch(items[0].tenantID, batch); err == nil {
immetrics.KafkaMessagePersistTotal.WithLabelValues(kind, "batch_ok").Add(float64(len(items)))
immetrics.MessagePersistDuration.WithLabelValues(kind, "batch_ok").Observe(time.Since(started).Seconds())
for _, item := range items {
if err = finishKafkaMessagePersist(ctx, item); err != nil {
if err = persistKafkaMessageIndividually(ctx, item); err != nil {
@@ -174,6 +182,8 @@ func handleKafkaMessagePersistBatch(ctx context.Context, messages []kafka.Messag
}
continue
} else {
immetrics.KafkaMessagePersistTotal.WithLabelValues(kind, "batch_failed").Add(float64(len(items)))
immetrics.MessagePersistDuration.WithLabelValues(kind, "batch_failed").Observe(time.Since(started).Seconds())
logs.Warn.Printf("kafka message batch persist failed, degrading to singles: tenant=%d kind=%s shard=%s size=%d err=%v",
items[0].tenantID, items[0].payload.MessageKind, items[0].payload.Message.ShardMonth, len(items), err)
}
@@ -227,6 +237,11 @@ func prepareKafkaMessagePersistItem(ctx context.Context, message kafka.Message,
}
func persistKafkaMessageIndividually(ctx context.Context, item *kafkaMessagePersistItem) error {
kind := item.payload.MessageKind
if kind == "" {
kind = "p2p"
}
started := time.Now()
operation := func() error {
err := store.PersistPreparedMessageBatch(item.tenantID, []store.PreparedMessageBatchItem{{
Message: &item.payload.Message, ReadBySender: item.payload.ReadBySender,
@@ -237,14 +252,24 @@ func persistKafkaMessageIndividually(ctx context.Context, item *kafkaMessagePers
if err != nil && !errors.Is(err, types.ErrDuplicate) {
return err
}
return finishKafkaMessagePersist(ctx, item)
if err = finishKafkaMessagePersist(ctx, item); err != nil {
return err
}
immetrics.KafkaMessagePersistTotal.WithLabelValues(kind, "single_ok").Inc()
immetrics.MessagePersistDuration.WithLabelValues(kind, "single_ok").Observe(time.Since(started).Seconds())
return nil
}
markFailed := func(err error) (*types.KafkaConsumeRecord, error) {
immetrics.KafkaMessagePersistTotal.WithLabelValues(kind, "retry").Inc()
return store.HTTPInfrastructure.MarkKafkaConsumeFailed(item.tenantID, item.envelope.EventID, kafkaBus.config.ConsumerGroup,
kafkaMessagePersistFailureReason(err), err.Error(), time.Now().UTC().Round(time.Millisecond))
}
markDead := func(failed *types.KafkaConsumeRecord, err error) error {
return markKafkaDeadLetter(ctx, item.tenantID, item.envelope, failed, kafkaMessagePersistFailureReason(err), err.Error())
immetrics.KafkaMessagePersistTotal.WithLabelValues(kind, "dead").Inc()
immetrics.MessagePersistDuration.WithLabelValues(kind, "dead").Observe(time.Since(started).Seconds())
reason := kafkaMessagePersistFailureReason(err)
immetrics.KafkaDeadLettersTotal.WithLabelValues(kind, reason).Inc()
return markKafkaDeadLetter(ctx, item.tenantID, item.envelope, failed, reason, err.Error())
}
return runKafkaMessageSingleRetries(ctx, kafkaBus.config.MessageRetries, operation, markFailed, markDead, waitKafkaRetry)
}
+69
View File
@@ -8,12 +8,14 @@ import (
"regexp"
"strings"
"sync"
"sync/atomic"
"time"
"github.com/segmentio/kafka-go"
"github.com/segmentio/kafka-go/sasl"
"github.com/segmentio/kafka-go/sasl/scram"
"github.com/tinode/chat/server/logs"
immetrics "github.com/tinode/chat/server/metrics"
"github.com/tinode/chat/server/store/types"
)
@@ -155,6 +157,11 @@ func initKafkaRuntime(raw json.RawMessage) error {
return nil
}
func kafkaConfigured(raw json.RawMessage) bool {
var cfg kafkaConfig
return len(raw) > 0 && json.Unmarshal(raw, &cfg) == nil && cfg.Enabled
}
func normalizeKafkaConfig(cfg *kafkaConfig) {
if cfg.ClientID == "" {
cfg.ClientID = "im-server"
@@ -333,6 +340,7 @@ func startKafkaConsumerWithGroup(topicName, groupID string, handler kafkaMessage
MaxWait: time.Second,
Dialer: kafkaBus.dialer(),
})
readerMetrics := startKafkaReaderMetrics(kafkaBus.ctx, reader, topic, groupID)
kafkaBus.wg.Add(1)
go func() {
defer kafkaBus.wg.Done()
@@ -346,6 +354,7 @@ func startKafkaConsumerWithGroup(topicName, groupID string, handler kafkaMessage
logs.Err.Println("Kafka fetch failed:", err)
continue
}
readerMetrics.observe(msg.Time)
commit := func(ctx context.Context, message kafka.Message) error {
return reader.CommitMessages(ctx, message)
}
@@ -355,6 +364,7 @@ func startKafkaConsumerWithGroup(topicName, groupID string, handler kafkaMessage
}
logs.Err.Printf("Kafka message stopped without commit: topic=%s partition=%d offset=%d err=%v", msg.Topic, msg.Partition, msg.Offset, err)
}
readerMetrics.clear()
}
}()
logs.Info.Printf("Kafka consumer started: topic=%s group=%s", topic, groupID)
@@ -373,6 +383,7 @@ func startKafkaBatchConsumer(topicName string, handler kafkaBatchHandler) {
Brokers: kafkaBus.config.Brokers, GroupID: groupID, Topic: topic, StartOffset: kafka.FirstOffset,
MinBytes: 1, MaxBytes: 10e6, MaxWait: time.Second, Dialer: kafkaBus.dialer(),
})
readerMetrics := startKafkaReaderMetrics(kafkaBus.ctx, reader, topic, groupID)
kafkaBus.wg.Add(1)
go func() {
defer kafkaBus.wg.Done()
@@ -387,17 +398,75 @@ func startKafkaBatchConsumer(topicName string, handler kafkaBatchHandler) {
logs.Err.Println("Kafka batch fetch failed:", err)
continue
}
if len(messages) > 0 {
readerMetrics.observe(messages[0].Time)
}
if err = consumeKafkaMessageBatch(kafkaBus.ctx, messages, handler, reader.CommitMessages, waitKafkaRetry); err != nil {
if errors.Is(err, context.Canceled) || errors.Is(kafkaBus.ctx.Err(), context.Canceled) {
return
}
logs.Err.Printf("Kafka batch stopped without commit: topic=%s size=%d err=%v", topic, len(messages), err)
}
readerMetrics.clear()
}
}()
logs.Info.Printf("Kafka batch consumer started: topic=%s group=%s size=%d wait_ms=%d", topic, groupID, kafkaBus.config.MessageBatchSize, kafkaBus.config.MessageBatchWait)
}
type kafkaReaderMetrics struct {
reader *kafka.Reader
topic string
group string
oldestNano atomic.Int64
}
func startKafkaReaderMetrics(ctx context.Context, reader *kafka.Reader, topic, group string) *kafkaReaderMetrics {
metrics := &kafkaReaderMetrics{reader: reader, topic: topic, group: group}
kafkaBus.wg.Add(1)
go func() {
defer kafkaBus.wg.Done()
ticker := time.NewTicker(5 * time.Second)
defer ticker.Stop()
metrics.update()
for {
select {
case <-ctx.Done():
return
case <-ticker.C:
metrics.update()
}
}
}()
return metrics
}
func (m *kafkaReaderMetrics) observe(messageTime time.Time) {
if !messageTime.IsZero() {
m.oldestNano.Store(messageTime.UnixNano())
}
m.update()
}
func (m *kafkaReaderMetrics) clear() {
m.oldestNano.Store(0)
m.update()
}
func (m *kafkaReaderMetrics) update() {
stats := m.reader.Stats()
if stats.Lag >= 0 {
immetrics.KafkaConsumerLag.WithLabelValues(clusterPodName(), m.topic, m.group).Set(float64(stats.Lag))
}
age := float64(0)
if oldest := m.oldestNano.Load(); oldest > 0 {
age = time.Since(time.Unix(0, oldest)).Seconds()
if age < 0 {
age = 0
}
}
immetrics.KafkaBacklogOldestAge.WithLabelValues(clusterPodName(), m.topic, m.group).Set(age)
}
func fetchKafkaMessageBatch(ctx context.Context, reader *kafka.Reader, maxSize int, maxWait time.Duration) ([]kafka.Message, error) {
first, err := reader.FetchMessage(ctx)
if err != nil {
+19
View File
@@ -34,6 +34,7 @@ import (
_ "github.com/tinode/chat/server/auth/code"
_ "github.com/tinode/chat/server/auth/rest"
_ "github.com/tinode/chat/server/auth/token"
adapter "github.com/tinode/chat/server/db"
"github.com/tinode/chat/server/store/types"
// Database backends
@@ -516,6 +517,23 @@ func main() {
logs.Info.Println("All done, good bye")
}()
statsRegisterDbStats()
if kafkaConfigured(config.Kafka) {
tenants, tenantErr := store.Tenants.ListActive(10000)
if tenantErr != nil {
logs.Err.Fatal("Failed to list tenants for Kafka message schema validation:", tenantErr)
}
tenantIDs := make([]types.TenantID, 0, len(tenants))
for i := range tenants {
tenantIDs = append(tenantIDs, tenants[i].ID)
}
validator, ok := store.Store.GetAdapter().(adapter.TenantMessageSchemaAdapter)
if !ok {
logs.Err.Fatal("Kafka message persistence requires a message schema validator")
}
if err = validator.TenantMessageSchemaValidate(tenantIDs); err != nil {
logs.Err.Fatal("Kafka message persistence schema validation failed:", err)
}
}
if err = initKafkaRuntime(config.Kafka); err != nil {
logs.Err.Fatal("Failed to initialize Kafka:", err)
@@ -860,6 +878,7 @@ func main() {
mux.HandleFunc(sspath, serveStatus)
}
mux.HandleFunc("/healthz", serveHealthz)
mux.HandleFunc("/livez", serveLivez)
mux.HandleFunc("/metrics", serveMetrics)
// Public legal pages are opened directly by clients before login.
+5
View File
@@ -238,6 +238,11 @@
"cluster_config": {
"self": "",
"nodes": [],
"proxy_to_master_buffer": 4096,
"proxy_to_master_workers": 16,
"proxy_to_master_enqueue_timeout_ms": 300,
"route_retries": 3,
"route_retry_backoff_ms": 25,
"failover": {
"enabled": false
}
+91 -2
View File
@@ -2,7 +2,9 @@ package metrics
import (
"expvar"
"os"
"strconv"
"strings"
"time"
"github.com/prometheus/client_golang/prometheus"
@@ -45,11 +47,98 @@ var (
}, func() float64 {
return float64(expvarIntValue("LiveSessions"))
})
IMWSConnectionsActive = prometheus.NewGaugeFunc(prometheus.GaugeOpts{
Name: "im_ws_connections_active",
Help: "Current active WebSocket connections, using the IM metric namespace.",
ConstLabels: prometheus.Labels{"pod": metricPodName()},
}, func() float64 {
return float64(expvarIntValue("LiveSessions"))
})
IMClusterLivePeers = prometheus.NewGaugeFunc(prometheus.GaugeOpts{
Name: "im_cluster_live_peers",
Help: "Current connected cluster peers.",
ConstLabels: prometheus.Labels{"pod": metricPodName()},
}, func() float64 {
return float64(expvarIntValue("LiveClusterNodes"))
})
IMClusterExpectedPeers = prometheus.NewGaugeFunc(prometheus.GaugeOpts{
Name: "im_cluster_expected_peers",
Help: "Expected cluster peers derived from configured total nodes.",
ConstLabels: prometheus.Labels{"pod": metricPodName()},
}, func() float64 {
total := expvarIntValue("TotalClusterNodes")
if total > 0 {
total--
}
return float64(total)
})
ClusterP2MQueueLength = prometheus.NewGaugeVec(prometheus.GaugeOpts{
Name: "im_cluster_p2m_queue_length",
Help: "Current proxy-to-master queue depth by pod and peer.",
}, []string{"pod", "peer"})
ClusterP2MQueueCapacity = prometheus.NewGaugeVec(prometheus.GaugeOpts{
Name: "im_cluster_p2m_queue_capacity",
Help: "Configured proxy-to-master queue capacity by pod and peer.",
}, []string{"pod", "peer"})
ClusterP2MEnqueueTotal = prometheus.NewCounterVec(prometheus.CounterOpts{
Name: "im_cluster_p2m_enqueue_total",
Help: "Proxy-to-master enqueue attempts by pod, peer, and result.",
}, []string{"pod", "peer", "result"})
ClusterRPCInflight = prometheus.NewGaugeVec(prometheus.GaugeOpts{
Name: "im_cluster_rpc_inflight",
Help: "Current synchronous cluster RPC calls by pod, peer, and method.",
}, []string{"pod", "peer", "method"})
ClusterRPCDuration = prometheus.NewHistogramVec(prometheus.HistogramOpts{
Name: "im_cluster_rpc_duration_seconds",
Help: "Cluster RPC duration by pod, peer, method, and result.",
Buckets: []float64{0.001, 0.003, 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5},
}, []string{"pod", "peer", "method", "result"})
ClusterRouteTotal = prometheus.NewCounterVec(prometheus.CounterOpts{
Name: "im_cluster_route_total",
Help: "Cluster route attempts by pod, peer, and result.",
}, []string{"pod", "peer", "result"})
ClusterProxyResponseTotal = prometheus.NewCounterVec(prometheus.CounterOpts{
Name: "im_cluster_proxy_response_total",
Help: "Cluster proxy responses by pod and result.",
}, []string{"pod", "result"})
MessagePersistDuration = prometheus.NewHistogramVec(prometheus.HistogramOpts{
Name: "im_message_persist_duration_seconds",
Help: "Kafka message persistence duration by message kind and result.",
Buckets: []float64{0.001, 0.003, 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10},
}, []string{"kind", "result"})
KafkaMessagePersistTotal = prometheus.NewCounterVec(prometheus.CounterOpts{
Name: "im_kafka_message_persist_total",
Help: "Kafka message persistence outcomes by message kind and result.",
}, []string{"kind", "result"})
KafkaConsumerLag = prometheus.NewGaugeVec(prometheus.GaugeOpts{
Name: "im_kafka_consumer_lag",
Help: "Kafka reader lag reported by kafka-go by pod, topic, and consumer group.",
}, []string{"pod", "topic", "group"})
KafkaBacklogOldestAge = prometheus.NewGaugeVec(prometheus.GaugeOpts{
Name: "im_kafka_backlog_oldest_age_seconds",
Help: "Age of the latest fetched Kafka message by pod, topic, and consumer group.",
}, []string{"pod", "topic", "group"})
KafkaDeadLettersTotal = prometheus.NewCounterVec(prometheus.CounterOpts{
Name: "im_kafka_dead_letters_total",
Help: "Kafka messages moved to dead letter by message kind and reason.",
}, []string{"kind", "reason"})
)
func init() {
Registry.MustRegister(WSConnectionsActive, HTTPRequestsTotal, HTTPRequestDuration, DBQueryDuration,
RealtimeFanoutEventsTotal, RealtimeFanoutDeliveryDuration)
Registry.MustRegister(WSConnectionsActive, IMWSConnectionsActive, IMClusterLivePeers, IMClusterExpectedPeers,
HTTPRequestsTotal, HTTPRequestDuration, DBQueryDuration,
RealtimeFanoutEventsTotal, RealtimeFanoutDeliveryDuration, ClusterP2MQueueLength,
ClusterP2MQueueCapacity, ClusterP2MEnqueueTotal, ClusterRPCInflight, ClusterRPCDuration,
ClusterRouteTotal, ClusterProxyResponseTotal, MessagePersistDuration, KafkaMessagePersistTotal)
Registry.MustRegister(KafkaConsumerLag, KafkaBacklogOldestAge, KafkaDeadLettersTotal)
}
func metricPodName() string {
if value := strings.TrimSpace(os.Getenv("HOSTNAME")); value != "" {
return value
}
return "standalone"
}
func ObserveDB(driverName, operation string, started time.Time, err error) {
+67
View File
@@ -4,12 +4,14 @@ import (
"bufio"
"context"
"encoding/json"
"fmt"
"io"
"net"
"net/http"
"regexp"
"strconv"
"strings"
"sync"
"time"
"github.com/prometheus/client_golang/prometheus/promhttp"
@@ -20,6 +22,8 @@ import (
var (
metricsHandler = promhttp.HandlerFor(immetrics.Registry, promhttp.HandlerOpts{})
uuidLikeMetricSegment = regexp.MustCompile(`^[0-9a-fA-F]{8}-[0-9a-fA-F-]{13,}$`)
clusterQueueHighSince = make(map[string]time.Time)
clusterQueueHealthMu sync.Mutex
)
type healthzResponse struct {
@@ -45,6 +49,28 @@ func serveHealthz(wrt http.ResponseWriter, req *http.Request) {
} else {
checks["mysql"] = "ok"
}
if globals.cluster != nil {
expected := len(globals.cluster.nodes)
live := 0
for _, node := range globals.cluster.nodes {
node.lock.Lock()
connected := node.connected
node.lock.Unlock()
if connected {
live++
}
}
checks["cluster"] = fmt.Sprintf("%d/%d peers connected", live, expected)
if live != expected {
status = http.StatusServiceUnavailable
}
if healthy, detail := clusterQueueHealthy(globals.cluster, time.Now()); !healthy {
checks["cluster_queue"] = detail
status = http.StatusServiceUnavailable
} else {
checks["cluster_queue"] = detail
}
}
body := healthzResponse{Status: "ok", Checks: checks}
if status != http.StatusOK {
@@ -56,6 +82,47 @@ func serveHealthz(wrt http.ResponseWriter, req *http.Request) {
}
}
func clusterQueueHealthy(cluster *Cluster, now time.Time) (bool, string) {
clusterQueueHealthMu.Lock()
defer clusterQueueHealthMu.Unlock()
healthy := true
detail := "ok"
for name, node := range cluster.nodes {
depth, capacity := 0, 0
for _, sender := range node.p2mSenders {
depth += len(sender)
capacity += cap(sender)
}
if capacity == 0 || depth*100 < capacity*90 {
delete(clusterQueueHighSince, name)
continue
}
since, exists := clusterQueueHighSince[name]
if !exists {
clusterQueueHighSince[name] = now
continue
}
if now.Sub(since) >= 30*time.Second {
healthy = false
detail = fmt.Sprintf("peer %s queue %d/%d above 90%% for %s", name, depth, capacity,
now.Sub(since).Round(time.Second))
}
}
return healthy, detail
}
func serveLivez(wrt http.ResponseWriter, req *http.Request) {
if req.Method != http.MethodGet && req.Method != http.MethodHead {
wrt.Header().Set("Allow", http.MethodGet+", "+http.MethodHead)
http.Error(wrt, "method not allowed", http.StatusMethodNotAllowed)
return
}
wrt.WriteHeader(http.StatusOK)
if req.Method != http.MethodHead {
_, _ = io.WriteString(wrt, "ok\n")
}
}
func serveMetrics(wrt http.ResponseWriter, req *http.Request) {
if req.Method != http.MethodGet && req.Method != http.MethodHead {
wrt.Header().Set("Allow", http.MethodGet+", "+http.MethodHead)
+44
View File
@@ -52,7 +52,44 @@ func TestServeHealthzError(t *testing.T) {
}
}
func TestServeLivez(t *testing.T) {
wrt := httptest.NewRecorder()
serveLivez(wrt, httptest.NewRequest(http.MethodGet, "/livez", nil))
if wrt.Code != http.StatusOK || wrt.Body.String() != "ok\n" {
t.Fatalf("unexpected livez response: code=%d body=%q", wrt.Code, wrt.Body.String())
}
}
func TestClusterQueueHealthRequiresSustainedHighWatermark(t *testing.T) {
clusterQueueHealthMu.Lock()
clusterQueueHighSince = make(map[string]time.Time)
clusterQueueHealthMu.Unlock()
queue := make(chan *ClusterReq, 10)
for i := 0; i < 9; i++ {
queue <- &ClusterReq{}
}
cluster := &Cluster{nodes: map[string]*ClusterNode{"peer": {p2mSenders: []chan *ClusterReq{queue}}}}
now := time.Now()
if healthy, _ := clusterQueueHealthy(cluster, now); !healthy {
t.Fatal("instant high watermark must not fail readiness")
}
if healthy, _ := clusterQueueHealthy(cluster, now.Add(31*time.Second)); healthy {
t.Fatal("sustained high watermark must fail readiness")
}
<-queue
if healthy, _ := clusterQueueHealthy(cluster, now.Add(32*time.Second)); !healthy {
t.Fatal("queue recovery must restore readiness")
}
}
func TestServeMetricsIncludesWSConnections(t *testing.T) {
immetrics.ClusterP2MQueueLength.WithLabelValues("test", "peer").Set(0)
immetrics.ClusterP2MEnqueueTotal.WithLabelValues("test", "peer", "ok").Add(0)
immetrics.ClusterRPCDuration.WithLabelValues("test", "peer", "Cluster.Route", "ok").Observe(0)
immetrics.ClusterRouteTotal.WithLabelValues("test", "peer", "ok").Add(0)
immetrics.KafkaMessagePersistTotal.WithLabelValues("p2p", "batch_ok").Add(0)
immetrics.KafkaConsumerLag.WithLabelValues("test", "topic", "group").Set(0)
immetrics.KafkaDeadLettersTotal.WithLabelValues("p2p", "test").Add(0)
wrt := httptest.NewRecorder()
serveMetrics(wrt, httptest.NewRequest(http.MethodGet, "/metrics", nil))
@@ -63,6 +100,13 @@ func TestServeMetricsIncludesWSConnections(t *testing.T) {
if !strings.Contains(body, "# TYPE ws_connections_active gauge") || !strings.Contains(body, "ws_connections_active ") {
t.Fatalf("unexpected body %s", body)
}
for _, metric := range []string{"im_ws_connections_active", "im_cluster_p2m_queue_length",
"im_cluster_p2m_enqueue_total", "im_cluster_rpc_duration_seconds", "im_cluster_route_total",
"im_kafka_message_persist_total", "im_kafka_consumer_lag", "im_kafka_dead_letters_total"} {
if !strings.Contains(body, "# HELP "+metric+" ") {
t.Fatalf("metric %s was not exported", metric)
}
}
}
func TestMonitorHTTPRecordsRequestMetrics(t *testing.T) {
+5
View File
@@ -238,6 +238,11 @@
"cluster_config": {
"self": "",
"nodes": [],
"proxy_to_master_buffer": 4096,
"proxy_to_master_workers": 16,
"proxy_to_master_enqueue_timeout_ms": 300,
"route_retries": 3,
"route_retry_backoff_ms": 25,
"failover": {
"enabled": false
}
+39 -6
View File
@@ -9,12 +9,34 @@ package main
import (
"errors"
"net/http"
"sync/atomic"
"time"
"github.com/tinode/chat/server/logs"
immetrics "github.com/tinode/chat/server/metrics"
"github.com/tinode/chat/server/store/types"
)
var (
clusterProxyOverloadLogAt atomic.Int64
clusterProxyOverloadSuppressed atomic.Int64
)
func logClusterProxyRouteFailure(topic, operation string, err error) {
if !errors.Is(err, errClusterLoadExceeded) && !errors.Is(err, errClusterOverloaded) {
logs.Warn.Printf("topic proxy[%s]: route %s failed - %s", topic, operation, err)
return
}
now := time.Now().Unix()
previous := clusterProxyOverloadLogAt.Load()
if previous == now || !clusterProxyOverloadLogAt.CompareAndSwap(previous, now) {
clusterProxyOverloadSuppressed.Add(1)
return
}
logs.Warn.Printf("topic proxy overload: topic=%s operation=%s suppressed=%d", topic, operation,
clusterProxyOverloadSuppressed.Swap(0))
}
func (t *Topic) runProxy(hub *Hub) {
killTimer := time.NewTimer(time.Hour)
killTimer.Stop()
@@ -27,8 +49,8 @@ func (t *Topic) runProxy(hub *Hub) {
msg.sess.queueOut(ErrLockedReply(msg, types.TimeNow()))
} else if err := globals.cluster.routeToTopicMaster(ProxyReqJoin, msg, t.name, msg.sess); err != nil {
// Response (ctrl message) will be handled when it's received via the proxy channel.
logs.Warn.Printf("proxy topic[%s]: route join request from proxy to master failed - %s", t.name, err)
msg.sess.queueOut(ErrClusterUnreachableReply(msg, types.TimeNow()))
logClusterProxyRouteFailure(t.name, "join", err)
msg.sess.queueOut(clusterRouteErrorReply(msg, err))
}
if msg.sess.inflightReqs != nil {
msg.sess.inflightReqs.Done()
@@ -51,8 +73,8 @@ func (t *Topic) runProxy(hub *Hub) {
case msg := <-t.clientMsg:
// Content message intended for broadcasting to recipients
if err := globals.cluster.routeToTopicMaster(ProxyReqBroadcast, msg, t.name, msg.sess); err != nil {
logs.Warn.Printf("topic proxy[%s]: route broadcast request from proxy to master failed - %s", t.name, err)
msg.sess.queueOut(ErrClusterUnreachableReply(msg, types.TimeNow()))
logClusterProxyRouteFailure(t.name, "broadcast", err)
msg.sess.queueOut(clusterRouteErrorReply(msg, err))
}
case msg := <-t.serverMsg:
@@ -71,8 +93,8 @@ func (t *Topic) runProxy(hub *Hub) {
case msg := <-t.meta:
// Request to get/set topic metadata
if err := globals.cluster.routeToTopicMaster(ProxyReqMeta, msg, t.name, msg.sess); err != nil {
logs.Warn.Printf("proxy topic[%s]: route meta request from proxy to master failed - %s", t.name, err)
msg.sess.queueOut(ErrClusterUnreachableReply(msg, types.TimeNow()))
logClusterProxyRouteFailure(t.name, "meta", err)
msg.sess.queueOut(clusterRouteErrorReply(msg, err))
}
case upd := <-t.supd:
@@ -122,6 +144,17 @@ func (t *Topic) runProxy(hub *Hub) {
}
}
func clusterRouteErrorReply(msg *ClientComMessage, err error) *ServerComMessage {
if errors.Is(err, errClusterLoadExceeded) || errors.Is(err, errClusterOverloaded) {
immetrics.ClusterProxyResponseTotal.WithLabelValues(clusterPodName(), "overloaded").Inc()
reply := ErrServiceUnavailableReply(msg, types.TimeNow())
reply.Ctrl.Text = "cluster overloaded"
return reply
}
immetrics.ClusterProxyResponseTotal.WithLabelValues(clusterPodName(), "unreachable").Inc()
return ErrClusterUnreachableReply(msg, types.TimeNow())
}
// Takes a session leave request, forwards it to the topic master and
// modifies the local state accordingly.
// Returns whether the operation was successful.