diff --git a/CLAUDE.md b/CLAUDE.md index 4ad9eeb..dd55ed9 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -44,6 +44,20 @@ maintains it. so it cannot make data look fresher; keep it that way. - **Import only `go/protocol` from `srcfl/ftw`.** `scripts/check-imports.sh` fails on anything else. +- **A home lives on one shard** (`internal/shard`). An instance that does not + hold a home names the host that does (4421, or 421 with `Ftw-Shard`) + before it reads message 1 or touches the registry. Nothing about a home + crosses between instances: no shared pub/sub, no shared storage. With no + `-shards` file one instance holds every home. `/mcp` and `/oauth` stay on + `cloud.ftw.energy` and forward to the home's shard once there is a second + one, because other parties' clients follow no redirect. +- **Counts name nobody.** `/metrics` listens on loopback only, and it and + the minute's log line sum over all homes: no home id, device or address. +- **A deploy drains.** On SIGTERM every socket, handshakes included, hears + 4503 with a spread before the process exits, and no drained box starts + `box.unreachable`. A part that holds sockets is a `drainer` in + `cmd/ftwcloudd`. Every close the service sends waits for the client's + answer (`internal/wsclose`), so the client reads the code, not a reset. ## Work @@ -54,20 +68,25 @@ maintains it. and the service is over it. The one-door plan gives each part a budget of its own, and the numbers are Fredrik's call. Until he sets them, a PR that grows a part says by how much. Lines of Go without tests, at - srcfl/ftw-cloud#15: + srcfl/ftw-cloud#17 (#15 in brackets): | Part | Lines | |---|---| - | `internal/appsession` (app session, one-shot read) | 1,020 | - | `internal/store` | 807 | - | `internal/uplink` | 719 | - | `internal/registry` | 694 | - | `cmd/ftwcloudd` | 553 | - | `internal/push` | 542 | - | `internal/apns` | 299 | - | `internal/server` | 205 | - | `internal/token` | 170 | - | All | 5,009 | + | `internal/appsession` (app session, one-shot read) | 1,116 (1,020) | + | `internal/push` | 1,029 (542) | + | `internal/uplink` | 938 (719) | + | `internal/store` | 854 (807) | + | `internal/registry` | 809 (694) | + | `cmd/ftwcloudd` | 701 (553) | + | `internal/metrics` | 448 (new) | + | `internal/apns` | 299 (299) | + | `internal/token` | 214 (170) | + | `internal/server` | 199 (205) | + | `internal/shard` | 188 (new) | + | `internal/wsclose` | 109 (new) | + | All | 6,904 (5,009) | + + `cmd/ftwload`, the load harness, is a tool and not the service (1,938). - Nothing is deployed from here without the owner. `deploy/` describes the running host; it does not run itself. - Keep task breakdowns and agent notes out of the repository. diff --git a/README.md b/README.md index 6dc9eb4..e147c6c 100644 --- a/README.md +++ b/README.md @@ -30,6 +30,14 @@ to it yet. and when an away box's alert is due. A box whose owner turns the readable copy off gets that copy deleted and a signed receipt (`purged {what: "copy"}`); a box whose link ends gets its home deleted and a receipt. +- **Room to grow.** Each home lives on one shard; an instance that does not + hold a home names the host that does, and clients follow once + (`internal/shard`, protocol "Shards and restarts"). With no `-shards` file + one instance holds every home. A deploy closes every socket with 4503 and + a spread, so boxes and phones come back over seconds rather than at once. + `/metrics` on loopback and one log line a minute count what the service + does without naming a home. `deploy/README.md` has the load numbers and + when to add a shard. - **A restart forgets no one.** At start the service reads every signed roster back from the registry and checks it with the home's key, so a home's phones are admitted before its box reconnects, and the wait for @@ -206,8 +214,14 @@ go test -run XXX -fuzz FuzzPhoneMessage -fuzztime 30s ./internal/appsession go test -run TestTheSnapshotArrivesFast -v ./internal/appsession # loopback p50/p95 go test -run XXX -bench BenchmarkSnapshot ./internal/appsession bash scripts/check-imports.sh +go build -o /tmp/ftwload/ftwcloudd ./cmd/ftwcloudd # then, briefly and on a quiet machine: +go run ./cmd/ftwload -ftwcloudd /tmp/ftwload/ftwcloudd -homes 1000 -phones 1 -duration 45s ``` +`cmd/ftwload` starts its own `ftwcloudd`, drives simulated boxes and phones +against it, prints latencies (its own and the service's from `/metrics`), +CPU and memory, and exits by itself. + The wire types come from `github.com/srcfl/ftw/go/protocol`, Apache-2.0, pinned to a commit in `go.mod`. A wire change is a pair of pull requests: first in `srcfl/ftw` (`go/protocol` and its golden vectors), then here, moving diff --git a/cmd/ftwcloudd/main.go b/cmd/ftwcloudd/main.go index 2bc334f..6bc5e3c 100644 --- a/cmd/ftwcloudd/main.go +++ b/cmd/ftwcloudd/main.go @@ -4,6 +4,7 @@ // // ftwcloudd keygen -out service.key make the service key; prints its public half // ftwcloudd keygen -noise -out noise.key make the Noise key phones dial; prints its public half +// ftwcloudd metrics print the running service's counts, from inside its container // ftwcloudd [flags] serve package main @@ -23,19 +24,23 @@ import ( "io" "log" "log/slog" + "net" "net/http" "os" "os/signal" "path/filepath" + "strconv" "strings" "syscall" "time" "github.com/srcfl/ftw-cloud/internal/apns" "github.com/srcfl/ftw-cloud/internal/appsession" + "github.com/srcfl/ftw-cloud/internal/metrics" "github.com/srcfl/ftw-cloud/internal/push" "github.com/srcfl/ftw-cloud/internal/registry" "github.com/srcfl/ftw-cloud/internal/server" + "github.com/srcfl/ftw-cloud/internal/shard" "github.com/srcfl/ftw-cloud/internal/store" "github.com/srcfl/ftw-cloud/internal/token" "github.com/srcfl/ftw-cloud/internal/uplink" @@ -52,6 +57,13 @@ func main() { } return } + if len(os.Args) > 1 && os.Args[1] == "metrics" { + if err := printMetrics(os.Args[2:]); err != nil { + fmt.Fprintln(os.Stderr, err) + os.Exit(1) + } + return + } if err := serve(os.Args[1:]); err != nil { slog.Error("ftwcloudd stopped", "err", err) os.Exit(1) @@ -73,6 +85,10 @@ func serve(args []string) error { apnsWatch := fs.String("apns-watch-topic", "energy.ftw.app.watchkitapp", "the watch app's bundle id") devPush := fs.String("dev-push-listen", "", "loopback address for registering a token by hand (development builds only)") devCapture := fs.String("dev-apns-capture", "", "write each alert to this directory instead of sending it to Apple (development builds only)") + shardsPath := fs.String("shards", "", "shard directory, JSON; without it this instance holds every home") + metricsAddr := fs.String("metrics-listen", defaultMetricsAddr, "loopback address for /metrics; empty turns it off") + restartRate := fs.Int("restart-rate", defaultRestartRate, "sockets a second the next instance can take after a restart; sets the spread of the redial") + restartMin := fs.Duration("restart-spread-min", 15*time.Second, "the shortest spread: longer than the port stays closed while the next container starts") _ = fs.Parse(args) harden() @@ -90,6 +106,15 @@ func serve(args []string) error { } else if err != nil { return err } + shards := shard.Single(*domain) + if *shardsPath != "" { + if shards, err = shard.Load(*shardsPath); err != nil { + return err + } + if shards.Host() != *domain { + return fmt.Errorf("shards: this instance is %s at %s, but -domain is %s", shards.Self(), shards.Host(), *domain) + } + } reg, err := registry.Open(filepath.Join(*stateDir, "registry.db")) if err != nil { return err @@ -99,15 +124,18 @@ func serve(args []string) error { st := store.New(nil) st.UseSuspensions(reg.Suspended) up := uplink.New(st, reg, key, log) + up.Shards = shards // A restart is a deploy, and commands ride through here: phones are // admitted by the rosters their boxes signed before, without waiting // for every box to reconnect. + restoreStart := time.Now() if n, err := up.Restore(); err != nil { return err } else if n > 0 { - log.Info("rosters restored from the registry", "homes", n) + log.Info("rosters restored from the registry", "homes", n, "took", time.Since(restoreStart).Round(time.Millisecond)) } tokens := token.New(st, reg, log) + tokens.Shards = shards srv := &server.Server{Store: st, Registry: reg, Uplink: up, Tokens: tokens, Log: log} // Alerts: the box's signed events to its phones through Apple, and @@ -129,6 +157,7 @@ func serve(args []string) error { } pushSvc := push.New(reg, sender, log) pushSvc.WatchApp = *apnsWatch + pushSvc.Owns = shards.Ours up.OnHeld = pushSvc.Held up.OnRoster = func(home string, r *cloudwire.Roster) { pushSvc.Roster(home, r) @@ -143,6 +172,7 @@ func serve(args []string) error { srv.App.Push = pushSvc srv.App.Tokens = tokens srv.App.Tunnel = up + srv.App.Shards = shards } app := srv.App up.OnConnect = func(home string, conn uint64) { @@ -184,10 +214,17 @@ func serve(args []string) error { ErrorLog: log0(), } + metrics.Default.GaugeFunc("ftwcloud_homes", "Homes held in memory.", func() int64 { return int64(st.Homes()) }) + metrics.Default.GaugeFunc("ftwcloud_homes_connected", "Homes whose box is connected.", func() int64 { return int64(up.Boxes()) }) + metrics.Runtime() + ctx, stop := signal.NotifyContext(context.Background(), syscall.SIGINT, syscall.SIGTERM) defer stop() go srv.Upkeep(ctx, time.Minute) - go pushSvc.Run(ctx) + // Push outlives the signal until the queued alerts are out. + pushCtx, stopPush := context.WithCancel(context.Background()) + defer stopPush() + go pushSvc.Run(pushCtx) if err := pushSvc.Resume(); err != nil { log.Warn("could not restart the dead man's switch", "err", err) } @@ -196,22 +233,133 @@ func serve(args []string) error { return err } } + if *metricsAddr != "" { + if err := serveMetrics(ctx, *metricsAddr); err != nil { + return err + } + } + go metrics.Default.Summarise(ctx, os.Stdout, shards.Self(), time.Minute) + + // A deploy: stop accepting, tell every box and phone to come back within + // a spread the next instance can take, let the queued alerts go, then + // exit. A box closed this way starts no box.unreachable. Every part + // that holds sockets is a drainer, so an agent's sessions are closed and + // counted in the spread too once that part adds itself here. + drainers := []drainer{up} + if app != nil { + drainers = append(drainers, app) + } + drained := make(chan struct{}) go func() { + defer close(drained) <-ctx.Done() shutdown, cancel := context.WithTimeout(context.Background(), 5*time.Second) defer cancel() - _ = httpSrv.Shutdown(shutdown) + go func() { _ = httpSrv.Shutdown(shutdown) }() + sockets := 0 + for _, d := range drainers { + sockets += d.Sockets() + } + spread := restartSpread(sockets, *restartRate, *restartMin) + reason := strconv.FormatInt(spread.Milliseconds(), 10) + for _, d := range drainers { + d.Drain(reason) + } + // Each socket waits for its client's answer to the close, so the + // client reads 4503 and the spread rather than a reset. + left := 0 + deadline := time.Now().Add(drainWait) + for _, d := range drainers { + left += d.WaitClosed(time.Until(deadline)) + } + log.Info("drained for a restart", "sockets", sockets, "still_open", left, "spread", spread) + if left := pushSvc.Flush(3 * time.Second); left > 0 { + log.Warn("alerts queued or waiting to go again at exit; they are lost", "count", left) + } + stopPush() }() pub, _ := cloudwire.PublicKeyBytesOf(&key.PublicKey) - log.Info("ftwcloudd listening", "addr", *listen, "service_key", base64.RawURLEncoding.EncodeToString(pub), - "noise_key", base64.RawURLEncoding.EncodeToString(noise.Public())) - if err := httpSrv.ListenAndServeTLS("", ""); err != nil && !errors.Is(err, http.ErrServerClosed) { + log.Info("ftwcloudd listening", "addr", *listen, "shard", shards.Self(), "shards", shards.Shards(), + "service_key", base64.RawURLEncoding.EncodeToString(pub), "noise_key", base64.RawURLEncoding.EncodeToString(noise.Public())) + err = httpSrv.ListenAndServeTLS("", "") + if err != nil && !errors.Is(err, http.ErrServerClosed) { return err } + <-drained return nil } +// drainer is a part that holds sockets and closes them before a restart. +type drainer interface { + // Sockets is how many sockets it holds, handshakes included. + Sockets() int + // Drain closes them with 4503 and reason, and turns away new ones. + Drain(reason string) + // WaitClosed waits at most d for their clients' answers and returns how + // many are still open. + WaitClosed(d time.Duration) int +} + +// drainWait bounds the wait for the clients' answers to the drain's close. +const drainWait = 2 * time.Second + +// defaultRestartRate is how many sockets a second one instance takes on +// the host, with room to spare: deploy/README.md, "Load", has the numbers. +const defaultRestartRate = 500 + +// restartSpread is how long sockets wait at most before they redial: their +// number at rate a second, at least floor, which covers the next instance's +// start, and at most cloudwire.RestartSpreadMaxMs. +func restartSpread(sockets, rate int, floor time.Duration) time.Duration { + if rate <= 0 { + rate = defaultRestartRate + } + d := time.Duration(sockets) * time.Second / time.Duration(rate) + return min(max(d, floor), time.Duration(cloudwire.RestartSpreadMaxMs)*time.Millisecond) +} + +// defaultMetricsAddr is inside the container only; an operator reads it +// with docker exec and ftwcloudd metrics. +const defaultMetricsAddr = "127.0.0.1:9464" + +// serveMetrics answers /metrics on a loopback address until ctx ends. +func serveMetrics(ctx context.Context, addr string) error { + host, _, err := net.SplitHostPort(addr) + if err != nil { + return fmt.Errorf("metrics-listen: %w", err) + } + if ip := net.ParseIP(host); host != "localhost" && (ip == nil || !ip.IsLoopback()) { + return fmt.Errorf("metrics-listen: %s is not a loopback address", addr) + } + ln, err := net.Listen("tcp", addr) + if err != nil { + return err + } + m := &http.Server{Handler: metrics.Default, ReadHeaderTimeout: 5 * time.Second, ErrorLog: log0()} + go func() { _ = m.Serve(ln) }() + go func() { + <-ctx.Done() + _ = m.Close() + }() + return nil +} + +// printMetrics prints the running service's /metrics. +func printMetrics(args []string) error { + fs := flag.NewFlagSet("metrics", flag.ExitOnError) + addr := fs.String("addr", defaultMetricsAddr, "where the service answers /metrics") + _ = fs.Parse(args) + c := &http.Client{Timeout: 5 * time.Second} + resp, err := c.Get("http://" + *addr + "/metrics") + if err != nil { + return err + } + defer resp.Body.Close() + _, err = io.Copy(os.Stdout, resp.Body) + return err +} + func log0() *log.Logger { return log.New(io.Discard, "", 0) } // loadAPNs reads Apple's key from dir: key.p8, key-id and team-id, as the diff --git a/cmd/ftwcloudd/main_test.go b/cmd/ftwcloudd/main_test.go new file mode 100644 index 0000000..2694c31 --- /dev/null +++ b/cmd/ftwcloudd/main_test.go @@ -0,0 +1,23 @@ +package main + +import ( + "testing" + "time" +) + +func TestTheRestartSpreadFollowsTheSockets(t *testing.T) { + for _, c := range []struct { + sockets, rate int + want time.Duration + }{ + {0, 500, 15 * time.Second}, + {4000, 500, 15 * time.Second}, + {12000, 500, 24 * time.Second}, + {1_000_000, 500, 60 * time.Second}, + {12000, 0, 24 * time.Second}, + } { + if got := restartSpread(c.sockets, c.rate, 15*time.Second); got != c.want { + t.Errorf("restartSpread(%d, %d) = %s, want %s", c.sockets, c.rate, got, c.want) + } + } +} diff --git a/cmd/ftwload/box.go b/cmd/ftwload/box.go new file mode 100644 index 0000000..5ee31fa --- /dev/null +++ b/cmd/ftwload/box.go @@ -0,0 +1,339 @@ +package main + +import ( + "bytes" + "context" + "crypto/ecdsa" + "crypto/elliptic" + "crypto/rand" + "crypto/tls" + "errors" + "fmt" + mrand "math/rand/v2" + "sort" + "sync" + "sync/atomic" + "time" + + "github.com/gorilla/websocket" + "github.com/srcfl/ftw/go/protocol" + "github.com/srcfl/ftw/go/protocol/appwire" + "github.com/srcfl/ftw/go/protocol/cloudwire" +) + +const ( + handshakeTimeout = 10 * time.Second + // readTimeout: the service pings every 15 s. + readTimeout = 60 * time.Second + writeTimeout = 10 * time.Second + // rosterSeq is the one roster each box signs; a box sends it again only + // when hello_ok says the service holds an older one. + rosterSeq = 1 +) + +// box is one home's gateway: one uplink, a signed roster that lists its +// phones, a live every -live, and every tun echoed straight back. +type box struct { + h *harness + key *ecdsa.PrivateKey + pk []byte + home string + boot []byte + born time.Time + grant cloudwire.Grant + phones []appwire.KeyPair + // ready is closed once the service has the roster, so phones dial a + // home that lists them. + ready chan struct{} + readyOnce sync.Once + + // wmu orders writes and the header's seq with them. + wmu sync.Mutex + seq uint64 + conn atomic.Pointer[websocket.Conn] + stormed atomic.Bool + + // sent is when each recent live left, by seq, for the phones' latency. + liveMu sync.Mutex + sent [64]liveSent +} + +type liveSent struct { + seq uint64 + at time.Time + counted bool +} + +func newBox(h *harness) *box { + key, _ := ecdsa.GenerateKey(elliptic.P256(), rand.Reader) + pk, _ := cloudwire.PublicKeyBytesOf(&key.PublicKey) + b := &box{h: h, key: key, pk: pk, home: cloudwire.HomeID(pk), boot: randBytes(cloudwire.BootBytes), + born: time.Now(), ready: make(chan struct{}), + grant: cloudwire.Grant{Scopes: []string{}, Purposes: []string{}, Controller: cloudwire.ControllerSourceful}} + if h.cfg.copy { + b.grant = cloudwire.Grant{ID: randBytes(cloudwire.GrantIDBytes), Scopes: []string{protocol.ScopeLiveRead}, + Purposes: []string{protocol.CloudPurposeServe}, Controller: cloudwire.ControllerSourceful} + } + for range h.cfg.phones { + k, _ := appwire.GenerateKeyPair() + b.phones = append(b.phones, k) + } + return b +} + +func (b *box) run(ctx context.Context, start time.Duration) { + if !sleep(ctx, start) { + return + } + attempt := 0 + for ctx.Err() == nil && !b.h.stopping.Load() { + began := time.Now() + conn, err := b.connect(ctx) + if err != nil { + if !b.h.redial(ctx, "box."+stepOf(err), err, &attempt) { + return + } + continue + } + hs := time.Since(began) + b.h.stats.boxHS.add(hs) + // Stored before the storm flag is read, so a storm that comes + // meanwhile either closes this socket or counts it as back. + b.conn.Store(conn) + if b.stormed.CompareAndSwap(true, false) { + b.h.recovered(hs) + } + attempt = 0 + err = b.session(ctx, conn) + if b.stormed.Load() && ctx.Err() == nil { + if !sleep(ctx, jitter(b.h.cfg.stormJitter)) { + return + } + continue + } + if !b.h.redial(ctx, "box.session", err, &attempt) { + return + } + } +} + +// connect dials /v1/box and runs the handshake: challenge, a hello signed +// over the nonce and the TLS exporter, hello_ok checked against the service +// key. Then the roster, if the service lacks it. +func (b *box) connect(ctx context.Context) (*websocket.Conn, error) { + conn, _, err := b.h.dialer.DialContext(ctx, b.h.url+"/v1/box", nil) + if err != nil { + return nil, &failure{"dial", err} + } + ok := false + defer func() { + if !ok { + _ = conn.Close() + } + }() + _ = conn.SetReadDeadline(time.Now().Add(handshakeTimeout)) + tc, _ := conn.NetConn().(*tls.Conn) + if tc == nil { + return nil, &failure{"handshake", errors.New("not TLS")} + } + cs := tc.ConnectionState() + ekm, err := cs.ExportKeyingMaterial(cloudwire.EKMLabel, nil, cloudwire.EKMBytes) + if err != nil { + return nil, &failure{"handshake", err} + } + env, err := readEnvelope(conn) + var ch cloudwire.Challenge + if err != nil || env.T != cloudwire.MsgChallenge || cloudwire.Unmarshal(env.B, &ch) != nil { + return nil, &failure{"handshake", orErr(err, "first message %q", env.T)} + } + boxNonce := randBytes(cloudwire.NonceBytes) + b.wmu.Lock() + err = b.sealLocked(conn, cloudwire.MsgHello, cloudwire.Hello{Header: b.headerLocked(), V: cloudwire.Version, PK: b.pk, + Nonce: ch.Nonce, EKM: ekm, BoxNonce: boxNonce, Build: "ftwload", Clock: cloudwire.ClockNTP, + Caps: []string{cloudwire.MsgLive, cloudwire.MsgRoster, cloudwire.CapTun, cloudwire.CapShard}, + RosterSeq: rosterSeq, GrantID: b.grant.ID}) + b.wmu.Unlock() + if err != nil { + return nil, &failure{"handshake", err} + } + env, err = readEnvelope(conn) + var hok cloudwire.HelloOK + switch { + case err != nil: + return nil, &failure{"handshake", err} + case env.T != cloudwire.MsgHelloOK || cloudwire.Verify(b.h.service, b.home, env) != nil || + cloudwire.Unmarshal(env.B, &hok) != nil || !bytes.Equal(hok.BoxNonce, boxNonce) || !bytes.Equal(hok.EKM, ekm): + return nil, &failure{"handshake", fmt.Errorf("hello_ok did not check out (%q)", env.T)} + } + if hok.RosterSeq < rosterSeq { + if err := b.sendRoster(conn); err != nil { + return nil, &failure{"handshake", err} + } + } + b.readyOnce.Do(func() { close(b.ready) }) + keepAlive(conn) + ok = true + return conn, nil +} + +func (b *box) sendRoster(conn *websocket.Conn) error { + b.wmu.Lock() + defer b.wmu.Unlock() + r := cloudwire.Roster{Header: b.headerLocked(), RosterSeq: rosterSeq, TTLS: 86_400, Grant: b.grant} + for _, k := range b.phones { + r.Devices = append(r.Devices, cloudwire.Device{ID: cloudwire.DeviceID(k.Public()), Key: k.Public(), Role: "owner", + Scopes: []string{protocol.ScopeLiveRead}, Epoch: 1, Tun: true}) + } + sort.Slice(r.Devices, func(i, j int) bool { return r.Devices[i].ID < r.Devices[j].ID }) + return b.sealLocked(conn, cloudwire.MsgRoster, r) +} + +// session sends live and echoes tun until the socket ends. +func (b *box) session(ctx context.Context, conn *websocket.Conn) error { + b.h.up(&b.h.boxesUp, b.h.wantBoxes, &b.h.allBoxesAt) + stop := context.AfterFunc(ctx, func() { _ = conn.Close() }) + done := make(chan struct{}) + go b.liveLoop(conn, done) + err := b.readLoop(conn) + close(done) + stop() + _ = conn.Close() + b.conn.CompareAndSwap(conn, nil) + b.h.boxesUp.Add(-1) + return err +} + +func (b *box) liveLoop(conn *websocket.Conn, done <-chan struct{}) { + t := time.NewTimer(jitter(b.h.cfg.live)) + defer t.Stop() + for { + select { + case <-done: + return + case <-t.C: + } + t.Reset(b.h.cfg.live) + b.wmu.Lock() + hdr := b.headerLocked() + env, err := cloudwire.Seal(b.key, b.home, cloudwire.MsgLive, cloudwire.Live{Header: hdr, + Fields: map[string]int64{"1": 1200, "2": -800, "3": 400}, Ages: map[string]int64{}}) + if err == nil { + b.liveMu.Lock() + b.sent[hdr.Seq%64] = liveSent{seq: hdr.Seq, at: time.Now(), counted: b.h.measuring.Load()} + b.liveMu.Unlock() + err = b.writeLocked(conn, env) + } + b.wmu.Unlock() + if err != nil { + return + } + } +} + +// readLoop echoes each tun with the same dev, sid and d, as if the box +// answered a command. Everything else is ignored. +func (b *box) readLoop(conn *websocket.Conn) error { + for { + env, err := readEnvelope(conn) + if err != nil { + return err + } + _ = conn.SetReadDeadline(time.Now().Add(readTimeout)) + if env.T != cloudwire.MsgTun { + continue + } + var t cloudwire.Tun + if cloudwire.Unmarshal(env.B, &t) != nil || t.Ended() { + continue + } + b.wmu.Lock() + err = b.writeLocked(conn, cloudwire.Envelope{T: cloudwire.MsgTun, B: env.B}) + b.wmu.Unlock() + if err != nil { + return err + } + } +} + +// headerLocked is the next header: seq rises per message, per boot, across +// reconnects. The caller holds wmu. +func (b *box) headerLocked() cloudwire.Header { + b.seq++ + wall := time.Now().UnixMilli() + return cloudwire.Header{Seq: b.seq, Boot: b.boot, UptimeMs: time.Since(b.born).Milliseconds(), WallMs: &wall} +} + +func (b *box) sealLocked(conn *websocket.Conn, t string, body any) error { + env, err := cloudwire.Seal(b.key, b.home, t, body) + if err != nil { + return err + } + return b.writeLocked(conn, env) +} + +func (b *box) writeLocked(conn *websocket.Conn, env cloudwire.Envelope) error { + raw, err := env.Encode() + if err != nil { + return err + } + frame, err := cloudwire.EncodeFrame(raw) + if err != nil { + return err + } + _ = conn.SetWriteDeadline(time.Now().Add(writeTimeout)) + return conn.WriteMessage(websocket.BinaryMessage, frame) +} + +func readEnvelope(conn *websocket.Conn) (cloudwire.Envelope, error) { + _, msg, err := conn.ReadMessage() + if err != nil { + return cloudwire.Envelope{}, err + } + payload, err := cloudwire.DecodeFrame(msg) + if err != nil { + return cloudwire.Envelope{}, err + } + return cloudwire.DecodeEnvelope(payload) +} + +// keepAlive answers the service's pings and keeps the read deadline ahead. +func keepAlive(conn *websocket.Conn) { + _ = conn.SetReadDeadline(time.Now().Add(readTimeout)) + conn.SetPingHandler(func(data string) error { + _ = conn.SetReadDeadline(time.Now().Add(readTimeout)) + _ = conn.WriteControl(websocket.PongMessage, []byte(data), time.Now().Add(writeTimeout)) + return nil + }) +} + +// failure names the step a dial failed at: dial or handshake. +type failure struct { + step string + err error +} + +func (f *failure) Error() string { return f.step + ": " + f.err.Error() } +func (f *failure) Unwrap() error { return f.err } + +func stepOf(err error) string { + var f *failure + if errors.As(err, &f) { + return f.step + } + return "dial" +} + +func orErr(err error, format string, args ...any) error { + if err != nil { + return err + } + return fmt.Errorf(format, args...) +} + +func randBytes(n int) []byte { + b := make([]byte, n) + _, _ = rand.Read(b) + return b +} + +func randN(n int64) int64 { return mrand.Int64N(n) } diff --git a/cmd/ftwload/main.go b/cmd/ftwload/main.go new file mode 100644 index 0000000..05d7e95 --- /dev/null +++ b/cmd/ftwload/main.go @@ -0,0 +1,612 @@ +// Command ftwload drives a local ftwcloudd with simulated boxes and phones +// and measures what the service costs: connects, handshakes, tun round trips, +// box-to-phone live latency, and the service's CPU and memory. +// +// It speaks only the wire (go/protocol), starts ftwcloudd itself as a child +// process on 127.0.0.1 with fresh keys and a self-signed certificate in a +// temporary directory, and exits by itself. Build the service first: +// +// go build -o /tmp/ftwload/ftwcloudd ./cmd/ftwcloudd +// go run ./cmd/ftwload -ftwcloudd /tmp/ftwload/ftwcloudd -homes 100 -duration 60s +// +// Timeline: box connects spread over the first half of -ramp, phone +// connects over the second half; the steady phase of -duration starts when +// all are up (or at the latest 10 s after the ramp). -storm-at and +// -sigterm-at count from the start of the steady phase. Tun and live +// latencies count only what was sent during the steady phase. +// +// The harness runs with -procs cores and the service with -server-procs +// (GOMAXPROCS, default 2, as on a 2-vCPU t4g.small). On macOS one source +// address reaches about 16k sockets (the ephemeral port range); beyond that +// add loopback aliases (sudo ifconfig lo0 alias 127.0.0.2) and pass -src. +// +// On a shared laptop: check that no heavy build runs first (pgrep -fl +// 'xcodebuild|swift-build|go test|go build'), keep load at or below twice the +// cores, and leave -max set. Whatever happens, the child is killed at -max: +// by the harness, on SIGINT or SIGTERM, and by a watchdog shell that outlives +// a crashed harness. Check with pgrep -fl ftwcloudd afterwards. +package main + +import ( + "context" + "crypto/ecdsa" + "crypto/elliptic" + "crypto/rand" + "crypto/tls" + "crypto/x509" + "crypto/x509/pkix" + "encoding/base64" + "encoding/pem" + "errors" + "flag" + "fmt" + "math/big" + "net" + "net/http" + "os" + "os/exec" + "os/signal" + "path/filepath" + "runtime" + "strconv" + "strings" + "sync" + "sync/atomic" + "syscall" + "time" + + "github.com/gorilla/websocket" + "github.com/srcfl/ftw/go/protocol/cloudwire" +) + +type config struct { + bin string + serverProcs, procs int + max time.Duration + homes, phones int + ramp, duration time.Duration + copy bool + live, cmd time.Duration + stormAt, stormJitter time.Duration + sigtermAt time.Duration + jsonPath, src string + serverMetrics bool +} + +func parseFlags() config { + var c config + flag.BoolVar(&c.serverMetrics, "server-metrics", true, "read the service's own latencies from its -metrics-listen (off for a build without it)") + flag.StringVar(&c.bin, "ftwcloudd", "", "path to a built ftwcloudd (go build -o /ftwcloudd ./cmd/ftwcloudd)") + flag.IntVar(&c.serverProcs, "server-procs", 2, "GOMAXPROCS for ftwcloudd") + flag.IntVar(&c.procs, "procs", 6, "GOMAXPROCS for the harness") + flag.DurationVar(&c.max, "max", 150*time.Second, "hard deadline for the whole run; ftwcloudd is killed then") + flag.IntVar(&c.homes, "homes", 100, "homes, one box each") + flag.IntVar(&c.phones, "phones", 1, "phones per home") + flag.DurationVar(&c.ramp, "ramp", 10*time.Second, "boxes connect over the first half, phones over the second") + flag.DurationVar(&c.duration, "duration", 60*time.Second, "steady phase") + flag.BoolVar(&c.copy, "copy", true, "readable copy on: the service forwards each box's live to its phones") + flag.DurationVar(&c.live, "live", time.Second, "how often each box sends live") + flag.DurationVar(&c.cmd, "cmd", time.Second, "how often each phone sends a tun the box echoes") + flag.DurationVar(&c.stormAt, "storm-at", 0, "close every box socket at once this far into the steady phase (0 off)") + flag.DurationVar(&c.stormJitter, "storm-jitter", 0, "after the storm, each box redials within this delay") + flag.DurationVar(&c.sigtermAt, "sigterm-at", 0, "send ftwcloudd SIGTERM this far into the steady phase (0 off)") + flag.StringVar(&c.jsonPath, "json", "", "also write the summary as JSON to this file") + flag.StringVar(&c.src, "src", "", "comma-separated local IPs to dial from, round robin") + flag.Parse() + return c +} + +func main() { os.Exit(run()) } + +func run() int { + cfg := parseFlags() + if cfg.bin == "" || cfg.homes < 1 || cfg.phones < 0 || cfg.live <= 0 || cfg.cmd <= 0 || cfg.max < 10*time.Second { + fmt.Fprintln(os.Stderr, "ftwload: need -ftwcloudd, -homes >= 1, -phones >= 0, positive -live and -cmd, -max >= 10s") + return 2 + } + runtime.GOMAXPROCS(cfg.procs) + dir, err := os.MkdirTemp("", "ftwload-") + if err != nil { + fmt.Fprintln(os.Stderr, "ftwload:", err) + return 1 + } + + // Every way out goes through cleanup: kill the child, drop the keys. + var child atomic.Pointer[server] + var cleanOnce sync.Once + cleanup := func() { + cleanOnce.Do(func() { + if s := child.Load(); s != nil { + s.kill() + } + _ = os.RemoveAll(dir) + }) + } + defer cleanup() + hard := time.AfterFunc(cfg.max, func() { + fmt.Fprintln(os.Stderr, "ftwload: hard deadline; ftwcloudd killed") + cleanup() + os.Exit(3) + }) + defer hard.Stop() + ctx, cancel := context.WithTimeout(context.Background(), cfg.max-4*time.Second) + defer cancel() + sigc := make(chan os.Signal, 2) + signal.Notify(sigc, syscall.SIGINT, syscall.SIGTERM) + go func() { + <-sigc // the first ends the run with a summary, the second at once + cancel() + <-sigc + cleanup() + os.Exit(130) + }() + + srv, err := startServer(ctx, cfg, dir, &child) + if err != nil { + fmt.Fprintln(os.Stderr, "ftwload:", err) + return 1 + } + dialer, err := newDialer(srv.pool, cfg.src) + if err != nil { + fmt.Fprintln(os.Stderr, "ftwload:", err) + return 2 + } + h := &harness{cfg: cfg, url: "wss://" + srv.addr, dialer: dialer, service: srv.service, noise: srv.noise, + stats: newStats(), wantBoxes: int64(cfg.homes), wantPhones: int64(cfg.homes * cfg.phones)} + // One sample of the idle service before any load, then one a second. + samp := &sampler{} + samp.take(srv.cmd.Process.Pid) + go samp.run(ctx, srv.cmd.Process.Pid, srv.exited) + + boxes := make([]*box, cfg.homes) + for i := range boxes { + boxes[i] = newBox(h) + } + clients, stopClients := context.WithCancel(ctx) + defer stopClients() + var wg sync.WaitGroup + h.t0 = time.Now() + half := cfg.ramp / 2 + for i, b := range boxes { + wg.Go(func() { b.run(clients, spread(half, i, cfg.homes)) }) + } + for i, b := range boxes { + for j, key := range b.phones { + at := h.t0.Add(half + spread(cfg.ramp-half, i*cfg.phones+j, cfg.homes*cfg.phones)) + p := &phone{b: b, key: key} + wg.Go(func() { p.run(clients, at) }) + } + } + + // Ramp, then the steady phase once everyone is up. + allBy := h.t0.Add(cfg.ramp + 10*time.Second) + for ctx.Err() == nil && time.Now().Before(allBy) && + (h.allBoxesAt.Load() == 0 || (h.wantPhones > 0 && h.allPhonesAt.Load() == 0) || time.Since(h.t0) < cfg.ramp) { + time.Sleep(20 * time.Millisecond) + } + steadyStart := time.Now() + h.measuring.Store(true) + var scrapeBefore promSnap + if srv.metricsAddr != "" { + scrapeBefore, _ = scrape(srv.metricsAddr) + } + cpuBefore := cpuSelf() + var stormC, sigC <-chan time.Time + if cfg.stormAt > 0 { + stormC = time.After(cfg.stormAt) + } + if cfg.sigtermAt > 0 { + sigC = time.After(cfg.sigtermAt) + } + end := time.After(cfg.duration) + var stormAt, sigAt time.Time + diedEarly := false +steady: + for { + select { + case <-ctx.Done(): + break steady + case <-end: + break steady + case <-stormC: + stormAt = time.Now() + h.storm(boxes) + case <-sigC: + sigAt = time.Now() + h.stopping.Store(true) + _ = srv.cmd.Process.Signal(syscall.SIGTERM) + break steady + case <-srv.exited: + diedEarly = true + break steady + } + } + steadyEnd := time.Now() + cpuHarness := cpuSelf() - cpuBefore + var view *serverView + if srv.metricsAddr != "" && scrapeBefore != nil && sigAt.IsZero() { + if after, err := scrape(srv.metricsAddr); err == nil { + view = newServerView(scrapeBefore, after) + } + } + h.measuring.Store(false) + h.quiet.Store(true) + boxesUp, phonesUp := h.boxesUp.Load(), h.phonesUp.Load() + + var exitedAt time.Time + if !sigAt.IsZero() { + // The service drains: wait for it to exit, then for the sockets + // to report how they ended. + select { + case <-srv.exited: + exitedAt = time.Now() + case <-ctx.Done(): + case <-time.After(65 * time.Second): + } + sleep(ctx, 500*time.Millisecond) + } else { + // Let the last echoes come back, at most 5 s, and a storm finish. + for drain := time.Now().Add(5 * time.Second); ctx.Err() == nil && time.Now().Before(drain) && h.stats.outstanding() > 0; { + time.Sleep(20 * time.Millisecond) + } + for wait := time.Now().Add(30 * time.Second); !stormAt.IsZero() && h.stormDone.Load() == 0 && + ctx.Err() == nil && time.Now().Before(wait); { + time.Sleep(50 * time.Millisecond) + } + } + stopClients() + waited := make(chan struct{}) + go func() { wg.Wait(); close(waited) }() + select { + case <-waited: + case <-time.After(3 * time.Second): + } + srv.kill() + + rep := h.report(samp, steadyStart, steadyEnd, stormAt, sigAt, exitedAt, boxesUp, phonesUp) + rep.Inside = view + rep.HarnessCPUPct = 100 * cpuHarness.Seconds() / steadyEnd.Sub(steadyStart).Seconds() + rep.ServerLog = scanLog(srv.logPath) + if diedEarly { + rep.Notes = append(rep.Notes, "ftwcloudd exited during the steady phase") + } + if ctx.Err() != nil { + rep.Notes = append(rep.Notes, "the run ended early (deadline or signal)") + } + rep.print(os.Stdout) + if cfg.jsonPath != "" { + if err := rep.writeJSON(cfg.jsonPath); err != nil { + fmt.Fprintln(os.Stderr, "ftwload:", err) + return 1 + } + } + return 0 +} + +// spread is the i-th of n start offsets evenly over d. +func spread(d time.Duration, i, n int) time.Duration { + if n <= 0 { + return 0 + } + return d * time.Duration(i) / time.Duration(n) +} + +// harness is what boxes and phones share. +type harness struct { + cfg config + url string + dialer *websocket.Dialer + service *ecdsa.PublicKey + noise []byte + stats *stats + t0 time.Time + + // measuring is on during the steady phase; quiet stops phones sending + // after it; stopping stops every redial once the service was told to + // stop. + measuring, quiet, stopping atomic.Bool + + wantBoxes, wantPhones int64 + boxesUp, phonesUp atomic.Int64 + allBoxesAt, allPhonesAt atomic.Int64 // ns after t0, 0 until reached + stormStart atomic.Int64 // unix ns + stormRecovered, stormDone atomic.Int64 // count; unix ns when all were back +} + +func (h *harness) up(n *atomic.Int64, want int64, at *atomic.Int64) { + if n.Add(1) == want { + at.CompareAndSwap(0, int64(time.Since(h.t0))) + } +} + +// storm closes every box socket at once, from the client side, without a +// close frame. Each box redials within -storm-jitter. +func (h *harness) storm(boxes []*box) { + h.stormStart.Store(time.Now().UnixNano()) + for _, b := range boxes { + b.stormed.Store(true) + } + for _, b := range boxes { + if c := b.conn.Load(); c != nil { + _ = c.Close() + } + } +} + +func (h *harness) recovered(hs time.Duration) { + h.stats.stormHS.add(hs) + if h.stormRecovered.Add(1) == h.wantBoxes { + h.stormDone.CompareAndSwap(0, time.Now().UnixNano()) + } +} + +// redial counts why a socket ended or failed to open and waits before the +// next dial. False means do not dial again. +func (h *harness) redial(ctx context.Context, label string, err error, attempt *int) bool { + if ctx.Err() != nil { + return false + } + delay := backoff(*attempt) + *attempt++ + var ce *websocket.CloseError + if errors.As(err, &ce) { + h.stats.fail(fmt.Sprintf("%s.close.%d", label, ce.Code)) + switch ce.Code { + case cloudwire.CloseRestart: + h.stats.restart(label, ce.Text) + delay = jitter(time.Duration(cloudwire.RestartSpreadMs(ce.Text)) * time.Millisecond) + *attempt = 0 + case cloudwire.CloseWrongShard: + // No second host here: note where it pointed and dial again. + h.stats.wrongShard(ce.Text) + } + } else { + h.stats.fail(label + ".error") + } + if h.stopping.Load() { + h.stats.afterStop(ce != nil && ce.Code == cloudwire.CloseRestart) + return false + } + return sleep(ctx, delay) +} + +// backoff is full jitter between 0 and 0.5 s doubled per attempt, up to 60 s. +func backoff(attempt int) time.Duration { + return jitter(min(60*time.Second, 500*time.Millisecond<= rank { + return b.le * 1000 + } + } + return math.Inf(1) + } + if total == 0 { + return serverLatency{} + } + return serverLatency{N: int64(total), P50: q(0.5), P95: q(0.95), P99: q(0.99)} +} + +// serverView is what the report shows from the service's metrics. +type serverView struct { + Forward map[string]serverLatency `json:"forward"` + Handshake map[string]serverLatency `json:"handshake"` + Drops map[string]int64 `json:"drops,omitempty"` + // At the end of the steady phase: live heap, all the runtime holds, + // and goroutines. + HeapMiB float64 `json:"heapMiB"` + GoMemMiB float64 `json:"goMemMiB"` + Goroutines int64 `json:"goroutines"` +} + +func newServerView(before, after promSnap) *serverView { + v := &serverView{Forward: map[string]serverLatency{}, Handshake: map[string]serverLatency{}, Drops: map[string]int64{}} + for _, p := range []string{"envelope", "tun_up", "tun_down"} { + v.Forward[p] = histogram(before, after, "ftwcloud_forward_seconds", `path="`+p+`"`) + } + for _, k := range []string{"box", "app"} { + v.Handshake[k] = histogram(before, after, "ftwcloud_handshake_seconds", `kind="`+k+`"`) + } + v.HeapMiB = after["ftwcloud_go_heap_bytes"] / (1 << 20) + v.GoMemMiB = after["ftwcloud_go_memory_bytes"] / (1 << 20) + v.Goroutines = int64(after["ftwcloud_go_goroutines"]) + for k, n := range after { + if r, ok := strings.CutPrefix(k, `ftwcloud_drops_total{reason="`); ok { + if d := int64(n - before[k]); d > 0 { + v.Drops[strings.TrimSuffix(r, `"}`)] = d + } + } + } + return v +} + +// cpuSelf is the harness's own CPU time so far. +func cpuSelf() time.Duration { + var ru syscall.Rusage + if syscall.Getrusage(syscall.RUSAGE_SELF, &ru) != nil { + return 0 + } + return time.Duration(ru.Utime.Nano() + ru.Stime.Nano()) +} diff --git a/cmd/ftwload/stats.go b/cmd/ftwload/stats.go new file mode 100644 index 0000000..cb328b2 --- /dev/null +++ b/cmd/ftwload/stats.go @@ -0,0 +1,553 @@ +package main + +import ( + "bufio" + "context" + "encoding/json" + "fmt" + "io" + "math" + "os" + "os/exec" + "slices" + "sort" + "strconv" + "strings" + "sync" + "sync/atomic" + "time" +) + +// maxSamples bounds each latency series; past it, reservoir sampling. +const maxSamples = 200_000 + +// series keeps latencies for percentiles. +type series struct { + mu sync.Mutex + n int64 + max time.Duration + samples []time.Duration +} + +func (s *series) add(d time.Duration) { + s.mu.Lock() + defer s.mu.Unlock() + s.n++ + s.max = max(s.max, d) + if len(s.samples) < maxSamples { + s.samples = append(s.samples, d) + } else if j := randN(s.n); j < maxSamples { + s.samples[j] = d + } +} + +type latency struct { + Count int64 `json:"count"` + P50 float64 `json:"p50Ms"` + P95 float64 `json:"p95Ms"` + P99 float64 `json:"p99Ms"` + Max float64 `json:"maxMs"` +} + +func (s *series) summary() latency { + s.mu.Lock() + sorted := slices.Clone(s.samples) + l := latency{Count: s.n, Max: ms(s.max)} + s.mu.Unlock() + if len(sorted) == 0 { + return l + } + slices.Sort(sorted) + at := func(q float64) float64 { + return ms(sorted[max(0, int(math.Ceil(q*float64(len(sorted))))-1)]) + } + l.P50, l.P95, l.P99 = at(0.50), at(0.95), at(0.99) + return l +} + +func (l latency) String() string { + if l.Count == 0 { + return "none" + } + return fmt.Sprintf("p50 %.2f p95 %.2f p99 %.2f max %.2f ms (n %d)", l.P50, l.P95, l.P99, l.Max, l.Count) +} + +func ms(d time.Duration) float64 { return float64(d) / float64(time.Millisecond) } + +// stats is every count the clients keep. +type stats struct { + boxHS, phoneHS, stormHS, tunRTT, live series + + tunSent, tunEchoed, tunLost, tunLate, tunEnded atomic.Int64 + + mu sync.Mutex + errors map[string]int64 + reasons map[string]int64 // 4503 reasons + shards map[string]int64 // 4421 reasons + restartBy map[string]int64 // 4503 by socket kind + stopped struct{ restart, other int64 } + lastStopAt time.Time +} + +func newStats() *stats { + return &stats{errors: map[string]int64{}, reasons: map[string]int64{}, shards: map[string]int64{}, + restartBy: map[string]int64{}} +} + +func (s *stats) outstanding() int64 { return s.tunSent.Load() - s.tunEchoed.Load() - s.tunLost.Load() } + +func (s *stats) fail(kind string) { + s.mu.Lock() + s.errors[kind]++ + s.mu.Unlock() +} + +func (s *stats) restart(label, reason string) { + s.mu.Lock() + defer s.mu.Unlock() + s.restartBy[strings.SplitN(label, ".", 2)[0]]++ + bump(s.reasons, reason) +} + +func (s *stats) wrongShard(host string) { + s.mu.Lock() + bump(s.shards, host) + s.mu.Unlock() +} + +// afterStop counts a socket that ended after the service was sent SIGTERM. +func (s *stats) afterStop(restart bool) { + s.mu.Lock() + defer s.mu.Unlock() + if restart { + s.stopped.restart++ + } else { + s.stopped.other++ + } + s.lastStopAt = time.Now() +} + +// bump counts a value, keeping at most 20 distinct ones. +func bump(m map[string]int64, v string) { + if _, ok := m[v]; !ok && len(m) >= 20 { + v = "(other)" + } + m[v]++ +} + +// -------------------------------------------------------------------------- +// The service's CPU and memory +// -------------------------------------------------------------------------- + +type sample struct { + at time.Time + rssKiB int64 + cpu time.Duration +} + +type sampler struct { + mu sync.Mutex + s []sample +} + +// run reads ps for the child once a second until it exits. +func (m *sampler) run(ctx context.Context, pid int, exited <-chan struct{}) { + t := time.NewTicker(time.Second) + defer t.Stop() + for { + select { + case <-ctx.Done(): + return + case <-exited: + return + case <-t.C: + } + m.take(pid) + } +} + +func (m *sampler) take(pid int) { + rss, cpu, ok := procStat(pid) + if !ok { + out, err := exec.Command("ps", "-o", "rss=,time=", "-p", strconv.Itoa(pid)).Output() + if err != nil { + return + } + f := strings.Fields(string(out)) + if len(f) < 2 { + return + } + var err1, err2 error + rss, err1 = strconv.ParseInt(f[0], 10, 64) + cpu, err2 = parseCPUTime(f[1]) + if err1 != nil || err2 != nil { + return + } + } + m.mu.Lock() + m.s = append(m.s, sample{at: time.Now(), rssKiB: rss, cpu: cpu}) + m.mu.Unlock() +} + +// parseCPUTime reads ps time: [dd-][hh:]mm:ss[.ss], as macOS and Linux +// print it. +func parseCPUTime(s string) (time.Duration, error) { + var days float64 + if d, rest, ok := strings.Cut(s, "-"); ok { + v, err := strconv.ParseFloat(d, 64) + if err != nil { + return 0, err + } + days, s = v, rest + } + var secs float64 + for _, part := range strings.Split(s, ":") { + v, err := strconv.ParseFloat(part, 64) + if err != nil { + return 0, err + } + secs = secs*60 + v + } + return time.Duration((days*86400 + secs) * float64(time.Second)), nil +} + +func (m *sampler) samples() []sample { + m.mu.Lock() + defer m.mu.Unlock() + return slices.Clone(m.s) +} + +// within is the samples taken in [a, b]. +func within(all []sample, a, b time.Time) []sample { + var out []sample + for _, s := range all { + if !s.at.Before(a) && !s.at.After(b) { + out = append(out, s) + } + } + return out +} + +// cpuPct is the average CPU over the samples, 100 = one core. +func cpuPct(s []sample) float64 { + if len(s) < 2 { + return 0 + } + first, last := s[0], s[len(s)-1] + return 100 * float64(last.cpu-first.cpu) / float64(last.at.Sub(first.at)) +} + +// peakCPUPct is the highest CPU between two neighbouring samples. +func peakCPUPct(s []sample) float64 { + var peak float64 + for i := 1; i < len(s); i++ { + peak = max(peak, cpuPct(s[i-1:i+1])) + } + return peak +} + +func mib(kib int64) float64 { return float64(kib) / 1024 } + +// -------------------------------------------------------------------------- +// The report +// -------------------------------------------------------------------------- + +type report struct { + Config struct { + Homes int `json:"homes"` + PhonesPerHome int `json:"phonesPerHome"` + Copy bool `json:"copy"` + LiveS float64 `json:"liveS"` + CmdS float64 `json:"cmdS"` + ServerProcs int `json:"serverProcs"` + HarnessProcs int `json:"harnessProcs"` + SteadyS float64 `json:"steadyS"` + } `json:"config"` + Connects struct { + BoxesUp int64 `json:"boxesUp"` + BoxesWanted int64 `json:"boxesWanted"` + PhonesUp int64 `json:"phonesUp"` + PhonesWanted int64 `json:"phonesWanted"` + AllBoxesS float64 `json:"allBoxesS"` // -1: never + AllPhonesS float64 `json:"allPhonesS"` // -1: never + } `json:"connects"` + Handshake struct { + Box latency `json:"box"` + Phone latency `json:"phone"` + } `json:"handshake"` + Tun struct { + RoundTrip latency `json:"roundTrip"` + Sent int64 `json:"sent"` + Echoed int64 `json:"echoed"` + Lost int64 `json:"lost"` + Late int64 `json:"late"` + Ended int64 `json:"ended"` + } `json:"tun"` + Live latency `json:"live"` + Errors map[string]int64 `json:"errors"` + Server struct { + CPUPct float64 `json:"cpuPct"` + PeakRSSMiB float64 `json:"peakRssMiB"` + SteadyRSSMiB float64 `json:"steadyRssMiB"` + IdleRSSMiB float64 `json:"idleRssMiB"` + CPUPctPer1k float64 `json:"cpuPctPer1kHomes"` + MiBPer1k float64 `json:"miBPer1kHomes"` // steady minus idle + Samples int `json:"samples"` + WrongShardSeen map[string]int64 `json:"wrongShardSeen,omitempty"` + } `json:"server"` + // Inside is the service's own latencies over the steady phase, from + // its /metrics; HarnessCPUPct the harness's own CPU meanwhile. + Inside *serverView `json:"inside,omitempty"` + HarnessCPUPct float64 `json:"harnessCpuPct"` + Storm *stormReport `json:"storm,omitempty"` + Sigterm *sigtermReport `json:"sigterm,omitempty"` + ServerLog logReport `json:"serverLog"` + Notes []string `json:"notes,omitempty"` +} + +type stormReport struct { + Recovered int64 `json:"recovered"` + Wanted int64 `json:"wanted"` + RecoveryS float64 `json:"recoveryS"` // -1: not all came back + Handshake latency `json:"handshake"` + PeakCPUPct float64 `json:"peakCpuPct"` + AvgCPUPct float64 `json:"avgCpuPct"` +} + +type sigtermReport struct { + SocketsUp int64 `json:"socketsUp"` + Restart map[string]int64 `json:"restart4503"` + Reasons map[string]int64 `json:"reasons"` + OtherEnds int64 `json:"otherEnds"` + LastEndS float64 `json:"lastEndS"` + ChildExitS float64 `json:"childExitS"` // -1: did not exit +} + +func (h *harness) report(samp *sampler, start, end, stormAt, sigAt, exitedAt time.Time, boxesUp, phonesUp int64) *report { + r := &report{} + c := h.cfg + r.Config.Homes, r.Config.PhonesPerHome, r.Config.Copy = c.homes, c.phones, c.copy + r.Config.LiveS, r.Config.CmdS = c.live.Seconds(), c.cmd.Seconds() + r.Config.ServerProcs, r.Config.HarnessProcs, r.Config.SteadyS = c.serverProcs, c.procs, end.Sub(start).Seconds() + + r.Connects.BoxesUp, r.Connects.BoxesWanted = boxesUp, h.wantBoxes + r.Connects.PhonesUp, r.Connects.PhonesWanted = phonesUp, h.wantPhones + since := func(ns int64) float64 { + if ns == 0 { + return -1 + } + return time.Duration(ns).Seconds() + } + r.Connects.AllBoxesS, r.Connects.AllPhonesS = since(h.allBoxesAt.Load()), since(h.allPhonesAt.Load()) + if h.wantPhones == 0 { + r.Connects.AllPhonesS = 0 + } + + st := h.stats + r.Handshake.Box, r.Handshake.Phone = st.boxHS.summary(), st.phoneHS.summary() + r.Tun.RoundTrip = st.tunRTT.summary() + r.Tun.Sent, r.Tun.Echoed, r.Tun.Lost = st.tunSent.Load(), st.tunEchoed.Load(), st.tunLost.Load() + r.Tun.Late, r.Tun.Ended = st.tunLate.Load(), st.tunEnded.Load() + r.Live = st.live.summary() + + all := samp.samples() + steady := within(all, start, end) + r.Server.Samples = len(steady) + r.Server.CPUPct = cpuPct(steady) + var sum int64 + for _, s := range steady { + sum += s.rssKiB + } + if len(steady) > 0 { + r.Server.SteadyRSSMiB = mib(sum / int64(len(steady))) + } + for _, s := range all { + r.Server.PeakRSSMiB = max(r.Server.PeakRSSMiB, mib(s.rssKiB)) + if s.at.Before(h.t0) { + r.Server.IdleRSSMiB = mib(s.rssKiB) + } + } + r.Server.CPUPctPer1k = r.Server.CPUPct / float64(c.homes) * 1000 + r.Server.MiBPer1k = (r.Server.SteadyRSSMiB - r.Server.IdleRSSMiB) / float64(c.homes) * 1000 + + st.mu.Lock() + defer st.mu.Unlock() + r.Errors = st.errors + if len(st.shards) > 0 { + r.Server.WrongShardSeen = st.shards + } + if !stormAt.IsZero() { + sr := &stormReport{Recovered: h.stormRecovered.Load(), Wanted: h.wantBoxes, RecoveryS: -1, Handshake: st.stormHS.summary()} + stormEnd := end + if done := h.stormDone.Load(); done != 0 { + stormEnd = time.Unix(0, done) + sr.RecoveryS = stormEnd.Sub(stormAt).Seconds() + } + // Whole-second samples: widen the window by one on each side. + win := within(all, stormAt.Add(-time.Second), stormEnd.Add(time.Second)) + sr.PeakCPUPct, sr.AvgCPUPct = peakCPUPct(win), cpuPct(win) + r.Storm = sr + } + if !sigAt.IsZero() { + sr := &sigtermReport{SocketsUp: boxesUp + phonesUp, Restart: st.restartBy, Reasons: st.reasons, + OtherEnds: st.stopped.other, LastEndS: -1, ChildExitS: -1} + if !st.lastStopAt.IsZero() { + sr.LastEndS = st.lastStopAt.Sub(sigAt).Seconds() + } + if !exitedAt.IsZero() { + sr.ChildExitS = exitedAt.Sub(sigAt).Seconds() + } + r.Sigterm = sr + } + return r +} + +func (r *report) print(w io.Writer) { + c := r.Config + copyOn := "off" + if c.Copy { + copyOn = "on" + } + fmt.Fprintf(w, "ftwload: %d homes x %d phones, copy %s, live %gs, cmd %gs, server GOMAXPROCS %d, steady %.1fs\n", + c.Homes, c.PhonesPerHome, copyOn, c.LiveS, c.CmdS, c.ServerProcs, c.SteadyS) + cn := r.Connects + fmt.Fprintf(w, "connects boxes %d/%d (all at %s) phones %d/%d (all at %s)\n", + cn.BoxesUp, cn.BoxesWanted, secs(cn.AllBoxesS), cn.PhonesUp, cn.PhonesWanted, secs(cn.AllPhonesS)) + fmt.Fprintf(w, "handshake box %s\n", r.Handshake.Box) + fmt.Fprintf(w, " phone %s\n", r.Handshake.Phone) + fmt.Fprintf(w, "tun %s\n", r.Tun.RoundTrip) + fmt.Fprintf(w, " sent %d echoed %d lost %d late %d ended by service %d\n", + r.Tun.Sent, r.Tun.Echoed, r.Tun.Lost, r.Tun.Late, r.Tun.Ended) + fmt.Fprintf(w, "live %s\n", r.Live) + s := r.Server + fmt.Fprintf(w, "server cpu %.1f%% (100 = one core, %d samples) rss peak %.1f MiB, steady %.1f MiB, idle %.1f MiB\n", + s.CPUPct, s.Samples, s.PeakRSSMiB, s.SteadyRSSMiB, s.IdleRSSMiB) + fmt.Fprintf(w, " per 1k homes: cpu %.1f%%, %.1f MiB above idle\n", s.CPUPctPer1k, s.MiBPer1k) + fmt.Fprintf(w, "harness cpu %.0f%%\n", r.HarnessCPUPct) + if in := r.Inside; in != nil { + fmt.Fprintf(w, "inside envelope %s\n", in.Forward["envelope"]) + fmt.Fprintf(w, " tun_up %s\n", in.Forward["tun_up"]) + fmt.Fprintf(w, " tun_down %s\n", in.Forward["tun_down"]) + fmt.Fprintf(w, " hs box %s\n", in.Handshake["box"]) + fmt.Fprintf(w, " hs app %s\n", in.Handshake["app"]) + fmt.Fprintf(w, " heap %.1f MiB, runtime %.1f MiB, %d goroutines\n", in.HeapMiB, in.GoMemMiB, in.Goroutines) + if len(in.Drops) > 0 { + fmt.Fprintf(w, " drops %s\n", counts(in.Drops)) + } + } + if st := r.Storm; st != nil { + fmt.Fprintf(w, "storm back %d/%d in %s, server cpu peak %.0f%% avg %.0f%%\n", + st.Recovered, st.Wanted, secs(st.RecoveryS), st.PeakCPUPct, st.AvgCPUPct) + fmt.Fprintf(w, " handshake %s\n", st.Handshake) + } + if sg := r.Sigterm; sg != nil { + fmt.Fprintf(w, "sigterm %d sockets up; 4503 box %d phone %d; other ends %d; last end %s; child exit %s\n", + sg.SocketsUp, sg.Restart["box"], sg.Restart["phone"], sg.OtherEnds, secs(sg.LastEndS), secs(sg.ChildExitS)) + if len(sg.Reasons) > 0 { + fmt.Fprintf(w, " reasons %s\n", counts(sg.Reasons)) + } + } + if len(s.WrongShardSeen) > 0 { + fmt.Fprintf(w, "4421 %s\n", counts(s.WrongShardSeen)) + } + if len(r.Errors) == 0 { + fmt.Fprintln(w, "errors none") + } else { + fmt.Fprintf(w, "errors %s\n", counts(r.Errors)) + } + fmt.Fprintf(w, "server log %d warn, %d error\n", r.ServerLog.Warn, r.ServerLog.Error) + for _, l := range r.ServerLog.Lines { + fmt.Fprintf(w, " %s\n", l) + } + for _, n := range r.Notes { + fmt.Fprintf(w, "note %s\n", n) + } +} + +func secs(s float64) string { + if s < 0 { + return "never" + } + return fmt.Sprintf("%.3fs", s) +} + +func counts(m map[string]int64) string { + keys := make([]string, 0, len(m)) + for k := range m { + keys = append(keys, k) + } + sort.Strings(keys) + parts := make([]string, len(keys)) + for i, k := range keys { + parts[i] = fmt.Sprintf("%q=%d", k, m[k]) + } + return strings.Join(parts, " ") +} + +func (r *report) writeJSON(path string) error { + b, err := json.MarshalIndent(r, "", " ") + if err != nil { + return err + } + return os.WriteFile(path, append(b, '\n'), 0o644) +} + +// logReport is what ftwcloudd logged at WARN and ERROR, a few lines of it. +type logReport struct { + Warn int `json:"warn"` + Error int `json:"error"` + Lines []string `json:"lines,omitempty"` +} + +func scanLog(path string) logReport { + var r logReport + f, err := os.Open(path) + if err != nil { + return r + } + defer f.Close() + sc := bufio.NewScanner(f) + for sc.Scan() { + line := sc.Text() + switch { + case strings.Contains(line, "level=WARN"): + r.Warn++ + case strings.Contains(line, "level=ERROR"), strings.HasPrefix(line, "panic"), strings.HasPrefix(line, "fatal"): + r.Error++ + default: + continue + } + if len(r.Lines) < 5 { + r.Lines = append(r.Lines, line) + } + } + return r +} + +// procStat reads a Linux child's RSS and CPU time from /proc, which is finer +// than ps and works where ps is busybox's. False elsewhere. +func procStat(pid int) (rssKiB int64, cpu time.Duration, ok bool) { + stat, err := os.ReadFile("/proc/" + strconv.Itoa(pid) + "/stat") + if err != nil { + return 0, 0, false + } + // The fields after the command, which sits in parentheses. + i := strings.LastIndexByte(string(stat), ')') + if i < 0 { + return 0, 0, false + } + f := strings.Fields(string(stat)[i+1:]) + // utime and stime are fields 14 and 15 (from 1), so 11 and 12 here; + // rss in pages is field 24, so 21 here. + if len(f) < 22 { + return 0, 0, false + } + ut, err1 := strconv.ParseInt(f[11], 10, 64) + st, err2 := strconv.ParseInt(f[12], 10, 64) + pages, err3 := strconv.ParseInt(f[21], 10, 64) + if err1 != nil || err2 != nil || err3 != nil { + return 0, 0, false + } + const tick = 100 // USER_HZ on Linux + return pages * int64(os.Getpagesize()) / 1024, time.Duration(ut+st) * time.Second / tick, true +} diff --git a/deploy/README.md b/deploy/README.md index f5db043..468264f 100644 --- a/deploy/README.md +++ b/deploy/README.md @@ -136,13 +136,182 @@ or, in a session (`aws ssm start-session --region eu-north-1 --target i-0ecac4cbc6b5f8adc`), `sudo ftw-cloud-deploy sha256:`. It pulls the image, refuses one whose commit is not on `main`, checks out that commit in `/opt/ftw-cloud`, fetches the key, starts a new container and deletes the old -image. Every box reconnects within seconds. To go back, run it with the -earlier digest. +image. The old container drains first; see [Deploys](#deploys). To go back, +run it with the earlier digest. It always makes a new container, even when only a mounted file changed. The relay ran into this: a file mounted on its own, like the service key, keeps the copy the container started with after the file changes on the host. +## Deploys + +A deploy stops the one process that carries every box's uplink and every +phone's session, so for each home commands wait until its box is back. The +service makes that short and spreads the return: + +1. `docker compose down` sends SIGTERM and waits up to 15 s + (`stop_grace_period`). +2. The old process stops accepting connections. It closes every socket, + boxes and phones and those still in their handshake, with 4503 and a + spread: the sockets it holds at 500 a second (`-restart-rate`), at least + 15 s (`-restart-spread-min`) and at most 60 s. The port stays closed for + about 4 to 8 s while compose takes the old container down and starts + the new one, so a shorter spread would send most clients to a closed + port; 12,000 sockets get 24 s. A run of the harness over a real stop and + start is still to do, and may lower the floor. +3. Each close waits for the client's answer, up to 2 s in all, so the + client reads 4503 and the spread rather than a reset. A stuck socket + holds up none of the others. Then queued alerts get up to 3 s; an alert + still queued or waiting to go again is lost, and the log says how many, + and a `box.unreachable` not yet taken by a phone goes again after the + restart. A box closed this way starts no `box.unreachable`. +4. It exits, in about 0.1 s in the load test. +5. The new container reads every signed roster back and checks the + signatures on all cores before it listens: 0.35 s for 10,000 homes on + two M5 cores (`BenchmarkRestore10k`), about 1.2 s on the host by the + estimate under [Load](#load). Phones are admitted at once; readings come + back with the boxes. +6. A box with srcfl/ftw#1645 redials at a random moment within the spread, + and so does a phone once the apps honour 4503. Older clients redial on + their own backoff, within 0.5 s, and those that come before the new + container is up back off further. A box that hears 4503 before + `hello_ok` counts it as a failure and backs off. + +The log shows `drained for a restart` with the sockets, those still open and +the spread, then `rosters restored from the registry` with how long that +took. A command in flight at the drain may be lost; the phone treats it as +unknown, not failed (protocol, "Shards and restarts"). + +**Blue/green, when an NLB is worth it.** One host cannot run two containers +on 443 with the port mapping in `compose.yml`. With a TCP NLB in front (it +keeps the TLS binding), start the new instance on a second host with the same +keys and a copy of the registry, register it with the target group, +deregister the old one, then send the old one SIGTERM. Its sockets come back +through the NLB to the new instance within the spread, and no client meets a +closed port, so the spread's floor can drop to a few seconds. + +## Watching it + +- **`/metrics`** answers on `127.0.0.1:9464` inside the container, in + Prometheus text: sockets by kind, homes, homes with a connected box, tun + messages and bytes each way, drops by reason, push queue depths, Apple's + answers, handshake and forward latency histograms, the Go heap and + goroutines. Nothing in it names a home or an address. Read it with + `docker exec ftw-cloud-ftwcloudd-1 ftwcloudd metrics`. +- **One line a minute** goes to stdout in CloudWatch's embedded metric + format: each counter's rise over the minute, each gauge, and p50, p95 and + p99 of each latency in milliseconds. Once the container logs to CloudWatch + Logs (the `awslogs` log driver, and `logs:CreateLogStream` and + `logs:PutLogEvents` for the instance role, which the owner adds), each + field is a metric in the `FTWCloud` namespace, by shard. +- What to watch: `forward_seconds_*_p99` (time inside the service), + `drops_*` (any rise), `push_queued_alert`, `homes_connected`, + `go_memory_bytes`. + +## Load + +`cmd/ftwload` starts a local `ftwcloudd`, connects N boxes and M phones per +box, and measures. Each box sends a signed `live` every second with the +readable copy on. Each phone looks at its home and sends a 64-byte `tun` +every second, which its box sends straight back. The service ran with +`GOMAXPROCS=2`, as on the host's two vCPUs, on an Apple M5 laptop, in a Linux +container unless marked macOS. Runs lasted under two minutes. **None of this +was measured on a t4g.small.** + +| Run | Service CPU (100 = one core) | Service RSS | Inside the service, p99 | Phone to box and back, p50 / p99 | +|---|---|---|---|---| +| 4,000 boxes, no phones | 34 % | 289 MiB | — | — | +| 3,000 homes, a phone each | 35 % | 518 MiB | — | 1.6 / 32 ms | +| 8,000 homes, a phone each (16,000 sockets) | 84 % | 1.43 GiB | envelope ≤ 2.5 ms, tun ≤ 0.25 ms | 6 / 160 ms | +| 2,000 homes, a phone each, macOS | 33 % | 377 MiB | envelope ≤ 1 ms, tun ≤ 0.1 ms | 0.8 / 27 ms | +| Storm: 4,000 boxes redial at once | peak 155 % | | | all back in 0.9 s | +| SIGTERM with 3,000 homes and phones | | | | 6,000 of 6,000 got 4503 with 12 s (before the 15 s floor); exit in 0.11 s | + +- **Per 1,000 boxes:** 8.4 % of a core and 69 MiB. The live heap is 22 MiB; + goroutine stacks and the collector's headroom make up the rest. Below + about 45 MiB the collector runs without pause, so that is the floor. The + test boxes sent only `live`; a real home also holds its newest `prices`, + `plan`, `lp`, `hb` and `health`, a few kilobytes each, so count about + 10 MiB more per 1,000 homes. +- **Per 1,000 phones on top**, each sending a command a second: about 3 % of + a core and 100 to 110 MiB. On macOS a phone cost more CPU. +- **Where box CPU goes,** in a macOS profile: reading the socket, about two + thirds; checking each message's signature, a quarter (17 µs each). +- **Handshakes:** about 4,400 box handshakes a second on two cores, + rosters written to SQLite included. +- **The service is not where latency comes from** at these loads: inside it a + message waits at most a few milliseconds at the 99th percentile. The tail + end to end is the harness and the laptop, which ran other work. + +**On a t4g.small (unmeasured).** These runs were not on the host. A Graviton2 core does +this work at roughly a third of an M5 core's speed, an estimate from public +single-core benchmarks, so take 3.5 times the CPU and the same memory, and +check against `/metrics` once real boxes connect: + +| Estimate, unmeasured | Per 1,000 boxes at one message a second | +|---|---| +| CPU | about 30 % of a vCPU | +| Memory | about 70 MiB | +| Handshakes the next instance takes | about 1,250 a second; `-restart-rate` is 500 | + +The first limit is CPU, not memory: + +- **About 1,300 boxes** fit in the burst baseline (20 % of each of the two + vCPUs). Past that the instance spends CPU credits, which unlimited mode + bills. +- **About 4,500 boxes** keep both vCPUs under 70 %. +- **About 20,000 boxes**, or about 8,000 homes with a phone connected each, + fit in `GOMEMLIMIT` (1,400 MiB). + +A box that sends every 5 s, as an unwatched box does today, costs a fraction +of this. + +**When to add a shard.** Add one when any of these holds over a busy day: + +- the instance averages more than 60 % of its two vCPUs; +- more than 4,000 homes have a box connected (`homes_connected`); +- the runtime holds more than 1.2 GiB (`go_memory_bytes`); +- a forward p99 inside the service passes 50 ms. + +Between about 1,300 and 4,000 boxes, a non-burstable instance with two vCPUs +is the cheaper first step; it needs no shard. + +## Shards + +With no `-shards` file one instance holds every home and nothing below +applies. Each shard is one instance with its own host +(`s2.cloud.ftw.energy`), volume and registry, and the same service key and +Noise key as the others, because boxes and phones carry those. Each holds the +same directory file apart from `self`: + +```json +{ + "self": "s1", + "shards": {"s1": "cloud.ftw.energy", "s2": "s2.cloud.ftw.energy"}, + "default": "s1", + "buckets": {"s2": ["128-255"]}, + "homes": {} +} +``` + +Homes fall into 256 buckets by a hash of their id. `homes` moves single +homes and wins over `buckets`. Every host must be `cloud.ftw.energy` or one +label under it, as clients check. An instance answers a home it does not +hold with that shard's host (protocol: "Shards and restarts"); clients follow +once and keep the host. A second shard holds homes only once their boxes list +`shard` in `hello.caps` (`boxes_following_shards`) and the apps follow 4421. + +Moving homes means copying their registry rows to the new shard and then +switching the directory on every instance. The tool for that comes with the +second shard, when there is a concrete need for it. + +**MCP and OAuth stay on the default host.** Assistants' MCP and OAuth +clients belong to other parties and follow neither 4421 nor 421. `/mcp` and +`/oauth/*` stay on `cloud.ftw.energy`; once there is a second shard, that +instance forwards each call to the shard that holds the home. An agent's +sessions are drained and counted in the spread like the phones': the part +that holds them adds itself to the drainers in `cmd/ftwcloudd`. + ## Checking it ```bash diff --git a/deploy/bootstrap.sh b/deploy/bootstrap.sh index 70a6e86..2dee30b 100644 --- a/deploy/bootstrap.sh +++ b/deploy/bootstrap.sh @@ -116,8 +116,9 @@ cat > /usr/local/sbin/ftw-cloud-deploy <<'DEPLOY' # ftw-cloud-deploy sha256:<64 hex> # # The Image workflow's run on main shows the digest. With no argument, it -# runs the digest in /etc/ftw-cloud/compose.env again. Every box reconnects -# within seconds; there is nothing to drain. +# runs the digest in /etc/ftw-cloud/compose.env again. The old container +# drains on SIGTERM: every box and phone hears 4503 and comes back within +# the spread it names (deploy/README.md, "Deploys"). set -euo pipefail export HOME=${HOME:-/root} repo=ghcr.io/srcfl/ftw-cloud diff --git a/deploy/compose.yml b/deploy/compose.yml index 5504f2a..4cb6852 100644 --- a/deploy/compose.yml +++ b/deploy/compose.yml @@ -24,6 +24,13 @@ services: environment: # /source publishes it, so anyone can compare it with what CI built. FTW_CLOUD_IMAGE: ${FTW_CLOUD_IMAGE} + # The host has 2 GiB. Near this the garbage collector works harder + # instead of letting the heap grow into the kernel's OOM killer. + GOMEMLIMIT: 1400MiB + # On SIGTERM the service closes every socket with 4503 and a spread, + # lets queued alerts go, and exits; give it the time (deploy/README.md, + # "Deploys"). + stop_grace_period: 15s volumes: # The registry and certificates. No readings are ever written here. - ftw-cloud-state:/state diff --git a/go.mod b/go.mod index fbaf99f..0bdb774 100644 --- a/go.mod +++ b/go.mod @@ -5,7 +5,7 @@ go 1.26.0 require ( github.com/fxamacker/cbor/v2 v2.9.4 github.com/gorilla/websocket v1.5.3 - github.com/srcfl/ftw/go/protocol v0.0.0-20261015164244-f5cdb92058c1 + github.com/srcfl/ftw/go/protocol v0.0.0-20261015204733-11a70217dece golang.org/x/crypto v0.57.0 golang.org/x/sys v0.48.0 modernc.org/sqlite v1.59.0 diff --git a/go.sum b/go.sum index 83b0615..e47b7c2 100644 --- a/go.sum +++ b/go.sum @@ -16,8 +16,8 @@ github.com/ncruces/go-strftime v1.0.0 h1:HMFp8mLCTPp341M/ZnA4qaf7ZlsbTc+miZjCLOF github.com/ncruces/go-strftime v1.0.0/go.mod h1:Fwc5htZGVVkseilnfgOVb9mKy6w1naJmn9CehxcKcls= github.com/remyoudompheng/bigfft v0.0.0-20230129092748-24d4a6f8daec h1:W09IVJc94icq4NjY3clb7Lk8O1qJ8BdBEF8z0ibU0rE= github.com/remyoudompheng/bigfft v0.0.0-20230129092748-24d4a6f8daec/go.mod h1:qqbHyh8v60DhA7CoWK5oRCqLrMHRGoxYCSS9EjAz6Eo= -github.com/srcfl/ftw/go/protocol v0.0.0-20261015164244-f5cdb92058c1 h1:JLItMdT1tX3ejgmW80VXcwZ77wBPY7WT2ewMGfPLDIc= -github.com/srcfl/ftw/go/protocol v0.0.0-20261015164244-f5cdb92058c1/go.mod h1:VEjr/o0yZijJ1nApuJK+nak6FxJ/fubAUBNOunqNrUU= +github.com/srcfl/ftw/go/protocol v0.0.0-20261015204733-11a70217dece h1:xCOem9DCuYJgtLJRNgHmpHQ08kHEnqGTnVurcDIK7Y8= +github.com/srcfl/ftw/go/protocol v0.0.0-20261015204733-11a70217dece/go.mod h1:VEjr/o0yZijJ1nApuJK+nak6FxJ/fubAUBNOunqNrUU= github.com/x448/float16 v0.8.4 h1:qLwI1I70+NjRFUR3zs1JPUCgaCXSh3SW62uAKT1mSBM= github.com/x448/float16 v0.8.4/go.mod h1:14CWIYCyZA/cWjXOioeEpHeN/83MdbZDRQHoFcYsOfg= golang.org/x/crypto v0.57.0 h1:3ZVCjf8Ggz7zneR/EHRVx68Ctf+2pmIMP2UFhh9cC6M= diff --git a/internal/appsession/appsession.go b/internal/appsession/appsession.go index 9713d4d..c34c22b 100644 --- a/internal/appsession/appsession.go +++ b/internal/appsession/appsession.go @@ -22,12 +22,16 @@ import ( "log/slog" "net/http" "sync" + "sync/atomic" "time" "github.com/gorilla/websocket" + "github.com/srcfl/ftw-cloud/internal/metrics" "github.com/srcfl/ftw-cloud/internal/push" "github.com/srcfl/ftw-cloud/internal/registry" + "github.com/srcfl/ftw-cloud/internal/shard" "github.com/srcfl/ftw-cloud/internal/store" + "github.com/srcfl/ftw-cloud/internal/wsclose" "github.com/srcfl/ftw/go/protocol/appwire" "github.com/srcfl/ftw/go/protocol/cloudwire" ) @@ -78,6 +82,17 @@ type Tunneler interface { Tun(home string, t cloudwire.Tun) bool } +// What the app sessions count, summed over all homes. +var ( + appSockets = metrics.Sockets("app") + appHandshake = metrics.Handshake("app") + onceHandshake = metrics.Handshake("once") + envelopeOut = metrics.Forward("envelope") + tunUp = metrics.Forward("tun_up") + appWrongShard = metrics.WrongShard("app") + onceWrongShard = metrics.WrongShard("once") +) + // WebOrigin is the one browser origin the service accepts on /v1/app: the // web app's. The phone and the box send no Origin. const WebOrigin = "https://app.ftw.energy" @@ -108,6 +123,16 @@ type Server struct { // Tunnel carries the phones' sessions to their boxes. Nil answers every // tun with its end. Set before serving. Tunnel Tunneler + // Shards says which homes this instance holds. Nil holds every home. + // Set before serving. + Shards *shard.Directory + + // sockets are every phone's socket from its upgrade on, so a drain + // reaches those still in their handshake. draining is set once Drain + // starts; restartReason is what its close says. + sockets wsclose.Set + draining atomic.Bool + restartReason atomic.Value mu sync.Mutex looking map[string]*look @@ -130,11 +155,11 @@ type Tokens interface { Drop(home, deviceID string) error } -// look is one home's phones that can see it, and the loop that keeps the +// look is one home's phones that can see it, and the timer that keeps the // box's watch in force while there is at least one. type look struct { - n int - stop chan struct{} + n int + timer *time.Timer } // New builds the handler. key is the service's Noise static key; the app @@ -156,6 +181,9 @@ var upgrader = websocket.Upgrader{ o := r.Header.Get("Origin") return o == "" || o == WebOrigin }, + // A phone's socket is idle between messages; it borrows a write buffer + // only while it writes. + WriteBufferPool: &sync.Pool{}, } func (s *Server) ServeHTTP(w http.ResponseWriter, r *http.Request) { @@ -173,20 +201,76 @@ func (s *Server) ServeHTTP(w http.ResponseWriter, r *http.Request) { return } defer conn.Close() + appSockets.Add(1) + defer appSockets.Add(-1) conn.SetReadLimit(maxPhoneMessage) - code, err := s.serve(conn, home) + sock := s.sockets.Add(conn) + defer s.sockets.Remove(sock) + // Drain sets draining before it takes the set, so a socket it did not + // see sees draining here. + if s.draining.Load() { + reason, _ := s.restartReason.Load().(string) + sock.Close(cloudwire.CloseRestart, reason) + sock.AwaitPeer() + return + } + // The close goes before message 1 is read: a browser cannot see the + // status of a refused upgrade, but every client reads a close. The + // phone's answer is awaited, so it reads the code rather than a reset. + if host, ours := s.owner(home); !ours { + appWrongShard.Inc() + sock.Close(cloudwire.CloseWrongShard, host) + sock.AwaitPeer() + return + } + var reading <-chan struct{} + code, err := s.serve(conn, home, &reading) if err != nil { s.log.Debug("app session closed", "err", err) } - if code != 0 { - _ = conn.WriteControl(websocket.CloseMessage, websocket.FormatCloseMessage(code, ""), time.Now().Add(time.Second)) + if code == 0 { + return + } + sock.Close(code, "") + if reading != nil { + <-reading // the session's reader takes the phone's answer + } else { + sock.AwaitPeer() } } +// owner is the host of the shard that holds home, and whether it is this +// instance. +func (s *Server) owner(home string) (string, bool) { + if s.Shards == nil { + return "", true + } + return s.Shards.Owner(home) +} + +// Sockets is how many phone sockets are open, handshakes included. +func (s *Server) Sockets() int { return s.sockets.Len() } + +// Drain closes every phone's socket with cloudwire.CloseRestart and reason, +// the spread in milliseconds, those still in their handshake too, and every +// socket that comes after. +func (s *Server) Drain(reason string) { + s.restartReason.Store(reason) + s.draining.Store(true) + s.sockets.CloseAll(cloudwire.CloseRestart, reason) +} + +// WaitClosed waits, at most d, until every phone has answered the drain's +// close or timed out, and returns how many sockets are still open. +func (s *Server) WaitClosed(d time.Duration) int { return s.sockets.WaitEmpty(d) } + var errProtocol = errors.New("appsession: the phone broke the protocol") -// serve runs one session and returns the close code to end it with. -func (s *Server) serve(conn *websocket.Conn, home string) (int, error) { +// serve runs one session and returns the close code to end it with. Once the +// session's reader runs, reading is set to a channel that closes when it +// stops, and only that reader may read the socket. +func (s *Server) serve(conn *websocket.Conn, home string, reading *<-chan struct{}) (int, error) { + start := time.Now() _ = conn.SetReadDeadline(time.Now().Add(handshakeTimeout)) kind, msg1, err := conn.ReadMessage() if err != nil { @@ -246,6 +330,7 @@ func (s *Server) serve(conn *websocket.Conn, home string) (int, error) { if err := c.write(msg2); err != nil { return 0, err } + appHandshake.Since(start) keys, err := hs.Split() if err != nil { return websocket.CloseInternalServerErr, err @@ -259,6 +344,8 @@ func (s *Server) serve(conn *websocket.Conn, home string) (int, error) { c.setLooking(hz >= cloudwire.HzLooking) defer c.stopLooking() + c.readDone = make(chan struct{}) + *reading = c.readDone return c.run(sess) } @@ -305,31 +392,27 @@ func (s *Server) setLooking(home string, delta int) { } l.n += delta switch { - case l.n > 0 && l.stop == nil: - l.stop = make(chan struct{}) - go s.renew(home, l.stop) + case l.n > 0 && l.timer == nil: + // A timer, not a goroutine per home: it renews the watch every + // renewEvery while this look is the home's. + var renew func() + renew = func() { + s.watcher.Watch(home) + s.mu.Lock() + defer s.mu.Unlock() + if s.looking[home] == l && l.n > 0 { + l.timer = time.AfterFunc(s.renewEvery, renew) + } + } + l.timer = time.AfterFunc(0, renew) case l.n <= 0: - if l.stop != nil { - close(l.stop) + if l.timer != nil { + l.timer.Stop() } delete(s.looking, home) } } -func (s *Server) renew(home string, stop <-chan struct{}) { - s.watcher.Watch(home) - t := time.NewTicker(s.renewEvery) - defer t.Stop() - for { - select { - case <-stop: - return - case <-t.C: - s.watcher.Watch(home) - } - } -} - // BoxConnected asks a box that just connected for one-second updates when a // phone is already looking, or a one-shot read asked for them less than a // minute ago. The uplink calls it after hello_ok. @@ -383,6 +466,8 @@ type phoneConn struct { // goroutine is done. replies chan []byte quit chan struct{} + // readDone closes when the reader stops. + readDone chan struct{} // sess is the store's session; tunSid the box session this phone ran // last through the tunnel, when hasTun. Touched by the read loop and, @@ -450,6 +535,7 @@ func (c *phoneConn) run(sess *store.Session) (int, error) { } read := make(chan result, 1) go func() { + defer close(c.readDone) code, err := c.readLoop() read <- result{code, err} }() @@ -457,22 +543,24 @@ func (c *phoneConn) run(sess *store.Session) (int, error) { defer ping.Stop() for { select { - case env := <-sess.C(): - if err := c.forward(env); err != nil { + case out := <-sess.C(): + if err := c.forward(out.Env); err != nil { return 0, err } + envelopeOut.Observe(out.Waited()) case env := <-c.replies: if err := c.forward(env); err != nil { return 0, err } case t := <-sess.Tun(): - env, err := cloudwire.Unsigned(cloudwire.MsgTun, t) + env, err := cloudwire.Unsigned(cloudwire.MsgTun, t.AppTun) if err != nil { return 0, err } if err := c.forward(env); err != nil { return 0, err } + tunUp.Observe(t.Waited()) case <-sess.Done(): return sess.Code(), nil case r := <-read: diff --git a/internal/appsession/once.go b/internal/appsession/once.go index 2264e33..20723b5 100644 --- a/internal/appsession/once.go +++ b/internal/appsession/once.go @@ -135,6 +135,12 @@ func (s *Server) ServeOnce(w http.ResponseWriter, r *http.Request) { w.WriteHeader(http.StatusBadRequest) return } + if host, ours := s.owner(home); !ours { + onceWrongShard.Inc() + w.Header().Set(cloudwire.ShardHeader, host) + w.WriteHeader(cloudwire.StatusWrongShard) + return + } // The watch sends no Origin. A browser always does, and has no business // here. if r.Header.Get("Origin") != "" { @@ -159,7 +165,9 @@ func (s *Server) ServeOnce(w http.ResponseWriter, r *http.Request) { return } defer s.once.leaveProcess() + start := time.Now() body, status := s.answerOnce(home, msg1) + onceHandshake.Since(start) if status != http.StatusOK { s.log.Debug("one-shot read refused", "status", status) w.WriteHeader(status) diff --git a/internal/metrics/metrics.go b/internal/metrics/metrics.go new file mode 100644 index 0000000..db3bc05 --- /dev/null +++ b/internal/metrics/metrics.go @@ -0,0 +1,306 @@ +// Package metrics counts what the service does, for its operator: sockets, +// homes, tunnel frames, drops, queue depths, Apple's answers and latencies. +// Nothing here names a home, a device or an address; every series is a sum +// over the whole process. +// +// The counts are served in Prometheus' text format on a loopback listener +// (ftwcloudd -metrics-listen) and summed once a minute into one log line +// (Logger). Each package keeps its own series as package variables on +// Default, so counting costs one atomic add and no wiring. +package metrics + +import ( + "fmt" + "io" + "math" + "net/http" + runtimemetrics "runtime/metrics" + "slices" + "sort" + "strings" + "sync" + "sync/atomic" + "time" +) + +// Counter only goes up. +type Counter struct{ v atomic.Int64 } + +// Inc adds one. +func (c *Counter) Inc() { c.v.Add(1) } + +// Add adds n. +func (c *Counter) Add(n int64) { c.v.Add(n) } + +// Load is the count so far. +func (c *Counter) Load() int64 { return c.v.Load() } + +// Gauge goes up and down. +type Gauge struct{ v atomic.Int64 } + +// Add moves the gauge by n, which may be negative. +func (g *Gauge) Add(n int64) { g.v.Add(n) } + +// Load is the gauge now. +func (g *Gauge) Load() int64 { return g.v.Load() } + +// LatencyBounds are the histogram buckets, in seconds: from a tenth of a +// millisecond, where a forward on one host lands, to ten seconds, where a +// write times out. +var LatencyBounds = []float64{0.0001, 0.00025, 0.0005, 0.001, 0.0025, 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10} + +// Histogram counts durations into buckets. +type Histogram struct { + bounds []float64 + counts []atomic.Int64 // one per bound, and one past the last + sumNs atomic.Int64 + n atomic.Int64 +} + +func newHistogram(bounds []float64) *Histogram { + return &Histogram{bounds: bounds, counts: make([]atomic.Int64, len(bounds)+1)} +} + +// Observe counts one duration. +func (h *Histogram) Observe(d time.Duration) { + i := sort.SearchFloat64s(h.bounds, d.Seconds()) + h.counts[i].Add(1) + h.sumNs.Add(int64(d)) + h.n.Add(1) +} + +// Since counts the time since t. +func (h *Histogram) Since(t time.Time) { h.Observe(time.Since(t)) } + +// snapshot is the bucket counts now. +func (h *Histogram) snapshot() []int64 { + out := make([]int64, len(h.counts)) + for i := range h.counts { + out[i] = h.counts[i].Load() + } + return out +} + +// quantile is the upper bound of the bucket that holds the q-th quantile of +// counts, a delta between two snapshots, or 0 without any. +func (h *Histogram) quantile(counts []int64, q float64) float64 { + var total int64 + for _, c := range counts { + total += c + } + if total == 0 { + return 0 + } + rank := int64(math.Ceil(q * float64(total))) + var seen int64 + for i, c := range counts { + seen += c + if seen >= rank { + if i == len(h.bounds) { + return math.Inf(1) + } + return h.bounds[i] + } + } + return math.Inf(1) +} + +type kind int + +const ( + counter kind = iota + gauge + histogram +) + +func (k kind) String() string { return [...]string{"counter", "gauge", "histogram"}[k] } + +// series is one name with one set of labels. +type series struct { + name, help, labels string + kind kind + c *Counter + g *Gauge + f func() int64 + h *Histogram +} + +// Set is a collection of series. +type Set struct { + mu sync.Mutex + series []*series +} + +// Default holds every series the service keeps. +var Default = &Set{} + +// labels renders pairs as name="value",..., in the order given. +func labels(pairs []string) string { + if len(pairs)%2 != 0 { + panic("metrics: labels come in pairs") + } + var b strings.Builder + for i := 0; i < len(pairs); i += 2 { + if i > 0 { + b.WriteByte(',') + } + fmt.Fprintf(&b, "%s=%q", pairs[i], pairs[i+1]) + } + return b.String() +} + +func (s *Set) add(x *series) { + s.mu.Lock() + defer s.mu.Unlock() + for _, y := range s.series { + if y.name == x.name && y.labels == x.labels { + panic("metrics: " + x.name + "{" + x.labels + "} twice") + } + } + s.series = append(s.series, x) +} + +// Counter adds a counter. pairs are label names and values. +func (s *Set) Counter(name, help string, pairs ...string) *Counter { + c := &Counter{} + s.add(&series{name: name, help: help, labels: labels(pairs), kind: counter, c: c}) + return c +} + +// Gauge adds a gauge the caller moves. +func (s *Set) Gauge(name, help string, pairs ...string) *Gauge { + g := &Gauge{} + s.add(&series{name: name, help: help, labels: labels(pairs), kind: gauge, g: g}) + return g +} + +// GaugeFunc adds a gauge read from f when the series are written. f must be +// cheap and must not block. +func (s *Set) GaugeFunc(name, help string, f func() int64, pairs ...string) { + s.add(&series{name: name, help: help, labels: labels(pairs), kind: gauge, f: f}) +} + +// Histogram adds a latency histogram with LatencyBounds. +func (s *Set) Histogram(name, help string, pairs ...string) *Histogram { + h := newHistogram(LatencyBounds) + s.add(&series{name: name, help: help, labels: labels(pairs), kind: histogram, h: h}) + return h +} + +func (x *series) value() int64 { + switch { + case x.c != nil: + return x.c.Load() + case x.g != nil: + return x.g.Load() + default: + return x.f() + } +} + +// WriteTo writes every series in Prometheus' text format. +func (s *Set) WriteTo(w io.Writer) (int64, error) { + s.mu.Lock() + all := slices.Clone(s.series) + s.mu.Unlock() + sort.SliceStable(all, func(i, j int) bool { return all[i].name < all[j].name }) + var b strings.Builder + last := "" + for _, x := range all { + if x.name != last { + fmt.Fprintf(&b, "# HELP %s %s\n# TYPE %s %s\n", x.name, x.help, x.name, x.kind) + last = x.name + } + if x.kind != histogram { + fmt.Fprintf(&b, "%s%s %d\n", x.name, braces(x.labels), x.value()) + continue + } + counts := x.h.snapshot() + var cum int64 + for i, c := range counts { + cum += c + le := "+Inf" + if i < len(x.h.bounds) { + le = fmt.Sprintf("%g", x.h.bounds[i]) + } + fmt.Fprintf(&b, "%s_bucket%s %d\n", x.name, braces(join(x.labels, `le="`+le+`"`)), cum) + } + fmt.Fprintf(&b, "%s_sum%s %g\n", x.name, braces(x.labels), float64(x.h.sumNs.Load())/1e9) + fmt.Fprintf(&b, "%s_count%s %d\n", x.name, braces(x.labels), x.h.n.Load()) + } + n, err := io.WriteString(w, b.String()) + return int64(n), err +} + +func braces(l string) string { + if l == "" { + return "" + } + return "{" + l + "}" +} + +func join(a, b string) string { + if a == "" { + return b + } + return a + "," + b +} + +// ServeHTTP answers GET /metrics. +func (s *Set) ServeHTTP(w http.ResponseWriter, r *http.Request) { + if r.URL.Path != "/metrics" { + http.NotFound(w, r) + return + } + w.Header().Set("Content-Type", "text/plain; version=0.0.4") + _, _ = s.WriteTo(w) +} + +// The service's series, named in one place so each name keeps one help +// line. Each call adds a series; call each once per label value, from a +// package variable. + +// Drop counts what the service dropped for one reason. +func Drop(reason string) *Counter { + return Default.Counter("ftwcloud_drops_total", "Messages and connections the service dropped, by reason.", "reason", reason) +} + +// Sockets is the open sockets of one kind. +func Sockets(kind string) *Gauge { + return Default.Gauge("ftwcloud_sockets", "Open sockets, by kind.", "kind", kind) +} + +// Handshake times one kind of handshake, from the upgrade or the request to +// the answer that ends it. +func Handshake(kind string) *Histogram { + return Default.Histogram("ftwcloud_handshake_seconds", "From a connection's upgrade, or a request's arrival, to the end of its handshake, by kind.", "kind", kind) +} + +// Forward times one path through the service, from a message's arrival to +// its write on the next socket, queueing included. +func Forward(path string) *Histogram { + return Default.Histogram("ftwcloud_forward_seconds", "From a message's arrival to its write on the next socket, queueing included, by path.", "path", path) +} + +// WrongShard counts connections and requests for a home another shard holds. +func WrongShard(kind string) *Counter { + return Default.Counter("ftwcloud_wrong_shard_total", "Connections and requests for a home another shard holds, by kind.", "kind", kind) +} + +// Runtime adds the Go runtime's heap, the memory it holds from the system, +// and its goroutines. Call it once. +func Runtime() { + read := func(name string) func() int64 { + return func() int64 { + s := []runtimemetrics.Sample{{Name: name}} + runtimemetrics.Read(s) + if s[0].Value.Kind() != runtimemetrics.KindUint64 { + return 0 + } + return int64(s[0].Value.Uint64()) + } + } + Default.GaugeFunc("ftwcloud_go_heap_bytes", "Bytes in live and not yet swept heap objects.", read("/memory/classes/heap/objects:bytes")) + Default.GaugeFunc("ftwcloud_go_memory_bytes", "Bytes the Go runtime holds from the system.", read("/memory/classes/total:bytes")) + Default.GaugeFunc("ftwcloud_go_goroutines", "Goroutines.", read("/sched/goroutines:goroutines")) +} diff --git a/internal/metrics/metrics_test.go b/internal/metrics/metrics_test.go new file mode 100644 index 0000000..0122920 --- /dev/null +++ b/internal/metrics/metrics_test.go @@ -0,0 +1,81 @@ +package metrics + +import ( + "encoding/json" + "strings" + "testing" + "time" +) + +func TestTheTextFormatHasEverySeries(t *testing.T) { + s := &Set{} + s.Counter("ftwcloud_drops_total", "Drops.", "reason", "tun_rate").Add(3) + s.Counter("ftwcloud_drops_total", "Drops.", "reason", "slow_phone").Inc() + s.Gauge("ftwcloud_sockets", "Sockets.", "kind", "box").Add(2) + s.GaugeFunc("ftwcloud_homes", "Homes.", func() int64 { return 7 }) + h := s.Histogram("ftwcloud_forward_seconds", "Forward.", "path", "tun_down") + h.Observe(300 * time.Microsecond) + h.Observe(20 * time.Second) + var b strings.Builder + if _, err := s.WriteTo(&b); err != nil { + t.Fatal(err) + } + out := b.String() + for _, want := range []string{ + "# TYPE ftwcloud_drops_total counter\n", + `ftwcloud_drops_total{reason="tun_rate"} 3`, + `ftwcloud_drops_total{reason="slow_phone"} 1`, + `ftwcloud_sockets{kind="box"} 2`, + "ftwcloud_homes 7", + `ftwcloud_forward_seconds_bucket{path="tun_down",le="0.00025"} 0`, + `ftwcloud_forward_seconds_bucket{path="tun_down",le="0.0005"} 1`, + `ftwcloud_forward_seconds_bucket{path="tun_down",le="+Inf"} 2`, + `ftwcloud_forward_seconds_count{path="tun_down"} 2`, + } { + if !strings.Contains(out, want) { + t.Errorf("missing %q in\n%s", want, out) + } + } + if strings.Count(out, "# TYPE ftwcloud_drops_total") != 1 { + t.Error("one name, one TYPE line") + } +} + +func TestTheLogLineCountsTheMinute(t *testing.T) { + s := &Set{} + c := s.Counter("ftwcloud_tun_frames_total", "Frames.", "dir", "up") + h := s.Histogram("ftwcloud_forward_seconds", "Forward.", "path", "tun_up") + c.Add(10) + h.Observe(time.Millisecond) + before := s.state() + c.Add(5) + for range 98 { + h.Observe(400 * time.Microsecond) + } + h.Observe(40 * time.Millisecond) + h.Observe(40 * time.Millisecond) + line, err := s.line(before, s.state(), "s1", time.UnixMilli(1_792_000_000_000)) + if err != nil { + t.Fatal(err) + } + var got map[string]any + if err := json.Unmarshal(line, &got); err != nil { + t.Fatal(err) + } + for k, want := range map[string]float64{ + "tun_frames_up": 5, + "forward_seconds_tun_up_n": 100, + "forward_seconds_tun_up_p50": 0.5, + "forward_seconds_tun_up_p99": 50, + } { + if got[k] != want { + t.Errorf("%s = %v, want %v (line %s)", k, got[k], want, line) + } + } + if got["Shard"] != "s1" || got["_aws"] == nil { + t.Errorf("line %s", line) + } + if strings.Contains(string(line), "home") { + t.Error("the line names a home") + } +} diff --git a/internal/metrics/summary.go b/internal/metrics/summary.go new file mode 100644 index 0000000..6103a38 --- /dev/null +++ b/internal/metrics/summary.go @@ -0,0 +1,142 @@ +package metrics + +import ( + "context" + "encoding/json" + "io" + "math" + "regexp" + "slices" + "strings" + "time" +) + +// Summarise writes one line every period to w until ctx ends: how much each +// counter rose over the period, each gauge now, and p50, p95 and p99 of each +// histogram over the period, in milliseconds. The line is CloudWatch's +// embedded metric format, so once the host ships its logs to CloudWatch Logs +// each field becomes a metric in the FTWCloud namespace, with the shard as +// its one dimension. It names no home. +func (s *Set) Summarise(ctx context.Context, w io.Writer, shard string, every time.Duration) { + t := time.NewTicker(every) + defer t.Stop() + last := s.state() + for { + select { + case <-ctx.Done(): + return + case now := <-t.C: + cur := s.state() + line, err := s.line(last, cur, shard, now) + last = cur + if err == nil { + _, _ = w.Write(append(line, '\n')) + } + } + } +} + +// state is every counter's count and every histogram's buckets now. +type state map[*series][]int64 + +func (s *Set) state() state { + s.mu.Lock() + all := slices.Clone(s.series) + s.mu.Unlock() + out := state{} + for _, x := range all { + if x.kind == histogram { + out[x] = x.h.snapshot() + } else { + out[x] = []int64{x.value()} + } + } + return out +} + +var unsafeName = regexp.MustCompile(`[^a-z0-9_]+`) + +// field is a series' name in the line: without the ftwcloud_ prefix and +// _total suffix, with its label values after it. +func field(x *series) string { + name := strings.TrimSuffix(strings.TrimPrefix(x.name, "ftwcloud_"), "_total") + for _, part := range strings.Split(x.labels, ",") { + if _, v, ok := strings.Cut(part, "="); ok { + name += "_" + strings.Trim(v, `"`) + } + } + return unsafeName.ReplaceAllString(strings.ToLower(name), "_") +} + +type emfMetric struct { + Name string `json:"Name"` + Unit string `json:"Unit"` +} + +type emfDirective struct { + Namespace string `json:"Namespace"` + Dimensions [][]string `json:"Dimensions"` + Metrics []emfMetric `json:"Metrics"` +} + +// emfMax is CloudWatch's limit on metrics per directive. +const emfMax = 100 + +func (s *Set) line(last, cur state, shard string, now time.Time) ([]byte, error) { + fields := map[string]any{"Shard": shard} + var metrics []emfMetric + put := func(name, unit string, v float64) { + if math.IsInf(v, 0) || math.IsNaN(v) { + return + } + fields[name] = v + metrics = append(metrics, emfMetric{Name: name, Unit: unit}) + } + keys := make([]*series, 0, len(cur)) + for x := range cur { + keys = append(keys, x) + } + slices.SortFunc(keys, func(a, b *series) int { return strings.Compare(field(a), field(b)) }) + for _, x := range keys { + now, before := cur[x], last[x] + switch x.kind { + case counter: + var prev int64 + if len(before) == 1 { + prev = before[0] + } + put(field(x), "Count", float64(now[0]-prev)) + case gauge: + put(field(x), "Count", float64(now[0])) + case histogram: + delta := slices.Clone(now) + for i := range delta { + if i < len(before) { + delta[i] -= before[i] + } + } + var n int64 + for _, c := range delta { + n += c + } + put(field(x)+"_n", "Count", float64(n)) + if n == 0 { + continue + } + for _, q := range []struct { + name string + q float64 + }{{"p50", 0.5}, {"p95", 0.95}, {"p99", 0.99}} { + put(field(x)+"_"+q.name, "Milliseconds", x.h.quantile(delta, q.q)*1000) + } + } + } + var directives []emfDirective + for len(metrics) > 0 { + n := min(len(metrics), emfMax) + directives = append(directives, emfDirective{Namespace: "FTWCloud", Dimensions: [][]string{{"Shard"}}, Metrics: metrics[:n]}) + metrics = metrics[n:] + } + fields["_aws"] = map[string]any{"Timestamp": now.UnixMilli(), "CloudWatchMetrics": directives} + return json.Marshal(fields) +} diff --git a/internal/push/push.go b/internal/push/push.go index 1d1b9af..55f18fc 100644 --- a/internal/push/push.go +++ b/internal/push/push.go @@ -29,14 +29,19 @@ package push import ( + "bytes" "context" "errors" "log/slog" + "math/rand/v2" + "net/http" "slices" "sync" + "sync/atomic" "time" "github.com/srcfl/ftw-cloud/internal/apns" + "github.com/srcfl/ftw-cloud/internal/metrics" "github.com/srcfl/ftw-cloud/internal/registry" "github.com/srcfl/ftw/go/protocol" "github.com/srcfl/ftw/go/protocol/cloudwire" @@ -65,12 +70,60 @@ const ( // the next change. unreachableExpiry = time.Hour widgetsExpiry = time.Hour - // queueSize bounds the alerts waiting to be sent. - queueSize = 256 // expireEvery is how often registrations of long-silent homes go. expireEvery = time.Hour + + // AlertWorkers send alerts side by side over Apple's HTTP/2 + // connections, so one slow answer from Apple holds up one alert, not + // every home's. + AlertWorkers = 4 + // MaxAlertsQueued bounds the alerts waiting. It is far above a burst + // of box.unreachable for every home at once; past it an alert is + // dropped, logged and counted, never silently. + MaxAlertsQueued = 50_000 + // An alert Apple or the network could not take goes again until it + // expires, after a wait that doubles from alertRetryAfter up to + // alertRetryMax, each between three quarters and all of it so retries + // from many homes do not arrive together. + alertRetryAfter = 2 * time.Second + alertRetryMax = 5 * time.Minute + // WidgetWorkers send widget pushes side by side, within the one rate. + WidgetWorkers = 3 + // widgetRetryAfter is when a widgets push Apple could not take goes + // once more. + widgetRetryAfter = 30 * time.Second + // WidgetHomesPerSecond and widgetBurst bound widget pushes over all + // homes. Tomorrow's prices reach every box within a minute or so; + // this turns that into a steady stream to Apple, which keeps alerts + // quick, and Apple budgets widget reloads per phone anyway. + WidgetHomesPerSecond = 20 + widgetBurst = 40 + // maxWidgetsQueued bounds the homes waiting for a widgets push. A home + // waits at most once: a second change before its push goes is the + // same push. + maxWidgetsQueued = 100_000 +) + +// Drops, queue depths and Apple's answers, summed over all homes. +var ( + alertsQueued = metrics.Default.Gauge("ftwcloud_push_queued", "Pushes waiting for a worker.", "kind", "alert") + widgetsQueued = metrics.Default.Gauge("ftwcloud_push_queued", "Pushes waiting for a worker.", "kind", "widgets") + alertsDropped = metrics.Drop("push_alert_queue_full") + widgetsDropped = metrics.Drop("push_widgets_queue_full") + widgetsMerged = metrics.Default.Counter("ftwcloud_push_coalesced_total", "Widget pushes merged into one already waiting.") + pushCapped = metrics.Drop("push_home_cap") + apnsResults = map[string]map[string]*metrics.Counter{} ) +func init() { + for _, k := range []string{cloudwire.PushKindAlert, KindWidgets} { + apnsResults[k] = map[string]*metrics.Counter{} + for _, r := range []string{"ok", "gone", "refused", "retry", "failed"} { + apnsResults[k][r] = metrics.Default.Counter("ftwcloud_apns_total", "Apple's answers per device, by kind and result.", "kind", k, "result", r) + } + } +} + // KindWidgets registers a widget's push token. cloudwire names only // PushKindAlert so far; the protocol's Push section names widgets. const KindWidgets = "widgets" @@ -111,14 +164,43 @@ type Service struct { // registered with app watch. Empty sends them nothing. The iPhone app's // is the sender's own. Set before serving. WatchApp string + // Owns reports whether this shard holds a home. Resume starts no + // box.unreachable for a home another shard holds, whose rows may still + // be here during a move. Nil holds every home. Set before Resume. + Owns func(home string) bool // after runs f after d and returns a function that stops it. Tests // replace it. after func(d time.Duration, f func()) (stop func() bool) - work chan func(context.Context) + // alerts wait for AlertWorkers; widgets for the one widget worker, + // each home once. busy counts the workers taking or sending an alert, + // and retrying the alerts waiting to go again. + alerts *fifo[alertJob] + widgets *fifo[string] + busy atomic.Int64 + retrying atomic.Int64 + gate gate + breaker breaker mu sync.Mutex homes map[string]*homeState + // widgetWaiting is the homes queued in widgets; widgetRetry the homes + // whose push failed once and goes once more. + widgetWaiting map[string]bool + widgetRetry map[string]bool +} + +// alertJob is one alert to a home's phones. On a retry, regs holds the +// registrations Apple did not take, and tries how often it went. +// unreachable marks box.unreachable, which is recorded as told only once a +// phone took it. +type alertJob struct { + home string + payload []byte + expires time.Time + tries int + regs []registry.PushReg + unreachable bool } // homeState is one home's box connection, as the dead man's switch sees it, @@ -149,23 +231,32 @@ func New(reg *registry.Registry, sender Sender, log *slog.Logger) *Service { } return &Service{ reg: reg, sender: sender, log: log, now: time.Now, - after: func(d time.Duration, f func()) func() bool { return time.AfterFunc(d, f).Stop }, - work: make(chan func(context.Context), queueSize), - homes: map[string]*homeState{}, + after: func(d time.Duration, f func()) func() bool { return time.AfterFunc(d, f).Stop }, + alerts: newFIFO[alertJob](MaxAlertsQueued, alertsQueued), + widgets: newFIFO[string](maxWidgetsQueued, widgetsQueued), + gate: gate{rate: WidgetHomesPerSecond, burst: widgetBurst, tokens: widgetBurst}, + homes: map[string]*homeState{}, + widgetWaiting: map[string]bool{}, + widgetRetry: map[string]bool{}, } } -// Run sends queued alerts and drops long-silent registrations until ctx -// ends. +// Run sends queued pushes and drops long-silent registrations until ctx +// ends: AlertWorkers send alerts, and one worker sends widget pushes at +// WidgetHomesPerSecond. func (s *Service) Run(ctx context.Context) { + for range AlertWorkers { + go s.alertWorker(ctx) + } + for range WidgetWorkers { + go s.widgetWorker(ctx) + } t := time.NewTicker(expireEvery) defer t.Stop() for { select { case <-ctx.Done(): return - case job := <-s.work: - job(ctx) case <-t.C: if n, err := s.reg.PushExpire(s.now()); err != nil { s.log.Warn("push upkeep failed", "err", err) @@ -176,16 +267,105 @@ func (s *Service) Run(ctx context.Context) { } } -// enqueue hands a job to Run without ever blocking the caller, which is a -// box's uplink. A full queue drops the job. -func (s *Service) enqueue(job func(context.Context)) { - select { - case s.work <- job: - default: - s.log.Warn("push queue full; an alert was dropped") +func (s *Service) alertWorker(ctx context.Context) { + for { + // busy rises before the pop, so Flush never sees an alert that is + // in neither the queue nor a worker. + s.busy.Add(1) + job, ok := s.alerts.pop() + if !ok { + s.busy.Add(-1) + select { + case <-ctx.Done(): + return + case <-s.alerts.wake: + } + continue + } + s.sendAlert(ctx, job) + s.busy.Add(-1) + } +} + +func (s *Service) widgetWorker(ctx context.Context) { + for { + home, ok := s.widgets.pop() + if !ok { + select { + case <-ctx.Done(): + return + case <-s.widgets.wake: + } + continue + } + retried := s.takeWidgets(home) + if !s.gate.wait(ctx) || !s.breaker.wait(ctx) { + return + } + if !s.sendWidgets(ctx, home) && !retried { + s.retryWidgets(home) + } + } +} + +// takeWidgets marks a home's widgets push as taken from the queue, and +// reports whether it is the one retry. +func (s *Service) takeWidgets(home string) (retried bool) { + s.mu.Lock() + defer s.mu.Unlock() + delete(s.widgetWaiting, home) + retried = s.widgetRetry[home] + delete(s.widgetRetry, home) + return retried +} + +// retryWidgets queues a home's failed widgets push once more, later. +func (s *Service) retryWidgets(home string) { + s.mu.Lock() + s.widgetRetry[home] = true + s.mu.Unlock() + s.after(widgetRetryAfter, func() { s.queueWidgets(home) }) +} + +// Flush waits until no alert is queued, being sent or waiting to go again, +// at most d, and returns how many were left. Widget pushes may be left; the +// next change sends them. +func (s *Service) Flush(d time.Duration) int { + deadline := time.Now().Add(d) + for time.Now().Before(deadline) { + if s.alerts.len() == 0 && s.busy.Load() == 0 && s.retrying.Load() == 0 { + return 0 + } + time.Sleep(20 * time.Millisecond) + } + return s.alerts.len() + int(s.retrying.Load()) +} + +// queueAlert hands an alert to the workers without ever blocking the +// caller, which is a box's uplink. +func (s *Service) queueAlert(job alertJob) { + if !s.alerts.push(job) { + alertsDropped.Inc() + s.log.Error("push: the alert queue is full; an alert was dropped", "queued", s.alerts.len()) } } +// queueWidgets asks for a widgets push to a home, once however many changes +// arrive before it goes. +func (s *Service) queueWidgets(home string) { + s.mu.Lock() + defer s.mu.Unlock() + if s.widgetWaiting[home] { + widgetsMerged.Inc() + return + } + if !s.widgets.push(home) { + widgetsDropped.Inc() + return + } + s.widgetWaiting[home] = true +} + // -------------------------------------------------------------------------- // Registrations, from a phone's app session // -------------------------------------------------------------------------- @@ -249,7 +429,7 @@ func (s *Service) Held(home, class string, envelope []byte) { s.Event(home, envelope) case cloudwire.MsgPrices, cloudwire.MsgLP: if s.widgetsChanged(home, class, envelope) { - s.enqueue(func(ctx context.Context) { s.send(ctx, home, KindWidgets, widgetsPayload, widgetsExpiry) }) + s.queueWidgets(home) } } } @@ -261,7 +441,7 @@ func (s *Service) Event(home string, envelope []byte) { if err != nil { return } - s.enqueue(func(ctx context.Context) { s.send(ctx, home, cloudwire.PushKindAlert, payload, eventExpiry) }) + s.queueAlert(alertJob{home: home, payload: payload, expires: s.now().Add(eventExpiry)}) } // widgetsChanged reports whether prices now reach further than before, or a @@ -412,6 +592,9 @@ func (s *Service) Resume() error { now := s.now() for _, a := range away { seen[a.Home] = true + if s.Owns != nil && !s.Owns(a.Home) { + continue + } if a.Told { s.mu.Lock() st := s.state(a.Home) @@ -427,7 +610,7 @@ func (s *Service) Resume() error { } wait := time.Duration(cloudwire.UnreachableAfterMs) * time.Millisecond for _, home := range homes { - if seen[home] { + if seen[home] || (s.Owns != nil && !s.Owns(home)) { continue } if err := s.reg.AwaySet(home, now.Add(wait)); err != nil { @@ -447,15 +630,14 @@ func (s *Service) unreachable(home string, gen uint64) { } st.told, st.stop = true, nil s.mu.Unlock() - if err := s.reg.AwayTold(home); err != nil { - s.log.Warn("could not record box.unreachable as sent", "err", err) - } s.log.Info("a box is out of reach; telling its phones") payload, err := cloudwire.AlertPayload(cloudwire.Alert{Home: home, Kind: protocol.PushBoxUnreachable}) if err != nil { return } - s.enqueue(func(ctx context.Context) { s.send(ctx, home, cloudwire.PushKindAlert, payload, unreachableExpiry) }) + // Told on disk only once a phone took it: an alert lost to a failure + // or an exit goes again after a restart. + s.queueAlert(alertJob{home: home, payload: payload, expires: s.now().Add(unreachableExpiry), unreachable: true}) } func (s *Service) state(home string) *homeState { @@ -487,33 +669,134 @@ func (s *Service) allow(home, kindName string) bool { return true } -// send posts one payload to every device of the home registered for a kind, -// and forgets the tokens Apple says are gone. -func (s *Service) send(ctx context.Context, home, kindName string, payload []byte, expiry time.Duration) { +// regs is a home's registrations of a kind that may get a push now. A +// device an owner has suspended keeps its tokens, so lifting the suspension +// brings its pushes back, but gets nothing meanwhile. A watch's token waits +// for the watch app's topic. +func (s *Service) regs(home, kindName string) ([]registry.PushReg, error) { + regs, err := s.reg.PushRegs(home, kindName) + if err != nil { + return nil, err + } + return slices.DeleteFunc(regs, func(r registry.PushReg) bool { + return s.reg.Suspended(home, r.DeviceID, r.Epoch) || (r.App == cloudwire.PushAppWatch && s.WatchApp == "") + }), nil +} + +// sendAlert posts an alert to the home's registered devices. What Apple or +// the network could not take goes again later, while the alert is worth +// showing, and only to devices that may still get it; a gone token is +// forgotten. +func (s *Service) sendAlert(ctx context.Context, job alertJob) { if s.sender == nil { return } - regs, err := s.reg.PushRegs(home, kindName) + fresh, err := s.regs(job.home, cloudwire.PushKindAlert) if err != nil { - s.log.Warn("could not read push registrations", "err", err) + s.log.Warn("could not read push registrations; the alert goes again", "err", err) + s.retryAlert(job, nil) return } - // A device an owner has suspended keeps its tokens, so lifting the - // suspension brings its alerts back, but gets nothing meanwhile. A - // watch's token waits for the watch app's topic. - regs = slices.DeleteFunc(regs, func(r registry.PushReg) bool { - return s.reg.Suspended(home, r.DeviceID, r.Epoch) || (r.App == cloudwire.PushAppWatch && s.WatchApp == "") - }) - if len(regs) == 0 { + if job.tries == 0 { + job.regs = fresh + if len(job.regs) == 0 { + s.told(job) + return + } + if !s.allow(job.home, cloudwire.PushKindAlert) { + pushCapped.Inc() + s.log.Warn("a home passed its push cap; push dropped", "kind", cloudwire.PushKindAlert, "cap_per_hour", MaxAlertsPerHour) + s.told(job) + return + } + } else { + // A device suspended, dropped by a roster or unregistered since + // the last try gets nothing. + job.regs = slices.DeleteFunc(job.regs, func(r registry.PushReg) bool { + return !slices.ContainsFunc(fresh, func(f registry.PushReg) bool { return bytes.Equal(f.Token, r.Token) }) + }) + if len(job.regs) == 0 { + s.told(job) + return + } + } + if !s.breaker.wait(ctx) { return } - k := kinds[kindName] - if !s.allow(home, kindName) { - s.log.Warn("a home passed its push cap; push dropped", "kind", kindName, "cap_per_hour", k.perHour) + job.tries++ + took, again := s.deliver(ctx, job.home, cloudwire.PushKindAlert, job.payload, job.expires, job.regs) + if took > 0 || len(again) == 0 { + s.told(job) + } + if len(again) > 0 { + s.retryAlert(job, again) + } +} + +// retryAlert sends job again after its next wait, to again when it is not +// nil, unless the alert has expired by then. +func (s *Service) retryAlert(job alertJob, again []registry.PushReg) { + wait := min(alertRetryAfter< 0 { + apnsResults[KindWidgets]["failed"].Add(int64(len(again))) + return false + } + return true +} + +// deliver posts one payload to each registration and returns how many Apple +// took, and those Apple or the network failed for now: an error, 429 or a +// 5xx. +func (s *Service) deliver(ctx context.Context, home, kindName string, payload []byte, exp time.Time, regs []registry.PushReg) (int, []registry.PushReg) { + k := kinds[kindName] + results := apnsResults[kindName] + var again []registry.PushReg var sent, gone, failed int - exp := s.now().Add(expiry) for _, r := range regs { // A watch and its phone get the same payload, so Apple shows one // alert when both are near; only the topic differs. @@ -523,20 +806,46 @@ func (s *Service) send(ctx context.Context, home, kindName string, payload []byt } res, err := s.sender.Send(ctx, apns.Notification{Environment: r.Environment, DeviceToken: r.Token, App: app, Type: k.pushType, Payload: payload, Expiration: exp}) + transient := err != nil || res.Status == http.StatusTooManyRequests || res.Status >= 500 + s.breaker.result(transient) switch { - case err != nil: + case transient: failed++ + results["retry"].Inc() + again = append(again, r) case res.OK(): sent++ + results["ok"].Inc() case res.Gone: gone++ + results["gone"].Inc() if err := s.reg.PushGone(home, r.Token, kindName, res.GoneSince); err != nil { s.log.Warn("could not forget a gone token", "err", err) } default: failed++ + results["refused"].Inc() s.log.Warn("APNs refused a push", "kind", kindName, "status", res.Status, "reason", res.Reason) } } - s.log.Info("push sent", "kind", kindName, "devices", sent, "gone", gone, "failed", failed) + s.log.Debug("push sent", "kind", kindName, "devices", sent, "gone", gone, "failed", failed) + return sent, again +} + +// sendQueued sends everything queued now, here, without the widget rate. +// Tests use it in place of the workers. +func (s *Service) sendQueued(ctx context.Context) { + for { + if job, ok := s.alerts.pop(); ok { + s.sendAlert(ctx, job) + continue + } + home, ok := s.widgets.pop() + if !ok { + return + } + if retried := s.takeWidgets(home); !s.sendWidgets(ctx, home) && !retried { + s.retryWidgets(home) + } + } } diff --git a/internal/push/push_test.go b/internal/push/push_test.go index 8546020..12aaf56 100644 --- a/internal/push/push_test.go +++ b/internal/push/push_test.go @@ -111,6 +111,8 @@ func newRig(t *testing.T) *rig { clock: &timers{now: time.Unix(1_791_820_800, 0)}, home: "fjzyr67buzpyncqmjliwgezvde"} r.svc = New(reg, r.apple, slog.New(slog.NewTextHandler(io.Discard, nil))) r.svc.now, r.svc.after = r.clock.time, r.clock.after + // The breaker sleeps in real time; only its own test lets it open. + r.svc.breaker.trips = 1 << 30 if err := reg.Claim(r.home, []byte("pk"), r.clock.time()); err != nil { t.Fatal(err) } @@ -131,16 +133,7 @@ func (r *rig) connected() { func (r *rig) gone(why string) { r.svc.BoxGone(r.home, why, r.conn) } // drain runs what the uplink queued, as Run would. -func (r *rig) drain() { - for { - select { - case job := <-r.svc.work: - job(context.Background()) - default: - return - } - } -} +func (r *rig) drain() { r.svc.sendQueued(context.Background()) } func (r *rig) register(t *testing.T, dev cloudwire.Device, scopes []string, token string) error { t.Helper() diff --git a/internal/push/queue.go b/internal/push/queue.go new file mode 100644 index 0000000..bd6aeb8 --- /dev/null +++ b/internal/push/queue.go @@ -0,0 +1,178 @@ +package push + +import ( + "context" + "sync" + "time" + + "github.com/srcfl/ftw-cloud/internal/metrics" +) + +// fifo is a bounded first-in first-out queue that never blocks the one who +// pushes. wake has a signal whenever something may be waiting. +type fifo[T any] struct { + mu sync.Mutex + items []T + head int + max int + wake chan struct{} + depth *metrics.Gauge +} + +func newFIFO[T any](max int, depth *metrics.Gauge) *fifo[T] { + return &fifo[T]{max: max, wake: make(chan struct{}, 1), depth: depth} +} + +func (q *fifo[T]) signal() { + select { + case q.wake <- struct{}{}: + default: + } +} + +// push adds x, or reports false when the queue is full. +func (q *fifo[T]) push(x T) bool { + q.mu.Lock() + if len(q.items)-q.head >= q.max { + q.mu.Unlock() + return false + } + q.items = append(q.items, x) + q.mu.Unlock() + q.depth.Add(1) + q.signal() + return true +} + +// pop takes the oldest item. Another worker is woken when more wait. +func (q *fifo[T]) pop() (T, bool) { + q.mu.Lock() + var zero T + if q.head == len(q.items) { + q.items, q.head = q.items[:0], 0 + q.mu.Unlock() + return zero, false + } + x := q.items[q.head] + q.items[q.head] = zero + q.head++ + if q.head > 1024 && q.head*2 > len(q.items) { + q.items, q.head = append(q.items[:0:0], q.items[q.head:]...), 0 + } + more := q.head < len(q.items) + q.mu.Unlock() + q.depth.Add(-1) + if more { + q.signal() + } + return x, true +} + +func (q *fifo[T]) len() int { + q.mu.Lock() + defer q.mu.Unlock() + return len(q.items) - q.head +} + +// gate lets rate passes a second through, after a burst. +type gate struct { + mu sync.Mutex + rate, burst float64 + tokens float64 + at time.Time + sleep func(context.Context, time.Duration) bool + nowForTesting func() time.Time +} + +func (g *gate) now() time.Time { + if g.nowForTesting != nil { + return g.nowForTesting() + } + return time.Now() +} + +// wait takes one pass, sleeping until there is one. False means ctx ended. +func (g *gate) wait(ctx context.Context) bool { + for { + g.mu.Lock() + now := g.now() + if !g.at.IsZero() { + g.tokens = min(g.burst, g.tokens+now.Sub(g.at).Seconds()*g.rate) + } + g.at = now + if g.tokens >= 1 { + g.tokens-- + g.mu.Unlock() + return true + } + need := time.Duration((1 - g.tokens) / g.rate * float64(time.Second)) + g.mu.Unlock() + sleep := g.sleep + if sleep == nil { + sleep = sleepCtx + } + if !sleep(ctx, need) { + return false + } + } +} + +func sleepCtx(ctx context.Context, d time.Duration) bool { + t := time.NewTimer(d) + defer t.Stop() + select { + case <-ctx.Done(): + return false + case <-t.C: + return true + } +} + +// breaker holds every push back for breakerOpen after breakerTrips of +// Apple's or the network's failures in a row, so an outage at Apple is +// waited out rather than met with every queued alert at once. +type breaker struct { + mu sync.Mutex + fails int + openUntil time.Time + // trips replaces breakerTrips when set; tests raise it. + trips int +} + +const ( + breakerTrips = 10 + breakerOpen = 30 * time.Second +) + +var breakerOpened = metrics.Default.Counter("ftwcloud_apns_breaker_open_total", "Times pushes were held back after Apple failed again and again.") + +// result counts one answer: a failure for now, or anything else. +func (b *breaker) result(transient bool) { + b.mu.Lock() + defer b.mu.Unlock() + if !transient { + b.fails = 0 + return + } + b.fails++ + trips := breakerTrips + if b.trips > 0 { + trips = b.trips + } + if b.fails >= trips { + b.fails = 0 + b.openUntil = time.Now().Add(breakerOpen) + breakerOpened.Inc() + } +} + +// wait sleeps while the breaker is open. False means ctx ended. +func (b *breaker) wait(ctx context.Context) bool { + b.mu.Lock() + d := time.Until(b.openUntil) + b.mu.Unlock() + if d <= 0 { + return true + } + return sleepCtx(ctx, d) +} diff --git a/internal/push/queue_test.go b/internal/push/queue_test.go new file mode 100644 index 0000000..43c8b7e --- /dev/null +++ b/internal/push/queue_test.go @@ -0,0 +1,318 @@ +package push + +import ( + "context" + "sync" + "testing" + "time" + + "github.com/srcfl/ftw-cloud/internal/apns" + "github.com/srcfl/ftw-cloud/internal/metrics" + "github.com/srcfl/ftw/go/protocol/cloudwire" +) + +// flakyApple fails the first n sends with status, then takes everything. +type flakyApple struct { + mu sync.Mutex + n int + status int + sent []apns.Notification +} + +func (f *flakyApple) Send(_ context.Context, n apns.Notification) (apns.Result, error) { + f.mu.Lock() + defer f.mu.Unlock() + f.sent = append(f.sent, n) + if f.n > 0 { + f.n-- + return apns.Result{Status: f.status}, nil + } + return apns.Result{Status: 200}, nil +} + +func (f *flakyApple) count() int { + f.mu.Lock() + defer f.mu.Unlock() + return len(f.sent) +} + +// An alert that Apple cannot take for a while goes again, after a wait that +// doubles, and arrives. +func TestAnAlertAppleCouldNotTakeGoesAgain(t *testing.T) { + r := newRig(t) + apple := &flakyApple{n: 2, status: 503} + r.svc.sender = apple + _ = r.register(t, r.owner, r.all, "owner-token") + r.svc.Event(r.home, []byte{0xa0}) + r.drain() + if apple.count() != 1 { + t.Fatalf("sent %d", apple.count()) + } + r.clock.advance(alertRetryAfter) + r.drain() + if apple.count() != 2 { + t.Fatalf("sent %d after the first wait", apple.count()) + } + r.clock.advance(alertRetryAfter) // the second wait is twice the first + r.drain() + if apple.count() != 2 { + t.Fatalf("sent %d before the doubled wait was over", apple.count()) + } + r.clock.advance(alertRetryAfter) + r.drain() + if apple.count() != 3 { + t.Fatalf("sent %d after the doubled wait", apple.count()) + } + r.clock.advance(time.Hour) + r.drain() + if apple.count() != 3 { + t.Fatalf("an alert Apple took went again: %d", apple.count()) + } +} + +// An alert goes again until it expires, then is given up and counted. +func TestAnAlertGoesAgainUntilItExpires(t *testing.T) { + r := newRig(t) + apple := &flakyApple{n: 1000, status: 429} + r.svc.sender = apple + _ = r.register(t, r.owner, r.all, "owner-token") + failed := apnsResults[cloudwire.PushKindAlert]["failed"].Load() + r.svc.Event(r.home, []byte{0xa0}) + for range 15 { + r.drain() + r.clock.advance(time.Minute) + } + sent := apple.count() + // Waits of 2, 4, 8 … 256 s, each up to a quarter shorter, fit in the + // event's ten minutes about nine times. + if sent < 8 || sent > 12 { + t.Fatalf("sent %d times in ten minutes", sent) + } + r.clock.advance(time.Hour) + r.drain() + if apple.count() != sent { + t.Fatal("an expired alert went again") + } + if apnsResults[cloudwire.PushKindAlert]["failed"].Load() == failed { + t.Fatal("the given-up alert was not counted") + } +} + +// box.unreachable is recorded as told only once a phone took it, so an +// alert that failed goes again after a restart. +func TestBoxUnreachableIsToldOnlyOnceAPhoneTookIt(t *testing.T) { + r := newRig(t) + apple := &flakyApple{n: 1, status: 503} + r.svc.sender = apple + _ = r.register(t, r.owner, r.all, "owner-token") + r.connected() + r.gone("") + r.clock.advance(601 * time.Second) + r.drain() + if apple.count() != 1 { + t.Fatalf("sent %d", apple.count()) + } + told := func() bool { + away, _ := r.reg.AwayAll() + return len(away) == 1 && away[0].Told + } + if told() { + t.Fatal("told before any phone took it") + } + r.clock.advance(alertRetryAfter) + r.drain() + if apple.count() != 2 || !told() { + t.Fatalf("sent %d, told %v", apple.count(), told()) + } +} + +// A device suspended between two tries gets nothing on the second. +func TestARetryGoesOnlyToDevicesThatMayStillGetIt(t *testing.T) { + r := newRig(t) + apple := &flakyApple{n: 2, status: 503} + r.svc.sender = apple + _ = r.register(t, r.owner, r.all, "owner-token") + viewer := r.viewer + viewer.Scopes = r.all + _ = r.register(t, viewer, r.all, "viewer-token") + r.svc.Event(r.home, []byte{0xa0}) + r.drain() + _ = r.reg.Suspend(r.home, viewer.ID, viewer.Epoch, r.clock.time()) + r.clock.advance(alertRetryAfter) + r.drain() + apple.mu.Lock() + defer apple.mu.Unlock() + if len(apple.sent) != 3 || string(apple.sent[2].DeviceToken) != "owner-token" { + var got []string + for _, n := range apple.sent { + got = append(got, string(n.DeviceToken)) + } + t.Fatalf("sent %v", got) + } +} + +// After many failures in a row the breaker holds pushes back, and one +// success closes it. +func TestTheBreakerOpensAfterFailuresInARow(t *testing.T) { + var b breaker + b.trips = 3 + b.result(true) + b.result(true) + b.result(false) + b.result(true) + b.result(true) + if time.Until(b.openUntil) > 0 { + t.Fatal("open without three failures in a row") + } + b.result(true) + if time.Until(b.openUntil) <= 0 { + t.Fatal("closed after three failures in a row") + } + ctx, cancel := context.WithCancel(context.Background()) + cancel() + if b.wait(ctx) { + t.Fatal("an open breaker let a push through") + } +} + +// Three price changes before the worker gets to a home are one widgets +// push. +func TestWidgetPushesForOneHomeMerge(t *testing.T) { + r := newRig(t) + box := newBoxSigner(t) + _ = r.registerWidgets(t, r.owner, r.all, "owner-widgets") + t0 := int64(1_791_820_800_000) + r.svc.Held(r.home, cloudwire.MsgPrices, box.prices(r.home, t0, 48, 12)) + before := widgetsMerged.Load() + for i := range 3 { + r.svc.Held(r.home, cloudwire.MsgPrices, box.prices(r.home, t0, 48, 24+i)) + } + if got := r.taken(); len(got) != 1 { + t.Fatalf("%d widgets pushes for one home", len(got)) + } + if widgetsMerged.Load()-before != 2 { + t.Fatalf("merged %d", widgetsMerged.Load()-before) + } +} + +// Alerts have workers of their own: a queue of widget pushes held back by +// the rate does not delay an alert. +func TestAnAlertDoesNotWaitBehindWidgets(t *testing.T) { + r := newRig(t) + apple := &flakyApple{} + r.svc.sender = apple + r.svc.now = time.Now + _ = r.register(t, r.owner, r.all, "owner-token") + // The widget worker may never pass. + r.svc.gate = gate{rate: 1e-9, burst: 1, sleep: func(ctx context.Context, _ time.Duration) bool { + <-ctx.Done() + return false + }} + for i := range 1000 { + r.svc.queueWidgets(string(rune('a'+i%26)) + time.Duration(i).String()) + } + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + go r.svc.Run(ctx) + start := time.Now() + r.svc.Event(r.home, []byte{0xa0}) + for apple.count() == 0 { + if time.Since(start) > 2*time.Second { + t.Fatal("the alert waited behind widgets") + } + time.Sleep(time.Millisecond) + } + if n := r.svc.Flush(time.Second); n != 0 { + t.Fatalf("%d alerts left after a flush", n) + } +} + +func TestTheQueueIsBoundedAndKeepsOrder(t *testing.T) { + q := newFIFO[int](3, &metrics.Gauge{}) + for i := range 3 { + if !q.push(i) { + t.Fatal("refused below its bound") + } + } + if q.push(3) { + t.Fatal("took one past its bound") + } + for want := range 3 { + if got, ok := q.pop(); !ok || got != want { + t.Fatalf("pop %d, %v; want %d", got, ok, want) + } + } + if _, ok := q.pop(); ok { + t.Fatal("popped from an empty queue") + } + // A long run through the queue keeps its memory to what waits. + for i := range 5000 { + q.push(i) + q.pop() + } + if cap(q.items) > 2048 { + t.Fatalf("queue holds %d slots for nothing", cap(q.items)) + } +} + +func TestTheGatePassesItsRate(t *testing.T) { + now := time.Unix(0, 0) + var slept time.Duration + g := gate{rate: 20, burst: 2, tokens: 2, nowForTesting: func() time.Time { return now }, + sleep: func(_ context.Context, d time.Duration) bool { + slept += d + now = now.Add(d) + return true + }} + for range 22 { + g.wait(context.Background()) + } + // Two in the burst, then twenty at 20 a second. + if slept < 950*time.Millisecond || slept > 1050*time.Millisecond { + t.Fatalf("22 passes slept %s", slept) + } +} + +// Flush counts an alert that waits to go again, so the exit says it is +// lost rather than dropping it without a word. +func TestFlushCountsAlertsWaitingToGoAgain(t *testing.T) { + r := newRig(t) + r.svc.sender = &flakyApple{n: 100, status: 503} + _ = r.register(t, r.owner, r.all, "owner-token") + r.svc.Event(r.home, []byte{0xa0}) + r.drain() + if n := r.svc.Flush(50 * time.Millisecond); n != 1 { + t.Fatalf("Flush left %d, want the one waiting to go again", n) + } + r.clock.advance(alertRetryAfter) + r.svc.alerts.pop() + if n := r.svc.Flush(50 * time.Millisecond); n != 0 { + t.Fatalf("Flush left %d after the retry was taken", n) + } +} + +// A widgets push Apple could not take goes once more, and no more. +func TestAFailedWidgetsPushGoesOnceMore(t *testing.T) { + r := newRig(t) + apple := &flakyApple{n: 2, status: 503} + r.svc.sender = apple + box := newBoxSigner(t) + _ = r.registerWidgets(t, r.owner, r.all, "owner-widgets") + t0 := int64(1_791_820_800_000) + r.svc.Held(r.home, cloudwire.MsgPrices, box.prices(r.home, t0, 48, 12)) + r.svc.Held(r.home, cloudwire.MsgPrices, box.prices(r.home, t0, 48, 24)) + r.drain() + if apple.count() != 1 { + t.Fatalf("sent %d", apple.count()) + } + r.clock.advance(widgetRetryAfter) + r.drain() + if apple.count() != 2 { + t.Fatalf("sent %d after the retry", apple.count()) + } + r.clock.advance(time.Hour) + r.drain() + if apple.count() != 2 { + t.Fatalf("a widgets push went a third time: %d", apple.count()) + } +} diff --git a/internal/push/resume_test.go b/internal/push/resume_test.go index eea31f9..2df59fd 100644 --- a/internal/push/resume_test.go +++ b/internal/push/resume_test.go @@ -12,6 +12,7 @@ func (r *rig) restart(t *testing.T) { t.Helper() r.svc = New(r.reg, r.apple, slog.New(slog.NewTextHandler(io.Discard, nil))) r.svc.now, r.svc.after = r.clock.time, r.clock.after + r.svc.breaker.trips = 1 << 30 if err := r.svc.Resume(); err != nil { t.Fatal(err) } @@ -90,3 +91,22 @@ func TestALateEndOfAnOlderConnectionSaysNothing(t *testing.T) { t.Fatalf("an absence was recorded: %+v", away) } } + +// A home another shard holds, whose rows are still here during a move, +// gets no box.unreachable from this shard's restart. +func TestARestartLeavesAnotherShardsHomesAlone(t *testing.T) { + r := newRig(t) + _ = r.register(t, r.owner, r.all, "tok") + r.connected() + r.svc = New(r.reg, r.apple, slog.New(slog.NewTextHandler(io.Discard, nil))) + r.svc.now, r.svc.after = r.clock.time, r.clock.after + r.svc.breaker.trips = 1 << 30 + r.svc.Owns = func(home string) bool { return home != r.home } + if err := r.svc.Resume(); err != nil { + t.Fatal(err) + } + r.clock.advance(time.Hour) + if n := unreachableSent(t, r); n != 0 { + t.Fatalf("sent %d for a home of another shard", n) + } +} diff --git a/internal/registry/push.go b/internal/registry/push.go index 790942d..aebb827 100644 --- a/internal/registry/push.go +++ b/internal/registry/push.go @@ -1,6 +1,7 @@ package registry import ( + "context" "database/sql" "time" @@ -61,7 +62,7 @@ CREATE TABLE IF NOT EXISTS push ( // PushHomes lists the homes with a registration of a kind. func (r *Registry) PushHomes(kind string) ([]string, error) { - rows, err := r.db.Query(`SELECT DISTINCT home FROM push WHERE kind = ?`, kind) + rows, err := r.rd.Query(`SELECT DISTINCT home FROM push WHERE kind = ?`, kind) if err != nil { return nil, err } @@ -84,23 +85,29 @@ func (r *Registry) PushRegister(reg PushReg) error { if app == "" { app = cloudwire.PushAppIPhone } - _, err := r.db.Exec(`INSERT INTO push (home, device_id, epoch, token, environment, kind, app, registered_ms) - VALUES (?, ?, ?, ?, ?, ?, ?, ?) - ON CONFLICT (home, token, kind) DO UPDATE SET device_id = excluded.device_id, epoch = excluded.epoch, - environment = excluded.environment, app = excluded.app, registered_ms = excluded.registered_ms`, - reg.Home, reg.DeviceID, int64(reg.Epoch), reg.Token, reg.Environment, reg.Kind, app, reg.At.UnixMilli()) - return err + // A phone registers rarely and does not register again until its next + // start, so the write is synced. + return r.durably(func(ctx context.Context, c *sql.Conn) error { + _, err := c.ExecContext(ctx, `INSERT INTO push (home, device_id, epoch, token, environment, kind, app, registered_ms) + VALUES (?, ?, ?, ?, ?, ?, ?, ?) + ON CONFLICT (home, token, kind) DO UPDATE SET device_id = excluded.device_id, epoch = excluded.epoch, + environment = excluded.environment, app = excluded.app, registered_ms = excluded.registered_ms`, + reg.Home, reg.DeviceID, int64(reg.Epoch), reg.Token, reg.Environment, reg.Kind, app, reg.At.UnixMilli()) + return err + }) } // PushUnregister forgets one of a device's tokens. func (r *Registry) PushUnregister(home, deviceID string, token []byte) error { - _, err := r.db.Exec(`DELETE FROM push WHERE home = ? AND device_id = ? AND token = ?`, home, deviceID, token) - return err + return r.durably(func(ctx context.Context, c *sql.Conn) error { + _, err := c.ExecContext(ctx, `DELETE FROM push WHERE home = ? AND device_id = ? AND token = ?`, home, deviceID, token) + return err + }) } // PushRegs returns a home's registrations of one kind. func (r *Registry) PushRegs(home, kind string) ([]PushReg, error) { - rows, err := r.db.Query(`SELECT device_id, epoch, token, environment, app, registered_ms FROM push + rows, err := r.rd.Query(`SELECT device_id, epoch, token, environment, app, registered_ms FROM push WHERE home = ? AND kind = ? ORDER BY registered_ms`, home, kind) if err != nil { return nil, err @@ -144,7 +151,7 @@ func (r *Registry) PushTrim(home, deviceID, kind string, keep int) error { // PushPrune keeps only the registrations keep allows: a device at its epoch, // for one kind, as a new roster says. func (r *Registry) PushPrune(home string, keep func(deviceID string, epoch uint64, kind string) bool) error { - rows, err := r.db.Query(`SELECT DISTINCT device_id, epoch, kind FROM push WHERE home = ?`, home) + rows, err := r.rd.Query(`SELECT DISTINCT device_id, epoch, kind FROM push WHERE home = ?`, home) if err != nil { return err } diff --git a/internal/registry/registry.go b/internal/registry/registry.go index c9e1d92..20813cf 100644 --- a/internal/registry/registry.go +++ b/internal/registry/registry.go @@ -6,6 +6,7 @@ package registry import ( + "context" "database/sql" "errors" "fmt" @@ -28,7 +29,11 @@ const ( // Registry is the SQLite file. type Registry struct { + // db is the one connection that writes; rd is a few that only read. + // The file is in WAL mode, so readers never wait for the writer, and + // a box's reconnect or a token read does not queue behind a write. db *sql.DB + rd *sql.DB // suspended mirrors the suspensions table, so admission, which runs // under a home's lock, never waits for SQLite. Every write updates it @@ -52,9 +57,20 @@ type Home struct { GrantID []byte } +// readers is how many connections may read at once. +const readers = 4 + // Open opens or creates the registry at path. +// +// synchronous(NORMAL) syncs the file at each checkpoint rather than at each +// commit. A power cut can lose the last commits but never corrupts the file. +// What that loses comes back by itself: a box sends its roster again at its +// next connect, and a phone registers again at its next start. A reconnect +// storm is then a matter of memory, not of disk syncs. The writes that +// narrow access, and would widen it again if lost, go through durably. func Open(path string) (*Registry, error) { - db, err := sql.Open("sqlite", "file:"+path+"?_pragma=journal_mode(WAL)&_pragma=secure_delete(ON)&_pragma=busy_timeout(5000)&_pragma=foreign_keys(1)") + const pragmas = "_pragma=journal_mode(WAL)&_pragma=synchronous(NORMAL)&_pragma=secure_delete(ON)&_pragma=busy_timeout(5000)&_pragma=foreign_keys(1)" + db, err := sql.Open("sqlite", "file:"+path+"?"+pragmas+"&_txlock=immediate") if err != nil { return nil, err } @@ -98,9 +114,15 @@ CREATE TABLE IF NOT EXISTS away ( _ = db.Close() return nil, fmt.Errorf("registry: schema: %w", err) } - r := &Registry{db: db, suspended: map[suspendKey]uint64{}} - if err := r.loadSuspensions(); err != nil { + rd, err := sql.Open("sqlite", "file:"+path+"?"+pragmas+"&_pragma=query_only(1)") + if err != nil { _ = db.Close() + return nil, err + } + rd.SetMaxOpenConns(readers) + r := &Registry{db: db, rd: rd, suspended: map[suspendKey]uint64{}} + if err := r.loadSuspensions(); err != nil { + _ = r.Close() return nil, fmt.Errorf("registry: suspensions: %w", err) } return r, nil @@ -134,8 +156,32 @@ func (r *Registry) forgetSuspensions(home string) { } } +// durably runs f on the one writing connection with each commit synced to +// disk, as synchronous(FULL) does: an owner's suspension, a purge, a token +// dropped or pruned, and a roster with a higher number, which may remove a +// device. A power cut must not undo any of them. +func (r *Registry) durably(f func(ctx context.Context, c *sql.Conn) error) error { + ctx := context.Background() + c, err := r.db.Conn(ctx) + if err != nil { + return err + } + defer c.Close() + if _, err := c.ExecContext(ctx, `PRAGMA synchronous = FULL`); err != nil { + return err + } + defer func() { _, _ = c.ExecContext(ctx, `PRAGMA synchronous = NORMAL`) }() + return f(ctx, c) +} + // Close closes the file. -func (r *Registry) Close() error { return r.db.Close() } +func (r *Registry) Close() error { + rdErr := r.rd.Close() + if err := r.db.Close(); err != nil { + return err + } + return rdErr +} // Claim registers a home at its box's first hello. A home id is a hash of the // key, so a second claim with another key is impossible by construction, and @@ -147,6 +193,14 @@ func (r *Registry) Claim(home string, pk []byte, now time.Time) error { } return err } + // A box that reconnects finds its row and writes nothing. + var known int + if err := r.rd.QueryRow(`SELECT COUNT(*) FROM homes WHERE home = ?`, home).Scan(&known); err != nil { + return err + } + if known > 0 { + return nil + } _, err := r.db.Exec(`INSERT INTO homes (home, pk, created_ms) VALUES (?, ?, ?) ON CONFLICT (home) DO NOTHING`, home, pk, now.UnixMilli()) return err @@ -160,7 +214,7 @@ func (r *Registry) Get(home string) (Home, bool, error) { var h Home var created, rosterMs int64 var seq int64 - err := r.db.QueryRow(`SELECT home, pk, created_ms, roster, roster_seq, roster_ms, grant_id FROM homes WHERE home = ?`, home). + err := r.rd.QueryRow(`SELECT home, pk, created_ms, roster, roster_seq, roster_ms, grant_id FROM homes WHERE home = ?`, home). Scan(&h.ID, &h.PK, &created, &h.Roster, &seq, &rosterMs, &h.GrantID) if errors.Is(err, sql.ErrNoRows) { return Home{}, false, nil @@ -179,7 +233,7 @@ func (r *Registry) Get(home string) (Home, bool, error) { // admit phones by again after a restart. It is upkeep at start, never a // request. func (r *Registry) Rosters() ([]Home, error) { - rows, err := r.db.Query(`SELECT home, pk, created_ms, roster, roster_seq, roster_ms, grant_id FROM homes WHERE roster IS NOT NULL`) + rows, err := r.rd.Query(`SELECT home, pk, created_ms, roster, roster_seq, roster_ms, grant_id FROM homes WHERE roster IS NOT NULL`) if err != nil { return nil, err } @@ -207,15 +261,19 @@ type Away struct { // AwaySet records that a home's box went and when box.unreachable is due. func (r *Registry) AwaySet(home string, due time.Time) error { - _, err := r.db.Exec(`INSERT INTO away (home, due_ms, told) SELECT ?, ?, 0 WHERE EXISTS (SELECT 1 FROM homes WHERE home = ?) - ON CONFLICT (home) DO UPDATE SET due_ms = excluded.due_ms, told = 0`, home, due.UnixMilli(), home) - return err + return r.durably(func(ctx context.Context, c *sql.Conn) error { + _, err := c.ExecContext(ctx, `INSERT INTO away (home, due_ms, told) SELECT ?, ?, 0 WHERE EXISTS (SELECT 1 FROM homes WHERE home = ?) + ON CONFLICT (home) DO UPDATE SET due_ms = excluded.due_ms, told = 0`, home, due.UnixMilli(), home) + return err + }) } // AwayTold records that box.unreachable went. func (r *Registry) AwayTold(home string) error { - _, err := r.db.Exec(`UPDATE away SET told = 1 WHERE home = ?`, home) - return err + return r.durably(func(ctx context.Context, c *sql.Conn) error { + _, err := c.ExecContext(ctx, `UPDATE away SET told = 1 WHERE home = ?`, home) + return err + }) } // AwayClear forgets a home's absence: its box is back, or the home is gone. @@ -226,7 +284,7 @@ func (r *Registry) AwayClear(home string) error { // AwayAll returns every home recorded as away. func (r *Registry) AwayAll() ([]Away, error) { - rows, err := r.db.Query(`SELECT home, due_ms, told FROM away`) + rows, err := r.rd.Query(`SELECT home, due_ms, told FROM away`) if err != nil { return nil, err } @@ -246,32 +304,48 @@ func (r *Registry) AwayAll() ([]Away, error) { // SetRoster keeps the signed roster envelope. func (r *Registry) SetRoster(home string, seq uint64, grantID, envelope []byte, now time.Time) error { - _, err := r.db.Exec(`UPDATE homes SET roster = ?, roster_seq = ?, roster_ms = ?, grant_id = ? WHERE home = ? AND roster_seq <= ?`, - envelope, int64(seq), now.UnixMilli(), grantID, home, int64(seq)) - return err + const q = `UPDATE homes SET roster = ?, roster_seq = ?, roster_ms = ?, grant_id = ? WHERE home = ? AND roster_seq <= ?` + args := []any{envelope, int64(seq), now.UnixMilli(), grantID, home, int64(seq)} + // The same number renews the time to live and can wait for the next + // checkpoint; a higher one may remove a device, so it is synced. + var held int64 + if err := r.rd.QueryRow(`SELECT roster_seq FROM homes WHERE home = ?`, home).Scan(&held); err != nil && !errors.Is(err, sql.ErrNoRows) { + return err + } + if int64(seq) <= held { + _, err := r.db.Exec(q, args...) + return err + } + return r.durably(func(ctx context.Context, c *sql.Conn) error { + _, err := c.ExecContext(ctx, q, args...) + return err + }) } // Purge deletes a home and leaves a tombstone, so the receipt can be sent // again if the first one is lost. func (r *Registry) Purge(home string, grantID []byte, now time.Time) error { - tx, err := r.db.Begin() + err := r.durably(func(ctx context.Context, c *sql.Conn) error { + tx, err := c.BeginTx(ctx, nil) + if err != nil { + return err + } + defer func() { _ = tx.Rollback() }() + if _, err := tx.Exec(`DELETE FROM homes WHERE home = ?`, home); err != nil { + return err + } + if _, err := tx.Exec(`DELETE FROM suspensions WHERE home = ?`, home); err != nil { + return err + } + if _, err := tx.Exec(`INSERT INTO tombstones (home, grant_id, deleted_ms) VALUES (?, ?, ?) + ON CONFLICT (home) DO NOTHING`, home, grantID, now.UnixMilli()); err != nil { + return err + } + return tx.Commit() + }) if err != nil { return err } - defer func() { _ = tx.Rollback() }() - if _, err := tx.Exec(`DELETE FROM homes WHERE home = ?`, home); err != nil { - return err - } - if _, err := tx.Exec(`DELETE FROM suspensions WHERE home = ?`, home); err != nil { - return err - } - if _, err := tx.Exec(`INSERT INTO tombstones (home, grant_id, deleted_ms) VALUES (?, ?, ?) - ON CONFLICT (home) DO NOTHING`, home, grantID, now.UnixMilli()); err != nil { - return err - } - if err := tx.Commit(); err != nil { - return err - } r.forgetSuspensions(home) return nil } @@ -279,7 +353,7 @@ func (r *Registry) Purge(home string, grantID []byte, now time.Time) error { // Tombstone returns a purged home's grant id and when it was deleted. func (r *Registry) Tombstone(home string) (time.Time, bool, error) { var ms int64 - err := r.db.QueryRow(`SELECT deleted_ms FROM tombstones WHERE home = ?`, home).Scan(&ms) + err := r.rd.QueryRow(`SELECT deleted_ms FROM tombstones WHERE home = ?`, home).Scan(&ms) if errors.Is(err, sql.ErrNoRows) { return time.Time{}, false, nil } @@ -292,7 +366,7 @@ func (r *Registry) Tombstone(home string) (time.Time, bool, error) { // TombstoneGrant returns the grant id a purged home was deleted under. func (r *Registry) TombstoneGrant(home string) []byte { var id []byte - _ = r.db.QueryRow(`SELECT grant_id FROM tombstones WHERE home = ?`, home).Scan(&id) + _ = r.rd.QueryRow(`SELECT grant_id FROM tombstones WHERE home = ?`, home).Scan(&id) return id } @@ -302,7 +376,7 @@ func (r *Registry) TombstoneGrant(home string) []byte { func (r *Registry) Expire(now time.Time) ([]string, error) { newCutoff := now.Add(-NewHomeGrace).UnixMilli() rosterCutoff := now.Add(-RosterGrace).UnixMilli() - rows, err := r.db.Query(`SELECT home FROM homes + rows, err := r.rd.Query(`SELECT home FROM homes WHERE (roster_ms = 0 AND created_ms < ?) OR (roster_ms > 0 AND roster_ms < ?)`, newCutoff, rosterCutoff) if err != nil { return nil, err @@ -340,10 +414,12 @@ func (r *Registry) Suspend(home, deviceID string, epoch uint64, now time.Time) e r.susMu.Lock() r.suspended[suspendKey{home, deviceID}] = epoch r.susMu.Unlock() - _, err := r.db.Exec(`INSERT INTO suspensions (home, device_id, epoch, since_ms) VALUES (?, ?, ?, ?) - ON CONFLICT (home, device_id) DO UPDATE SET epoch = excluded.epoch, since_ms = excluded.since_ms`, - home, deviceID, int64(epoch), now.UnixMilli()) - return err + return r.durably(func(ctx context.Context, c *sql.Conn) error { + _, err := c.ExecContext(ctx, `INSERT INTO suspensions (home, device_id, epoch, since_ms) VALUES (?, ?, ?, ?) + ON CONFLICT (home, device_id) DO UPDATE SET epoch = excluded.epoch, since_ms = excluded.since_ms`, + home, deviceID, int64(epoch), now.UnixMilli()) + return err + }) } // Unsuspend lifts a suspension. @@ -369,11 +445,15 @@ func (r *Registry) Suspended(home, deviceID string, epoch uint64) bool { // PruneSuspensions drops the suspensions a new roster ended: devices it no // longer lists, and devices whose epoch moved. func (r *Registry) PruneSuspensions(home string, epochs map[string]uint64) error { - rows, err := r.db.Query(`SELECT device_id, epoch FROM suspensions WHERE home = ?`, home) + rows, err := r.rd.Query(`SELECT device_id, epoch FROM suspensions WHERE home = ?`, home) if err != nil { return err } - var gone []string + type entry struct { + id string + epoch uint64 + } + var gone []entry for rows.Next() { var id string var epoch int64 @@ -382,14 +462,32 @@ func (r *Registry) PruneSuspensions(home string, epochs map[string]uint64) error return err } if e, ok := epochs[id]; !ok || e != uint64(epoch) { - gone = append(gone, id) + gone = append(gone, entry{id, uint64(epoch)}) } } _ = rows.Close() - for _, id := range gone { - if err := r.Unsuspend(home, id); err != nil { + for _, g := range gone { + if err := r.unsuspendAt(home, g.id, g.epoch); err != nil { return err } } return nil } + +// unsuspendAt lifts a suspension only if it is still at epoch: an owner who +// suspended the device again, at its new epoch, while a roster was being +// pruned keeps that suspension. +// The file goes first and memory after, each only at epoch, so whichever +// order a new suspension lands in, it stays; and admission, which reads +// memory under a home's lock, never waits for the file. +func (r *Registry) unsuspendAt(home, deviceID string, epoch uint64) error { + if _, err := r.db.Exec(`DELETE FROM suspensions WHERE home = ? AND device_id = ? AND epoch = ?`, home, deviceID, int64(epoch)); err != nil { + return err + } + r.susMu.Lock() + defer r.susMu.Unlock() + if held, ok := r.suspended[suspendKey{home, deviceID}]; ok && held == epoch { + delete(r.suspended, suspendKey{home, deviceID}) + } + return nil +} diff --git a/internal/registry/registry_test.go b/internal/registry/registry_test.go index 6a9a685..d7e696c 100644 --- a/internal/registry/registry_test.go +++ b/internal/registry/registry_test.go @@ -98,3 +98,58 @@ func TestASuspensionHoldsUntilTheRosterMovesPastIt(t *testing.T) { t.Fatal("a purge left the suspension") } } + +// The writes that narrow access are synced, and the writer goes back to +// NORMAL after each, so a reconnect storm still costs no syncs. +func TestDurableWritesLeaveTheWriterAtNormal(t *testing.T) { + r, err := Open(filepath.Join(t.TempDir(), "registry.db")) + if err != nil { + t.Fatal(err) + } + defer r.Close() + now := time.Now() + home := "aaaaaaaaaaaaaaaaaaaaaaaaaa" + if err := r.Claim(home, []byte("pk"), now); err != nil { + t.Fatal(err) + } + for name, write := range map[string]func() error{ + "a higher roster": func() error { return r.SetRoster(home, 2, nil, []byte("roster"), now) }, + "a suspension": func() error { return r.Suspend(home, "phone", 1, now) }, + "a dropped token": func() error { return r.TokenDrop(home, "phone") }, + "a purge": func() error { return r.Purge(home, nil, now) }, + } { + if err := write(); err != nil { + t.Fatalf("%s: %v", name, err) + } + var mode int + if err := r.db.QueryRow(`PRAGMA synchronous`).Scan(&mode); err != nil || mode != 1 { + t.Fatalf("after %s the writer is at synchronous %d, %v; want 1 (NORMAL)", name, mode, err) + } + } +} + +// A roster prune lifts a suspension only at the epoch it read: an owner who +// suspended the device again at its new epoch meanwhile keeps it. +func TestAPruneDoesNotLiftASuspensionMadeSinceItRead(t *testing.T) { + r, err := Open(filepath.Join(t.TempDir(), "registry.db")) + if err != nil { + t.Fatal(err) + } + defer r.Close() + home, now := "aaaaaaaaaaaaaaaaaaaaaaaaaa", time.Now() + _ = r.Claim(home, []byte("pk"), now) + _ = r.Suspend(home, "phone", 1, now) + // The prune read epoch 1; the owner suspends epoch 2 before it deletes. + _ = r.Suspend(home, "phone", 2, now) + if err := r.unsuspendAt(home, "phone", 1); err != nil { + t.Fatal(err) + } + if !r.Suspended(home, "phone", 2) { + t.Fatal("the suspension at the new epoch was lifted in memory") + } + var n int + _ = r.rd.QueryRow(`SELECT COUNT(*) FROM suspensions WHERE home = ? AND epoch = 2`, home).Scan(&n) + if n != 1 { + t.Fatal("the suspension at the new epoch was lifted on disk") + } +} diff --git a/internal/registry/token.go b/internal/registry/token.go index e0a7312..8aab632 100644 --- a/internal/registry/token.go +++ b/internal/registry/token.go @@ -1,6 +1,7 @@ package registry import ( + "context" "database/sql" "errors" "time" @@ -37,18 +38,20 @@ CREATE TABLE IF NOT EXISTS tokens ( // TokenIssue binds a token's hash to a roster entry, in place of the // device's old token. func (r *Registry) TokenIssue(row TokenRow, hash []byte) error { - _, err := r.db.Exec(`INSERT INTO tokens (home, device_id, epoch, hash, expires_ms) VALUES (?, ?, ?, ?, ?) - ON CONFLICT (home, device_id) DO UPDATE SET epoch = excluded.epoch, hash = excluded.hash, - expires_ms = excluded.expires_ms`, - row.Home, row.DeviceID, int64(row.Epoch), hash, row.Expires.UnixMilli()) - return err + return r.durably(func(ctx context.Context, c *sql.Conn) error { + _, err := c.ExecContext(ctx, `INSERT INTO tokens (home, device_id, epoch, hash, expires_ms) VALUES (?, ?, ?, ?, ?) + ON CONFLICT (home, device_id) DO UPDATE SET epoch = excluded.epoch, hash = excluded.hash, + expires_ms = excluded.expires_ms`, + row.Home, row.DeviceID, int64(row.Epoch), hash, row.Expires.UnixMilli()) + return err + }) } // TokenLookup returns the binding of a token's hash, if it has not expired. func (r *Registry) TokenLookup(hash []byte, now time.Time) (TokenRow, bool, error) { var row TokenRow var epoch, ms int64 - err := r.db.QueryRow(`SELECT home, device_id, epoch, expires_ms FROM tokens WHERE hash = ? AND expires_ms > ?`, + err := r.rd.QueryRow(`SELECT home, device_id, epoch, expires_ms FROM tokens WHERE hash = ? AND expires_ms > ?`, hash, now.UnixMilli()).Scan(&row.Home, &row.DeviceID, &epoch, &ms) if errors.Is(err, sql.ErrNoRows) { return TokenRow{}, false, nil @@ -62,8 +65,10 @@ func (r *Registry) TokenLookup(hash []byte, now time.Time) (TokenRow, bool, erro // TokenDrop forgets a device's token, as when an owner suspends it. func (r *Registry) TokenDrop(home, deviceID string) error { - _, err := r.db.Exec(`DELETE FROM tokens WHERE home = ? AND device_id = ?`, home, deviceID) - return err + return r.durably(func(ctx context.Context, c *sql.Conn) error { + _, err := c.ExecContext(ctx, `DELETE FROM tokens WHERE home = ? AND device_id = ?`, home, deviceID) + return err + }) } // TokenDropHash forgets one token by its hash. @@ -75,7 +80,7 @@ func (r *Registry) TokenDropHash(hash []byte) error { // TokenPrune keeps only the tokens whose device keep allows at its epoch, as // a new roster says. func (r *Registry) TokenPrune(home string, keep func(deviceID string, epoch uint64) bool) error { - rows, err := r.db.Query(`SELECT device_id, epoch FROM tokens WHERE home = ?`, home) + rows, err := r.rd.Query(`SELECT device_id, epoch FROM tokens WHERE home = ?`, home) if err != nil { return err } @@ -95,14 +100,19 @@ func (r *Registry) TokenPrune(home string, keep func(deviceID string, epoch uint } } _ = rows.Close() + if len(gone) == 0 { + return nil + } // The epoch is part of the match, so a token the device got at its new // epoch meanwhile stays. - for _, e := range gone { - if _, err := r.db.Exec(`DELETE FROM tokens WHERE home = ? AND device_id = ? AND epoch = ?`, home, e.id, e.epoch); err != nil { - return err + return r.durably(func(ctx context.Context, c *sql.Conn) error { + for _, e := range gone { + if _, err := c.ExecContext(ctx, `DELETE FROM tokens WHERE home = ? AND device_id = ? AND epoch = ?`, home, e.id, e.epoch); err != nil { + return err + } } - } - return nil + return nil + }) } // TokenExpire forgets the tokens that have expired. diff --git a/internal/server/e2e_test.go b/internal/server/e2e_test.go index 9ce63dd..377a83a 100644 --- a/internal/server/e2e_test.go +++ b/internal/server/e2e_test.go @@ -64,6 +64,7 @@ type stack struct { apple *capturedApple up *uplink.Uplink reg *registry.Registry + app *appsession.Server } func newStack(t *testing.T) *stack { @@ -104,7 +105,7 @@ func newStack(t *testing.T) *stack { srv.TLS = &tls.Config{MinVersion: tls.VersionTLS13} srv.StartTLS() t.Cleanup(srv.Close) - return &stack{t: t, srv: srv, st: st, serviceKey: serviceKey, noise: noise, apple: apple, up: up, reg: reg} + return &stack{t: t, srv: srv, st: st, serviceKey: serviceKey, noise: noise, apple: apple, up: up, reg: reg, app: app} } // testBox is a box's half of the uplink. diff --git a/internal/server/scale_e2e_test.go b/internal/server/scale_e2e_test.go new file mode 100644 index 0000000..65c5bc4 --- /dev/null +++ b/internal/server/scale_e2e_test.go @@ -0,0 +1,131 @@ +package server + +import ( + "bytes" + "crypto/tls" + "crypto/x509" + "errors" + "net/http" + "strings" + "testing" + "time" + + "github.com/gorilla/websocket" + "github.com/srcfl/ftw-cloud/internal/shard" + "github.com/srcfl/ftw/go/protocol/appwire" + "github.com/srcfl/ftw/go/protocol/cloudwire" +) + +// onS2 is this instance as s1, with home on s2. +func onS2(t *testing.T, home string) *shard.Directory { + t.Helper() + d, err := shard.File{Self: "s1", Default: "s1", + Shards: map[string]string{"s1": "cloud.ftw.energy", "s2": "s2.cloud.ftw.energy"}, + Homes: map[string]string{home: "s2"}}.Directory() + if err != nil { + t.Fatal(err) + } + return d +} + +func (s *stack) client() *http.Client { + pool := x509.NewCertPool() + pool.AddCert(s.srv.Certificate()) + return &http.Client{Transport: &http.Transport{TLSClientConfig: &tls.Config{RootCAs: pool, MinVersion: tls.VersionTLS13}}} +} + +// closeOf reads until the socket closes and returns its code and reason. +func closeOf(t *testing.T, conn *websocket.Conn) (int, string) { + t.Helper() + _ = conn.SetReadDeadline(time.Now().Add(3 * time.Second)) + for { + if _, _, err := conn.ReadMessage(); err != nil { + var ce *websocket.CloseError + if errors.As(err, &ce) { + return ce.Code, ce.Text + } + t.Fatalf("no close: %v", err) + } + } +} + +// A phone that dials an instance not holding its home hears the host that +// does before its message 1 is read, so it spends no handshake here. It +// writes message 1 at once, as phones do; the service waits for the phone's +// answer to its close, so the phone reads 4421 and not a reset. +func TestAPhoneOfAnotherShardIsSentThereBeforeMessage1(t *testing.T) { + s := newStack(t) + box := s.connectTunBox() + s.app.Shards = onS2(t, box.home) + pool := x509.NewCertPool() + pool.AddCert(s.srv.Certificate()) + d := websocket.Dialer{TLSClientConfig: &tls.Config{RootCAs: pool, MinVersion: tls.VersionTLS13}} + conn, _, err := d.Dial(strings.Replace(s.srv.URL, "https://", "wss://", 1)+"/v1/app?home="+box.home, nil) + if err != nil { + t.Fatal(err) + } + defer conn.Close() + key, _ := appwire.GenerateKeyPair() + init, _ := appwire.NewInitiator(appwire.InitiatorOptions{StaticKey: key, RemoteStatic: s.noise.Public(), + Prologue: cloudwire.AppPrologue(box.home)}) + payload, _ := cloudwire.Unsigned(cloudwire.MsgNow, cloudwire.Now{Hz: 1}) + msg1, _ := init.WriteMessage(payload) + if err := conn.WriteMessage(websocket.BinaryMessage, msg1); err != nil { + t.Fatal(err) + } + if code, host := closeOf(t, conn); code != cloudwire.CloseWrongShard || host != "s2.cloud.ftw.energy" { + t.Fatalf("close %d %q", code, host) + } +} + +// A watch that posts to an instance not holding its home gets 421 and the +// host, with an empty body, before its message 1 is read. +func TestAWatchOfAnotherShardGets421(t *testing.T) { + s := newStack(t) + box := s.connectTunBox() + s.app.Shards = onS2(t, box.home) + resp, err := s.client().Post(s.srv.URL+"/v1/app/once?home="+box.home, "application/octet-stream", bytes.NewReader([]byte{1, 2, 3})) + if err != nil { + t.Fatal(err) + } + defer resp.Body.Close() + if resp.StatusCode != cloudwire.StatusWrongShard || resp.Header.Get(cloudwire.ShardHeader) != "s2.cloud.ftw.energy" || resp.ContentLength > 0 { + t.Fatalf("%d %q %d", resp.StatusCode, resp.Header.Get(cloudwire.ShardHeader), resp.ContentLength) + } +} + +// Before the service stops, every phone and box is told to come back within +// the spread. +func TestDrainSendsPhonesAndBoxesToComeBack(t *testing.T) { + s := newStack(t) + box := s.connectTunBox() + key, _ := appwire.GenerateKeyPair() + box.roster(2, grantOff, nil, key.Public()) + var phone *tunPhone + eventually(t, "the phone is admitted", func() bool { + phone = s.dialPhone(box.home, key, cloudwire.Now{Hz: 1}, "") + return phone.conn != nil && phone.tr != nil + }) + if n := s.app.Sockets(); n < 1 { + t.Fatalf("%d phones to drain", n) + } + s.app.Drain("1500") + s.up.Drain("1500") + // The phone's reader closes tuns once it has recorded why it ended. + for range phone.tuns { + } + var ce *websocket.CloseError + if !errors.As(phone.ended, &ce) || ce.Code != cloudwire.CloseRestart || ce.Text != "1500" { + t.Fatalf("the phone heard %v", phone.ended) + } + select { + case <-box.closed: + case <-time.After(3 * time.Second): + t.Fatal("the box's uplink stayed open") + } + box.mu.Lock() + defer box.mu.Unlock() + if !errors.As(box.ended, &ce) || ce.Code != cloudwire.CloseRestart || ce.Text != "1500" { + t.Fatalf("the box heard %v", box.ended) + } +} diff --git a/internal/server/server.go b/internal/server/server.go index 6f78aad..969fd97 100644 --- a/internal/server/server.go +++ b/internal/server/server.go @@ -144,19 +144,13 @@ func revision() string { func (s *Server) Upkeep(ctx context.Context, every time.Duration) { t := time.NewTicker(every) defer t.Stop() - var tunDropped int64 for { select { case <-ctx.Done(): return case <-t.C: - // Tunnel messages dropped past a home's limits, as a count for - // the whole service; it names no home. - if n := s.Uplink.TunDropped.Load(); n > tunDropped { - s.Log.Warn("tun dropped past homes' limits", "since_last", n-tunDropped, "total", n) - tunDropped = n - } s.Store.Sweep() + s.Uplink.Sweep() if err := s.Registry.TokenExpire(time.Now()); err != nil { s.Log.Warn("token upkeep failed", "err", err) } diff --git a/internal/server/tunnel_e2e_test.go b/internal/server/tunnel_e2e_test.go index 19b760c..1140a3a 100644 --- a/internal/server/tunnel_e2e_test.go +++ b/internal/server/tunnel_e2e_test.go @@ -34,6 +34,7 @@ func sessionPrologue(boxStatic []byte) []byte { // the box's half of each phone's session. type tunBox struct { t *testing.T + ended error // why the socket closed, once closed is key *ecdsa.PrivateKey home string static appwire.KeyPair @@ -167,6 +168,9 @@ func (b *tunBox) serve() { _ = b.conn.SetReadDeadline(time.Time{}) _, msg, err := b.conn.ReadMessage() if err != nil { + b.mu.Lock() + b.ended = err + b.mu.Unlock() return } payload, _ := cloudwire.DecodeFrame(msg) diff --git a/internal/shard/shard.go b/internal/shard/shard.go new file mode 100644 index 0000000..f51e958 --- /dev/null +++ b/internal/shard/shard.go @@ -0,0 +1,188 @@ +// Package shard says which instance of the service holds a home. +// docs/protocol-cloud.md in srcfl/ftw, "Shards and restarts", is the rule. +// +// Every home lives on exactly one shard, and its box, phones, watch and +// extensions all meet there, so no home's data crosses between instances. +// Each instance holds the same directory: each shard's host, a shard for +// each of 256 buckets of homes, and single homes moved on their own. An +// instance that gets a home it does not hold names the host that does, and +// the client follows. +// +// With no directory file there is one shard, this one, and it holds every +// home. +package shard + +import ( + "crypto/sha256" + "encoding/json" + "fmt" + "os" + "strconv" + "strings" + + "github.com/srcfl/ftw/go/protocol/cloudwire" +) + +// Buckets is how many buckets homes fall into. It never changes: moving +// homes moves buckets, or single homes, between shards. +const Buckets = 256 + +// bucketTag starts what a home's bucket is hashed from. +const bucketTag = "ftw.cloud.shard\x00" + +// Bucket is the bucket a home falls into. +func Bucket(home string) int { + sum := sha256.Sum256([]byte(bucketTag + home)) + return int(sum[0]) +} + +// Directory maps homes to shards. +type Directory struct { + self string + hosts map[string]string + buckets [Buckets]string + homes map[string]string +} + +// Single is the directory with one shard, named s1, at host. +func Single(host string) *Directory { + d := &Directory{self: "s1", hosts: map[string]string{"s1": host}, homes: map[string]string{}} + for i := range d.buckets { + d.buckets[i] = "s1" + } + return d +} + +// File is the directory as an operator writes it: +// +// { +// "self": "s1", +// "shards": {"s1": "cloud.ftw.energy", "s2": "s2.cloud.ftw.energy"}, +// "default": "s1", +// "buckets": {"s2": ["128-255"]}, +// "homes": {"": "s2"} +// } +// +// self is this instance. A bucket that no range names belongs to default. +// homes moves single homes and wins over buckets. Every instance carries the +// same file apart from self. +type File struct { + Self string `json:"self"` + Shards map[string]string `json:"shards"` + Default string `json:"default"` + Buckets map[string][]string `json:"buckets"` + Homes map[string]string `json:"homes"` +} + +// Load reads a directory file. Every host must be cloudwire.DefaultHost or +// one label under it, as clients check before they follow. +func Load(path string) (*Directory, error) { + raw, err := os.ReadFile(path) + if err != nil { + return nil, err + } + var f File + dec := json.NewDecoder(strings.NewReader(string(raw))) + dec.DisallowUnknownFields() + if err := dec.Decode(&f); err != nil { + return nil, fmt.Errorf("shard: %s: %w", path, err) + } + d, err := f.Directory() + if err != nil { + return nil, fmt.Errorf("shard: %s: %w", path, err) + } + return d, nil +} + +// Directory checks the file and builds the directory from it. Clients +// follow a host only if it is cloudwire.DefaultHost or one label under it, +// so a directory that names any other is refused. +func (f File) Directory() (*Directory, error) { + if _, ok := f.Shards[f.Default]; !ok { + return nil, fmt.Errorf("default shard %q has no host", f.Default) + } + for name, host := range f.Shards { + if name == "" || !cloudwire.ShardHostOK(cloudwire.DefaultHost, host) { + return nil, fmt.Errorf("shard %q at %q: a host must be %s or one label under it", name, host, cloudwire.DefaultHost) + } + } + if _, ok := f.Shards[f.Self]; !ok { + return nil, fmt.Errorf("self %q is not a shard", f.Self) + } + d := &Directory{self: f.Self, hosts: f.Shards, homes: map[string]string{}} + for i := range d.buckets { + d.buckets[i] = f.Default + } + set := map[int]string{} + for name, ranges := range f.Buckets { + if _, ok := f.Shards[name]; !ok { + return nil, fmt.Errorf("buckets for %q, which is not a shard", name) + } + for _, r := range ranges { + lo, hi, err := bucketRange(r) + if err != nil { + return nil, err + } + for b := lo; b <= hi; b++ { + if other, ok := set[b]; ok && other != name { + return nil, fmt.Errorf("bucket %d is both %q and %q", b, other, name) + } + set[b], d.buckets[b] = name, name + } + } + } + for home, name := range f.Homes { + if !cloudwire.ValidHome(home) { + return nil, fmt.Errorf("%q is not a home id", home) + } + if _, ok := f.Shards[name]; !ok { + return nil, fmt.Errorf("home on %q, which is not a shard", name) + } + d.homes[home] = name + } + return d, nil +} + +// bucketRange reads "7" or "128-255". +func bucketRange(r string) (int, int, error) { + a, b, isRange := strings.Cut(r, "-") + lo, err := strconv.Atoi(strings.TrimSpace(a)) + hi := lo + if err == nil && isRange { + hi, err = strconv.Atoi(strings.TrimSpace(b)) + } + if err != nil || lo < 0 || hi >= Buckets || lo > hi { + return 0, 0, fmt.Errorf("bucket range %q: want n or lo-hi within 0-%d", r, Buckets-1) + } + return lo, hi, nil +} + +// Self is this instance's name. +func (d *Directory) Self() string { return d.self } + +// Host is this instance's host. +func (d *Directory) Host() string { return d.hosts[d.self] } + +// Shards is how many shards the directory names. +func (d *Directory) Shards() int { return len(d.hosts) } + +// Owner is the host of the shard that holds home, and whether that is this +// instance. +func (d *Directory) Owner(home string) (host string, ours bool) { + name := d.Of(home) + return d.hosts[name], name == d.self +} + +// Of is the name of the shard that holds home. +func (d *Directory) Of(home string) string { + if name, moved := d.homes[home]; moved { + return name + } + return d.buckets[Bucket(home)] +} + +// Ours reports whether this instance holds home. +func (d *Directory) Ours(home string) bool { + _, ours := d.Owner(home) + return ours +} diff --git a/internal/shard/shard_test.go b/internal/shard/shard_test.go new file mode 100644 index 0000000..9786b53 --- /dev/null +++ b/internal/shard/shard_test.go @@ -0,0 +1,127 @@ +package shard + +import ( + "os" + "path/filepath" + "strconv" + "strings" + "testing" +) + +const homeA = "fjzyr67buzpyncqmjliwgezvde" + +func TestOneShardHoldsEveryHome(t *testing.T) { + d := Single("cloud.ftw.energy") + for _, home := range []string{homeA, "aaaaaaaaaaaaaaaaaaaaaaaaaa", "zzzzzzzzzzzzzzzzzzzzzzzzzz"} { + if host, ours := d.Owner(home); !ours || host != "cloud.ftw.energy" { + t.Fatalf("Owner(%s) = %s, %v", home, host, ours) + } + } + if d.Shards() != 1 || d.Host() != "cloud.ftw.energy" { + t.Fatal(d.Shards(), d.Host()) + } +} + +func TestBucketsAndMovedHomesNameTheirShard(t *testing.T) { + b := Bucket(homeA) + f := File{Self: "s1", Default: "s1", + Shards: map[string]string{"s1": "cloud.ftw.energy", "s2": "s2.cloud.ftw.energy"}, + Buckets: map[string][]string{"s2": {itoa(b)}}} + d, err := f.Directory() + if err != nil { + t.Fatal(err) + } + if host, ours := d.Owner(homeA); ours || host != "s2.cloud.ftw.energy" { + t.Fatalf("a home in s2's bucket: %s, %v", host, ours) + } + // Moved back on its own, it is s1's again. + f.Homes = map[string]string{homeA: "s1"} + if d, err = f.Directory(); err != nil { + t.Fatal(err) + } + if !d.Ours(homeA) { + t.Fatal("a moved home is not where the directory says") + } + // The same file on s2 is the mirror image. + f.Self, f.Homes = "s2", nil + if d, err = f.Directory(); err != nil { + t.Fatal(err) + } + if !d.Ours(homeA) { + t.Fatal("s2 does not hold its own bucket") + } +} + +// Buckets spread homes evenly enough that moving half of them moves about +// half the homes. +func TestBucketsSpreadHomes(t *testing.T) { + counts := make([]int, Buckets) + alphabet := "abcdefghijklmnopqrstuvwxyz234567" + for i := range 64 * Buckets { + var b strings.Builder + for j := range 26 { + b.WriteByte(alphabet[(i*7+j*13+i/32*j)%32]) + } + counts[Bucket(b.String())]++ + } + upper := 0 + for i := Buckets / 2; i < Buckets; i++ { + upper += counts[i] + } + if share := float64(upper) / float64(64*Buckets); share < 0.45 || share > 0.55 { + t.Fatalf("the upper half of the buckets holds %.2f of the homes", share) + } +} + +func TestADirectoryThatCouldSendAClientAwayIsRefused(t *testing.T) { + good := func() File { + return File{Self: "s1", Default: "s1", + Shards: map[string]string{"s1": "cloud.ftw.energy", "s2": "s2.cloud.ftw.energy"}} + } + for name, change := range map[string]func(*File){ + "a host off the domain": func(f *File) { f.Shards["s2"] = "evil.example" }, + "a whole other base": func(f *File) { + f.Shards = map[string]string{"s1": "cloud.example", "s2": "s2.cloud.example"} + }, + "two labels deep": func(f *File) { f.Shards["s2"] = "a.b.cloud.ftw.energy" }, + "no default": func(f *File) { f.Default = "s9" }, + "self unknown": func(f *File) { f.Self = "s9" }, + "buckets for nobody": func(f *File) { f.Buckets = map[string][]string{"s9": {"1"}} }, + "bucket out of range": func(f *File) { f.Buckets = map[string][]string{"s2": {"200-256"}} }, + "bucket twice": func(f *File) { + f.Shards["s3"] = "s3.cloud.ftw.energy" + f.Buckets = map[string][]string{"s2": {"0-10"}, "s3": {"10"}} + }, + "a home id that is not one": func(f *File) { f.Homes = map[string]string{"x": "s2"} }, + "a home for nobody": func(f *File) { f.Homes = map[string]string{homeA: "s9"} }, + } { + f := good() + change(&f) + if _, err := f.Directory(); err == nil { + t.Errorf("%s: accepted", name) + } + } + if _, err := good().Directory(); err != nil { + t.Fatal(err) + } +} + +func TestLoadReadsTheFileAndRefusesUnknownFields(t *testing.T) { + dir := t.TempDir() + ok := filepath.Join(dir, "ok.json") + _ = os.WriteFile(ok, []byte(`{"self":"s2","default":"s1","shards":{"s1":"cloud.ftw.energy","s2":"s2.cloud.ftw.energy"},"buckets":{"s2":["0-255"]}}`), 0o600) + d, err := Load(ok) + if err != nil { + t.Fatal(err) + } + if d.Self() != "s2" || d.Host() != "s2.cloud.ftw.energy" || !d.Ours(homeA) { + t.Fatalf("%+v", d) + } + bad := filepath.Join(dir, "bad.json") + _ = os.WriteFile(bad, []byte(`{"self":"s1","default":"s1","shards":{"s1":"cloud.ftw.energy"},"bukets":{}}`), 0o600) + if _, err := Load(bad); err == nil { + t.Fatal("a misspelt field was accepted") + } +} + +func itoa(n int) string { return strconv.Itoa(n) } diff --git a/internal/store/session.go b/internal/store/session.go index 54b869f..4a7c1ee 100644 --- a/internal/store/session.go +++ b/internal/store/session.go @@ -2,10 +2,45 @@ package store import ( "bytes" + "time" + "github.com/srcfl/ftw-cloud/internal/metrics" "github.com/srcfl/ftw/go/protocol/cloudwire" ) +// What the store drops, summed over all homes. +var ( + dropSlowPhone = metrics.Drop("phone_too_slow") + dropPhoneTun = metrics.Drop("phone_tun_queue_full") +) + +// Out is one envelope for a phone and when its box frame arrived, so the +// time it waited here can be measured. At is on the monotonic clock since +// the process started, eight bytes where a time.Time is 24: each phone's +// queues hold hundreds. +type Out struct { + Env []byte + At time.Duration +} + +// TunOut is one tun for a phone and when it arrived. +type TunOut struct { + cloudwire.AppTun + At time.Duration +} + +// epoch starts the clock Out and TunOut are stamped with. +var epoch = time.Now() + +// stamp is now on that clock. +func stamp() time.Duration { return time.Since(epoch) } + +// Waited is how long the envelope has waited since it arrived. +func (o Out) Waited() time.Duration { return stamp() - o.At } + +// Waited is how long the tun has waited since it arrived. +func (t TunOut) Waited() time.Duration { return stamp() - t.At } + // Limits on the phones reading one home. const ( // MaxSessionsPerHome bounds the phones one home can hold open at once. @@ -34,9 +69,9 @@ const ( // them. The store ends it when the device's access changes. type Session struct { x *Handle - c chan []byte + c chan Out // tun carries the box's side of the phone's own session. - tun chan cloudwire.AppTun + tun chan TunOut // sid is the box session the phone runs now, when hasSid. sid uint32 hasSid bool @@ -78,17 +113,17 @@ func (x *Handle) Open() (Snapshot, *Session, error) { if len(x.h.sessions) >= MaxSessionsPerHome { return Snapshot{}, nil, ErrBusy } - sess := &Session{x: x, c: make(chan []byte, SessionQueue), tun: make(chan cloudwire.AppTun, TunQueue), + sess := &Session{x: x, c: make(chan Out, SessionQueue), tun: make(chan TunOut, TunQueue), done: make(chan struct{})} x.h.sessions[sess] = struct{}{} return x.snapshotLocked(), sess, nil } // C carries the envelopes to forward. -func (s *Session) C() <-chan []byte { return s.c } +func (s *Session) C() <-chan Out { return s.c } // Tun carries the box's tun messages for this phone. -func (s *Session) Tun() <-chan cloudwire.AppTun { return s.tun } +func (s *Session) Tun() <-chan TunOut { return s.tun } // SetSid records the box session the phone runs now, so the end of the // box's uplink reaches it. @@ -107,8 +142,9 @@ func (s *Session) Ended(sid uint32) { return } select { - case s.tun <- cloudwire.AppTun{Sid: sid}: + case s.tun <- TunOut{AppTun: cloudwire.AppTun{Sid: sid}, At: stamp()}: default: + dropPhoneTun.Inc() } } @@ -125,8 +161,9 @@ func (x *Handle) Tun(t cloudwire.Tun) bool { continue } select { - case sess.tun <- cloudwire.AppTun{Sid: t.Sid, D: t.D}: + case sess.tun <- TunOut{AppTun: cloudwire.AppTun{Sid: t.Sid, D: t.D}, At: stamp()}: default: + dropPhoneTun.Inc() } return true } @@ -141,8 +178,9 @@ func (h *home) tunGoneLocked() { continue } select { - case sess.tun <- cloudwire.AppTun{Sid: sess.sid}: + case sess.tun <- TunOut{AppTun: cloudwire.AppTun{Sid: sess.sid}, At: stamp()}: default: + dropPhoneTun.Inc() } sess.hasSid = false } @@ -167,13 +205,14 @@ func (s *Session) Close() { // deliver queues one envelope without ever blocking the box. The caller holds // the home's lock. -func (s *Session) deliver(env []byte) { +func (s *Session) deliver(env []byte, at time.Duration) { if s.ended { return } select { - case s.c <- env: + case s.c <- Out{Env: env, At: at}: default: + dropSlowPhone.Inc() s.endLocked(closeSlow) } } diff --git a/internal/store/store.go b/internal/store/store.go index 49cd462..80f8f19 100644 --- a/internal/store/store.go +++ b/internal/store/store.go @@ -78,6 +78,13 @@ func New(now func() time.Time) *Store { return &Store{homes: map[string]*home{}, now: now} } +// Homes is how many homes the store holds. +func (s *Store) Homes() int { + s.mu.Lock() + defer s.mu.Unlock() + return len(s.homes) +} + // UseSuspensions sets where owners' suspensions are kept. Call it before // serving. func (s *Store) UseSuspensions(suspended func(home, deviceID string, epoch uint64) bool) { @@ -314,9 +321,10 @@ func (x *Handle) Put(t string, env []byte, seq uint64, carriesTable bool) error x.h.full = &held } x.h.lastSeen = x.s.now() + at := stamp() for sess := range x.h.sessions { if sess.x.mayRead(t) { - sess.deliver(env) + sess.deliver(env, at) } } return nil diff --git a/internal/store/store_test.go b/internal/store/store_test.go index 20055da..afdfdda 100644 --- a/internal/store/store_test.go +++ b/internal/store/store_test.go @@ -185,15 +185,15 @@ func TestASessionMissesNothingAfterItsSnapshot(t *testing.T) { _ = box.Put(cloudwire.MsgLive, []byte("live-3"), 9, false) select { case got := <-sess.C(): - if string(got) != "live-3" { - t.Fatalf("the session got %q", got) + if string(got.Env) != "live-3" || got.At <= 0 { + t.Fatalf("the session got %q at %v", got.Env, got.At) } default: t.Fatal("nothing reached the session") } select { case got := <-sess.C(): - t.Fatalf("the session also got %q", got) + t.Fatalf("the session also got %q", got.Env) default: } } diff --git a/internal/token/token.go b/internal/token/token.go index a27a684..e066639 100644 --- a/internal/token/token.go +++ b/internal/token/token.go @@ -2,8 +2,12 @@ // GET /v1/now with it. docs/protocol-cloud.md in srcfl/ftw, "Extension // token", is the wire format. // -// A token is 32 random bytes, base64url without padding. The registry keeps -// its SHA-256 and the roster entry it is bound to, never the token. A read +// A token is the home id, a dot, and 32 random bytes in base64url without +// padding. The home id lets any instance of the service tell which shard +// holds the token and send the reader there (421 with Ftw-Shard). The +// registry keeps the SHA-256 of the random bytes and the roster entry they +// are bound to, never the token, and a token whose home is not its row's is +// refused. A read // reaches the home only through store.For with that roster entry, so a token // stops working the moment the roster drops the device, moves its epoch or // runs out, an owner suspends the device, or the grant ends. It reads the @@ -23,7 +27,9 @@ import ( "time" "github.com/fxamacker/cbor/v2" + "github.com/srcfl/ftw-cloud/internal/metrics" "github.com/srcfl/ftw-cloud/internal/registry" + "github.com/srcfl/ftw-cloud/internal/shard" "github.com/srcfl/ftw-cloud/internal/store" "github.com/srcfl/ftw/go/protocol/cloudwire" ) @@ -50,6 +56,29 @@ type Service struct { reg *registry.Registry log *slog.Logger now func() time.Time + + // Shards says which homes this instance holds. Nil holds every home. + // Set before serving. + Shards *shard.Directory +} + +var wrongShard = metrics.WrongShard("now") + +// errWrongShard is a token another shard holds; host is that shard's. +type errWrongShard struct{ host string } + +func (e errWrongShard) Error() string { return "token: another shard holds this home" } + +// Split reads a token as its home id and its secret. A token from before +// shards has no home id. ok is false when the token cannot be one. +func Split(tok string) (home, secret string, ok bool) { + home, secret, dotted := strings.Cut(tok, ".") + if !dotted { + home, secret = "", tok + } else if !cloudwire.ValidHome(home) { + return "", "", false + } + return home, secret, secret != "" } // New builds the service. @@ -82,7 +111,7 @@ func (s *Service) Issue(home string, dev cloudwire.Device) (cloudwire.Token, err } return cloudwire.Token{}, store.ErrDenied } - return cloudwire.Token{Token: base64.RawURLEncoding.EncodeToString(raw), ExpiresInS: int64(Life / time.Second)}, nil + return cloudwire.Token{Token: home + "." + base64.RawURLEncoding.EncodeToString(raw), ExpiresInS: int64(Life / time.Second)}, nil } // Drop forgets a device's token, as when an owner suspends it. @@ -122,7 +151,13 @@ func (s *Service) ServeHTTP(w http.ResponseWriter, r *http.Request) { return } body, err := s.read(r.Header.Get("Authorization")) + var moved errWrongShard switch { + case errors.As(err, &moved): + wrongShard.Inc() + w.Header().Set(cloudwire.ShardHeader, moved.host) + w.WriteHeader(cloudwire.StatusWrongShard) + return case errors.Is(err, store.ErrDenied): w.Header().Set("WWW-Authenticate", "Bearer") w.WriteHeader(http.StatusUnauthorized) @@ -142,7 +177,16 @@ func (s *Service) read(auth string) ([]byte, error) { if !ok || !strings.EqualFold(scheme, "Bearer") { return nil, store.ErrDenied } - raw, err := base64.RawURLEncoding.DecodeString(strings.TrimSpace(value)) + home, secret, ok := Split(strings.TrimSpace(value)) + if !ok { + return nil, store.ErrDenied + } + if home != "" && s.Shards != nil { + if host, ours := s.Shards.Owner(home); !ours { + return nil, errWrongShard{host} + } + } + raw, err := base64.RawURLEncoding.DecodeString(secret) if err != nil || len(raw) != tokenBytes { return nil, store.ErrDenied } @@ -151,7 +195,7 @@ func (s *Service) read(auth string) ([]byte, error) { if err != nil { return nil, err } - if !ok { + if !ok || (home != "" && row.Home != home) { return nil, store.ErrDenied } x, err := s.store.For(store.Principal{Kind: store.Token, Home: row.Home, DeviceID: row.DeviceID, Epoch: row.Epoch}) diff --git a/internal/token/token_test.go b/internal/token/token_test.go index 1b4bb12..0e113ba 100644 --- a/internal/token/token_test.go +++ b/internal/token/token_test.go @@ -17,6 +17,7 @@ import ( "time" "github.com/srcfl/ftw-cloud/internal/registry" + "github.com/srcfl/ftw-cloud/internal/shard" "github.com/srcfl/ftw-cloud/internal/store" "github.com/srcfl/ftw/go/protocol" "github.com/srcfl/ftw/go/protocol/cloudwire" @@ -137,7 +138,7 @@ func (h *harness) issue(id string, epoch uint64) string { if err != nil { h.t.Fatal(err) } - if tok.ExpiresInS != 7*24*3600 || len(tok.Token) != 43 { + if home, secret, ok := Split(tok.Token); tok.ExpiresInS != 7*24*3600 || !ok || home != h.home || len(secret) != 43 { h.t.Fatalf("token %q expires in %d s", tok.Token, tok.ExpiresInS) } return tok.Token @@ -330,7 +331,8 @@ func TestOnlyGETOverTLS13(t *testing.T) { func hashOf(t *testing.T, tok string) []byte { t.Helper() - raw, err := base64.RawURLEncoding.DecodeString(tok) + _, secret, _ := Split(tok) + raw, err := base64.RawURLEncoding.DecodeString(secret) if err != nil { t.Fatal(err) } @@ -370,3 +372,41 @@ func TestAPruneKeepsATokenOfTheNewEpoch(t *testing.T) { t.Fatalf("the new epoch's token read %d", code) } } + +// A token carries its home, so an instance that does not hold the home +// names the shard that does, and one whose home was changed is refused. +func TestATokenOfAnotherShardIsSentThere(t *testing.T) { + h := newHarness(t) + tok := h.issue("owner", 1) + get := func(tok string) *httptest.ResponseRecorder { + w := httptest.NewRecorder() + r := httptest.NewRequest(http.MethodGet, "/v1/now", nil) + r.TLS = &tls.ConnectionState{Version: tls.VersionTLS13} + r.Header.Set("Authorization", "Bearer "+tok) + h.svc.ServeHTTP(w, r) + return w + } + if w := get(tok); w.Code != http.StatusOK { + t.Fatalf("on its own shard: %d", w.Code) + } + d, err := shard.File{Self: "s1", Default: "s1", + Shards: map[string]string{"s1": "cloud.ftw.energy", "s2": "s2.cloud.ftw.energy"}, + Homes: map[string]string{h.home: "s2"}}.Directory() + if err != nil { + t.Fatal(err) + } + h.svc.Shards = d + w := get(tok) + if w.Code != cloudwire.StatusWrongShard || w.Header().Get(cloudwire.ShardHeader) != "s2.cloud.ftw.energy" || w.Body.Len() != 0 { + t.Fatalf("on another shard: %d %q %q", w.Code, w.Header().Get(cloudwire.ShardHeader), w.Body.String()) + } + h.svc.Shards = nil + _, secret, _ := Split(tok) + if w := get("aaaaaaaaaaaaaaaaaaaaaaaaaa." + secret); w.Code != http.StatusUnauthorized { + t.Fatalf("a token under another home: %d", w.Code) + } + // A token from before shards, the secret alone, still reads. + if w := get(secret); w.Code != http.StatusOK { + t.Fatalf("a token without its home: %d", w.Code) + } +} diff --git a/internal/uplink/restore_bench_test.go b/internal/uplink/restore_bench_test.go new file mode 100644 index 0000000..4d5bbd8 --- /dev/null +++ b/internal/uplink/restore_bench_test.go @@ -0,0 +1,53 @@ +package uplink + +import ( + "crypto/ecdsa" + "crypto/elliptic" + "crypto/rand" + "io" + "log/slog" + "path/filepath" + "testing" + "time" + + "github.com/srcfl/ftw-cloud/internal/registry" + "github.com/srcfl/ftw-cloud/internal/store" + "github.com/srcfl/ftw/go/protocol/cloudwire" +) + +// BenchmarkRestore10k is a deploy's start with 10,000 homes in the +// registry: every signed roster read back and checked before the service +// listens. go test -run XXX -bench Restore10k -benchtime 3x ./internal/uplink +func BenchmarkRestore10k(b *testing.B) { + reg, err := registry.Open(filepath.Join(b.TempDir(), "registry.db")) + if err != nil { + b.Fatal(err) + } + defer reg.Close() + now := time.Now() + for range 10_000 { + key, _ := ecdsa.GenerateKey(elliptic.P256(), rand.Reader) + pk, _ := cloudwire.PublicKeyBytesOf(&key.PublicKey) + home := cloudwire.HomeID(pk) + bx := &box{key: key, pk: pk, home: home, boot: []byte{1, 2, 3, 4, 5, 6, 7, 8}} + env, err := cloudwire.Seal(key, home, cloudwire.MsgRoster, bx.roster()) + if err != nil { + b.Fatal(err) + } + raw, _ := env.Encode() + if err := reg.Claim(home, pk, now); err != nil { + b.Fatal(err) + } + if err := reg.SetRoster(home, 1, nil, raw, now); err != nil { + b.Fatal(err) + } + } + log := slog.New(slog.NewTextHandler(io.Discard, nil)) + b.ResetTimer() + for range b.N { + up := New(store.New(nil), reg, nil, log) + if n, err := up.Restore(); err != nil || n != 10_000 { + b.Fatalf("restored %d, %v", n, err) + } + } +} diff --git a/internal/uplink/scale_test.go b/internal/uplink/scale_test.go new file mode 100644 index 0000000..749b3c5 --- /dev/null +++ b/internal/uplink/scale_test.go @@ -0,0 +1,286 @@ +package uplink + +import ( + "crypto/tls" + "crypto/x509" + "errors" + "sync/atomic" + "testing" + "time" + + "github.com/gorilla/websocket" + "github.com/srcfl/ftw-cloud/internal/shard" + "github.com/srcfl/ftw-cloud/internal/wsclose" + "github.com/srcfl/ftw/go/protocol" + "github.com/srcfl/ftw/go/protocol/cloudwire" +) + +func closeCode(err error) (int, string) { + var ce *websocket.CloseError + if errors.As(err, &ce) { + return ce.Code, ce.Text + } + return 0, "" +} + +// twoShards puts home on s2 and makes this instance s1. +func twoShards(t *testing.T, home string) *shard.Directory { + t.Helper() + d, err := shard.File{Self: "s1", Default: "s1", + Shards: map[string]string{"s1": "cloud.ftw.energy", "s2": "s2.cloud.ftw.energy"}, + Homes: map[string]string{home: "s2"}}.Directory() + if err != nil { + t.Fatal(err) + } + return d +} + +// A box whose home another shard holds hears that shard's host after +// hello, and leaves nothing in this instance's registry. +func TestABoxOfAnotherShardIsSentThere(t *testing.T) { + s := newService(t) + b := newBox(t) + s.up.Shards = twoShards(t, b.home) + before := wrongShard.Load() + _, err := b.connect(s, nil) + if code, host := closeCode(err); code != cloudwire.CloseWrongShard || host != "s2.cloud.ftw.energy" { + t.Fatalf("close %d %q (%v)", code, host, err) + } + if _, ok, _ := s.reg.Get(b.home); ok { + t.Fatal("a home of another shard was claimed here") + } + if wrongShard.Load() != before+1 { + t.Fatal("not counted") + } + // A home of this shard connects as before. + other := newBox(t) + if _, err := other.connect(s, nil); err != nil { + t.Fatal(err) + } +} + +// A box that redials faster than its home's connect limit is turned away +// before it touches the registry; its tunnel limits carry over to the next +// connection. +func TestABoxThatRedialsFastIsTurnedAway(t *testing.T) { + s := newService(t) + b := newBox(t) + for range connectBurst { + if _, err := b.connect(s, nil); err != nil { + t.Fatal(err) + } + _ = b.conn.Close() + } + before := dropConnect.Load() + _, err := b.connect(s, nil) + if code, _ := closeCode(err); code != cloudwire.CloseBusy { + t.Fatalf("close %d (%v)", code, err) + } + if dropConnect.Load() != before+1 { + t.Fatal("not counted") + } +} + +func TestTunLimitsOutliveTheConnection(t *testing.T) { + s := newService(t) + b := tunConnect(t, s) + wait(t, "the box is the home's", func() bool { return s.up.Tun(b.home, cloudwire.Tun{Dev: "owner", Sid: 1}) }) + lim := s.up.limitsFor(b.home) + s.up.release(lim) + lim.take(func() bool { + lim.downMsgs.tokens = -1e6 // empty for longer than the test runs + return true + }) + _ = b.conn.Close() + wait(t, "the box is gone", func() bool { return s.up.Boxes() == 0 }) + tunConnectAs(t, s, b) + before := dropTunDown.Load() + wait(t, "the box is back", func() bool { return s.up.Boxes() == 1 }) + s.up.Tun(b.home, cloudwire.Tun{Dev: "owner", Sid: 1, D: []byte{1}}) + if dropTunDown.Load() != before+1 { + t.Fatal("a reconnect refilled the home's tunnel") + } +} + +// Drain closes every box with CloseRestart and the spread, and their +// absence starts no box.unreachable. +func TestDrainSendsEveryBoxToComeBack(t *testing.T) { + s := newService(t) + gone := 0 + s.up.OnGone = func(string, string, uint64) { gone++ } + b := newBox(t) + if _, err := b.connect(s, nil); err != nil { + t.Fatal(err) + } + b.send(cloudwire.MsgRoster, b.roster(protocol.ScopeLiveRead)) + wait(t, "the box is the home's", func() bool { return s.up.Boxes() == 1 }) + s.up.Drain("3000") + _, _, err := b.conn.ReadMessage() + if code, reason := closeCode(err); code != cloudwire.CloseRestart || reason != "3000" { + t.Fatalf("close %d %q (%v)", code, reason, err) + } + wait(t, "the box is gone", func() bool { return s.up.Boxes() == 0 }) + if gone != 0 { + t.Fatal("a drained box started box.unreachable") + } + // A box that dials while the service drains hears it before the + // challenge. + pool := x509.NewCertPool() + pool.AddCert(s.srv.Certificate()) + d := websocket.Dialer{TLSClientConfig: &tls.Config{RootCAs: pool, MinVersion: tls.VersionTLS13}} + conn, _, err := d.Dial("wss://"+s.srv.Listener.Addr().String()+"/v1/box", nil) + if err != nil { + t.Fatal(err) + } + defer conn.Close() + _, _, err = conn.ReadMessage() + if code, reason := closeCode(err); code != cloudwire.CloseRestart || reason != "3000" { + t.Fatalf("close %d %q (%v)", code, reason, err) + } +} + +// After a restart, an instance restores only the homes it holds. +func TestRestoreTakesOnlyThisShardsHomes(t *testing.T) { + s := newService(t) + mine, theirs := newBox(t), newBox(t) + for _, b := range []*box{mine, theirs} { + if _, err := b.connect(s, nil); err != nil { + t.Fatal(err) + } + b.send(cloudwire.MsgRoster, b.roster(protocol.ScopeLiveRead)) + home := b.home + wait(t, "the roster is stored", func() bool { + h, ok, _ := s.reg.Get(home) + return ok && h.Roster != nil + }) + } + up := New(s.store, s.reg, s.key, nil) + up.Shards = twoShards(t, theirs.home) + n, err := up.Restore() + if err != nil || n != 1 { + t.Fatalf("restored %d, %v", n, err) + } +} + +// stall makes home's box hang on every write while holding its write lock, +// as a socket the box stopped reading does once the kernel's buffers are +// full, until the test ends. +func stall(t *testing.T, s *service, home string) { + t.Helper() + release := make(chan struct{}) + t.Cleanup(func() { close(release) }) + s.up.mu.Lock() + defer s.up.mu.Unlock() + c := s.up.conns[home] + if c == nil { + t.Fatal("no box to stall") + } + c.write = func([]byte) error { + c.writeMu.Lock() + defer c.writeMu.Unlock() + <-release + return errors.New("stalled") + } +} + +// A box that stops reading holds up only its own home: a phone of another +// home reaches its box at once while writes to the stuck one hang. +func TestAStuckBoxDoesNotHoldUpAnotherHome(t *testing.T) { + s := newService(t) + stuck := tunConnect(t, s) + live := tunConnect(t, s) + wait(t, "both boxes are their homes'", func() bool { return s.up.Boxes() == 2 }) + stall(t, s, stuck.home) + got := make(chan struct{}, 64) + go func() { + for { + if _, _, err := live.conn.ReadMessage(); err != nil { + return + } + got <- struct{}{} + } + }() + // A few phones of the stuck home, each hanging in its write. + var blocked atomic.Int64 + for range 4 { + go func() { + blocked.Add(1) + s.up.Tun(stuck.home, cloudwire.Tun{Dev: "owner", Sid: 1, D: []byte{1}}) + blocked.Add(-1) + }() + } + wait(t, "the stuck home's phones hang", func() bool { return blocked.Load() == 4 }) + for i := range 10 { + start := time.Now() + if !s.up.Tun(live.home, cloudwire.Tun{Dev: "owner", Sid: 2, D: []byte{byte(i)}}) { + t.Fatal("the live box is gone") + } + select { + case <-got: + case <-time.After(time.Second): + t.Fatal("a tun for another home waited behind the stuck box") + } + if d := time.Since(start); d > 200*time.Millisecond { + t.Fatalf("a tun for another home took %s", d) + } + } + if blocked.Load() != 4 { + t.Fatal("the stuck home's writes did not hang; the test proves nothing") + } +} + +// One box whose writes hang does not hold up the drain of the others: the +// close does not wait for the write lock. +func TestAStuckBoxDoesNotHoldUpTheDrain(t *testing.T) { + s := newService(t) + stuck := tunConnect(t, s) + live := newBox(t) + if _, err := live.connect(s, nil); err != nil { + t.Fatal(err) + } + wait(t, "both boxes are their homes'", func() bool { return s.up.Boxes() == 2 }) + stall(t, s, stuck.home) + go s.up.Tun(stuck.home, cloudwire.Tun{Dev: "owner", Sid: 1, D: []byte{1}}) + time.Sleep(50 * time.Millisecond) + start := time.Now() + s.up.Drain("1000") + _ = live.conn.SetReadDeadline(time.Now().Add(time.Second)) + _, _, err := live.conn.ReadMessage() + if code, _ := closeCode(err); code != cloudwire.CloseRestart { + t.Fatalf("the live box heard %v", err) + } + if d := time.Since(start); d > 500*time.Millisecond { + t.Fatalf("the live box heard 4503 after %s", d) + } + _, _, err = stuck.conn.ReadMessage() + if code, _ := closeCode(err); code != cloudwire.CloseRestart { + t.Fatalf("the stuck box heard %v", err) + } + if n := s.up.WaitClosed(drainWait + wsclose.Wait); n != 0 { + t.Fatalf("%d sockets still open after the drain's wait", n) + } +} + +// A box still in its handshake when the drain starts hears 4503 too. +func TestTheDrainReachesABoxInItsHandshake(t *testing.T) { + s := newService(t) + pool := x509.NewCertPool() + pool.AddCert(s.srv.Certificate()) + d := websocket.Dialer{TLSClientConfig: &tls.Config{RootCAs: pool, MinVersion: tls.VersionTLS13}} + conn, _, err := d.Dial("wss://"+s.srv.Listener.Addr().String()+"/v1/box", nil) + if err != nil { + t.Fatal(err) + } + defer conn.Close() + // It reads the challenge and never says hello. + if _, _, err := conn.ReadMessage(); err != nil { + t.Fatal(err) + } + wait(t, "the socket is tracked", func() bool { return s.up.Sockets() == 1 }) + s.up.Drain("2000") + _ = conn.SetReadDeadline(time.Now().Add(time.Second)) + _, _, err = conn.ReadMessage() + if code, reason := closeCode(err); code != cloudwire.CloseRestart || reason != "2000" { + t.Fatalf("a box in its handshake heard %v", err) + } +} diff --git a/internal/uplink/tunnel_test.go b/internal/uplink/tunnel_test.go index 0a8316e..8476209 100644 --- a/internal/uplink/tunnel_test.go +++ b/internal/uplink/tunnel_test.go @@ -37,7 +37,8 @@ func TestNothingReachesABoxBeforeHelloOK(t *testing.T) { } } }() - for range 20 { + // As many connections as the home's connect limit lets through at once. + for range connectBurst { // connect fails the test on anything but hello_ok after hello. if _, err := b.connect(s, nil); err != nil { t.Fatal(err) @@ -129,7 +130,12 @@ func TestARosterGrantHasThreeShapes(t *testing.T) { // tunnel, with the readable copy off. func tunConnect(t *testing.T, s *service) *box { t.Helper() - b := newBox(t) + return tunConnectAs(t, s, newBox(t)) +} + +// tunConnectAs connects b again, as the same home. +func tunConnectAs(t *testing.T, s *service, b *box) *box { + t.Helper() pool := x509.NewCertPool() pool.AddCert(s.srv.Certificate()) d := websocket.Dialer{TLSClientConfig: &tls.Config{RootCAs: pool, MinVersion: tls.VersionTLS13}} @@ -192,11 +198,21 @@ func TestPastTheTunLimitsTheServiceDrops(t *testing.T) { s := newService(t) b := tunConnect(t, s) wait(t, "the box is the home's", func() bool { return s.up.Tun(b.home, cloudwire.Tun{Dev: "owner", Sid: 1}) }) + // The box reads what it gets, as a live one does; one that stops + // reading has its socket closed after the write deadline. + go func() { + for { + if _, _, err := b.conn.ReadMessage(); err != nil { + return + } + } + }() big := make([]byte, cloudwire.TunDataMax) + before := dropTunDown.Load() for range 300 { s.up.Tun(b.home, cloudwire.Tun{Dev: "owner", Sid: 1, D: big}) } - if s.up.TunDropped.Load() == 0 { + if dropTunDown.Load() == before { t.Fatal("nothing was dropped past 4 MiB in a burst") } if !s.up.Tun(b.home, cloudwire.Tun{Dev: "owner", Sid: 1}) { diff --git a/internal/uplink/uplink.go b/internal/uplink/uplink.go index c82f913..94cd332 100644 --- a/internal/uplink/uplink.go +++ b/internal/uplink/uplink.go @@ -19,6 +19,7 @@ import ( "fmt" "log/slog" "net/http" + "runtime" "slices" "sync" "sync/atomic" @@ -26,8 +27,11 @@ import ( "github.com/fxamacker/cbor/v2" "github.com/gorilla/websocket" + "github.com/srcfl/ftw-cloud/internal/metrics" "github.com/srcfl/ftw-cloud/internal/registry" + "github.com/srcfl/ftw-cloud/internal/shard" "github.com/srcfl/ftw-cloud/internal/store" + "github.com/srcfl/ftw-cloud/internal/wsclose" "github.com/srcfl/ftw/go/protocol" "github.com/srcfl/ftw/go/protocol/cloudwire" ) @@ -61,6 +65,33 @@ const ( // maxPendingTTL how long one may last. maxPending = 4 maxPendingTTL = 3600 + // A box redials after a drop, a deploy or a redirect, a few times an + // hour. Past connectBurst at one per connectEvery, a home's box is + // turned away before it touches the registry; its backoff grows. + connectBurst = 10 + connectEvery = 6 * time.Second + // limitsIdle is how long a home's limits outlive its last connection, + // longer than any of its buckets takes to fill again. + limitsIdle = 2 * time.Minute + // drainWait bounds Drain's wait for the boxes' answers to its close. + drainWait = 2 * time.Second +) + +// What the uplink counts, summed over all homes. +var ( + boxSockets = metrics.Sockets("box") + boxHandshake = metrics.Handshake("box") + tunDown = metrics.Forward("tun_down") + wrongShard = metrics.WrongShard("box") + tunFramesUp = metrics.Default.Counter("ftwcloud_tun_frames_total", "tun messages forwarded, up from boxes and down to them.", "dir", "up") + tunFramesDown = metrics.Default.Counter("ftwcloud_tun_frames_total", "tun messages forwarded, up from boxes and down to them.", "dir", "down") + tunBytesUp = metrics.Default.Counter("ftwcloud_tun_bytes_total", "Bytes of tun d forwarded, up from boxes and down to them.", "dir", "up") + tunBytesDown = metrics.Default.Counter("ftwcloud_tun_bytes_total", "Bytes of tun d forwarded, up from boxes and down to them.", "dir", "down") + dropTunUp = metrics.Drop("tun_rate_up") + dropTunDown = metrics.Drop("tun_rate_down") + dropUnknown = metrics.Drop("box_unknown_type") + dropConnect = metrics.Drop("box_connect_rate") + boxesFollow = metrics.Default.Gauge("ftwcloud_boxes_following_shards", "Connected boxes that list shard in hello.caps.") ) // Uplink is the /v1/box handler. @@ -73,12 +104,18 @@ type Uplink struct { mu sync.Mutex conns map[string]*boxConn - - // Dropped counts box messages of a type this service does not know. A - // newer box works with an older service by this rule. - Dropped atomic.Int64 - // TunDropped counts tun messages past a home's limits. - TunDropped atomic.Int64 + // limits are each home's rate limits, kept across its connections. + limits map[string]*limits + + // Shards says which homes this instance holds. Nil holds every home. + // Set before serving. + Shards *shard.Directory + // sockets are every box's socket from its upgrade on, so a drain + // reaches those still in their handshake. draining is set once Drain + // starts; restartReason is what its close says. + sockets wsclose.Set + draining atomic.Bool + restartReason atomic.Value // OnConnect runs after a box's hello_ok, so the app sessions can ask a // box that just came back for one-second updates and push can stop @@ -102,7 +139,111 @@ func New(st *store.Store, reg *registry.Registry, key *ecdsa.PrivateKey, log *sl if log == nil { log = slog.Default() } - return &Uplink{store: st, registry: reg, key: key, log: log, now: time.Now, conns: map[string]*boxConn{}} + return &Uplink{store: st, registry: reg, key: key, log: log, now: time.Now, conns: map[string]*boxConn{}, + limits: map[string]*limits{}} +} + +// limits are one home's rate limits. They outlive the connection, so a box +// that redials does not start again with full buckets. +type limits struct { + mu sync.Mutex + // msgs counts the box's signed messages; connects its connections. + msgs, connects bucket + // The tunnel's limits: up from the box, down from the home's phones. + // upHard is twice the up limits: a box past it is not pacing its + // tunnel, and its uplink closes. + upMsgs, upBytes bucket + upHardMsgs, upHardBytes bucket + downMsgs, downBytes bucket + // conns is how many connections use these now, and idle since when + // none has. + conns int + idle time.Time +} + +func newLimits(now time.Time) *limits { + return &limits{ + msgs: newBucket(rateBurst, ratePerSec, now), connects: newBucket(connectBurst, 1/connectEvery.Seconds(), now), + upMsgs: newBucket(tunMsgBurst, tunMsgPerSec, now), upBytes: newBucket(tunByteBurst, tunBytePerSec, now), + upHardMsgs: newBucket(2*tunMsgBurst, 2*tunMsgPerSec, now), upHardBytes: newBucket(2*tunByteBurst, 2*tunBytePerSec, now), + downMsgs: newBucket(tunMsgBurst, tunMsgPerSec, now), downBytes: newBucket(tunByteBurst, tunBytePerSec, now), + } +} + +// take runs f on the limits under their lock. +func (l *limits) take(f func() bool) bool { + l.mu.Lock() + defer l.mu.Unlock() + return f() +} + +// limitsFor returns a home's limits and counts one more connection on them. +func (u *Uplink) limitsFor(home string) *limits { + u.mu.Lock() + defer u.mu.Unlock() + l := u.limits[home] + if l == nil { + l = newLimits(u.now()) + u.limits[home] = l + } + l.conns++ + return l +} + +// release counts one connection fewer on a home's limits. +func (u *Uplink) release(l *limits) { + u.mu.Lock() + defer u.mu.Unlock() + l.conns-- + if l.conns == 0 { + l.idle = u.now() + } +} + +// Sweep forgets the limits of homes whose box has been gone for longer than +// any bucket takes to fill. Upkeep calls it. +func (u *Uplink) Sweep() { + now := u.now() + u.mu.Lock() + defer u.mu.Unlock() + for home, l := range u.limits { + if l.conns == 0 && now.Sub(l.idle) > limitsIdle { + delete(u.limits, home) + } + } +} + +// Boxes is how many boxes are connected now. +func (u *Uplink) Boxes() int { + u.mu.Lock() + defer u.mu.Unlock() + return len(u.conns) +} + +// Sockets is how many box sockets are open, handshakes included. +func (u *Uplink) Sockets() int { return u.sockets.Len() } + +// Drain closes every box's socket with cloudwire.CloseRestart and reason, +// the spread in milliseconds, those still in their handshake too, and turns +// away any that come after. Their absence starts no box.unreachable: the +// service is the one going. +func (u *Uplink) Drain(reason string) { + u.restartReason.Store(reason) + u.draining.Store(true) + u.sockets.CloseAll(cloudwire.CloseRestart, reason) +} + +// WaitClosed waits, at most d, until every box has answered the drain's +// close or timed out, and returns how many sockets are still open. +func (u *Uplink) WaitClosed(d time.Duration) int { return u.sockets.WaitEmpty(d) } + +// owner is the host of the shard that holds home, and whether it is this +// instance. +func (u *Uplink) owner(home string) (string, bool) { + if u.Shards == nil { + return "", true + } + return u.Shards.Owner(home) } var upgrader = websocket.Upgrader{ @@ -110,6 +251,9 @@ var upgrader = websocket.Upgrader{ // A box sends no Origin. A browser always does, and has no business // here. CheckOrigin: func(r *http.Request) bool { return r.Header.Get("Origin") == "" }, + // A box's socket is idle between messages; it borrows a write buffer + // only while it writes. + WriteBufferPool: &sync.Pool{}, } func (u *Uplink) ServeHTTP(w http.ResponseWriter, r *http.Request) { @@ -131,13 +275,19 @@ func (u *Uplink) ServeHTTP(w http.ResponseWriter, r *http.Request) { } defer conn.Close() conn.SetReadLimit(maxBoxFrame) - now := u.now() - c := &boxConn{u: u, conn: conn, ekm: ekm, tokens: rateBurst, refilled: now, - upMsgs: newBucket(tunMsgBurst, tunMsgPerSec, now), upBytes: newBucket(tunByteBurst, tunBytePerSec, now), - upHardMsgs: newBucket(2*tunMsgBurst, 2*tunMsgPerSec, now), - upHardBytes: newBucket(2*tunByteBurst, 2*tunBytePerSec, now), - downMsgs: newBucket(tunMsgBurst, tunMsgPerSec, now), downBytes: newBucket(tunByteBurst, tunBytePerSec, now)} + boxSockets.Add(1) + defer boxSockets.Add(-1) + sock := u.sockets.Add(conn) + defer u.sockets.Remove(sock) + c := &boxConn{u: u, conn: conn, sock: sock, ekm: ekm, started: time.Now()} c.write = c.writeFrame + // Drain sets draining before it takes the set, so a socket it did not + // see sees draining here. + if u.draining.Load() { + reason, _ := u.restartReason.Load().(string) + c.closeAndWait(cloudwire.CloseRestart, reason) + return + } if err := c.run(); err != nil && !websocket.IsCloseError(err, websocket.CloseNormalClosure, websocket.CloseGoingAway) { u.log.Debug("box uplink closed", "err", err) } @@ -160,20 +310,25 @@ func (u *Uplink) Watch(home string) { // past the home's limits is dropped and counted, and Tun still says true, // because the box is there. func (u *Uplink) Tun(home string, t cloudwire.Tun) bool { + start := time.Now() u.mu.Lock() c := u.conns[home] u.mu.Unlock() if c == nil || !c.tun { return false } - c.downMu.Lock() - ok := tunAllowed(&c.downMsgs, &c.downBytes, len(t.D), u.now()) - c.downMu.Unlock() - if !ok { - u.TunDropped.Add(1) + now := u.now() + if !c.lim.take(func() bool { return tunAllowed(&c.lim.downMsgs, &c.lim.downBytes, len(t.D), now) }) { + dropTunDown.Inc() return true } - return c.send(tun(t)) == nil + if c.send(tun(t)) != nil { + return false + } + tunDown.Since(start) + tunFramesDown.Inc() + tunBytesDown.Add(int64(len(t.D))) + return true } // Restore holds each home's last signed roster again after a restart, read @@ -185,25 +340,55 @@ func (u *Uplink) Restore() (int, error) { if err != nil { return 0, err } - n := 0 + // Checking a signature is most of the work, so the rosters are checked + // side by side, one worker per core: a deploy admits phones sooner. + var n, bad atomic.Int64 + work := make(chan registry.Home) + var wg sync.WaitGroup + for range runtime.GOMAXPROCS(0) { + wg.Add(1) + go func() { + defer wg.Done() + for h := range work { + r, ok := verifiedRoster(h) + if !ok { + bad.Add(1) + continue + } + u.store.Seed(h.ID, r, h.RosterAt) + n.Add(1) + } + }() + } for _, h := range homes { - pub, err := cloudwire.ParsePublicKey(h.PK) - if err != nil || cloudwire.HomeID(h.PK) != h.ID { - continue - } - env, err := cloudwire.DecodeEnvelope(h.Roster) - if err != nil || env.T != cloudwire.MsgRoster || cloudwire.Verify(pub, h.ID, env) != nil { - u.log.Warn("a stored roster does not verify; its home waits for its box") - continue - } - var r cloudwire.Roster - if cloudwire.Unmarshal(env.B, &r) != nil { - continue + // A home another shard holds now is that shard's to restore. + if _, ours := u.owner(h.ID); ours { + work <- h } - u.store.Seed(h.ID, &r, h.RosterAt) - n++ } - return n, nil + close(work) + wg.Wait() + if bad.Load() > 0 { + u.log.Warn("stored rosters that do not verify; their homes wait for their boxes", "count", bad.Load()) + } + return int(n.Load()), nil +} + +// verifiedRoster is a stored roster, if it verifies with its home's key. +func verifiedRoster(h registry.Home) (*cloudwire.Roster, bool) { + pub, err := cloudwire.ParsePublicKey(h.PK) + if err != nil || cloudwire.HomeID(h.PK) != h.ID { + return nil, false + } + env, err := cloudwire.DecodeEnvelope(h.Roster) + if err != nil || env.T != cloudwire.MsgRoster || cloudwire.Verify(pub, h.ID, env) != nil { + return nil, false + } + var r cloudwire.Roster + if cloudwire.Unmarshal(env.B, &r) != nil { + return nil, false + } + return &r, true } // boxConn is one box's connection. @@ -224,19 +409,14 @@ type boxConn struct { tun bool // bye is the reason the box gave for leaving, if it gave one. bye string - - tokens float64 - refilled time.Time - - // The tunnel's limits: up from the box, read on its goroutine; down - // from the home's phones, from theirs. upHard is twice the up limits: a - // box past it is not pacing its tunnel, and its uplink closes. - upMsgs, upBytes bucket - upHardMsgs bucket - upHardBytes bucket - downMu sync.Mutex - downMsgs bucket - downBytes bucket + // sock closes the socket with a code; started is when it was + // upgraded; lim the home's limits, once hello named the home. + sock *wsclose.Socket + started time.Time + lim *limits + // pinger pings the box every pingEvery until stopped. + pinger atomic.Pointer[time.Timer] + stopped atomic.Bool } // bucket is a token bucket. @@ -271,13 +451,28 @@ func tunAllowed(msgs, bytes *bucket, n int, now time.Time) bool { return true } +// writeFrame writes one frame. A write that fails or times out closes the +// socket, so the box's read loop ends and the box redials, rather than +// a socket that can read but never write lingering until its deadline. func (c *boxConn) writeFrame(frame []byte) error { c.writeMu.Lock() defer c.writeMu.Unlock() - if err := c.conn.SetWriteDeadline(time.Now().Add(writeTimeout)); err != nil { - return err + err := c.conn.SetWriteDeadline(time.Now().Add(writeTimeout)) + if err == nil { + err = c.conn.WriteMessage(websocket.BinaryMessage, frame) + } + if err != nil { + _ = c.conn.Close() } - return c.conn.WriteMessage(websocket.BinaryMessage, frame) + return err +} + +// closeAndWait ends the uplink with a close code and reason, and waits for +// the box's answer, so the box reads the code rather than a reset. Only the +// box's own goroutine calls it. +func (c *boxConn) closeAndWait(code int, reason string) { + c.sock.Close(code, reason) + c.sock.AwaitPeer() } var errProtocol = errors.New("uplink: the box broke the protocol") @@ -304,6 +499,20 @@ func (c *boxConn) run() error { if err != nil { return err } + // Another shard's home goes there before it touches this registry; a + // service about to stop sends the box to the next one. + if host, ours := c.u.owner(c.home); !ours { + wrongShard.Inc() + c.closeAndWait(cloudwire.CloseWrongShard, host) + return nil + } + c.lim = c.u.limitsFor(c.home) + defer c.u.release(c.lim) + if !c.lim.take(func() bool { return c.lim.connects.take(1, c.u.now()) }) { + dropConnect.Inc() + c.closeAndWait(cloudwire.CloseBusy, "") + return nil + } switch err := c.u.registry.Claim(c.home, hello.PK, c.u.now()); { case errors.Is(err, registry.ErrPurged): @@ -321,6 +530,11 @@ func (c *boxConn) run() error { if err := c.send(helloOK{BoxNonce: hello.BoxNonce, EKM: c.ekm, Have: map[string]string{}, RosterSeq: c.rosterSeq()}); err != nil { return err } + boxHandshake.Since(c.started) + if slices.Contains(hello.Caps, cloudwire.CapShard) { + boxesFollow.Add(1) + defer boxesFollow.Add(-1) + } // The connection becomes the home's only after hello_ok has gone, so a // watch or a tun from a phone can never reach the box before it: the // box closes on anything else while it waits for hello_ok. @@ -341,7 +555,7 @@ func (c *boxConn) run() error { delete(c.u.conns, c.home) } c.u.mu.Unlock() - if current && c.u.OnGone != nil { + if current && c.u.OnGone != nil && !c.u.draining.Load() { c.u.OnGone(c.home, c.bye, gen) } }() @@ -350,9 +564,14 @@ func (c *boxConn) run() error { } } - done := make(chan struct{}) - defer close(done) - go c.ping(done) + // The ping is a timer, not a goroutine of its own: a box's socket is + // idle most of the time, and ten thousand idle stacks are memory. + pinger := time.AfterFunc(pingEvery, c.ping) + c.pinger.Store(pinger) + defer func() { + c.stopped.Store(true) + pinger.Stop() + }() _ = c.conn.SetReadDeadline(time.Now().Add(readTimeout)) c.conn.SetPongHandler(func(string) error { return c.conn.SetReadDeadline(time.Now().Add(readTimeout)) @@ -413,13 +632,21 @@ func (c *boxConn) fromBox(env cloudwire.Envelope) error { return fmt.Errorf("%w: a tun the service cannot route", errProtocol) } now := c.u.now() - if !tunAllowed(&c.upHardMsgs, &c.upHardBytes, len(t.D), now) { + hard, ok := true, true + c.lim.take(func() bool { + hard = tunAllowed(&c.lim.upHardMsgs, &c.lim.upHardBytes, len(t.D), now) + ok = hard && tunAllowed(&c.lim.upMsgs, &c.lim.upBytes, len(t.D), now) + return ok + }) + if !hard { return fmt.Errorf("%w: tun at twice the home's limits", errProtocol) } - if !tunAllowed(&c.upMsgs, &c.upBytes, len(t.D), now) { - c.u.TunDropped.Add(1) + if !ok { + dropTunUp.Inc() return nil } + tunFramesUp.Inc() + tunBytesUp.Add(int64(len(t.D))) if !c.handle.Tun(t) && !t.Ended() && c.tun { return c.send(tun{Dev: t.Dev, Sid: t.Sid}) } @@ -437,31 +664,22 @@ func (c *boxConn) rosterSeq() uint64 { return seq } -func (c *boxConn) ping(done <-chan struct{}) { - t := time.NewTicker(pingEvery) - defer t.Stop() - for { - select { - case <-done: - return - case <-t.C: - if c.conn.WriteControl(websocket.PingMessage, nil, time.Now().Add(writeTimeout)) != nil { - return - } - } +// ping sends one ping and sets the next, until the connection ends or a +// ping cannot be written. +func (c *boxConn) ping() { + if c.stopped.Load() || c.conn.WriteControl(websocket.PingMessage, nil, time.Now().Add(writeTimeout)) != nil { + return + } + if t := c.pinger.Load(); t != nil && !c.stopped.Load() { + t.Reset(pingEvery) } } -// allow is a token bucket over the box's messages. +// allow is a token bucket over the box's signed messages, kept with the +// home's limits. func (c *boxConn) allow() bool { now := c.u.now() - c.tokens = min(rateBurst, c.tokens+now.Sub(c.refilled).Seconds()*ratePerSec) - c.refilled = now - if c.tokens < 1 { - return false - } - c.tokens-- - return true + return c.lim.take(func() bool { return c.lim.msgs.take(1, now) }) } // parseUplink reads one box frame. Only binary lane 1 frames carry the @@ -512,7 +730,7 @@ func (c *boxConn) apply(env cloudwire.Envelope) (stop bool, err error) { } if _, forwarded := cloudwire.ClassScope[env.T]; !forwarded { - c.u.Dropped.Add(1) + dropUnknown.Inc() return false, nil } if !c.handle.Serving() { diff --git a/internal/uplink/uplink_test.go b/internal/uplink/uplink_test.go index 1321708..0f12fdf 100644 --- a/internal/uplink/uplink_test.go +++ b/internal/uplink/uplink_test.go @@ -300,12 +300,13 @@ func TestAnUnknownBoxMessageIsCountedNotFatal(t *testing.T) { s := newService(t) b := newBox(t) _, _ = b.connect(s, nil) + before := dropUnknown.Load() b.send(cloudwire.MsgRoster, b.roster(protocol.ScopeLiveRead)) b.send("stats.future", map[string]any{"seq": b.header().Seq}) b.send(cloudwire.MsgLive, cloudwire.Live{Header: b.header(), Fields: map[string]int64{"2": 1}}) wait(t, "the live after the stranger", func() bool { return len(snapshot(t, s, b.home)) == 1 }) - if s.up.Dropped.Load() != 1 { - t.Fatalf("dropped %d", s.up.Dropped.Load()) + if n := dropUnknown.Load() - before; n != 1 { + t.Fatalf("dropped %d", n) } } @@ -373,7 +374,8 @@ func FuzzBoxMessage(f *testing.F) { u := New(st, reg, key, slog.New(slog.NewTextHandler(io.Discard, nil))) handle, _ := st.For(store.Principal{Kind: store.Box, Home: home}) _ = reg.Claim(home, pk, time.Now()) - c := &boxConn{u: u, home: home, pub: &key.PublicKey, handle: handle, write: func([]byte) error { return nil }} + c := &boxConn{u: u, home: home, pub: &key.PublicKey, handle: handle, write: func([]byte) error { return nil }, + lim: newLimits(time.Now())} env, err := cloudwire.SealBytes(key, home, typ, body) if err != nil || typ == "" { return @@ -400,11 +402,8 @@ func FuzzBoxTun(f *testing.F) { st := store.New(nil) u := New(st, nil, key, slog.New(slog.NewTextHandler(io.Discard, nil))) handle, _ := st.For(store.Principal{Kind: store.Box, Home: home}) - now := time.Now() c := &boxConn{u: u, home: home, pub: &key.PublicKey, handle: handle, tun: true, - write: func([]byte) error { return nil }, - upMsgs: newBucket(tunMsgBurst, tunMsgPerSec, now), upBytes: newBucket(tunByteBurst, tunBytePerSec, now), - upHardMsgs: newBucket(2*tunMsgBurst, 2*tunMsgPerSec, now), upHardBytes: newBucket(2*tunByteBurst, 2*tunBytePerSec, now)} + write: func([]byte) error { return nil }, lim: newLimits(time.Now())} _ = c.fromBox(cloudwire.Envelope{T: cloudwire.MsgTun, B: body}) }) } diff --git a/internal/wsclose/wsclose.go b/internal/wsclose/wsclose.go new file mode 100644 index 0000000..c875546 --- /dev/null +++ b/internal/wsclose/wsclose.go @@ -0,0 +1,109 @@ +// Package wsclose ends a WebSocket as RFC 6455 asks: send a close, wait for +// the peer's, then close the TCP connection. A server that closes right after +// its close frame, with the peer's data still unread, makes Linux send a +// reset, and the peer sees 1006 instead of the code it was meant to read, +// such as 4421 with the right shard or 4503 with the spread. +// +// A Set tracks every socket a handler holds from the upgrade on, so a drain +// reaches those still in their handshake too. +package wsclose + +import ( + "sync" + "sync/atomic" + "time" + + "github.com/gorilla/websocket" +) + +// Wait is how long a close waits for the peer's. +const Wait = time.Second + +// Socket is one tracked socket. +type Socket struct { + Conn *websocket.Conn + sent atomic.Bool +} + +// Close sends one close frame, the first one asked for, and makes the read +// that waits for the peer's answer end within Wait. A timer closes the +// connection after twice Wait in any case. False means a close was sent +// already. +func (s *Socket) Close(code int, reason string) bool { + if !s.sent.CompareAndSwap(false, true) { + return false + } + // gorilla lets WriteControl run beside a data write, so a write stuck + // on a full socket does not hold the close back. + _ = s.Conn.WriteControl(websocket.CloseMessage, websocket.FormatCloseMessage(code, reason), time.Now().Add(Wait)) + _ = s.Conn.SetReadDeadline(time.Now().Add(Wait)) + time.AfterFunc(2*Wait, func() { _ = s.Conn.Close() }) + return true +} + +// AwaitPeer reads and discards until the peer's close or the deadline Close +// set. Only the goroutine that reads the socket may call it. +func (s *Socket) AwaitPeer() { + for { + if _, _, err := s.Conn.ReadMessage(); err != nil { + return + } + } +} + +// Set is the sockets a handler holds now. +type Set struct { + mu sync.Mutex + m map[*Socket]struct{} +} + +// Add tracks a socket from its upgrade on. +func (t *Set) Add(c *websocket.Conn) *Socket { + s := &Socket{Conn: c} + t.mu.Lock() + defer t.mu.Unlock() + if t.m == nil { + t.m = map[*Socket]struct{}{} + } + t.m[s] = struct{}{} + return s +} + +// Remove stops tracking a socket, when its handler returns. +func (t *Set) Remove(s *Socket) { + t.mu.Lock() + defer t.mu.Unlock() + delete(t.m, s) +} + +// Len is how many sockets are tracked. +func (t *Set) Len() int { + t.mu.Lock() + defer t.mu.Unlock() + return len(t.m) +} + +// CloseAll sends every tracked socket a close with code and reason, side by +// side, and returns how many there were. +func (t *Set) CloseAll(code int, reason string) int { + t.mu.Lock() + all := make([]*Socket, 0, len(t.m)) + for s := range t.m { + all = append(all, s) + } + t.mu.Unlock() + for _, s := range all { + go s.Close(code, reason) + } + return len(all) +} + +// WaitEmpty waits, at most d, until no socket is tracked, and returns how +// many still are. +func (t *Set) WaitEmpty(d time.Duration) int { + deadline := time.Now().Add(d) + for t.Len() > 0 && time.Now().Before(deadline) { + time.Sleep(10 * time.Millisecond) + } + return t.Len() +}