Phase 10: hardening and ops

Implements PLAN.md Phase 10.

Simplified Sliding Sync (MSC4186) is served at the unstable
org.matrix.simplified_msc3575 endpoint and advertised in /versions. Lists
are sorted by activity and filtered by DM, invite, encryption, room type,
space and tag; room subscriptions, required_state with wildcards, $ME and
$LAZY, and the to_device, e2ee, account_data, receipts and typing
extensions are supported. Per-connection state is kept in memory and an
unknown pos answers M_UNKNOWN_POS.

Threads and relations: m.relates_to is indexed on roomserver_events
(migration 0012), /relations (with recursion) and /threads are served, and
every event a timeline read returns carries its m.thread, m.replace and
m.reference summaries in unsigned.m.relations. Notifications carry a
thread ID (migration 0013): threaded receipts clear only their thread, and
sync reports unread_thread_notifications when the filter asks.

Spaces: /hierarchy walks a space breadth first, asking other servers about
rooms this one is not in through the new federation hierarchy endpoint;
room_summary describes one room. /search runs on FTS5 (sqlite, pocketbase)
or tsvector (postgres), bounded to what each user may see, with context,
profiles, state, grouping and paging.

The PocketBase driver is real: the sqlite schema and store on an embedded
PocketBase app's database, with media in its filesystem, local or S3
(database.pocketbase.s3). It runs the full storage test suite.

Ops: OpenTelemetry tracing over OTLP/HTTP (tracing.*), with server spans
per route, component spans, and trace propagation on federation, push and
application service calls. New metrics for persisted events, waiting
syncs, sliding sync connections and the database pool, with a Grafana
dashboard. deploy/ adds a Compose setup (PostgreSQL, Prometheus, Grafana,
Jaeger) and a Helm chart; cmd/warp-loadtest loads a server and reports
request and delivery latencies.

The load tester found a long-standing bug, fixed here: on a server where
no account data had been written, every incremental /sync re-sent the push
rules and returned at once, and an all-zero token was taken for an initial
sync, so long polls became busy loops.

The PostgreSQL migrations and search dialect compile but were not run
against a live PostgreSQL in this change.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

server/internal/setup/observability.go

@@ -0,0 +1,90 @@
+package setup
+
+import (
+	"context"
+	"database/sql"
+
+	"github.com/prometheus/client_golang/prometheus"
+	"github.com/prometheus/client_golang/prometheus/collectors"
+
+	"github.com/dariuszjaniak/warp/server/internal/metrics"
+	"github.com/dariuszjaniak/warp/server/internal/roomserver"
+	"github.com/dariuszjaniak/warp/server/internal/syncapi"
+)
+
+// The homeserver's own metrics, beside the HTTP and runtime ones every
+// route gets: what a dashboard (deploy/grafana) shows about a server's
+// rooms rather than its requests.
+//
+// They are gauges read on scrape and one counter fed from the roomserver's
+// emit stage, so that none of them costs anything between scrapes.
+
+// eventCounter counts persisted events from the emit stage.
+type eventCounter struct {
+	events *prometheus.CounterVec
+}
+
+// EventPersisted implements roomserver.Notifier.
+func (c *eventCounter) EventPersisted(_ context.Context, n roomserver.Notification) {
+	origin := "local"
+	if n.Origin != "" {
+		origin = "federation"
+	}
+	kind := "message"
+	if n.Event != nil && n.Event.IsState() {
+		kind = "state"
+	}
+	c.events.WithLabelValues(origin, kind).Inc()
+}
+
+// registerServerMetrics adds the homeserver's collectors to the registry,
+// and returns the event counter to put on the emit stage.
+func (s *Server) registerServerMetrics(notifier *syncapi.Notifier) *eventCounter {
+	counter := &eventCounter{events: prometheus.NewCounterVec(prometheus.CounterOpts{
+		Namespace: metrics.Namespace,
+		Name:      "events_persisted_total",
+		Help:      "Room events persisted, by where they came from and whether they are state.",
+	}, []string{"origin", "kind"})}
+	s.metrics.MustRegister(counter.events)
+
+	s.metrics.MustRegister(prometheus.NewGaugeFunc(prometheus.GaugeOpts{
+		Namespace: metrics.Namespace,
+		Subsystem: "sync",
+		Name:      "waiting",
+		Help:      "Syncs blocked in a long poll, classic and sliding.",
+	}, func() float64 { return float64(notifier.Listeners()) }))
+
+	s.metrics.MustRegister(prometheus.NewGaugeFunc(prometheus.GaugeOpts{
+		Namespace: metrics.Namespace,
+		Subsystem: "sync",
+		Name:      "sliding_connections",
+		Help:      "Sliding sync connections whose state the server is holding.",
+	}, func() float64 {
+		if s.sync == nil {
+			return 0
+		}
+		return float64(s.sync.SlidingConnections())
+	}))
+
+	s.metrics.MustRegister(prometheus.NewGaugeFunc(prometheus.GaugeOpts{
+		Namespace: metrics.Namespace,
+		Name:      "federation_enabled",
+		Help:      "1 while federation is switched on.",
+	}, func() float64 {
+		if s.settings != nil && s.settings.FederationEnabled() {
+			return 1
+		}
+		return 0
+	}))
+	return counter
+}
+
+// registerDBMetrics adds the connection pool's statistics, for a driver
+// that is built on database/sql.
+func (s *Server) registerDBMetrics() {
+	pool, ok := s.db.(interface{ DB() *sql.DB })
+	if !ok {
+		return
+	}
+	s.metrics.MustRegister(collectors.NewDBStatsCollector(pool.DB(), s.db.Driver()))
+}

server/internal/setup/phase10_test.go

@@ -0,0 +1,170 @@
+package setup_test
+
+import (
+	"net/http"
+	"net/url"
+	"os"
+	"path/filepath"
+	"strings"
+	"testing"
+	"time"
+
+	"github.com/dariuszjaniak/warp/server/internal/config"
+)
+
+// The Phase 10 tests: the PocketBase driver and the new endpoints, through
+// the whole stack.
+
+// TestPocketBaseServer runs a server on the pocketbase driver: accounts,
+// rooms, search and media, with the media landing in PocketBase's own
+// filesystem rather than under media.base_path.
+func TestPocketBaseServer(t *testing.T) {
+	dir := t.TempDir()
+	dataDir := filepath.Join(dir, "pb_data")
+	mediaDir := filepath.Join(dir, "media")
+	srv := newSigningServer(t, func(cfg *config.Config) {
+		cfg.Database.Driver = "pocketbase"
+		cfg.Database.ConnectionString = dataDir
+		cfg.Registration.Enabled = true
+		cfg.ClientAPI.RateLimit.Enabled = false
+		cfg.Media.BasePath = mediaDir
+	})
+
+	health := get(t, srv, http.MethodGet, "/healthz")
+	if health.Code != http.StatusOK || !strings.Contains(health.Body.String(), `"database":"pocketbase"`) {
+		t.Fatalf("healthz: %d %s", health.Code, health.Body.String())
+	}
+
+	token := registerThrough(t, srv, "alice")
+	rec := post(t, srv, "/_matrix/client/v3/createRoom", map[string]any{"name": "On PocketBase"}, token)
+	if rec.Code != http.StatusOK {
+		t.Fatalf("createRoom: %d %s", rec.Code, rec.Body.String())
+	}
+	roomID := decode[map[string]string](t, rec)["room_id"]
+
+	rec = send(t, srv, http.MethodPut,
+		"/_matrix/client/v3/rooms/"+url.PathEscape(roomID)+"/send/m.room.message/t1",
+		"application/json", []byte(`{"msgtype":"m.text","body":"stored in a pocket"}`), token, nil)
+	if rec.Code != http.StatusOK {
+		t.Fatalf("send: %d %s", rec.Code, rec.Body.String())
+	}
+
+	rec = post(t, srv, "/_matrix/client/v3/search", map[string]any{
+		"search_categories": map[string]any{"room_events": map[string]any{"search_term": "pocket"}},
+	}, token)
+	if rec.Code != http.StatusOK || !strings.Contains(rec.Body.String(), "stored in a pocket") {
+		t.Errorf("search: %d %s", rec.Code, rec.Body.String())
+	}
+
+	server, id := uploadThrough(t, srv, token, "text/plain", "note.txt", []byte("pocket media"))
+	rec = getWithToken(t, srv, "/_matrix/client/v1/media/download/"+server+"/"+id, token)
+	if rec.Code != http.StatusOK || rec.Body.String() != "pocket media" {
+		t.Fatalf("download: %d %q", rec.Code, rec.Body.String())
+	}
+
+	var found bool
+	_ = filepath.WalkDir(filepath.Join(dataDir, "storage", "warp_media"), func(_ string, d os.DirEntry, err error) error {
+		if err == nil && !d.IsDir() {
+			found = true
+		}
+		return nil
+	})
+	if !found {
+		t.Error("the upload is not in PocketBase's storage directory")
+	}
+	if _, err := os.Stat(mediaDir); !os.IsNotExist(err) {
+		t.Errorf("media.base_path was used: %v", err)
+	}
+}
+
+func TestVersionsAdvertisesSlidingSync(t *testing.T) {
+	srv := newTestServer(t, nil)
+	rec := get(t, srv, http.MethodGet, "/_matrix/client/versions")
+	features := decode[map[string]any](t, rec)["unstable_features"].(map[string]any)
+	if features["org.matrix.simplified_msc3575"] != true {
+		t.Errorf("unstable_features = %v", features)
+	}
+}
+
+func TestPhase10RoutesAreWiredUp(t *testing.T) {
+	srv := newSigningServer(t, func(c *config.Config) {
+		c.Registration.Enabled = true
+		c.ClientAPI.RateLimit.Enabled = false
+	})
+	token := registerThrough(t, srv, "alice")
+	rec := post(t, srv, "/_matrix/client/v3/createRoom", map[string]any{
+		"creation_content": map[string]any{"type": "m.space"},
+	}, token)
+	roomID := decode[map[string]string](t, rec)["room_id"]
+	escaped := url.PathEscape(roomID)
+
+	for _, path := range []string{
+		"/_matrix/client/v1/rooms/" + escaped + "/hierarchy",
+		"/_matrix/client/v1/rooms/" + escaped + "/threads",
+		"/_matrix/client/v1/room_summary/" + escaped,
+	} {
+		if rec := getWithToken(t, srv, path, token); rec.Code != http.StatusOK {
+			t.Errorf("%s: %d %s", path, rec.Code, rec.Body.String())
+		}
+	}
+	rec = post(t, srv, "/_matrix/client/unstable/org.matrix.simplified_msc3575/sync", map[string]any{
+		"lists": map[string]any{"all": map[string]any{"ranges": [][2]int{{0, 5}}}},
+	}, token)
+	if rec.Code != http.StatusOK || !strings.Contains(rec.Body.String(), `"pos"`) {
+		t.Errorf("sliding sync: %d %s", rec.Code, rec.Body.String())
+	}
+}
+
+func TestServerMetrics(t *testing.T) {
+	srv := newSigningServer(t, nil)
+	token := registerThrough(t, srv, "alice")
+	if rec := post(t, srv, "/_matrix/client/v3/createRoom", map[string]any{}, token); rec.Code != http.StatusOK {
+		t.Fatalf("createRoom: %d", rec.Code)
+	}
+	body := get(t, srv, http.MethodGet, "/metrics").Body.String()
+	for _, want := range []string{
+		`warp_events_persisted_total{kind="state",origin="local"}`,
+		"warp_sync_waiting 0",
+		"warp_sync_sliding_connections 0",
+		"warp_federation_enabled 0",
+		"go_sql_open_connections",
+	} {
+		if !strings.Contains(body, want) {
+			t.Errorf("/metrics has no %s", want)
+		}
+	}
+}
+
+// TestIdleSyncLongPolls is the regression test for two ways an idle
+// /sync came back at once instead of waiting, which made every client's
+// long poll a busy loop: push rules sent again on every sync of a server
+// with no account data written yet, and an all-zero token taken for a
+// first sync on a server whose streams had not moved at all.
+func TestIdleSyncLongPolls(t *testing.T) {
+	for _, withRoom := range []bool{false, true} {
+		t.Run(map[bool]string{false: "empty server", true: "with a room"}[withRoom], func(t *testing.T) {
+			srv := newSigningServer(t, nil)
+			token := registerThrough(t, srv, "alice")
+			if withRoom {
+				if rec := post(t, srv, "/_matrix/client/v3/createRoom", map[string]any{}, token); rec.Code != http.StatusOK {
+					t.Fatalf("createRoom: %d", rec.Code)
+				}
+			}
+
+			first := decode[map[string]any](t, getWithToken(t, srv, "/_matrix/client/v3/sync", token))
+			since, _ := first["next_batch"].(string)
+
+			body := decode[map[string]any](t, getWithToken(t, srv, "/_matrix/client/v3/sync?timeout=0&since="+url.QueryEscape(since), token))
+			accountData, _ := body["account_data"].(map[string]any)
+			if events, _ := accountData["events"].([]any); len(events) != 0 {
+				t.Errorf("an idle incremental sync sent account data again: %d events", len(events))
+			}
+
+			start := time.Now()
+			getWithToken(t, srv, "/_matrix/client/v3/sync?timeout=1000&since="+url.QueryEscape(since), token)
+			if waited := time.Since(start); waited < 900*time.Millisecond {
+				t.Errorf("an idle sync returned after %s instead of waiting out its timeout", waited)
+			}
+		})
+	}
+}

server/internal/setup/routes.go

@@ -6,6 +6,7 @@ import (
 
 	"github.com/dariuszjaniak/warp/server/internal/buildinfo"
 	"github.com/dariuszjaniak/warp/server/internal/httputil"
+	"github.com/dariuszjaniak/warp/server/internal/tracing"
 )
 
 // SpecVersions is what GET /_matrix/client/versions reports.
@@ -20,8 +21,11 @@ import (
 var SpecVersions = []string{"v1.13", "v1.14"}
 
 // UnstableFeatures advertises MSC support. Simplified Sliding Sync
-// (MSC4186) is Phase 10.
-var UnstableFeatures = map[string]bool{}
+// (MSC4186) is how Element X and the matrix-rust-sdk find out they can
+// skip /sync.
+var UnstableFeatures = map[string]bool{
+	"org.matrix.simplified_msc3575": true,
+}
 
 type versionsResponse struct {
 	Versions         []string        `json:"versions"`
@@ -51,7 +55,12 @@ type healthResponse struct {
 
 // routes registers every endpoint this server serves.
 func (s *Server) routes() *httputil.Router {
-	r := httputil.NewRouter(s.metrics.Instrument)
+	// Every route is counted and traced under its pattern. The span is
+	// inside the metrics wrapper so that what the histogram times is what
+	// the trace shows.
+	r := httputil.NewRouter(func(route string, h http.Handler) http.Handler {
+		return s.metrics.Instrument(route, tracing.Instrument(route, h))
+	})
 
 	r.HandleFunc("GET /_matrix/client/versions", s.handleVersions)
 	r.HandleFunc("GET /.well-known/matrix/client", s.handleWellKnownClient)

server/internal/setup/server.go

@@ -33,6 +33,7 @@ import (
 	"github.com/dariuszjaniak/warp/server/internal/storage"
 	_ "github.com/dariuszjaniak/warp/server/internal/storage/drivers" // link in the storage drivers
 	"github.com/dariuszjaniak/warp/server/internal/syncapi"
+	"github.com/dariuszjaniak/warp/server/internal/tracing"
 	"github.com/dariuszjaniak/warp/server/internal/userapi"
 )
 
@@ -47,6 +48,10 @@ type Server struct {
 	federation *federation.Gate
 	signingKey *signing.KeyPair
 
+	// stopTracing flushes and stops the tracer provider tracing.Setup
+	// installed.
+	stopTracing func(context.Context) error
+
 	users     *userapi.API
 	rooms     *roomserver.API
 	sync      *syncapi.API
@@ -122,21 +127,29 @@ func New(ctx context.Context, cfg *config.Config, opts Options) (*Server, error)
 
 	s := &Server{cfg: cfg, log: log, metrics: metrics.NewRegistry()}
 
+	stopTracing, err := tracing.Setup(ctx, tracing.Config{
+		Enabled:        cfg.Tracing.Enabled,
+		Endpoint:       cfg.Tracing.Endpoint,
+		SampleRatio:    cfg.Tracing.SampleRatio,
+		ServiceName:    cfg.Tracing.ServiceName,
+		ServiceVersion: buildinfo.Version,
+		ServerName:     cfg.Global.ServerName,
+	})
+	if err != nil {
+		return nil, err
+	}
+	s.stopTracing = stopTracing
+
 	if opts.Database != nil {
 		s.db = opts.Database
 	} else {
-		db, err := storage.Open(ctx, storage.Config{
-			Driver:           cfg.Database.Driver,
-			ConnectionString: cfg.Database.ConnectionString,
-			MaxOpenConns:     cfg.Database.MaxOpenConns,
-			MaxIdleConns:     cfg.Database.MaxIdleConns,
-			ConnMaxLifetime:  cfg.Database.ConnMaxLifetime,
-		}, log)
+		db, err := storage.Open(ctx, cfg.Database.Storage(), log)
 		if err != nil {
 			return nil, err
 		}
 		s.db, s.ownsDB = db, true
 	}
+	s.registerDBMetrics()
 
 	if err := s.prepareSchema(ctx); err != nil {
 		_ = s.closeDB()
@@ -258,6 +271,7 @@ func New(ctx context.Context, cfg *config.Config, opts Options) (*Server, error)
 		notifier := syncapi.NewNotifier()
 		emit := &fanout{}
 		emit.add(notifier)
+		emit.add(s.registerServerMetrics(notifier))
 
 		clientTLS := opts.FederationTLS
 		if clientTLS == nil {
@@ -734,6 +748,14 @@ func (s *Server) Close() error {
 		// cursors.
 		s.appservices.Close()
 	}
+	if s.stopTracing != nil {
+		// Spans still in the batch are sent rather than lost.
+		ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second)
+		defer cancel()
+		if err := s.stopTracing(ctx); err != nil {
+			s.log.Warn("could not flush traces", "error", err)
+		}
+	}
 	return s.closeDB()
 }
 

server/internal/setup/threads_test.go

@@ -0,0 +1,121 @@
+package setup_test
+
+import (
+	"net/http"
+	"net/url"
+	"testing"
+
+	"github.com/dariuszjaniak/warp/server/internal/setup"
+)
+
+// threadCounts is the part of a sync the per-thread count test reads.
+type threadCounts struct {
+	NotificationCount int `json:"notification_count"`
+	HighlightCount    int `json:"highlight_count"`
+}
+
+type threadSync struct {
+	Rooms struct {
+		Join map[string]struct {
+			UnreadNotifications       *threadCounts           `json:"unread_notifications"`
+			UnreadThreadNotifications map[string]threadCounts `json:"unread_thread_notifications"`
+		} `json:"join"`
+	} `json:"rooms"`
+}
+
+// threadSyncOnce is an initial sync, with the per-thread counts asked for
+// or not.
+func threadSyncOnce(t *testing.T, srv *setup.Server, token string, byThread bool) threadSync {
+	t.Helper()
+	path := "/_matrix/client/v3/sync?timeout=0"
+	if byThread {
+		path += "&filter=" + url.QueryEscape(`{"room":{"timeline":{"unread_thread_notifications":true}}}`)
+	}
+	rec := getWithToken(t, srv, path, token)
+	if rec.Code != http.StatusOK {
+		t.Fatalf("sync: %d %s", rec.Code, rec.Body.String())
+	}
+	return decode[threadSync](t, rec)
+}
+
+// TestThreadNotificationCountsThroughTheAPI follows notifications into a
+// thread and out again: counted under the thread with the filter flag and
+// in the room total without it, and read by a thread receipt, a main
+// receipt and an unthreaded one, each clearing only its own part.
+func TestThreadNotificationCountsThroughTheAPI(t *testing.T) {
+	srv := newSigningServer(t, nil)
+	alice := registerThrough(t, srv, "alice")
+	bob := registerThrough(t, srv, "bob")
+
+	roomID := createPublicRoom(t, srv, alice)
+	mustOK(t, post(t, srv, "/_matrix/client/v3/rooms/"+url.PathEscape(roomID)+"/join", map[string]any{}, bob), "join")
+	waitForPush(t, srv)
+
+	inThread := func(root string) map[string]any {
+		return map[string]any{"rel_type": "m.thread", "event_id": root}
+	}
+	root := sendText(t, srv, bob, roomID, "r", map[string]any{"msgtype": "m.text", "body": "a thread"})
+	sendText(t, srv, bob, roomID, "a", map[string]any{"msgtype": "m.text", "body": "first reply",
+		"m.relates_to": inThread(root)})
+	reply := sendText(t, srv, bob, roomID, "b", map[string]any{"msgtype": "m.text", "body": "second reply",
+		"m.mentions":   map[string]any{"user_ids": []string{"@alice:warp.example"}},
+		"m.relates_to": inThread(root)})
+	sendText(t, srv, bob, roomID, "c", map[string]any{"msgtype": "m.text", "body": "back in the room"})
+	waitForPush(t, srv)
+
+	// Without the flag the room counts everything, as before threads.
+	plain := threadSyncOnce(t, srv, alice, false).Rooms.Join[roomID]
+	if c := plain.UnreadNotifications; c == nil || *c != (threadCounts{NotificationCount: 4, HighlightCount: 1}) {
+		t.Errorf("room total = %+v", c)
+	}
+	if plain.UnreadThreadNotifications != nil {
+		t.Errorf("thread counts without the flag: %+v", plain.UnreadThreadNotifications)
+	}
+
+	// With it the root and the later message are the main timeline's, and
+	// the replies are the thread's.
+	split := threadSyncOnce(t, srv, alice, true).Rooms.Join[roomID]
+	if c := split.UnreadNotifications; c == nil || *c != (threadCounts{NotificationCount: 2}) {
+		t.Errorf("main timeline = %+v", c)
+	}
+	if got := split.UnreadThreadNotifications; len(got) != 1 ||
+		got[root] != (threadCounts{NotificationCount: 2, HighlightCount: 1}) {
+		t.Errorf("thread counts = %+v", got)
+	}
+
+	receipt := func(eventID string, body map[string]any) {
+		t.Helper()
+		mustOK(t, post(t, srv, "/_matrix/client/v3/rooms/"+url.PathEscape(roomID)+"/receipt/m.read/"+url.PathEscape(eventID),
+			body, alice), "receipt")
+	}
+
+	// Reading the thread leaves the main timeline unread.
+	receipt(reply, map[string]any{"thread_id": root})
+	split = threadSyncOnce(t, srv, alice, true).Rooms.Join[roomID]
+	if c := split.UnreadNotifications; c == nil || c.NotificationCount != 2 || len(split.UnreadThreadNotifications) != 0 {
+		t.Errorf("after the thread receipt: %+v, %+v", c, split.UnreadThreadNotifications)
+	}
+	if c := threadSyncOnce(t, srv, alice, false).Rooms.Join[roomID].UnreadNotifications; c == nil || c.NotificationCount != 2 {
+		t.Errorf("room total after the thread receipt = %+v", c)
+	}
+
+	// A new reply, then a main receipt on the root: the root is read, the
+	// later message and the new reply are not.
+	third := sendText(t, srv, bob, roomID, "d", map[string]any{"msgtype": "m.text", "body": "third reply",
+		"m.relates_to": inThread(root)})
+	waitForPush(t, srv)
+	receipt(root, map[string]any{"thread_id": "main"})
+	split = threadSyncOnce(t, srv, alice, true).Rooms.Join[roomID]
+	if c := split.UnreadNotifications; c == nil || c.NotificationCount != 1 ||
+		split.UnreadThreadNotifications[root].NotificationCount != 1 {
+		t.Errorf("after the main receipt: %+v, %+v", c, split.UnreadThreadNotifications)
+	}
+
+	// An unthreaded receipt reads the lot up to its event, whichever
+	// thread that event is in: here the newest, a reply.
+	receipt(third, map[string]any{})
+	split = threadSyncOnce(t, srv, alice, true).Rooms.Join[roomID]
+	if c := split.UnreadNotifications; c == nil || c.NotificationCount != 0 || len(split.UnreadThreadNotifications) != 0 {
+		t.Errorf("after the unthreaded receipt: %+v, %+v", c, split.UnreadThreadNotifications)
+	}
+}