From 6143695745c8cf5a868979733ecc0d4feda8ae46 Mon Sep 17 00:00:00 2001 From: Shannon Atkinson Date: Fri, 4 Sep 2026 16:06:58 -0700 Subject: [PATCH 1/8] fix: four devices from the poka-yoke audit, and one regression it caught Closes #706. Closes #710. Closes #714. Closes #716. Refs #720. Five of the sixteen findings in the 2026-09-04 audit, chosen as the ones whose device reaches CONTROL for a bounded cost. The rest are filed with their proposed rung and are not in this change. #706 -- A PASSWORD CHANGE LEFT ITS TOKENS' SOCKETS STREAMING. Revocation had two halves: delete the row, and mark the id in an in-process set the /ws tick reads. handleRevokeAPIToken did both; handleChangePassword, which calls DeleteAllAPITokens, marked nothing. A socket opened with an admin token kept receiving admin-shaped events until it or the process died, while the response correctly reported zero surviving tokens. The revoke handler had predicted it exactly: "a second deletion path that did not do this would be a silent hole." handleChangePassword was that path. The set is now GONE. The tick asks the store (db.APITokenExists), the way the session half beside it already asks for users.token_epoch, and fails closed on a read error for the reason stated there. That is Control rather than Warning: there is no second half left to forget, so resetadmin (#718) and whatever is added next are honoured without being told to be. Cost is one indexed read per socket per ping period, which is what the epoch check already costs. Its test asserted the old premise -- that a deletion bypassing the handler is invisible -- and closed with "if something else now writes to it, this test's premise is stale". Something did. It now pins the stronger property, that a deletion made anywhere ends the socket, and keeps the half that still matters: this check closes sockets early and is not an authorisation source. #710 -- requireScope passed a request with NO PRINCIPAL. Its siblings requireSession and requireCSRF both fail closed on the same condition. Every group carrying it today also carries requireAuth, so this changes no live behaviour; it removes the affordance of mounting them apart or in the wrong order. The p.token == nil arm is a different case and stays: a session principal is not a scoped token. #714 -- stopAux took (slot, name) and recovered the rest from a switch. Two silent mistakes were available: e.stopAux(&e.preview, "recorder") compiles and reads correctly while releasing the wrong port and leaking the preview's, and the switch had no default, so a fourth consumer would skip its release and leave reconcile believing the child was up. One auxSlot value per consumer means there is no second argument to mismatch and no switch to fall through. It also brings these three into line with every other subscriber in the package, which stores its name at subscribe time rather than recomputing a literal at teardown. The test table now names the PRODUCTION slots instead of carrying its own copy of the same correspondence. #720 -- kill() gained the reaped-check its two siblings carry. killGroup issues a raw syscall.Kill(-pid, SIGKILL), which names a process group by number and bypasses Go's ErrProcessDone; on a reaped pid that can signal a group this supervisor never started. The safety argument was correct and was a comment spanning three functions. Now it is a guard. #716 -- AND THE REGRESSION IT CAUSED, recorded rather than quietly fixed. Making the policy switch fail closed dropped every passthrough event -- Log, Status, Levels, Stats, Loudness -- because wsPassthrough is `iota`, the zero value, and had no case of its own: it had always reached the sender through the default arm being replaced. The opening burst on a fresh install delivered nothing, and TestTheWebSocketOpeningBurstSurvivesZeroSources caught it. That is the general hazard of tightening a default, and it is now a comment at the case: the arm being replaced has to be enumerated first, and a zero-valued constant is the member most likely to be sitting in it unnoticed. wsPassthrough is explicit now, and default still fails closed for a constant added later -- which was the point, since passing an unknown policy through sends a read-scoped socket the admin shape. Two mutations, each red: the socket no longer asking the store, and passthrough falling back to the closed default. internal/api, internal/engine, internal/supervisor and internal/db all green. Claude-Session: https://claude.ai/code/session_01A8N3W5ct9SZtHK9sCDD9cL --- internal/api/api.go | 137 ++++++++++++------------------ internal/api/token_handlers.go | 1 - internal/api/ws.go | 2 +- internal/api/ws_policy.go | 24 +++++- internal/api/ws_revoke_test.go | 54 +++++++----- internal/db/tokens.go | 26 ++++++ internal/engine/engine.go | 98 ++++++++++++++++----- internal/engine/lifecycle_test.go | 59 +++++++------ internal/supervisor/supervisor.go | 30 ++++++- 9 files changed, 274 insertions(+), 157 deletions(-) diff --git a/internal/api/api.go b/internal/api/api.go index 0e42ffe1..e7a6be5f 100644 --- a/internal/api/api.go +++ b/internal/api/api.go @@ -402,49 +402,13 @@ type Server struct { // for why the state is in memory rather than in a table. devices deviceFlows - // revokedMu guards revoked and wsPingEvery. - revokedMu sync.RWMutex - // revoked is the set of api_tokens.id values this process has deleted. - // - // IT EXISTS FOR ONE READER: the /ws ping tick (#159). A socket's principal - // is captured once, at upgrade, and requireAuth never runs again -- so - // revoking a token, which is the operator's ONLY lever after a leak, did - // not reach a socket that was already open. It stayed open, and it stayed - // at the scope it was opened with, until the client went away. Under a - // single-administrator product that is defensible; "revoke does not revoke" - // is not a sentence to leave in the product. - // - // IN-PROCESS AND WRITE-ONLY-ON-REVOKE, and the three alternatives were all - // worse: - // - // Re-looking the token up on each tick (LookupAPIToken) means retaining - // the PLAINTEXT bearer for the life of the socket so there is something - // to look up with, and firing a last_used_at write per socket per minute - // at a single SQLite connection, and adding a database-error path to a - // loop where the only safe answer to an error is "do not close the - // socket" -- which is a branch that must never be got wrong and would - // never be exercised. + // revokedMu guards wsPingEvery. // - // A process-global epoch counter bumped on every mutation does not - // survive a restart, has to be touched by every future mutation site, and - // invites somebody to treat the counter as the authorisation decision. - // - // Broadcasting revocations over a channel couples the socket loop to the - // store's lifecycle for a signal that is one map lookup. - // - // UNBOUNDED BY DESIGN, and the bound is the process. An entry is ~8 bytes - // and is added only when an operator revokes a token by hand; an install - // that revoked ten thousand tokens between restarts would be holding 80 kB. - // Pruning would need to know that no socket still holds the id, which is - // the state this map exists to avoid tracking. - // - // It is NOT an authorisation source. Absence from this set means "this - // process has not seen that token deleted", which is not the same as "the - // token is valid" -- a token deleted by another process, or by an operator - // editing the database, is absent here. Every REQUEST still goes through - // requireAuth, which asks the database. This only ever CLOSES a socket - // early; it never keeps one open. - revoked map[int64]struct{} + // It used to guard a `revoked` set as well -- the process-local half of API + // token revocation. That set is gone: the /ws tick asks the store directly + // (Server.tokenRevoked, #706), so there is no second half to keep in sync + // and no deletion path that can forget to write it. + revokedMu sync.RWMutex // wsPingEvery overrides pingPeriod, and is set only by tests. // // The revocation check rides the existing ping tick, so a test of it has to @@ -619,7 +583,6 @@ func New(o Options) *Server { logins: auth.NewThrottle(), setups: auth.NewThrottle(), kickKeys: &chat.KickKeyFetcher{}, - revoked: map[int64]struct{}{}, sessions: auth.New( o.Secrets.Derive("session-jwt"), // ServesTLS, not the legacy tls.enabled: an install that writes @@ -1416,51 +1379,46 @@ func (s *Server) requestLogger(next http.Handler) http.Handler { }) } -// markRevoked records that this process deleted an API token, so any /ws socket -// still holding it can be closed on its next ping tick. See Server.revoked. +// tokenRevoked reports whether an open socket's API token has been revoked. // -// Called AFTER the delete succeeds, never before: a failed delete leaves the -// token working, and an entry here would then close a socket whose credential -// is still valid -- a self-inflicted outage in the one code path an operator -// reaches for during an incident. -func (s *Server) markRevoked(id int64) { - if s == nil || id == 0 { - return - } - s.revokedMu.Lock() - if s.revoked == nil { - s.revoked = map[int64]struct{}{} - } - s.revoked[id] = struct{}{} - s.revokedMu.Unlock() -} - -// isRevoked reports whether this process has deleted the given token id. +// #706. THE STORE IS THE ONE SOURCE OF TRUTH, and it did not used to be. +// +// Revocation has two halves -- delete the row, and end any socket opened with +// it -- and the second half used to be an in-process map written by exactly one +// handler. handleRevokeAPIToken wrote it; handleChangePassword, which calls +// DeleteAllAPITokens, did not. So a password change removed every token from +// the database and left their sockets streaming admin-shaped events until the +// socket or the process died, while the response correctly reported zero +// surviving tokens. // -// One read-lock and one map lookup, per socket, per ping period. Nothing here -// touches the database, and it must not start to: see Server.revoked. -func (s *Server) isRevoked(id int64) bool { +// The revoke handler's own comment had predicted exactly this: "a second +// deletion path that did not do this would be a silent hole." +// +// Asking the store instead of a map makes every deletion path -- that handler, +// the password change, resetadmin (#718), and whatever is added next -- close +// the socket without being told to. That is the difference between a device and +// a convention: there is no second half left to forget. +// +// FAIL CLOSED on a read error, for the reason sessionEpochChanged below states: +// an unreachable store is not a reason to keep streaming to a client we can no +// longer check, and a store this socket cannot read is one requireAuth cannot +// read either. +// +// One indexed read per socket per ping period, the same cost as the session +// half beside it. +func (s *Server) tokenRevoked(id int64) bool { if s == nil || id == 0 { return false } - s.revokedMu.RLock() - _, ok := s.revoked[id] - s.revokedMu.RUnlock() - return ok + exists, err := s.store.APITokenExists(id) + if err != nil { + s.log.Warn("cannot check whether an open socket's API token survives; closing it", + "token", id, "err", err) + return true + } + return !exists } -// sessionEpochChanged reports whether a session signed at `was` has since been -// revoked, which for a session means the user's password was changed. -// -// Deliberately NOT modelled on the revoked set above. That set is an in-process -// note of something this process did, and it is documented as never being an -// authorisation source; the epoch is the opposite -- the database is the only -// thing that knows it, a bump can arrive from another process or from sqlite3, -// and there is nothing in memory that would hear about it. So this reads the -// store, once per socket per ping period. -// -// Fails CLOSED, exactly as auth.(*Manager).checkEpoch does on the request path: -// a store that cannot answer is not a store that has said yes. func (s *Server) sessionEpochChanged(userID, was int64) bool { if s == nil || userID == 0 { return false @@ -1719,7 +1677,22 @@ var readScopeDeniedPatterns = map[string]bool{ func (s *Server) requireScope(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { p, ok := principalFrom(r.Context()) - if !ok || p.token == nil || p.token.Scope == db.ScopeAdmin { + // NO PRINCIPAL IS A REFUSAL, not a pass. #710. + // + // requireSession and requireCSRF both fail closed on !ok; this one + // passed, which made "mounted without requireAuth, or after it in the + // wrong order" a silent loss of scope enforcement rather than a 401. + // Every group carrying this today also carries requireAuth, so this + // changes no live behaviour -- it removes the affordance. + // + // The p.token == nil arm below is a DIFFERENT case and is deliberate: + // a session principal is not a scoped token, which is what the comment + // above this function says. + if !ok { + writeError(w, http.StatusUnauthorized, "not signed in") + return + } + if p.token == nil || p.token.Scope == db.ScopeAdmin { next.ServeHTTP(w, r) return } diff --git a/internal/api/token_handlers.go b/internal/api/token_handlers.go index b6aa177f..b808bcb3 100644 --- a/internal/api/token_handlers.go +++ b/internal/api/token_handlers.go @@ -129,7 +129,6 @@ func (s *Server) handleRevokeAPIToken(w http.ResponseWriter, r *http.Request) { // This is the only writer of the revoked set, and it is the reason // DeleteAPIToken having exactly one call site was worth checking: a second // deletion path that did not do this would be a silent hole. - s.markRevoked(id) s.log.Info("api token revoked", "id", id) s.publishAudit(auditAPITokenRevoked(name, s.clientIP(r))) writeJSON(w, http.StatusOK, map[string]string{"status": "revoked"}) diff --git a/internal/api/ws.go b/internal/api/ws.go index 0bbf1c37..dac4dd43 100644 --- a/internal/api/ws.go +++ b/internal/api/ws.go @@ -216,7 +216,7 @@ func (s *Server) handleWS(w http.ResponseWriter, r *http.Request) { // below closes the connection either way; treating the write failure // as a reason not to return would keep the socket that this branch // exists to end. - if s.isRevoked(tokenID) { + if s.tokenRevoked(tokenID) { _ = conn.SetWriteDeadline(time.Now().Add(writeWait)) _ = conn.WriteMessage(websocket.CloseMessage, websocket.FormatCloseMessage(websocket.ClosePolicyViolation, diff --git a/internal/api/ws_policy.go b/internal/api/ws_policy.go index c1a5b10a..81a137fd 100644 --- a/internal/api/ws_policy.go +++ b/internal/api/ws_policy.go @@ -118,13 +118,35 @@ func eventView(ev events.Event, readOnly bool) (events.Event, bool) { return events.Event{}, false } switch policy { + case wsPassthrough: + // EXPLICIT, and it was not before. wsPassthrough is `iota`, so it is the + // zero value, and it used to reach the sender through the `default` arm + // rather than through a case of its own. Making the default fail closed + // therefore dropped every passthrough event -- Log, Status, Levels, + // Stats, Loudness -- and the opening burst on a fresh install delivered + // nothing. Caught by TestTheWebSocketOpeningBurstSurvivesZeroSources. + // + // Worth recording because it is the general hazard of tightening a + // default: the arm being replaced has to be enumerated first, and a + // zero-valued constant is the member most likely to be sitting in it + // unnoticed. + return ev, true case wsDrop: return events.Event{}, false case wsRedactText: ev.Data = redactEventText(ev.Data) return ev, true default: - return ev, true + // FAIL CLOSED, for the same reason the !classified arm above does. #716. + // + // This used to `return ev, true` -- a policy constant added without a + // case here would send a read-scoped socket the ADMIN shape of the + // event, which is the one direction a widening must never take. The + // repo already makes this argument about scopes, in requireScope: "a + // value that arrived from a newer schema or a hand-edited row should + // narrow what a credential can do, never widen it." The same reasoning + // applies to the redaction that scope selects. + return events.Event{}, false } } diff --git a/internal/api/ws_revoke_test.go b/internal/api/ws_revoke_test.go index 56827f74..35181d4d 100644 --- a/internal/api/ws_revoke_test.go +++ b/internal/api/ws_revoke_test.go @@ -231,14 +231,23 @@ func TestRevokingATokenLeavesASessionSocketAlone(t *testing.T) { } } -// TestTheRevokedSetIsNotConsultedForAuthorisation states the limit of the set, -// so nobody promotes it into an authorisation source. +// A DELETION MADE ANYWHERE IS SEEN BY AN OPEN SOCKET. #706. // -// Absence from the set means "this process has not seen that token deleted", -// which is NOT "the token is valid": a token deleted by another process, or by -// an operator with sqlite3, is absent from it. Every request still asks the -// database through requireAuth. The set only ever CLOSES a socket early. -func TestTheRevokedSetIsNotConsultedForAuthorisation(t *testing.T) { +// This test used to assert the opposite, and was right to: revocation's second +// half was an in-process set, and absence from it meant only "this process has +// not seen that token deleted". A deletion by another process, by +// handleChangePassword's DeleteAllAPITokens, or by an operator with sqlite3 was +// invisible to it -- so a socket opened with that token kept streaming. +// +// The old test closed with "if something else now writes to it, this test's +// premise is stale". Something else did: the set is gone, and the /ws tick asks +// the store. So the property inverts, and the stronger one is what is pinned +// here -- a token deleted BEHIND the handler's back still ends its socket. +// +// The second half is unchanged and still matters: requireAuth asks the database +// on every request, so this check is only ever the thing that closes a socket +// EARLY. It is not an authorisation source and must not become one. +func TestADeletionMadeOutsideTheHandlerStillEndsTheSocket(t *testing.T) { h, store, sign := renditionServer(t, defaultTools()) s := serverUnderTest(t, h) @@ -246,25 +255,32 @@ func TestTheRevokedSetIsNotConsultedForAuthorisation(t *testing.T) { tok := createScopedToken(t, h, sign, name, db.ScopeAdmin) id := tokenIDByName(t, h, sign, name) - // Delete through the STORE, bypassing the handler, which is what another - // process or a hand-edited database looks like from in here. + // Delete through the STORE, bypassing the handler -- which is what another + // process, a hand-edited database, or a password change looks like from in + // here. The last of those is the one that was silently missed. if err := store.DeleteAPIToken(id); err != nil { t.Fatalf("delete: %v", err) } - if s.isRevoked(id) { - t.Fatal("the revoked set knows about a deletion that did not go through the " + - "handler; if something else now writes to it, this test's premise is stale") + if !s.tokenRevoked(id) { + t.Fatal("a token deleted outside handleRevokeAPIToken is not seen as revoked, " + + "so a socket opened with it would keep streaming. That is #706: the check " + + "must read the store, not a set that one handler writes.") + } + + // And a token that still exists is NOT reported revoked, or the check would + // close every socket and pass this file by being uselessly strict. + live := "still-here" + createScopedToken(t, h, sign, live, db.ScopeAdmin) + if s.tokenRevoked(tokenIDByName(t, h, sign, live)) { + t.Error("a live token was reported revoked") } - // The request is still refused, because requireAuth asks the database and - // not the set. + // The request is still refused, because requireAuth asks the database. r := jsonRequest(t, http.MethodGet, "/api/v1/status", nil) r.Header.Set("Authorization", "Bearer "+tok) if w := do(t, h, r); w.Code != http.StatusUnauthorized { - t.Errorf("GET /api/v1/status with a token deleted outside the handler: status %d, "+ - "want 401. The revoked set must never become the thing that decides -- it "+ - "cannot see a deletion it was not told about, so consulting it INSTEAD of the "+ - "database would turn a missed notification into an authorisation bypass.", - w.Code) + t.Errorf("GET /api/v1/status with a deleted token: status %d, want 401. This "+ + "check closes sockets early; it must never become the thing that decides "+ + "authorisation, which is still requireAuth's job.", w.Code) } } diff --git a/internal/db/tokens.go b/internal/db/tokens.go index a3434a4f..ee922852 100644 --- a/internal/db/tokens.go +++ b/internal/db/tokens.go @@ -158,6 +158,32 @@ func (d *DB) ListAPITokens() ([]APIToken, error) { } // DeleteAPIToken revokes a token. +// APITokenExists reports whether a token row is still there. +// +// #706. It exists so a live /ws socket can ask the STORE whether its token +// survives, rather than consulting an in-process set that only one handler +// writes to. Revocation had two halves -- delete the row, and mark the id in +// that set -- and only the single-token path did both, so a password change +// deleted every token from the database and left their sockets streaming. +// +// One indexed read per socket per ping period, which is exactly what the +// session half beside it (TokenEpoch) already costs and is documented as +// acceptable there. +func (d *DB) APITokenExists(id int64) (bool, error) { + if id == 0 { + return false, nil + } + var one int + err := d.sql.QueryRow(`SELECT 1 FROM api_tokens WHERE id = ?`, id).Scan(&one) + if errors.Is(err, sql.ErrNoRows) { + return false, nil + } + if err != nil { + return false, err + } + return true, nil +} + func (d *DB) DeleteAPIToken(id int64) error { res, err := d.sql.Exec(`DELETE FROM api_tokens WHERE id = ?`, id) if err != nil { diff --git a/internal/engine/engine.go b/internal/engine/engine.go index 0c536b17..f3514417 100644 --- a/internal/engine/engine.go +++ b/internal/engine/engine.go @@ -1731,7 +1731,7 @@ func (e *Engine) reconcileRecorder(s db.Settings) { // about to fill takes the database and the preview down with it. if !s.Recording.Enabled || !e.recman.RecordingAllowed() { if cur != nil { - e.stopAux(&e.recorder, "recorder") + e.stopAux(auxRecorder) } return } @@ -1743,7 +1743,7 @@ func (e *Engine) reconcileRecorder(s db.Settings) { return } if cur != nil { - e.stopAux(&e.recorder, "recorder") + e.stopAux(auxRecorder) } if err := os.MkdirAll(e.cfg.RecordingsDir(), 0o755); err != nil { @@ -2105,7 +2105,7 @@ func (e *Engine) startPreviewLocked(s db.Settings) { // stopPreviewLocked tears the encoder down. The caller must hold previewMu. func (e *Engine) stopPreviewLocked() { - e.stopAux(&e.preview, "preview") + e.stopAux(auxPreview) // The playlist left behind would be served to the next viewer, pointing at // segments the next start is about to delete. Scoped to THIS source: while // it cleared the shared directory, an engine tearing down took the live @@ -2189,7 +2189,7 @@ func (e *Engine) reconcileMeters(s db.Settings) { if !s.Meters.Enabled || len(src.Tracks) == 0 || !known { if cur != nil { - e.stopAux(&e.meters, "meters") + e.stopAux(auxMeters) } return } @@ -2207,7 +2207,7 @@ func (e *Engine) reconcileMeters(s db.Settings) { return } if cur != nil { - e.stopAux(&e.meters, "meters") + e.stopAux(auxMeters) } port, err := e.alloc.Allocate() @@ -3048,8 +3048,69 @@ func (e *Engine) teardownRendition(r *rendition) { } } -func (e *Engine) stopAux(slot **supervisor.Process, name string) { +// auxSlot names one auxiliary child completely: its process slot, its port, its +// signature, its hub, and the subscriber name it registered under. +// +// #714. stopAux used to take (slot, name) as two arguments and recover the rest +// from a `switch name`. Two mistakes were available in that shape and both were +// silent: +// +// - e.stopAux(&e.preview, "recorder") compiles and reads correctly. It stops +// the preview, releases the RECORDER's port, unsubscribes "recorder" from +// the ingest hub rather than the preview's, and leaks the preview's port +// and subscription for ever. +// - the switch had no default, so a fourth consumer left port == 0, skipped +// the release, never cleared its signature, and left reconcile believing +// the child was still running. Nothing failed and nothing logged. +// +// One argument means there is no second argument to mismatch, and a value per +// consumer means there is no switch to fall through. That is the whole device. +// +// This also brings the three aux consumers into line with every other +// subscriber in the package: destinations, renditions, feeds, silence, +// loudness, clips, captions and playout all store their name at subscribe time +// and reuse the STORED value at teardown. Recorder, preview and meters were the +// only three recomputing a bare string literal, and they were exactly the three +// routed through the switch. +type auxSlot struct { + name string + proc func(*Engine) **supervisor.Process + port func(*Engine) *int + sig func(*Engine) *string + // hub is the consumer's own hub pointer, or nil when it always reads the + // ingest hub. The preview and meters read whichever tier is on air, so both + // must unsubscribe from the hub they actually JOINED -- unsubscribing from + // e.hub instead leaves a live subscription on a selector hub that is about + // to close. + hub func(*Engine) **relay.Hub +} + +var ( + auxRecorder = auxSlot{ + name: "recorder", + proc: func(e *Engine) **supervisor.Process { return &e.recorder }, + port: func(e *Engine) *int { return &e.recorderPort }, + sig: func(e *Engine) *string { return &e.recorderSig }, + } + auxPreview = auxSlot{ + name: "preview", + proc: func(e *Engine) **supervisor.Process { return &e.preview }, + port: func(e *Engine) *int { return &e.previewPort }, + sig: func(e *Engine) *string { return &e.previewSig }, + hub: func(e *Engine) **relay.Hub { return &e.previewHub }, + } + auxMeters = auxSlot{ + name: "meters", + proc: func(e *Engine) **supervisor.Process { return &e.meters }, + port: func(e *Engine) *int { return &e.metersPort }, + sig: func(e *Engine) *string { return &e.metersSig }, + hub: func(e *Engine) **relay.Hub { return &e.metersHub }, + } +) + +func (e *Engine) stopAux(a auxSlot) { e.mu.Lock() + slot := a.proc(e) proc := *slot *slot = nil var port int @@ -3058,21 +3119,14 @@ func (e *Engine) stopAux(slot **supervisor.Process, name string) { // the hub they actually JOINED -- unsubscribing from e.hub instead leaves a // live subscription on a selector hub that is about to close. hub := e.hub - switch name { - case "recorder": - port, e.recorderPort = e.recorderPort, 0 - e.recorderSig = "" - case "preview": - port, e.previewPort = e.previewPort, 0 - e.previewSig = "" - if e.previewHub != nil { - hub, e.previewHub = e.previewHub, nil - } - case "meters": - port, e.metersPort = e.metersPort, 0 - e.metersSig = "" - if e.metersHub != nil { - hub, e.metersHub = e.metersHub, nil + { + pp := a.port(e) + port, *pp = *pp, 0 + *a.sig(e) = "" + if a.hub != nil { + if hp := a.hub(e); *hp != nil { + hub, *hp = *hp, nil + } } } e.mu.Unlock() @@ -3082,7 +3136,7 @@ func (e *Engine) stopAux(slot **supervisor.Process, name string) { _ = proc.Stop(ctx) cancel() } - hub.Unsubscribe(name) + hub.Unsubscribe(a.name) if port != 0 { e.alloc.Release(port) } diff --git a/internal/engine/lifecycle_test.go b/internal/engine/lifecycle_test.go index 2d3b606d..b9223c0b 100644 --- a/internal/engine/lifecycle_test.go +++ b/internal/engine/lifecycle_test.go @@ -417,22 +417,25 @@ func TestANilChildEndsOneTeardownRatherThanTheWholeReconcile(t *testing.T) { // Clearing the wrong one leaks the right one and cycles a healthy child. func TestStoppingOneAuxiliaryChildClearsOnlyItsOwnPortAndSignature(t *testing.T) { type slot struct { - name string - of func(*Engine) **supervisor.Process + aux auxSlot port func(*Engine) int sig func(*Engine) string } + // AGAINST THE PRODUCTION SLOTS, not a parallel list. #714. + // + // This table used to carry its own copy of the recorder/preview/meters + // correspondence -- which is the same duplication the production switch + // had, and would have gone on passing if the two drifted apart. Naming the + // real auxSlot values means a fourth consumer added to production without a + // row here is a compile error at `aux`, not a silently unexercised path. slots := []slot{ - {"recorder", func(e *Engine) **supervisor.Process { return &e.recorder }, - func(e *Engine) int { return e.recorderPort }, func(e *Engine) string { return e.recorderSig }}, - {"preview", func(e *Engine) **supervisor.Process { return &e.preview }, - func(e *Engine) int { return e.previewPort }, func(e *Engine) string { return e.previewSig }}, - {"meters", func(e *Engine) **supervisor.Process { return &e.meters }, - func(e *Engine) int { return e.metersPort }, func(e *Engine) string { return e.metersSig }}, + {auxRecorder, func(e *Engine) int { return e.recorderPort }, func(e *Engine) string { return e.recorderSig }}, + {auxPreview, func(e *Engine) int { return e.previewPort }, func(e *Engine) string { return e.previewSig }}, + {auxMeters, func(e *Engine) int { return e.metersPort }, func(e *Engine) string { return e.metersSig }}, } for _, stopping := range slots { - t.Run(stopping.name, func(t *testing.T) { + t.Run(stopping.aux.name, func(t *testing.T) { e := lifeEngine(t) // Three ports and no spare: a released port is the ONLY one // Allocate can return afterwards, which is what identifies it. @@ -452,56 +455,56 @@ func TestStoppingOneAuxiliaryChildClearsOnlyItsOwnPortAndSignature(t *testing.T) e.alloc = relay.NewPortAllocator(base, 3) ports := map[string]int{} for _, s := range slots { - ports[s.name] = mustAllocate(t, e.alloc, "reserving "+s.name+"'s port") - e.hub.Subscribe(s.name, ports[s.name]) + ports[s.aux.name] = mustAllocate(t, e.alloc, "reserving "+s.aux.name+"'s port") + e.hub.Subscribe(s.aux.name, ports[s.aux.name]) } e.recorder, e.preview, e.meters = loudTestProc(), loudTestProc(), loudTestProc() e.recorderPort, e.previewPort, e.metersPort = ports["recorder"], ports["preview"], ports["meters"] e.recorderSig, e.previewSig, e.metersSig = "rec-sig", "prev-sig", "met-sig" - e.stopAux(stopping.of(e), stopping.name) + e.stopAux(stopping.aux) - if got := *stopping.of(e); got != nil { + if got := *stopping.aux.proc(e); got != nil { t.Error("the slot still holds a process, so the next reconcile believes " + "the child is running and never starts a replacement") } if got := stopping.port(e); got != 0 { t.Errorf("%s port = %d after stopping it, want 0; the engine will try to "+ - "release it a second time when the next child takes it", stopping.name, got) + "release it a second time when the next child takes it", stopping.aux.name, got) } if got := stopping.sig(e); got != "" { t.Errorf("%s signature = %q after stopping it, want empty; a stale signature "+ - "makes the next reconcile believe the stopped child is up to date", stopping.name, got) + "makes the next reconcile believe the stopped child is up to date", stopping.aux.name, got) } - if hasSubscriber(e.hub, stopping.name) { - t.Errorf("the hub still forwards to %s after it was stopped", stopping.name) + if hasSubscriber(e.hub, stopping.aux.name) { + t.Errorf("the hub still forwards to %s after it was stopped", stopping.aux.name) } for _, other := range slots { - if other.name == stopping.name { + if other.aux.name == stopping.aux.name { continue } - if *other.of(e) == nil { - t.Errorf("stopping %s also cleared %s's process slot", stopping.name, other.name) + if *other.aux.proc(e) == nil { + t.Errorf("stopping %s also cleared %s's process slot", stopping.aux.name, other.aux.name) } - if got := other.port(e); got != ports[other.name] { + if got := other.port(e); got != ports[other.aux.name] { t.Errorf("stopping %s changed %s's port to %d, want %d; that child's port "+ "is now either leaked or about to be released twice", - stopping.name, other.name, got, ports[other.name]) + stopping.aux.name, other.aux.name, got, ports[other.aux.name]) } if other.sig(e) == "" { t.Errorf("stopping %s cleared %s's signature, which cycles a healthy child", - stopping.name, other.name) + stopping.aux.name, other.aux.name) } - if !hasSubscriber(e.hub, other.name) { - t.Errorf("stopping %s unsubscribed %s from the hub", stopping.name, other.name) + if !hasSubscriber(e.hub, other.aux.name) { + t.Errorf("stopping %s unsubscribed %s from the hub", stopping.aux.name, other.aux.name) } } // The released port is identifiable because nothing else is free. - if got := mustAllocate(t, e.alloc, "after stopping "+stopping.name); got != ports[stopping.name] { + if got := mustAllocate(t, e.alloc, "after stopping "+stopping.aux.name); got != ports[stopping.aux.name] { t.Errorf("the allocator handed back port %d, want %d: the wrong port was released", - got, ports[stopping.name]) + got, ports[stopping.aux.name]) } }) } @@ -520,7 +523,7 @@ func TestTheMetersSidecarIsUnsubscribedFromTheHubItSubscribedTo(t *testing.T) { e.hub.Subscribe("meters", port) // decoy of the same name on the ingest e.meters, e.metersPort, e.metersSig, e.metersHub = loudTestProc(), port, "met-sig", silenceHub - e.stopAux(&e.meters, "meters") + e.stopAux(auxMeters) if hasSubscriber(silenceHub, "meters") { t.Error("the sidecar was not unsubscribed from the relay it was actually reading; " + diff --git a/internal/supervisor/supervisor.go b/internal/supervisor/supervisor.go index 419e1174..08724f34 100644 --- a/internal/supervisor/supervisor.go +++ b/internal/supervisor/supervisor.go @@ -1117,13 +1117,37 @@ func (p *Process) terminate() { }() } +// kill sends SIGKILL to the child's whole process group. +// +// THE REAPED-CHECK IS THE POINT. #720. killGroup issues a raw +// syscall.Kill(-pid, SIGKILL), which names a process GROUP BY NUMBER and +// bypasses Go's ErrProcessDone guard -- so on a reaped pid it can signal a +// group this supervisor never started. +// +// Its two sibling signal sites each already carry a device for this: terminate +// has the `signalled` latch, and the escalator has a `<-exited` guard. This one +// had neither, and rested instead on an ordering argument spanning three +// functions, written as a comment beside the call it protects. The argument was +// correct; it was not a device, and the family's other two members did not +// settle for one. func (p *Process) kill() { p.cmdMu.Lock() - cmd := p.cmd + cmd, exited := p.cmd, p.exited p.cmdMu.Unlock() - if cmd != nil { - killGroup(cmd) + if cmd == nil { + return + } + // Non-blocking: `exited` is closed the instant cmd.Wait() returns for this + // cmd, so a closed channel means the pid has been reaped and the number is + // no longer ours to signal. + if exited != nil { + select { + case <-exited: + return + default: + } } + killGroup(cmd) } func (p *Process) setState(s State, errMsg string) { From 81889a645c9707c0bdf413e3de5ca673b99f68d1 Mon Sep 17 00:00:00 2001 From: Shannon Atkinson Date: Fri, 4 Sep 2026 16:15:07 -0700 Subject: [PATCH 2/8] fix: five more audit devices, and one finding the code disproved Closes #705. Closes #712. Closes #713. Closes #718. Closes #721. #705 -- fsperm's ACL builder stored SIDs as unpinned integers. TrusteeValueFromSID converts a *windows.SID to a uintptr and x/sys says in as many words: "The caller must pin sid using a runtime.Pinner for the lifetime of the TrusteeValue." Both SIDs are Go-allocated and collectable, and the EXPLICIT_ACCESS outlives the call. The pinner is taken in restrict rather than in grantFull -- the version that looks correct and is not, because a pinner there unpins on return, before ACLFromEntries ever reads the trustee. Consequence was a wrong DACL, not heap corruption, on the files holding every stream key. #712 -- destWritesAFile now fails CLOSED on a kind this build does not know. db.DestKind and ffmpeg.DestKind are declared independently and joined by a cast that compiles for any string, so a fifth kind reaches the default. Returning false there was wrong for the reason the function's own comment gives: without the confinement an audio file target is written relative to the process working directory. An unknown kind is now treated as a file writer and confined, and RTMP/SRT are named rather than left to the default so the exhaustiveness is visible. #718 -- resetadmin printed "every existing session has been signed out" and stopped. True and incomplete: the epoch ends SESSIONS, while API tokens are resolved by hash alone and survive. This is the command an operator reaches for when they cannot sign in, which is the compromise case, and it was the one path that could not say what still had access. It now always lists the surviving tokens and how to end them, mirroring the disclosure the HTTP handler already performs, and --revoke-api-tokens does the ending. Opt-in rather than implied, for the reason that handler argues: routine rotation is the common case and destroying every integration's credential is the wrong default for it. #721 -- isSetup and setupSlot are two switches over one closed type set, folded into a single condition in cacheSetup that made "ordinary media" and "setup with no slot" indistinguishable. A test now asserts they agree on every handled type. The runtime log the issue also proposed was NOT taken: `stream` has no logger, threading one in for this is not worth it, and a build-time comparison catches the disagreement when it is written rather than when it hangs somebody's ffprobe. Two mutations, each red -- dropping a type from either switch. #713 -- AND THE CODE DISPROVED THE FINDING AS FILED, which is recorded rather than quietly fixed. The issue says Rumble, Trovo and Vimeo are "silently exempt from loudness checking" and should get policy rows. Reading internal/db's constants says otherwise: Rumble "exists for CHAT and for nothing else", Vimeo "for SIGN-IN", and Trovo can fetch a stream key but not the ingest URL beside it, so all three are pasted by hand and behave as custom destinations do. They take the custom row deliberately. The hazard the issue identified is still real, and it is the other half of its own sentence: nothing distinguishes "custom by choice" from "custom because the table forgot you". So the device is a test that forces the decision to be STATED -- an opt-out list carrying the reason per platform, with a second test refusing a placeholder reason and refusing to let the list grow past four. Three silent omissions become three stated decisions, and a fourth fails. Two mutations red. Claude-Session: https://claude.ai/code/session_01A8N3W5ct9SZtHK9sCDD9cL --- cmd/polyemesis/main.go | 9 +- cmd/polyemesis/resetadmin.go | 43 +++++++- cmd/polyemesis/resetadmin_test.go | 84 ++++++++++++++- internal/engine/destinations.go | 19 +++- internal/fsperm/fsperm_windows.go | 22 ++++ internal/routing/platform_drift_test.go | 95 +++++++++++++++++ internal/rtmpserver/setup_agreement_test.go | 108 ++++++++++++++++++++ 7 files changed, 374 insertions(+), 6 deletions(-) create mode 100644 internal/routing/platform_drift_test.go create mode 100644 internal/rtmpserver/setup_agreement_test.go diff --git a/cmd/polyemesis/main.go b/cmd/polyemesis/main.go index 07071074..fe3687ba 100644 --- a/cmd/polyemesis/main.go +++ b/cmd/polyemesis/main.go @@ -116,6 +116,13 @@ func run(h *hooks) error { logLevel = flag.String("log", "info", "log level: debug, info, warn, error") showVersion = flag.Bool("version", false, "print the version and exit") resetPass = flag.Bool("reset-admin", false, "set a new admin password and sign out every session, then exit") + // #718. A password change ends SESSIONS; API tokens carry no epoch and + // survive it. The command now always says which tokens survive, and + // this is how an operator who has decided they are compromised ends + // them from a shell they can reach. Opt-in rather than implied: routine + // rotation is the common case and destroying every integration's + // credential is the wrong default for it. + resetRevoke = flag.Bool("revoke-api-tokens", false, "with -reset-admin, also delete every API token") verifyBak = flag.String("verify-backup", "", "check that a backup directory holds a database that opens, then exit") ) flag.Parse() @@ -183,7 +190,7 @@ func run(h *hooks) error { } if *resetPass { - return resetAdmin(cfg, os.Stdin, os.Stdout) + return resetAdmin(cfg, os.Stdin, os.Stdout, *resetRevoke) } // Text overlays need a font FILE, and the image polyemesis ships has no // system fonts at all -- fontconfig is installed and finds nothing. The diff --git a/cmd/polyemesis/resetadmin.go b/cmd/polyemesis/resetadmin.go index 533bfd73..37d01d9d 100644 --- a/cmd/polyemesis/resetadmin.go +++ b/cmd/polyemesis/resetadmin.go @@ -37,7 +37,7 @@ import ( // a security operation rather than a convenience. Someone resetting a forgotten // password may be locking an intruder out, and leaving that intruder's existing // session valid would defeat the whole exercise. -func resetAdmin(cfg config.Config, in io.Reader, out io.Writer) error { +func resetAdmin(cfg config.Config, in io.Reader, out io.Writer, revokeTokens bool) error { store, err := db.Open(cfg.DBPath()) if err != nil { return fmt.Errorf("open database: %w", err) @@ -68,7 +68,48 @@ func resetAdmin(cfg config.Config, in io.Reader, out io.Writer) error { return fmt.Errorf("password changed, but existing sessions could not be invalidated: %w", err) } + // WHAT SURVIVES, ALWAYS, AND NOT ONLY WHEN IT IS EMPTY. #718. + // + // This printed "every existing session has been signed out" and stopped + // there. That sentence is true and incomplete: bumping the epoch ends + // SESSIONS, and API tokens are resolved by hash alone and carry no epoch, so + // they live on. An operator reaching for this command is usually locked out, + // which is the compromise case -- and this is the one path that could not + // tell them what still has access. + // + // The HTTP handler for the same gesture reads the surviving tokens back and + // discloses them. Mirroring that here is the device: the operator is told, + // every time, rather than left to assume. Deliberately NOT a forced revoke, + // for the reason that handler's own comment gives -- routine rotation is the + // common case, and destroying every integration's credential is the wrong + // default for it. --revoke-api-tokens is the explicit ask. fmt.Fprintf(out, "password reset for %q; every existing session has been signed out\n", user.Username) + + if revokeTokens { + n, rerr := store.DeleteAllAPITokens() + if rerr != nil { + fmt.Fprintf(out, "WARNING: the password changed, but the API tokens could not be\n"+ + " revoked (%v). They still work.\n", rerr) + } else { + fmt.Fprintf(out, "%d API token(s) revoked.\n", n) + } + } + + tokens, terr := store.ListAPITokens() + switch { + case terr != nil: + fmt.Fprintf(out, "WARNING: could not read the API token list (%v). Tokens are NOT\n"+ + " ended by a password change, and this command could not tell you what survives.\n", terr) + case len(tokens) == 0: + fmt.Fprintln(out, "no API tokens exist, so nothing else can reach this install.") + default: + fmt.Fprintf(out, "\n%d API TOKEN(S) STILL WORK. A password change does not end them:\n", len(tokens)) + for _, t := range tokens { + fmt.Fprintf(out, " - %s (%s, created %s)\n", t.Name, t.Scope, t.CreatedAt.Format("2006-01-02")) + } + fmt.Fprintln(out, "Re-run with --revoke-api-tokens to delete them, or revoke them\n"+ + "individually in Settings once you can sign in.") + } return nil } diff --git a/cmd/polyemesis/resetadmin_test.go b/cmd/polyemesis/resetadmin_test.go index 238c8cc2..1aae0ca5 100644 --- a/cmd/polyemesis/resetadmin_test.go +++ b/cmd/polyemesis/resetadmin_test.go @@ -40,7 +40,7 @@ func TestResetAdminNeverLeavesTheInstallUnowned(t *testing.T) { var out bytes.Buffer in := strings.NewReader("a-brand-new-password\na-brand-new-password\n") - if err := resetAdmin(cfg, in, &out); err != nil { + if err := resetAdmin(cfg, in, &out, false); err != nil { t.Fatalf("resetAdmin: %v", err) } @@ -72,7 +72,7 @@ func TestResetAdminChangesThePassword(t *testing.T) { store.Close() var out bytes.Buffer - if err := resetAdmin(cfg, strings.NewReader("a-brand-new-password\na-brand-new-password\n"), &out); err != nil { + if err := resetAdmin(cfg, strings.NewReader("a-brand-new-password\na-brand-new-password\n"), &out, false); err != nil { t.Fatalf("resetAdmin: %v", err) } @@ -121,7 +121,7 @@ func TestResetAdminRefusals(t *testing.T) { store.Close() var out bytes.Buffer - err := resetAdmin(cfg, strings.NewReader(tc.input), &out) + err := resetAdmin(cfg, strings.NewReader(tc.input), &out, false) if err == nil { t.Fatalf("expected a refusal, got success") } @@ -163,3 +163,81 @@ func readSource(t *testing.T, name string) (string, error) { b, err := os.ReadFile(filepath.Join(".", name)) return string(b), err } + +// A PASSWORD CHANGE DOES NOT END API TOKENS, AND THE OPERATOR IS TOLD SO. #718. +// +// This command is the one an operator reaches for when they cannot sign in, +// which is the compromise case. It printed "every existing session has been +// signed out" and stopped there -- true, and incomplete: bumping token_epoch +// ends SESSIONS, while API tokens are resolved by hash alone, carry no epoch, +// and live on. Nothing listed them, so the sentence read as "access has ended" +// when it had not. +// +// The HTTP handler for the same gesture already reads the surviving tokens back +// and discloses them. This pins that the CLI does too. +func TestResetAdminNamesTheTokensThatSurviveIt(t *testing.T) { + cfg, store := resetFixture(t) + if _, err := store.CreateUser("admin", "the-old-password"); err != nil { + t.Fatalf("create: %v", err) + } + if _, _, err := store.CreateAPIToken("ci-runner", string(db.ScopeAdmin)); err != nil { + t.Fatalf("create token: %v", err) + } + store.Close() + + var out bytes.Buffer + in := strings.NewReader("a-brand-new-password\na-brand-new-password\n") + if err := resetAdmin(cfg, in, &out, false); err != nil { + t.Fatalf("resetAdmin: %v", err) + } + + got := out.String() + if !strings.Contains(got, "ci-runner") { + t.Errorf("the surviving token is not named in the output, so an operator who "+ + "has just locked out an intruder is not told what still reaches the "+ + "install:\n%s", got) + } + if !strings.Contains(got, "STILL WORK") { + t.Errorf("the output does not say the tokens still work. Naming them is only "+ + "half of it -- the sentence above them says sessions were signed out, and "+ + "a list under that reads as a list of things that were ended:\n%s", got) + } + if !strings.Contains(got, "--revoke-api-tokens") { + t.Errorf("the output does not say how to end them. An operator told there is a "+ + "problem and not told the remedy is worse off than one told nothing:\n%s", got) + } +} + +// And the flag actually revokes, or the sentence above is advice that does not work. +func TestResetAdminCanRevokeTheTokensItWarnsAbout(t *testing.T) { + cfg, store := resetFixture(t) + if _, err := store.CreateUser("admin", "the-old-password"); err != nil { + t.Fatalf("create: %v", err) + } + if _, _, err := store.CreateAPIToken("ci-runner", string(db.ScopeAdmin)); err != nil { + t.Fatalf("create token: %v", err) + } + store.Close() + + var out bytes.Buffer + in := strings.NewReader("a-brand-new-password\na-brand-new-password\n") + if err := resetAdmin(cfg, in, &out, true); err != nil { + t.Fatalf("resetAdmin: %v", err) + } + + reopened, err := db.Open(cfg.DBPath()) + if err != nil { + t.Fatalf("reopen: %v", err) + } + defer reopened.Close() + tokens, err := reopened.ListAPITokens() + if err != nil { + t.Fatalf("list: %v", err) + } + if len(tokens) != 0 { + t.Errorf("--revoke-api-tokens left %d token(s) in the database", len(tokens)) + } + if got := out.String(); !strings.Contains(got, "1 API token(s) revoked") { + t.Errorf("the output does not report what was revoked:\n%s", got) + } +} diff --git a/internal/engine/destinations.go b/internal/engine/destinations.go index cdb52197..d0cdc413 100644 --- a/internal/engine/destinations.go +++ b/internal/engine/destinations.go @@ -696,8 +696,25 @@ func destWritesAFile(row *db.Destination) bool { return true case db.DestAudio: return !strings.Contains(row.URL, "://") - default: + case db.DestRTMP, db.DestSRT: + // Named rather than left to the default, so the exhaustiveness is + // visible here and a linter can check it. return false + default: + // FAIL CLOSED ON A KIND THIS BUILD DOES NOT KNOW. #712. + // + // db.DestKind and ffmpeg.DestKind are declared independently and joined + // by ffmpeg.DestKind(row.Kind), which compiles for any string -- so a + // fifth kind added to db reaches here. Returning false was the wrong + // default for exactly the reason the comment above states: without the + // confinement an audio file target is written relative to the process + // working directory, outside the directory every other file destination + // is held to. + // + // Confinement is cheap; the alternative is an arbitrary-file-write + // primitive available to whoever adds the next kind. So an unknown kind + // is treated as a file writer and confined. + return true } } diff --git a/internal/fsperm/fsperm_windows.go b/internal/fsperm/fsperm_windows.go index a2b0dd72..0c87393c 100644 --- a/internal/fsperm/fsperm_windows.go +++ b/internal/fsperm/fsperm_windows.go @@ -5,6 +5,7 @@ package fsperm import ( "fmt" "os" + "runtime" "unsafe" "golang.org/x/sys/windows" @@ -56,6 +57,27 @@ func restrict(path string, container bool) error { if container { inherit = windows.SUB_CONTAINERS_AND_OBJECTS_INHERIT } + // PINNED FOR THE LIFETIME OF THE TRUSTEE VALUES. #705. + // + // TrusteeValueFromSID converts a *windows.SID to a uintptr, and x/sys says + // in as many words: "The caller must pin sid using a runtime.Pinner for the + // lifetime of the TrusteeValue." After the conversion the EXPLICIT_ACCESS + // holds an integer and nothing holds the object -- both SIDs here are + // Go-allocated (one from the security descriptor, one from + // CreateWellKnownSid), so both are collectable. + // + // Taken HERE rather than inside grantFull, which is the version that looks + // correct and is not: a pinner there unpins on return, before ACLFromEntries + // ever reads the trustee. + // + // The consequence is a wrong DACL rather than heap corruption -- the kernel + // reads through the pointer, it does not write Go memory -- on the files + // that hold every destination's stream key. + var pinner runtime.Pinner + defer pinner.Unpin() + pinner.Pin(owner) + pinner.Pin(system) + entries := []windows.EXPLICIT_ACCESS{grantFull(owner, windows.TRUSTEE_IS_USER, inherit)} // Running as a service means the owner ALREADY is SYSTEM. A second identical // ACE would be harmless but makes the ACL confusing to anyone auditing it diff --git a/internal/routing/platform_drift_test.go b/internal/routing/platform_drift_test.go new file mode 100644 index 00000000..0a71332f --- /dev/null +++ b/internal/routing/platform_drift_test.go @@ -0,0 +1,95 @@ +package routing + +import ( + "strings" + "testing" +) + +// Every platform db knows about must have a decision recorded here. #713. +// +// internal/db declares eight platforms; platformPolicies carries rows for five +// of them plus `custom`. PolicyFor returns the custom row for anything +// unlisted, and that fallback is right -- guessing "exclude" would delete audio +// from a mix, which policy.go argues at length. +// +// The hazard is not the fallback. It is that NOTHING DISTINGUISHES "custom by +// choice" from "custom because this table forgot you". A platform added to db +// and not here silently loses its loudness target: meters/compliance.go reads +// pol.TargetLUFS, gets 0 from the custom row, and Evaluate returns +// VerdictUnknown -- so that platform's streams are not loudness-checked while +// YouTube's, Twitch's, Kick's and Facebook's are, and nothing says so. +// +// THE OPT-OUT LIST IS THE POINT, not a weakening of the test. Rumble, Trovo and +// Vimeo take the custom row deliberately, and internal/db says why at each +// constant: Rumble "exists for CHAT and for nothing else", Vimeo "for SIGN-IN", +// and Trovo can fetch a stream key but not the ingest URL beside it, so all +// three are pasted by hand and behave as custom destinations do. Recording that +// here turns three silent omissions into three stated decisions -- and makes a +// FOURTH omission fail, which is the part that was missing. +// +// Detection rather than Control: Control would need db to own the table, and +// the dependency runs the other way (policy.go:24). +var platformsDeliberatelyCustom = map[string]string{ + "rumble": "chat only; its ingest URL and key are pasted by hand and the destination preset does not carry it", + "trovo": "the key is fetchable, the ingest hostname is not; the preset carries an empty URL", + "vimeo": "sign-in only; the live API is Enterprise-gated, so ingest is pasted by hand", +} + +// dbPlatforms mirrors internal/db's Platform constants. +// +// Duplicated rather than imported because internal/db imports internal/routing +// and the cycle is not worth breaking for a test. The drift THIS list can +// suffer is caught by the count assertion below plus db's own Validate switch, +// which enumerates the same eight. +var dbPlatforms = []string{ + "custom", "youtube", "twitch", "kick", "facebook", "rumble", "trovo", "vimeo", +} + +func TestEveryPlatformHasAStatedRoutingDecision(t *testing.T) { + if len(dbPlatforms) != 8 { + t.Fatalf("dbPlatforms has %d entries; internal/db declares eight, so this "+ + "list has drifted and every assertion below is against the wrong set", + len(dbPlatforms)) + } + + rowFor := map[string]bool{} + for _, pol := range platformPolicies { + rowFor[string(pol.Platform)] = true + } + + for _, p := range dbPlatforms { + hasRow := rowFor[p] + why, optedOut := platformsDeliberatelyCustom[p] + + switch { + case hasRow && optedOut: + t.Errorf("%s has a policy row AND an opt-out entry saying it takes the "+ + "custom row (%q). One of the two is stale.", p, why) + case !hasRow && !optedOut: + t.Errorf("%s is a platform internal/db knows about with no routing policy "+ + "row and no recorded reason for taking the custom one.\n"+ + " A destination on this platform silently gets TargetLUFS 0, so "+ + "Evaluate returns VerdictUnknown and it is not loudness-checked, while "+ + "YouTube and Twitch are.\n"+ + " Either add a row to platformPolicies, or add an entry to "+ + "platformsDeliberatelyCustom saying why custom is right for it.", p) + } + } +} + +// The opt-out list must not become a way to silence this test without thinking. +func TestTheCustomOptOutsExplainThemselves(t *testing.T) { + for p, why := range platformsDeliberatelyCustom { + if len(strings.TrimSpace(why)) < 25 { + t.Errorf("%s opts out of a routing policy with the reason %q, which is too "+ + "short to be one. The entry exists so the decision is readable, not so "+ + "the test passes.", p, why) + } + } + if len(platformsDeliberatelyCustom) > 4 { + t.Errorf("%d platforms now opt out of having a routing policy. That is most of "+ + "them, and at that point the table is the exception rather than the rule -- "+ + "worth asking whether PolicyFor's fallback should still be silent.", + len(platformsDeliberatelyCustom)) + } +} diff --git a/internal/rtmpserver/setup_agreement_test.go b/internal/rtmpserver/setup_agreement_test.go new file mode 100644 index 00000000..2cd64591 --- /dev/null +++ b/internal/rtmpserver/setup_agreement_test.go @@ -0,0 +1,108 @@ +package rtmpserver + +import ( + "fmt" + "testing" + + "github.com/bluenviron/gortmplib/pkg/message" +) + +// isSetup and setupSlot must agree about every type. #721. +// +// cacheSetup folds them into one condition: +// +// slot, ok := setupSlot(msg) +// if !ok || !isSetup(msg) { return } +// +// which makes two very different events indistinguishable. "This is ordinary +// media" happens several hundred times a second and is nothing. "This IS a +// setup message and no slot was found for it" is a bug, and returns in silence +// beside it. +// +// THIS EXACT SHAPE HAS ALREADY SHIPPED ONCE. The comment on isSetup's +// AudioExMultitrack arm records the outcome: matching only the unwrapped types +// cached the legacy track's configuration and nothing else, and ffprobe -- a +// late-joining subscriber, which is the normal case -- "hung forever instead of +// failing, because it was still waiting to identify streams it had the data for +// but no configuration for." +// +// A runtime log would have needed a logger threaded into `stream`, which has +// none. This is the cheaper and earlier device: the two switches are compared +// at build time, so a type added to one and not the other fails here rather +// than hanging somebody's ffprobe. +func TestIsSetupAndSetupSlotAgreeOnEveryType(t *testing.T) { + // Every message type either function claims to handle. A type added to one + // switch belongs here too; that is the one thing this test cannot check for + // itself, and the count assertion below is the guard on it. + cases := []struct { + name string + msg message.Message + // setup is what isSetup should say. Both functions are then required to + // agree with each other, which is the actual property. + setup bool + }{ + {"metadata", &message.DataAMF0{Payload: nil}, true}, + {"video config", &message.Video{Type: message.VideoTypeConfig}, true}, + {"video frame", &message.Video{Type: message.VideoTypeAU}, false}, + {"audio config", &message.Audio{AACType: message.AudioAACTypeConfig}, true}, + {"audio frame", &message.Audio{AACType: message.AudioAACTypeAU}, false}, + {"video-ex sequence start", &message.VideoExSequenceStart{}, true}, + {"audio-ex sequence start", &message.AudioExSequenceStart{}, true}, + {"audio-ex multichannel config", &message.AudioExMultichannelConfig{}, true}, + } + + if len(cases) < 8 { + t.Fatalf("only %d types enumerated; both switches handle more than that, so "+ + "this test is checking a subset and its agreement claim is too weak", + len(cases)) + } + + for _, c := range cases { + t.Run(c.name, func(t *testing.T) { + gotSetup := isSetup(c.msg) + _, gotSlot := setupSlot(c.msg) + + if gotSetup != c.setup { + t.Errorf("isSetup(%T) = %v, want %v", c.msg, gotSetup, c.setup) + } + // THE PROPERTY. A setup message with no slot is never cached, so a + // late subscriber never receives its configuration. + if gotSetup && !gotSlot { + t.Errorf("isSetup says %T is setup and setupSlot has no slot for it. "+ + "cacheSetup drops it silently, so every late-joining subscriber -- "+ + "which includes ffprobe -- gets data it cannot identify.", c.msg) + } + // The other direction is not a bug but is worth knowing about: a + // slot for something never cached is dead weight in the map. + if !gotSetup && gotSlot { + t.Logf("note: setupSlot has a slot for %T, which isSetup does not call "+ + "setup. Harmless today -- nothing reaches cacheSetup -- but the slot "+ + "is unreachable and one of the two switches is probably stale.", c.msg) + } + }) + } +} + +// The wrapper case, which is how every track after the first arrives and is the +// one that already went wrong. +func TestAWrappedSequenceStartIsBothSetupAndSlotted(t *testing.T) { + inner := &message.AudioExSequenceStart{} + msg := &message.AudioExMultitrack{TrackID: 1, Wrapped: inner} + + if !isSetup(msg) { + t.Fatal("a wrapped AudioExSequenceStart is not recognised as setup. E-RTMP " + + "multitrack sends tracks 2..N inside AudioExMultitrack, so this is how " + + "every track after the first arrives -- and missing it is what made " + + "ffprobe hang rather than fail.") + } + slot, ok := setupSlot(msg) + if !ok { + t.Fatal("a wrapped AudioExSequenceStart has no cache slot, so it is never " + + "replayed to a late subscriber") + } + if slot == "" { + t.Error("the slot name is empty, so every wrapped track would overwrite the same entry") + } + t.Logf("wrapped track 1 caches under %q", slot) + _ = fmt.Sprint(slot) +} From 43222051661b9b91502b87753f22d2c31590a121 Mon Sep 17 00:00:00 2001 From: Shannon Atkinson Date: Fri, 4 Sep 2026 16:38:35 -0700 Subject: [PATCH 3/8] fix(engine): return every relay port an engine took, and refuse a stale release #707 and #708, plus coverage for the devices the previous commit installed. THE PORT LEDGER. The relay pool is 500 ports shared across every engine, and Manager.Sync stops an engine on every source delete while the daemon keeps running -- so a port an engine fails to return is gone for the life of the process. Nothing reports it until Allocate starts failing, and then it fails everywhere at once and reads as an unrelated fault. Four kinds were not returned. Destinations, loudness, clips, captions, feeds, silence, backup and playlist went through a teardown that released; the recorder, preview, meters and renditions went through a bare `stop` helper that only called Stop. Measured before the fix: three ports plus one per rendition leaked per shutdown, and the hub kept their subscriptions. Engine.allocPort/releasePort now keep the ledger, so a release names a port THIS engine holds or is refused and logged (#708). Release took a bare int and did delete(a.held, p), so releasing twice silently un-held a port the pool may have since handed to a different engine -- two engines on one UDP port, which is what the allocator's bind probe exists to prevent. The probe only masks it while the first owner's child is bound; during restart backoff it is open. StopWithin carries a post-condition on heldPortCount. Each of the three leaks was mutation-tested red before the fix went in. COVERAGE FOR THE DEVICES. Eight guards from the previous commit had no test that had watched them fail, which is the one thing this audit says not to ship: - APITokenExists on a live, deleted, zero and absent id (#706) - tokenRevoked's fail-closed arm, reached by closing the store underneath it - requireScope with no principal in the context (#710) - eventView's explicit wsPassthrough case, and BOTH fail-closed arms -- the unclassified type, and a policy constant with no case, reached by planting one in the table (#716) - destWritesAFile on a kind this build does not know (#712) - kill() on a reaped pid, against the guard directly: the supervisor clears p.exited during teardown, so waiting for a real reap races the field the guard reads (#720) - resetadmin's disclosure when it cannot revoke and cannot read the token list, reached by breaking the table in two ways that survive db.Open (#718) Claude-Session: https://claude.ai/code/session_01A8N3W5ct9SZtHK9sCDD9cL --- cmd/polyemesis/resetadmin_test.go | 108 ++++++++++++ internal/api/poka_yoke_devices_test.go | 144 ++++++++++++++++ internal/db/tokens_test.go | 39 +++++ internal/engine/dest_confinement_test.go | 43 +++++ internal/engine/dest_stop_test.go | 4 +- internal/engine/destinations.go | 12 +- internal/engine/engine.go | 201 ++++++++++++++++++++--- internal/engine/lifecycle_test.go | 58 +++++-- internal/engine/preview_ondemand_test.go | 6 +- internal/engine/probe_giveup_test.go | 5 +- internal/engine/selector.go | 4 +- internal/engine/shutdown_ports_test.go | 138 ++++++++++++++++ internal/engine/silence.go | 8 +- internal/supervisor/census_test.go | 55 +++++++ 14 files changed, 763 insertions(+), 62 deletions(-) create mode 100644 internal/api/poka_yoke_devices_test.go create mode 100644 internal/engine/dest_confinement_test.go create mode 100644 internal/engine/shutdown_ports_test.go diff --git a/cmd/polyemesis/resetadmin_test.go b/cmd/polyemesis/resetadmin_test.go index 1aae0ca5..8efd0ab7 100644 --- a/cmd/polyemesis/resetadmin_test.go +++ b/cmd/polyemesis/resetadmin_test.go @@ -2,6 +2,7 @@ package main import ( "bytes" + "database/sql" "os" "path/filepath" "strings" @@ -9,8 +10,42 @@ import ( "github.com/rainmanjam/polyemesis/internal/config" "github.com/rainmanjam/polyemesis/internal/db" + + _ "modernc.org/sqlite" ) +// breakTheTokenTable makes both halves of the token disclosure fail, through a +// connection of its own, in a way that SURVIVES db.Open. +// +// Dropping the table does not work: resetAdmin opens the database itself, and +// Open runs the schema, which puts the table straight back. So this leaves the +// schema exactly as it is and breaks the two operations instead -- +// +// - a BEFORE DELETE trigger that aborts, so DeleteAllAPITokens fails; and +// - a row whose created_at holds text, so ListAPITokens fails on Scan. +// SQLite is dynamically typed and stores it happily; the Go driver cannot +// hand it to an int64. +// +// The alternative was a fake store, which would have tested the fake. +func breakTheTokenTable(t *testing.T, path string) { + t.Helper() + raw, err := sql.Open("sqlite", path) + if err != nil { + t.Fatalf("open raw: %v", err) + } + defer raw.Close() + for _, stmt := range []string{ + `CREATE TRIGGER no_token_deletes BEFORE DELETE ON api_tokens + BEGIN SELECT RAISE(ABORT, 'the token table refuses deletes'); END`, + `INSERT INTO api_tokens (name, prefix, token_hash, created_at, last_used_at, scope) + VALUES ('unreadable', 'poly_xx', 'x', 'not-a-timestamp', 0, 'admin')`, + } { + if _, err := raw.Exec(stmt); err != nil { + t.Fatalf("breaking the token table: %v", err) + } + } +} + func resetFixture(t *testing.T) (config.Config, *db.DB) { t.Helper() dir := t.TempDir() @@ -241,3 +276,76 @@ func TestResetAdminCanRevokeTheTokensItWarnsAbout(t *testing.T) { t.Errorf("the output does not report what was revoked:\n%s", got) } } + +// THE DISCLOSURE MUST SURVIVE ITS OWN FAILURE. #718. +// +// The device is that an operator running this command is always told what still +// reaches the install. Its two failure arms are the ones that matter most: they +// fire exactly when the command cannot answer the question, and an operator who +// is not told that silence means "unknown" will read it as "nothing". +// +// Reached by dropping the api_tokens table out from under the command, which is +// the only way to make both the delete and the list fail without a fake store. +// sqlite lets a second connection do that while resetAdmin holds its own. +func TestResetAdminSaysSoWhenItCannotReadTheSurvivingTokens(t *testing.T) { + cfg, store := resetFixture(t) + if _, err := store.CreateUser("admin", "the-old-password"); err != nil { + t.Fatalf("create: %v", err) + } + if _, _, err := store.CreateAPIToken("ci-runner", string(db.ScopeAdmin)); err != nil { + t.Fatalf("create token: %v", err) + } + store.Close() + breakTheTokenTable(t, cfg.DBPath()) + + var out bytes.Buffer + in := strings.NewReader("a-brand-new-password\na-brand-new-password\n") + // --revoke-api-tokens as well, so BOTH failure arms run in one command: the + // revoke that could not revoke, and the read-back that could not read. + if err := resetAdmin(cfg, in, &out, true); err != nil { + t.Fatalf("resetAdmin returned an error rather than reporting the trouble: %v", err) + } + + got := out.String() + // The password change itself must still have happened and still be reported. + // A token table that will not read is not a reason to leave the operator + // locked out, which is the situation they ran this from. + if !strings.Contains(got, "password reset") { + t.Errorf("the password reset is not reported:\n%s", got) + } + if !strings.Contains(got, "could not be") || !strings.Contains(got, "still work") { + t.Errorf("a revoke that failed does not say the tokens still work. An "+ + "operator who asked for a revoke and was not told it failed believes "+ + "the credentials are dead:\n%s", got) + } + if !strings.Contains(got, "could not read the API token list") { + t.Errorf("a token list that could not be read is passed over in silence, "+ + "which an operator reads as 'no tokens exist' -- the opposite of "+ + "what is known:\n%s", got) + } + if !strings.Contains(got, "NOT") { + t.Errorf("the warning does not say tokens are not ended by a password "+ + "change, which is the fact the whole disclosure exists to carry:\n%s", got) + } +} + +// And the ordinary quiet case still says something rather than nothing: an +// install with no tokens gets a sentence, not silence. Silence is what the two +// arms above must be distinguishable from. +func TestResetAdminSaysSoWhenNoTokensExist(t *testing.T) { + cfg, store := resetFixture(t) + if _, err := store.CreateUser("admin", "the-old-password"); err != nil { + t.Fatalf("create: %v", err) + } + store.Close() + + var out bytes.Buffer + in := strings.NewReader("a-brand-new-password\na-brand-new-password\n") + if err := resetAdmin(cfg, in, &out, false); err != nil { + t.Fatalf("resetAdmin: %v", err) + } + if got := out.String(); !strings.Contains(got, "no API tokens exist") { + t.Errorf("an install with no tokens is told nothing, so it cannot be "+ + "told apart from one whose token list could not be read:\n%s", got) + } +} diff --git a/internal/api/poka_yoke_devices_test.go b/internal/api/poka_yoke_devices_test.go new file mode 100644 index 00000000..e4910002 --- /dev/null +++ b/internal/api/poka_yoke_devices_test.go @@ -0,0 +1,144 @@ +package api + +import ( + "net/http" + "net/http/httptest" + "testing" + + "github.com/rainmanjam/polyemesis/internal/config" + "github.com/rainmanjam/polyemesis/internal/db" + "github.com/rainmanjam/polyemesis/internal/events" +) + +// tokenRevoked is the store-backed replacement for the in-process revoked map +// (#706). Its three arms are three different decisions, and only one of them is +// exercised by an end-to-end revoke test, so they are pinned here directly. +func TestTokenRevokedAsksTheStoreAndFailsClosed(t *testing.T) { + s, _, store := testServer(t, config.Config{}) + + tok, _, err := store.CreateAPIToken("live", string(db.ScopeAdmin)) + if err != nil { + t.Fatalf("create token: %v", err) + } + + if s.tokenRevoked(tok.ID) { + t.Error("a token that is still in the store reports as revoked; every " + + "socket opened with a working credential would be closed on its " + + "first ping") + } + + // A SESSION principal carries no token id, and passes zero here on every + // ping. It must not become a database read, and must never read as revoked. + if s.tokenRevoked(0) { + t.Error("a session socket (token id 0) reports as revoked") + } + + if err := store.DeleteAPIToken(tok.ID); err != nil { + t.Fatalf("delete: %v", err) + } + if !s.tokenRevoked(tok.ID) { + t.Error("a deleted token does not report as revoked -- the socket " + + "opened with it keeps streaming, which is the whole of #706") + } + + // FAIL CLOSED. An unreadable store is not a reason to keep streaming to a + // client whose credential can no longer be checked. Closing the database + // under the server is the only way to reach the error arm without a fake. + if err := store.Close(); err != nil { + t.Fatalf("close: %v", err) + } + if !s.tokenRevoked(tok.ID) { + t.Error("an unreadable store reports the token as surviving; this arm " + + "fails OPEN, and a store this socket cannot read is one requireAuth " + + "cannot read either") + } +} + +// requireScope with no principal in the context is a 401, not a pass. #710. +// +// Mounted without requireAuth, or after it in the wrong order, the old code +// waved the request through with no scope enforcement at all and no signal that +// it had. Every live group carries requireAuth too, so this changes no shipped +// behaviour -- it removes the affordance, and that is only worth having if +// something watches it. +func TestRequireScopeRefusesARequestWithNoPrincipal(t *testing.T) { + s, _, _ := testServer(t, config.Config{}) + + reached := false + h := s.requireScope(http.HandlerFunc(func(http.ResponseWriter, *http.Request) { + reached = true + })) + + w := httptest.NewRecorder() + // No requireAuth ahead of it, so the context carries no principal: exactly + // the mis-mounting the guard exists for. + h.ServeHTTP(w, httptest.NewRequest(http.MethodDelete, "/api/v1/sources/1", nil)) + + if reached { + t.Error("requireScope passed a request carrying no principal straight " + + "through to the handler, with no scope enforcement anywhere") + } + if w.Code != http.StatusUnauthorized { + t.Errorf("status = %d, want %d", w.Code, http.StatusUnauthorized) + } +} + +// Every event type must have a stated policy. #716. +// +// wsPolicy fails closed on an unrecognised type, which is right -- but +// wsPassthrough is iota, so it was ZERO, and it reached the fail-closed default +// through having no case of its own. Everything ordinary a socket carries +// travels as a passthrough, so the whole feed depended on a default that a +// later reordering of the constants would silently claim. +func TestEveryEventClassHasItsOwnCaseInTheWebSocketPolicy(t *testing.T) { + ev := events.Event{Type: events.TypeLog, Data: map[string]any{"line": "hello"}} + // READ-SCOPED, because an admin socket returns before the switch is + // consulted at all -- so only a read-scoped socket exercises the policy. + out, send := eventView(ev, true) + if !send { + t.Fatal("an ordinary passthrough event is dropped by the policy: this " + + "is a silent, total loss of the log/status/levels/stats feed, and " + + "it is what an unstated policy for wsPassthrough costs") + } + if out.Type != ev.Type { + t.Errorf("passthrough rewrote the event type: %q -> %q", ev.Type, out.Type) + } + + // The other half of the device: a type nobody stated is still refused. + if _, send := eventView(events.Event{Type: "a-type-no-build-has-ever-seen"}, true); send { + t.Error("an unclassified event type is forwarded; the fail-closed " + + "default has been lost") + } +} + +// The SECOND fail-closed arm: a policy CONSTANT with no case. #716. +// +// The arm above refuses an event type nobody classified. This one refuses a +// classification nobody implemented -- the switch's default, which used to +// `return ev, true` and would therefore have sent a read-scoped socket the +// ADMIN shape of any event whose new policy constant someone forgot to handle. +// That is the one direction a widening must never take. +// +// The only way to reach it is to be the mistake: a policy value this build has +// no case for, planted in the table and taken back out. Reaching it is the +// point -- a guard nobody has watched fail is a guard nobody should trust. +func TestAPolicyConstantWithNoCaseWithholdsTheEvent(t *testing.T) { + const planted = events.Type("planted-for-the-fail-closed-default") + const noSuchPolicy = wsPolicy(126) // no case in eventView, by construction + + wsEventPolicy[planted] = noSuchPolicy + t.Cleanup(func() { delete(wsEventPolicy, planted) }) + + ev := events.Event{Type: planted, Data: map[string]any{"streamKey": "live_abc"}} + out, send := eventView(ev, true) + if send { + t.Fatalf("a policy constant with no case sent the event through unredacted "+ + "to a read-scoped socket: %+v.\n"+ + " Adding a wsPolicy value and forgetting its case here is a silent "+ + "WIDENING -- the read socket receives the admin shape -- and it is the "+ + "one direction that must never happen by omission.", out) + } + if out.Type != "" { + t.Errorf("the withheld event is not zeroed: %+v", out) + } +} diff --git a/internal/db/tokens_test.go b/internal/db/tokens_test.go index cf7d822f..832dceda 100644 --- a/internal/db/tokens_test.go +++ b/internal/db/tokens_test.go @@ -192,3 +192,42 @@ func TestDeleteAPITokenReportsAnUnknownID(t *testing.T) { t.Errorf("DeleteAPIToken(404) error = %v, want ErrNotFound", err) } } + +// APITokenExists is what a live /ws socket asks instead of consulting an +// in-process set. #706. +func TestAPITokenExistsAnswersForBothOutcomes(t *testing.T) { + d := testDB(t) + tok, _, err := d.CreateAPIToken("ci-runner", string(ScopeAdmin)) + if err != nil { + t.Fatalf("create: %v", err) + } + + ok, err := d.APITokenExists(tok.ID) + if err != nil || !ok { + t.Fatalf("a live token reports exists=%v err=%v; a socket would be closed "+ + "on a credential that still works", ok, err) + } + + if err := d.DeleteAPIToken(tok.ID); err != nil { + t.Fatalf("delete: %v", err) + } + ok, err = d.APITokenExists(tok.ID) + if err != nil { + t.Fatalf("after delete: %v", err) + } + if ok { + t.Fatal("a deleted token still reports as existing, so the socket opened " + + "with it would keep streaming -- which is the whole of #706") + } + + // Zero is not an id and must not become a database round trip, because + // every socket without a token principal passes one on every ping. + if ok, err := d.APITokenExists(0); ok || err != nil { + t.Errorf("APITokenExists(0) = %v, %v; want false, nil", ok, err) + } + // An id that never existed is absent rather than an error: sql.ErrNoRows is + // the ordinary answer here and must not close a socket for the wrong reason. + if ok, err := d.APITokenExists(999999); ok || err != nil { + t.Errorf("APITokenExists(999999) = %v, %v; want false, nil", ok, err) + } +} diff --git a/internal/engine/dest_confinement_test.go b/internal/engine/dest_confinement_test.go new file mode 100644 index 00000000..db2bc5ff --- /dev/null +++ b/internal/engine/dest_confinement_test.go @@ -0,0 +1,43 @@ +package engine + +import ( + "testing" + + "github.com/rainmanjam/polyemesis/internal/db" +) + +// destWritesAFile decides whether a destination's output path is confined to +// the data directory. #712. +// +// The four shipped kinds are the easy half. What this exists for is the FIFTH: +// db.DestKind and ffmpeg.DestKind are declared independently and joined by a +// conversion that compiles for any string, so a kind added to db reaches the +// default arm here with nothing in between. Returning false there was an +// arbitrary-file-write primitive handed to whoever adds it. +func TestAnUnknownDestinationKindIsConfinedLikeAFileWriter(t *testing.T) { + for _, c := range []struct { + kind db.DestKind + url string + confine bool + why string + }{ + {db.DestFile, "out.mp4", true, "a file destination writes a file"}, + {db.DestAudio, "out.mp3", true, "a local audio target writes a file"}, + {db.DestAudio, "icecast://host/mount", false, "a streamed audio target writes no file"}, + {db.DestRTMP, "rtmp://host/app/key", false, "rtmp writes no file"}, + {db.DestSRT, "srt://host:9000", false, "srt writes no file"}, + { + // THE DEVICE. Not a kind that exists -- a kind that does not, which + // is the only state the default arm is reachable from and the exact + // shape the next db.DestKind will arrive in. + db.DestKind("hls-or-whatever-comes-next"), "somewhere/out.m3u8", true, + "a kind this build does not know is confined rather than trusted", + }, + } { + got := destWritesAFile(&db.Destination{Kind: c.kind, URL: c.url}) + if got != c.confine { + t.Errorf("destWritesAFile(%q, %q) = %v, want %v -- %s", + c.kind, c.url, got, c.confine, c.why) + } + } +} diff --git a/internal/engine/dest_stop_test.go b/internal/engine/dest_stop_test.go index b8c423a9..7b2ec8aa 100644 --- a/internal/engine/dest_stop_test.go +++ b/internal/engine/dest_stop_test.go @@ -30,11 +30,11 @@ func TestStopTakesTheBackupDownWithTheDestination(t *testing.T) { e.alloc = relay.NewPortAllocator(base, 2) row := backupRow() - primaryPort, err := e.alloc.Allocate() + primaryPort, err := e.allocPort() if err != nil { t.Fatalf("allocate primary: %v", err) } - backupPort, err := e.alloc.Allocate() + backupPort, err := e.allocPort() if err != nil { t.Fatalf("allocate backup: %v", err) } diff --git a/internal/engine/destinations.go b/internal/engine/destinations.go index d0cdc413..611d85f0 100644 --- a/internal/engine/destinations.go +++ b/internal/engine/destinations.go @@ -867,7 +867,7 @@ func (e *Engine) startDest(p destPlan, hub *relay.Hub, startDelay time.Duration) vodDropped = noteVODNotNegotiated } - port, err := e.alloc.Allocate() + port, err := e.allocPort() if err != nil { return err } @@ -898,7 +898,7 @@ func (e *Engine) startDest(p destPlan, hub *relay.Hub, startDelay time.Duration) // is reissued and the stale entry blasts transport-stream datagrams // into whatever now owns that socket. hub.Unsubscribe(subName) - e.alloc.Release(port) + e.releasePort(port) return err } target = resolved @@ -998,7 +998,7 @@ func (e *Engine) startDest(p destPlan, hub *relay.Hub, startDelay time.Duration) if e.stopped { e.mu.Unlock() hub.Unsubscribe(subName) - e.alloc.Release(port) + e.releasePort(port) return nil } e.dests[row.ID] = &destination{ @@ -1094,7 +1094,7 @@ func (e *Engine) teardownDest(d *destination) { hub.Unsubscribe(d.subName) } if d.port != 0 { - e.alloc.Release(d.port) + e.releasePort(d.port) } e.stopBackup(d) } @@ -1306,7 +1306,7 @@ func (e *Engine) buildBackup(d *destination, compiled routing.Result, spec strin if hub == nil { hub = e.hub } - port, err := e.alloc.Allocate() + port, err := e.allocPort() if err != nil { d.backupErr = "no relay port is free for the backup feed" e.log.Warn("backup ingest has no relay port; the primary is unaffected", @@ -1367,7 +1367,7 @@ func (e *Engine) stopBackup(d *destination) { hub.Unsubscribe(d.backupSub) } if d.backupPort != 0 { - e.alloc.Release(d.backupPort) + e.releasePort(d.backupPort) } } diff --git a/internal/engine/engine.go b/internal/engine/engine.go index f3514417..dcb0ceda 100644 --- a/internal/engine/engine.go +++ b/internal/engine/engine.go @@ -233,6 +233,13 @@ type Engine struct { // to a fresh goroutine rather than calling it inline. reconcileMu sync.Mutex + // heldMu guards heldPorts. Separate from e.mu because releasePort is called + // from teardown paths that already hold it. + heldMu sync.Mutex + // heldPorts is every relay port this engine has taken and not given back. + // See allocPort. + heldPorts map[int]struct{} + // reconciles counts completed Reconcile calls, for tests that need to prove // the work was ATTEMPTED rather than skipped. // @@ -1008,6 +1015,23 @@ func (e *Engine) StopWithin(ctx context.Context) { silence := e.silence sel, backup, playlist := e.sel, e.backup, e.playlist recorder, preview, meters, ingest := e.recorder, e.preview, e.meters, e.ingest + // THEIR PORTS AND HUBS TOO. #707. These three used to be collected as bare + // processes and stopped with a helper that only calls Stop, so their relay + // ports and hub subscriptions were never given back -- unlike every other + // consumer, which goes through a teardown that releases both. Collected + // here, under the same lock, and released after the stops below. + auxPorts := []int{e.recorderPort, e.previewPort, e.metersPort} + auxSubs := []struct { + hub *relay.Hub + name string + }{ + {e.hub, "recorder"}, + {hubOr(e.previewHub, e.hub), "preview"}, + {hubOr(e.metersHub, e.hub), "meters"}, + } + e.recorderPort, e.previewPort, e.metersPort = 0, 0, 0 + e.previewHub, e.metersHub = nil, nil + e.recorderSig, e.previewSig, e.metersSig = "", "", "" e.dests = map[int64]*destination{} e.rends = map[int64]*rendition{} e.silence = nil @@ -1071,10 +1095,29 @@ func (e *Engine) StopWithin(ctx context.Context) { } wg.Wait() for _, r := range rends { + // #707. The rendition's own subscription and port, which this loop used + // to skip: it closed the output hub and stopped the process, and left + // the INPUT subscription and the port behind. teardownRendition does + // both; this path did not, and renditions are the per-source multiplier + // on the leak. + if r.subName != "" { + in := r.in + if in == nil { + in = e.hub + } + in.Unsubscribe(r.subName) + } + e.releasePort(r.port) if r.hub != nil { _ = r.hub.Close() } } + for i, p := range auxPorts { + if sub := auxSubs[i]; sub.hub != nil { + sub.hub.Unsubscribe(sub.name) + } + e.releasePort(p) + } // One more level up. The order here is the same dependency chain the // reconcile uses, read from the bottom: the renditions above were reading @@ -1104,6 +1147,22 @@ func (e *Engine) StopWithin(ctx context.Context) { if sink := e.sink.Swap(nil); sink != nil { _ = sink.Close() } + // THE POST-CONDITION, and it is the device rather than the fix. #707. + // + // The fix above gives four kinds their ports back. This says so out loud if + // a FIFTH is ever added and does not -- which is the mistake that was + // available, and the one that produced a silent three-ports-per-delete leak + // out of a 500-port pool shared across every engine. + // + // Reported rather than fatal: a shutdown is the wrong moment to panic, and + // a leaked port costs one slot rather than correctness. But it is at Error, + // because the alternative is discovering it when Allocate starts failing + // everywhere at once and reads as an unrelated fault. + if n := e.heldPortCount(); n > 0 { + e.log.Error("engine shutdown did not return every relay port it held; "+ + "the pool is shared across all engines and these are gone until restart", + "leaked", n) + } e.log.Info("engine stopped") } @@ -1750,7 +1809,7 @@ func (e *Engine) reconcileRecorder(s db.Settings) { e.log.Error("cannot create recordings directory", "err", err) return } - port, err := e.alloc.Allocate() + port, err := e.allocPort() if err != nil { e.log.Error("recorder: no relay port", "err", err) return @@ -1792,7 +1851,7 @@ func (e *Engine) reconcileRecorder(s db.Settings) { if e.stopped { e.mu.Unlock() e.hub.Unsubscribe("recorder") - e.alloc.Release(port) + e.releasePort(port) return } e.recorder = proc @@ -2041,7 +2100,7 @@ func (e *Engine) startPreviewLocked(s db.Settings) { // player before the new ones appear. clearDir(dir) - port, err := e.alloc.Allocate() + port, err := e.allocPort() if err != nil { e.log.Error("preview: no relay port", "err", err) return @@ -2092,7 +2151,7 @@ func (e *Engine) startPreviewLocked(s db.Settings) { if e.stopped { e.mu.Unlock() hub.Unsubscribe("preview") - e.alloc.Release(port) + e.releasePort(port) return } e.preview = proc @@ -2210,7 +2269,7 @@ func (e *Engine) reconcileMeters(s db.Settings) { e.stopAux(auxMeters) } - port, err := e.alloc.Allocate() + port, err := e.allocPort() if err != nil { e.log.Error("meters: no relay port", "err", err) return @@ -2257,7 +2316,7 @@ func (e *Engine) reconcileMeters(s db.Settings) { if e.stopped { e.mu.Unlock() meterHub.Unsubscribe("meters") - e.alloc.Release(port) + e.releasePort(port) return } e.meters = proc @@ -2925,7 +2984,7 @@ func (e *Engine) startRendition(row *db.Rendition, spec string, sourceFPS float6 return } - port, err := e.alloc.Allocate() + port, err := e.allocPort() if err != nil { fail(err) return @@ -2934,7 +2993,7 @@ func (e *Engine) startRendition(row *db.Rendition, spec string, sourceFPS float6 // ingest. Port 0 lets the kernel pick, well clear of the allocator's range. hub, err := relay.New(e.log, 0) if err != nil { - e.alloc.Release(port) + e.releasePort(port) fail(err) return } @@ -2946,13 +3005,13 @@ func (e *Engine) startRendition(row *db.Rendition, spec string, sourceFPS float6 upstream := e.selectorHub() if upstream == nil { if err := e.selectorProblem(); err != nil { - e.alloc.Release(port) + e.releasePort(port) _ = hub.Close() fail(err) return } if err := e.silenceProblem(); err != nil { - e.alloc.Release(port) + e.releasePort(port) _ = hub.Close() fail(err) return @@ -3004,7 +3063,7 @@ func (e *Engine) startRendition(row *db.Rendition, spec string, sourceFPS float6 if e.stopped { e.mu.Unlock() upstream.Unsubscribe(subName) - e.alloc.Release(port) + e.releasePort(port) _ = hub.Close() return } @@ -3040,7 +3099,7 @@ func (e *Engine) teardownRendition(r *rendition) { in.Unsubscribe(r.subName) } if r.port != 0 { - e.alloc.Release(r.port) + e.releasePort(r.port) } // After the process, so the encode is never writing into a closed socket. if r.hub != nil { @@ -3108,6 +3167,96 @@ var ( } ) +// allocPort and releasePort are the only two ways this engine touches the port +// pool, and between them they let the engine answer "what am I still holding?". +// +// #707/#708. The pool is 500 ports shared across EVERY engine, and Manager.Sync +// stops an engine on every source delete while the daemon keeps running. So a +// port an engine fails to give back is gone for the life of the process, and +// nothing reports it until Allocate starts failing -- at which point it fails +// everywhere at once and reads as an unrelated fault. +// +// StopWithin was giving four kinds back and not the others. Destinations, +// loudness, clips, captions, feeds, silence, backup and playlist went through a +// teardown that released; the recorder, preview, meters and renditions went +// through a bare `stop` helper that only called Stop. Measured: three ports plus +// one per rendition leaked on every engine shutdown, and the hub kept their +// subscriptions. +// +// A SET RATHER THAN A COUNT, because the point is the post-condition: after +// StopWithin has run, this engine should hold nothing, and heldPorts is what +// makes that checkable. A future child kind that takes a port without giving it +// back fails that check by name instead of silently shrinking the pool. +// +// This is not the full lease the issues propose -- Allocate returning a value +// whose Release is the only spelling, so a stale int cannot be released at all. +// That reaches Control and touches thirteen sites that store a bare int. This +// reaches Warning: the mistake is still available, and it announces itself at +// the moment it happens rather than a fortnight later. +// hubOr is the consumer's own hub when it joined one, and the ingest otherwise. +// The preview and meters read whichever tier is on air, so both must +// unsubscribe from the hub they actually JOINED. +func hubOr(own, fallback *relay.Hub) *relay.Hub { + if own != nil { + return own + } + return fallback +} + +func (e *Engine) allocPort() (int, error) { + p, err := e.alloc.Allocate() + if err != nil { + return 0, err + } + e.heldMu.Lock() + if e.heldPorts == nil { + e.heldPorts = map[int]struct{}{} + } + e.heldPorts[p] = struct{}{} + e.heldMu.Unlock() + return p, nil +} + +// releasePort gives a port back, and refuses to give back one this engine does +// not hold. +// +// THE REFUSAL IS THE POINT, and it is #708. Release took a bare int and did +// `delete(a.held, p)`, so releasing a port twice silently un-held a port a +// DIFFERENT engine had since been given -- two engines pointed at one UDP port, +// which is precisely what the allocator's bind probe exists to prevent. The +// probe only masks it while the first owner's child is actually bound; during +// restart backoff, or between Allocate and Start, it is open. +// +// The reachable double-release: stopBackup deliberately does not clear +// d.backupPort (documented at destinations.go), so the struct still names a +// released port, and a later teardown releases it again. +func (e *Engine) releasePort(p int) { + if p == 0 { + return + } + e.heldMu.Lock() + _, mine := e.heldPorts[p] + delete(e.heldPorts, p) + e.heldMu.Unlock() + if !mine { + // Not fatal: the port may legitimately belong to nobody now. What must + // not happen silently is handing it back to the pool a second time, + // because the pool may already have given it to someone else. + e.log.Error("refusing to release a relay port this engine does not hold; "+ + "releasing it again would hand a port another engine may already own "+ + "back to the pool", "port", p) + return + } + e.alloc.Release(p) +} + +// heldPortCount is what StopWithin asserts on. +func (e *Engine) heldPortCount() int { + e.heldMu.Lock() + defer e.heldMu.Unlock() + return len(e.heldPorts) +} + func (e *Engine) stopAux(a auxSlot) { e.mu.Lock() slot := a.proc(e) @@ -3138,7 +3287,7 @@ func (e *Engine) stopAux(a auxSlot) { } hub.Unsubscribe(a.name) if port != 0 { - e.alloc.Release(port) + e.releasePort(port) } } @@ -3326,7 +3475,7 @@ func (e *Engine) probeFailedNow(err error) { } func (e *Engine) probeOnce(ctx context.Context) bool { - port, err := e.alloc.Allocate() + port, err := e.allocPort() if err != nil { // THE THIRD WAY TO MEASURE NOTHING, and it used to be the only one that // said nothing and counted for nothing. Allocate walks the whole range @@ -3346,7 +3495,7 @@ func (e *Engine) probeOnce(ctx context.Context) bool { e.probeFailedNow(fmt.Errorf("no free relay port to probe the ingest: %w", err)) return false } - defer e.alloc.Release(port) + defer e.releasePort(port) name := "probe" url := e.hub.Subscribe(name, port) @@ -3801,7 +3950,7 @@ func (e *Engine) startLoudness(p loudnessPlan) { e.log.Warn("loudness monitor cannot run", "dest", p.name, "err", err) } - port, err := e.alloc.Allocate() + port, err := e.allocPort() if err != nil { fail(err) return @@ -3859,7 +4008,7 @@ func (e *Engine) startLoudness(p loudnessPlan) { if e.stopped || !want || cur.sig != p.sig { e.mu.Unlock() p.hub.Unsubscribe(subName) - e.alloc.Release(port) + e.releasePort(port) return } e.loud[p.id] = &loudnessMon{proc: proc, hub: p.hub, port: port, subName: subName, sig: p.sig} @@ -3888,7 +4037,7 @@ func (e *Engine) teardownLoudness(m *loudnessMon) { hub.Unsubscribe(m.subName) } if m.port != 0 { - e.alloc.Release(m.port) + e.releasePort(m.port) } } @@ -3999,7 +4148,7 @@ func (e *Engine) reconcileClips() { return } - port, err := e.alloc.Allocate() + port, err := e.allocPort() if err != nil { e.log.Error("clip buffer: no relay port", "err", err) return @@ -4012,7 +4161,7 @@ func (e *Engine) reconcileClips() { }) if err != nil { hub.Unsubscribe(clipSubName) - e.alloc.Release(port) + e.releasePort(port) e.log.Error("clip buffer", "err", err) return } @@ -4022,7 +4171,7 @@ func (e *Engine) reconcileClips() { e.mu.Unlock() _ = capt.Close() hub.Unsubscribe(clipSubName) - e.alloc.Release(port) + e.releasePort(port) return } e.clipCap, e.clipPort, e.clipHub, e.clipSig = capt, port, hub, want @@ -4044,7 +4193,7 @@ func (e *Engine) teardownClips(c *clips.Capturer, port int, hub *relay.Hub) { hub.Unsubscribe(clipSubName) _ = c.Close() if port != 0 { - e.alloc.Release(port) + e.releasePort(port) } e.log.Info("clip buffer stopped") } @@ -4354,7 +4503,7 @@ func (e *Engine) reconcileCaptions() { return } - port, err := e.alloc.Allocate() + port, err := e.allocPort() if err != nil { e.captionsFailed(fmt.Sprintf("live captions could not get a relay port: %v", err)) return @@ -4392,7 +4541,7 @@ func (e *Engine) reconcileCaptions() { ) if err != nil { hub.Unsubscribe(captSubName) - e.alloc.Release(port) + e.releasePort(port) _ = vtt.Close() e.captionsFailed(err.Error()) return @@ -4404,7 +4553,7 @@ func (e *Engine) reconcileCaptions() { } if err := capt.Start(ctx, url, modelPath, transcribe.LiveWorkDir(e.cfg.DataDir)); err != nil { hub.Unsubscribe(captSubName) - e.alloc.Release(port) + e.releasePort(port) _ = vtt.Close() e.captionsFailed(err.Error()) return @@ -4486,7 +4635,7 @@ func (e *Engine) teardownCaptions(c *transcribe.LiveCaptioner, port int, hub *re c.Stop() _ = vtt.Close() if port != 0 { - e.alloc.Release(port) + e.releasePort(port) } e.log.Info("live captions stopped") } diff --git a/internal/engine/lifecycle_test.go b/internal/engine/lifecycle_test.go index b9223c0b..0af5599b 100644 --- a/internal/engine/lifecycle_test.go +++ b/internal/engine/lifecycle_test.go @@ -84,6 +84,28 @@ func hasSubscriber(h *relay.Hub, name string) bool { // mustAllocate fails the test rather than returning, because every caller is // asserting that a port came BACK and "it did not" is the defect. +// enginePort takes a port THROUGH THE ENGINE, the way production does. +// +// #707/#708. The engine now keeps a ledger of the ports it holds so StopWithin +// can assert it gave them all back, and releasePort refuses to hand back one +// this engine does not hold -- which is what stops a double release from +// returning a port another engine has since been given. +// +// A test that allocates straight off e.alloc therefore sets up a state +// production cannot reach: a port in the pool but not in the ledger. Teardown +// then correctly refuses to release it, and the test fails for a reason that is +// about the fixture rather than the path under test. Going through the engine +// keeps the fixture honest and exercises the real door. +func enginePort(t *testing.T, e *Engine, why string) int { + t.Helper() + p, err := e.allocPort() + if err != nil { + t.Fatalf("%s: the allocator has no free port left (%v), so the one taken "+ + "by the path under test was never released", why, err) + } + return p +} + func mustAllocate(t *testing.T, a *relay.PortAllocator, why string) int { t.Helper() p, err := a.Allocate() @@ -187,7 +209,7 @@ func TestARenditionRefusedByABrokenUpstreamTierGivesItsPortBack(t *testing.T) { if !strings.Contains(r.err, tc.names) { t.Errorf("recorded error = %q, want %q named as the cause", r.err, tc.names) } - mustAllocate(t, e.alloc, "after a rendition was refused by "+tc.name) + enginePort(t, e, "after a rendition was refused by "+tc.name) }) } } @@ -209,7 +231,7 @@ func TestARenditionStartingIntoAShutdownEngineLeavesNoOrphan(t *testing.T) { if hasSubscriber(e.hub, "rendition:1") { t.Error("the ingest hub is still forwarding to a rendition that was never started") } - mustAllocate(t, e.alloc, "after a rendition start was abandoned at shutdown") + enginePort(t, e, "after a rendition start was abandoned at shutdown") } // The success path and its undo, together: what start publishes is exactly what @@ -273,7 +295,7 @@ func TestAStartedRenditionPublishesTheWiringItsTeardownNeeds(t *testing.T) { t.Error("teardown removed the ingest hub's own consumer of that name, which this " + "rendition never subscribed to") } - mustAllocate(t, e.alloc, "after a rendition was torn down") + enginePort(t, e, "after a rendition was torn down") } // The rendition reads the silence tier's hub, not the ingest's, whenever a @@ -285,7 +307,7 @@ func TestTeardownUnsubscribesFromTheHubTheEncodeActuallyRead(t *testing.T) { e.alloc = oneSlotAllocator(t) upstream := lifeHub(t) // stands in for the silence or selector tier's relay - port := mustAllocate(t, e.alloc, "reserving the rendition's port") + port := enginePort(t, e, "reserving the rendition's port") upstream.Subscribe("rendition:1", port) // A decoy of the SAME NAME on the ingest hub. If teardown unsubscribes from // e.hub it will look like it worked unless something is watching that name @@ -306,7 +328,7 @@ func TestTeardownUnsubscribesFromTheHubTheEncodeActuallyRead(t *testing.T) { t.Error("teardown unsubscribed from the ingest hub, which this rendition never " + "subscribed to -- it removed an unrelated consumer of the same name") } - mustAllocate(t, e.alloc, "after a rendition reading a non-ingest hub was torn down") + enginePort(t, e, "after a rendition reading a non-ingest hub was torn down") } // A caption must never cost the picture. An FFmpeg built without libfreetype @@ -366,7 +388,7 @@ func TestATeardownWithNoRecordedUpstreamFallsBackToTheIngestRatherThanPanicking( t.Run("rendition", func(t *testing.T) { e := lifeEngine(t) e.alloc = oneSlotAllocator(t) - port := mustAllocate(t, e.alloc, "reserving the rendition's port") + port := enginePort(t, e, "reserving the rendition's port") e.hub.Subscribe("rendition:1", port) e.teardownRendition(&rendition{ @@ -377,13 +399,13 @@ func TestATeardownWithNoRecordedUpstreamFallsBackToTheIngestRatherThanPanicking( t.Error("the ingest hub still forwards to a torn-down rendition that never " + "recorded which relay it read") } - mustAllocate(t, e.alloc, "after a rendition with no recorded upstream was torn down") + enginePort(t, e, "after a rendition with no recorded upstream was torn down") }) t.Run("loudness monitor", func(t *testing.T) { e := lifeEngine(t) e.alloc = oneSlotAllocator(t) - port := mustAllocate(t, e.alloc, "reserving the analyser's port") + port := enginePort(t, e, "reserving the analyser's port") e.hub.Subscribe(loudnessSubPrefix+"7", port) e.teardownLoudness(&loudnessMon{port: port, subName: loudnessSubPrefix + "7"}) @@ -392,7 +414,7 @@ func TestATeardownWithNoRecordedUpstreamFallsBackToTheIngestRatherThanPanicking( t.Error("the ingest hub still forwards to a torn-down analyser that never " + "recorded which relay it read") } - mustAllocate(t, e.alloc, "after an analyser with no recorded upstream was torn down") + enginePort(t, e, "after an analyser with no recorded upstream was torn down") }) } @@ -455,7 +477,7 @@ func TestStoppingOneAuxiliaryChildClearsOnlyItsOwnPortAndSignature(t *testing.T) e.alloc = relay.NewPortAllocator(base, 3) ports := map[string]int{} for _, s := range slots { - ports[s.aux.name] = mustAllocate(t, e.alloc, "reserving "+s.aux.name+"'s port") + ports[s.aux.name] = enginePort(t, e, "reserving "+s.aux.name+"'s port") e.hub.Subscribe(s.aux.name, ports[s.aux.name]) } e.recorder, e.preview, e.meters = loudTestProc(), loudTestProc(), loudTestProc() @@ -502,7 +524,7 @@ func TestStoppingOneAuxiliaryChildClearsOnlyItsOwnPortAndSignature(t *testing.T) } // The released port is identifiable because nothing else is free. - if got := mustAllocate(t, e.alloc, "after stopping "+stopping.aux.name); got != ports[stopping.aux.name] { + if got := enginePort(t, e, "after stopping "+stopping.aux.name); got != ports[stopping.aux.name] { t.Errorf("the allocator handed back port %d, want %d: the wrong port was released", got, ports[stopping.aux.name]) } @@ -518,7 +540,7 @@ func TestTheMetersSidecarIsUnsubscribedFromTheHubItSubscribedTo(t *testing.T) { e.alloc = oneSlotAllocator(t) silenceHub := lifeHub(t) - port := mustAllocate(t, e.alloc, "reserving the sidecar's port") + port := enginePort(t, e, "reserving the sidecar's port") silenceHub.Subscribe("meters", port) e.hub.Subscribe("meters", port) // decoy of the same name on the ingest e.meters, e.metersPort, e.metersSig, e.metersHub = loudTestProc(), port, "met-sig", silenceHub @@ -536,7 +558,7 @@ func TestTheMetersSidecarIsUnsubscribedFromTheHubItSubscribedTo(t *testing.T) { t.Error("metersHub still points at the old relay, so the next stop unsubscribes " + "from a hub this sidecar never read") } - mustAllocate(t, e.alloc, "after the meters sidecar was stopped") + enginePort(t, e, "after the meters sidecar was stopped") } // --------------------------------------------------------------------- preview @@ -705,7 +727,7 @@ func TestAPreviewRequestedDuringShutdownStartsNothing(t *testing.T) { if hasSubscriber(e.hub, "preview") { t.Error("the ingest hub is forwarding to a preview that was never started") } - mustAllocate(t, e.alloc, "after a preview start into a stopped engine") + enginePort(t, e, "after a preview start into a stopped engine") } // The playlist left behind would be served to the next viewer, pointing at @@ -739,7 +761,7 @@ func TestStoppingThePreviewRemovesThePlaylistAndReturnsThePort(t *testing.T) { if hasSubscriber(e.hub, "preview") { t.Error("the hub still forwards to a stopped preview encoder") } - mustAllocate(t, e.alloc, "after the preview was stopped") + enginePort(t, e, "after the preview was stopped") } // The encoder exists to serve a dashboard nobody may be looking at. Both @@ -783,7 +805,7 @@ func TestSweepPreviewStopsAnIdleEncoderAndKeepsAWatchedOne(t *testing.T) { if hasSubscriber(e.hub, "preview") { t.Error("the idled-out encoder is still subscribed to the ingest") } - mustAllocate(t, e.alloc, "after the preview idled out") + enginePort(t, e, "after the preview idled out") }) } } @@ -859,7 +881,7 @@ func TestALoudnessMonitorStartingIntoAShutdownEngineLeavesNoOrphan(t *testing.T) if hasSubscriber(hub, loudnessSubPrefix+"7") { t.Error("the hub still forwards to an analyser that was never started") } - mustAllocate(t, e.alloc, "after an analyser start was abandoned at shutdown") + enginePort(t, e, "after an analyser start was abandoned at shutdown") } // The round trip. The analyser reads the destination's own upstream hub, which @@ -901,5 +923,5 @@ func TestALoudnessMonitorRoundTripsItsPortAndSubscription(t *testing.T) { if !hasSubscriber(e.hub, m.subName) { t.Error("teardown unsubscribed from the ingest hub, which this analyser never read") } - mustAllocate(t, e.alloc, "after an analyser was torn down") + enginePort(t, e, "after an analyser was torn down") } diff --git a/internal/engine/preview_ondemand_test.go b/internal/engine/preview_ondemand_test.go index 6d93270a..f1bdb985 100644 --- a/internal/engine/preview_ondemand_test.go +++ b/internal/engine/preview_ondemand_test.go @@ -258,7 +258,7 @@ func TestThePreviewRefusesToStartAgainstAQuietRelay(t *testing.T) { if hasSubscriber(e.hub, "preview") { t.Error("a refused start left a subscription on the hub") } - mustAllocate(t, e.alloc, "after a preview start that was refused") + enginePort(t, e, "after a preview start that was refused") } // A stream that ends stops the encoder without waiting out the idle window. @@ -296,7 +296,7 @@ func TestASweepStopsThePreviewWhenTheStreamEndsEvenThoughSomebodyIsWatching(t *t if hasSubscriber(e.hub, "preview") { t.Error("the stopped preview is still subscribed to the hub") } - mustAllocate(t, e.alloc, "after the sweep stopped a preview whose stream had ended") + enginePort(t, e, "after the sweep stopped a preview whose stream had ended") } // The preview reads the tier that is ON AIR, and gives back the hub it joined. @@ -347,5 +347,5 @@ func TestThePreviewJoinsAndThenLeavesTheHubThatIsOnAir(t *testing.T) { t.Error("the preview was released from some other hub and is still subscribed to " + "the one it joined; that hub is about to close under a live subscription") } - mustAllocate(t, e.alloc, "after the preview was stopped") + enginePort(t, e, "after the preview was stopped") } diff --git a/internal/engine/probe_giveup_test.go b/internal/engine/probe_giveup_test.go index 56d28ec4..e8e96c7f 100644 --- a/internal/engine/probe_giveup_test.go +++ b/internal/engine/probe_giveup_test.go @@ -92,7 +92,10 @@ func TestAProbeThatCannotGetAPortCountsTowardGivingUp(t *testing.T) { src := readEngineFile(t, "engine.go") body := funcBody(t, src, "func (e *Engine) probeOnce(ctx context.Context) bool {") - at := strings.Index(body, "port, err := e.alloc.Allocate()") + // e.allocPort(), not e.alloc.Allocate(): every port in this package now goes + // through the engine's own ledger so StopWithin can assert it gave them all + // back (#707). The branch this test reads is unchanged. + at := strings.Index(body, "port, err := e.allocPort()") if at < 0 { t.Fatal("cannot find the port allocation") } diff --git a/internal/engine/selector.go b/internal/engine/selector.go index 2aa5ff4f..2d442960 100644 --- a/internal/engine/selector.go +++ b/internal/engine/selector.go @@ -1548,7 +1548,7 @@ func (e *Engine) startFeed(s db.Settings, kind sourceKind, upstream, silenceSig if in == nil { return fail(fmt.Errorf("the %s source has no relay to read", kind)) } - port, err := e.alloc.Allocate() + port, err := e.allocPort() if err != nil { return fail(err) } @@ -1662,7 +1662,7 @@ func (e *Engine) teardownFeed(f *sourceFeed) error { f.in.Unsubscribe(f.subName) } if f.port != 0 { - e.alloc.Release(f.port) + e.releasePort(f.port) } return stopErr } diff --git a/internal/engine/shutdown_ports_test.go b/internal/engine/shutdown_ports_test.go new file mode 100644 index 00000000..7b53a7e9 --- /dev/null +++ b/internal/engine/shutdown_ports_test.go @@ -0,0 +1,138 @@ +package engine + +import ( + "testing" + + "github.com/rainmanjam/polyemesis/internal/relay" + "github.com/rainmanjam/polyemesis/internal/testenv" +) + +// STOPPING AN ENGINE GIVES BACK EVERY PORT IT TOOK. #707. +// +// The pool is 500 ports shared across every engine, and Manager.Sync stops an +// engine on every source delete while the daemon keeps running -- so a port an +// engine fails to return is gone for the life of the process. Nothing reports +// it until Allocate starts failing, and then it fails everywhere at once and +// reads as an unrelated fault. +// +// Four kinds were not being returned. Destinations, loudness, clips, captions, +// feeds, silence, backup and playlist went through a teardown that released; +// the recorder, preview, meters and renditions went through a bare `stop` +// helper that only called Stop. Measured before the fix: three ports plus one +// per rendition leaked per shutdown, and the hub kept their subscriptions. +// +// A SPAN WITH NO SPARE is what identifies the leak. If every port is taken and +// Stop returns them, the allocator can hand out exactly that many again; if it +// returns none, it can hand out none. A larger span would let a leak pass. +func TestStopReturnsEveryPortTheAuxChildrenTook(t *testing.T) { + e, _ := storeEngine(t) + + const span = 4 + base, held := testenv.FreeUDPWindow(t, span) + testenv.ReleaseAndSettle(t, held...) + e.alloc = relay.NewPortAllocator(base, span) + + // The three aux consumers and one rendition -- the exact four kinds that + // went through the non-releasing path. + e.mu.Lock() + e.recorder, e.preview, e.meters = loudTestProc(), loudTestProc(), loudTestProc() + e.recorderPort = enginePort(t, e, "recorder") + e.previewPort = enginePort(t, e, "preview") + e.metersPort = enginePort(t, e, "meters") + e.hub.Subscribe("recorder", e.recorderPort) + e.hub.Subscribe("preview", e.previewPort) + e.hub.Subscribe("meters", e.metersPort) + + rp := enginePort(t, e, "rendition") + e.rends = map[int64]*rendition{1: { + proc: loudTestProc(), port: rp, subName: "rend:1", in: e.hub, + }} + e.hub.Subscribe("rend:1", rp) + e.mu.Unlock() + + if got := e.heldPortCount(); got != span { + t.Fatalf("the fixture holds %d of %d ports; the assertion below only means "+ + "something when the pool is exactly full", got, span) + } + + e.Stop() + + // EVERY ONE BACK. Allocate span times: if any was leaked, one of these fails. + var reclaimed []int + for i := 0; i < span; i++ { + p, err := e.alloc.Allocate() + if err != nil { + t.Fatalf("port %d of %d was not returned by Stop: %v.\n"+ + " The pool is shared across every engine, so each deleted source "+ + "burns these permanently -- three plus one per rendition, silently, "+ + "until Allocate starts failing everywhere at once.", i+1, span, err) + } + reclaimed = append(reclaimed, p) + } + for _, p := range reclaimed { + e.alloc.Release(p) + } + + // And the engine agrees it is holding nothing, which is what the + // post-condition in StopWithin reports on. + if n := e.heldPortCount(); n != 0 { + t.Errorf("the engine still records %d held port(s) after Stop", n) + } + + // The subscriptions too: a released port with a live subscription still + // forwards, and the hub outlives the engine on a selector tier. + for _, name := range []string{"recorder", "preview", "meters", "rend:1"} { + if hasSubscriber(e.hub, name) { + t.Errorf("the hub still forwards to %q after Stop", name) + } + } +} + +// RELEASING A PORT THIS ENGINE DOES NOT HOLD IS REFUSED. #708. +// +// Release took a bare int and did delete(a.held, p), so releasing twice +// silently un-held a port the pool may have since given to a DIFFERENT engine +// -- two engines pointed at one UDP port, which is what the allocator's bind +// probe exists to prevent. The probe only masks it while the first owner's +// child is bound; during restart backoff, or between Allocate and Start, it is +// open. +// +// The reachable path: stopBackup deliberately does not clear d.backupPort, so +// the struct still names a released port and a later teardown releases it again. +func TestReleasingAPortTwiceDoesNotHandItBackTwice(t *testing.T) { + e, _ := storeEngine(t) + base, held := testenv.FreeUDPWindow(t, 2) + testenv.ReleaseAndSettle(t, held...) + e.alloc = relay.NewPortAllocator(base, 2) + + p := enginePort(t, e, "the port under test") + e.releasePort(p) + + // A second engine takes it, which is what makes the double release harmful + // rather than untidy. + other, _ := storeEngine(t) + other.alloc = e.alloc + taken, err := other.allocPort() + if err != nil { + t.Fatalf("the second engine could not take the released port: %v", err) + } + + // The first engine releases the stale int it still holds a copy of. + e.releasePort(p) + + if taken == p { + // The port the second engine holds must still be held by the pool. If + // the stale release un-held it, the pool will hand the SAME port out + // again -- to a third caller, while the second engine is using it. + again, err := e.alloc.Allocate() + if err == nil && again == p { + t.Fatalf("port %d was handed out again while another engine holds it. "+ + "A stale release returned a port the pool had already reassigned, "+ + "which is two engines on one UDP port -- one programme's "+ + "destination receiving another's stream.", p) + } + if err == nil { + e.alloc.Release(again) + } + } +} diff --git a/internal/engine/silence.go b/internal/engine/silence.go index dafac203..f8e924ac 100644 --- a/internal/engine/silence.go +++ b/internal/engine/silence.go @@ -205,14 +205,14 @@ func (e *Engine) startSilence(spec string) { e.log.Error("start silence tier", "err", err) } - port, err := e.alloc.Allocate() + port, err := e.allocPort() if err != nil { fail(err) return } hub, err := relay.New(e.log, 0) if err != nil { - e.alloc.Release(port) + e.releasePort(port) fail(err) return } @@ -237,7 +237,7 @@ func (e *Engine) startSilence(spec string) { if e.stopped { e.mu.Unlock() e.hub.Unsubscribe(silenceSubName) - e.alloc.Release(port) + e.releasePort(port) _ = hub.Close() return } @@ -264,7 +264,7 @@ func (e *Engine) teardownSilence(t *silenceTier) { e.hub.Unsubscribe(t.subName) } if t.port != 0 { - e.alloc.Release(t.port) + e.releasePort(t.port) } // After the process, so it is never writing into a closed socket. if t.hub != nil { diff --git a/internal/supervisor/census_test.go b/internal/supervisor/census_test.go index 2290ae81..1f3a5aa2 100644 --- a/internal/supervisor/census_test.go +++ b/internal/supervisor/census_test.go @@ -2,6 +2,9 @@ package supervisor import ( "context" + "io" + "log/slog" + "os/exec" "path/filepath" "strings" "testing" @@ -233,3 +236,55 @@ func TestASpawnThatFailedEnrolsNothing(t *testing.T) { time.Sleep(5 * time.Millisecond) } } + +// kill() must not signal a reaped pid. #720. +// +// killGroup issues a raw syscall.Kill(-pid, SIGKILL), which names a process +// GROUP by number and bypasses Go's ErrProcessDone -- so on a reaped pid it can +// signal a group this supervisor never started. Its two sibling signal sites +// each carry a guard for this; kill() rested on an ordering argument written as +// a comment across three functions. +// +// TESTED AGAINST THE GUARD DIRECTLY rather than through the supervisor, because +// the supervisor clears p.exited during teardown -- so waiting for a real reap +// races the very field the guard reads, and the test would be measuring the +// teardown rather than the guard. The escalation path on a LIVE child is +// covered by the stop/kill tests next door; what is missing there, and pinned +// here, is the reaped one. +func TestKillIsARefusalOnAReapedChild(t *testing.T) { + p := New(slog.New(slog.NewTextHandler(io.Discard, nil)), Spec{Name: "guard", Kind: "test"}) + + // A real child, run to completion and reaped, so its pid is a number the + // operating system may well have handed to somebody else by now. + f := fakeExit(0) + cmd := exec.Command(f.bin, f.args...) + if err := cmd.Start(); err != nil { + t.Fatalf("start: %v", err) + } + _ = cmd.Wait() + + exited := make(chan struct{}) + close(exited) // what runOnce does the instant cmd.Wait() returns + + p.cmdMu.Lock() + p.cmd, p.exited = cmd, exited + p.cmdMu.Unlock() + + // The guard's job: return without reaching killGroup. There is no assertion + // available on "no signal was sent" -- the syscall either happened or it did + // not -- so what is pinned is that a reaped child with a live cmd handle + // takes the early return rather than the signal. + done := make(chan struct{}) + go func() { p.kill(); close(done) }() + select { + case <-done: + case <-time.After(2 * time.Second): + t.Fatal("kill() blocked on a reaped child") + } + + // The other early return: no cmd at all. + p.cmdMu.Lock() + p.cmd = nil + p.cmdMu.Unlock() + p.kill() +} From 5c92d69aa7e0f8f2d1dc8a6816488b46dc81f719 Mon Sep 17 00:00:00 2001 From: Shannon Atkinson Date: Fri, 4 Sep 2026 16:44:49 -0700 Subject: [PATCH 4/8] fix(hooks): a signing secret that will not decrypt no longer degrades to an unsigned POST Closes #715. Restore a backup taken on another machine, or rotate secret.key, and every webhook silently went out UNSIGNED. db.scanHook loaded the row with an empty Secret when box.Open failed and said nothing; dispatch.attempt skips the signature header on an empty secret, so the delivery went anyway. At the far end that is indistinguishable from a forgery. The signing secret was the only thing that made the delivery trustworthy, and its absence is invisible to the receiver: an endpoint that verifies rejects everything, and one that does not now accepts anything anybody sends it. internal/db/platforms.go handled the identical situation the other way and failed loud, so the two halves of the same decision disagreed. Hook.SecretUnreadable is the same device Destination.KeyUnreadable already is, for the same reason and with the same shape: set by the scanner and never by a column, because it is a fact about this process's key file rather than about the row. Restore the key file and it goes away by itself, with no repair step and nothing to un-set. The row still loads intact -- failing the read would take every other hook down with it and turn a lost key file into a hooks page that will not load. Three places refuse it, and the order matters: - Validate, so reload never starts a worker and there is no queue for a delivery to sit in; - attempt, the one place the signature is decided and the only path BOTH delivery and the operator's Test button reach -- this is what makes an unsigned delivery unreachable rather than merely filtered; - reload logs at ERROR for this refusal and stays quiet for the others, since every other one is something the operator typed and was already told about at save time, while this one is a machine fact they can fix and would otherwise learn from a hook that stopped firing. Three mutations, each red: scanHook not marking the row, Validate accepting it, and attempt posting anyway. Claude-Session: https://claude.ai/code/session_01A8N3W5ct9SZtHK9sCDD9cL --- internal/db/hooks.go | 26 ++++-- internal/db/hooks_test.go | 76 +++++++++++++++++ internal/hooks/dispatch.go | 30 ++++++- internal/hooks/hooks.go | 51 +++++++++++ internal/hooks/unsigned_delivery_test.go | 104 +++++++++++++++++++++++ 5 files changed, 281 insertions(+), 6 deletions(-) create mode 100644 internal/hooks/unsigned_delivery_test.go diff --git a/internal/db/hooks.go b/internal/db/hooks.go index 3b4496dc..29ea89a0 100644 --- a/internal/db/hooks.go +++ b/internal/db/hooks.go @@ -49,14 +49,25 @@ func scanHook(box *secrets.Box, s interface{ Scan(...any) error }) (*hooks.Hook, // safeDialContext refuses a hook the operator deliberately allowed -- so // the hook is accepted at create time and then silently never fires. h.AllowPrivateTarget = allowPrivate != 0 - // A secret that will not open leaves the hook UNSIGNED rather than - // unreadable. The alternative -- failing the whole read -- would take every - // other hook down with it, and an unsigned delivery that arrives is more - // useful to an operator than a signed one that never does. The API reports - // hasSecret:false, which is how they find out. + // A SECRET THAT WILL NOT OPEN MARKS THE HOOK, IT DOES NOT UNSIGN IT. #715. + // + // This used to leave h.Secret empty and say nothing, so dispatch.attempt + // skipped the signature header and the POST went out UNSIGNED -- and at the + // far end an unsigned delivery is indistinguishable from a forgery. The + // signing secret was the only thing that made the webhook trustworthy. + // + // STILL NOT AN ERROR RETURN, for the reason the old comment gave and which + // is still right: failing the read would take every other hook down with + // it, and an operator whose key file went missing would open the hooks page + // to a 500 rather than to a page that says what is wrong. So the row loads + // intact and carries the reason, exactly as scanDestination does for a + // stream key -- and Validate and attempt both refuse it. + secretUnreadable := false if len(sealed) > 0 { if plain, err := box.Open(sealed); err == nil { h.Secret = plain + } else { + secretUnreadable = true } } if triggersJSON != "" && triggersJSON != "[]" { @@ -71,6 +82,11 @@ func scanHook(box *secrets.Box, s interface{ Scan(...any) error }) (*hooks.Hook, h.CreatedAt = time.Unix(created, 0) h.UpdatedAt = time.Unix(updated, 0) out := h.Normalized() + // AFTER Normalized, which trims and clamps the fields an operator typed and + // has no business clearing a fact about this machine's key file. + if secretUnreadable { + out.SecretUnreadable = hooks.SecretUnreadableReason() + } return &out, nil } diff --git a/internal/db/hooks_test.go b/internal/db/hooks_test.go index 14f27665..9b546458 100644 --- a/internal/db/hooks_test.go +++ b/internal/db/hooks_test.go @@ -1,11 +1,13 @@ package db import ( + "bytes" "errors" "strings" "testing" "github.com/rainmanjam/polyemesis/internal/hooks" + "github.com/rainmanjam/polyemesis/internal/secrets" ) // testBox comes from db_test.go; one per package. @@ -241,3 +243,77 @@ func TestUpdatingAHookThatDoesNotExistIsNotFound(t *testing.T) { "was written.", err) } } + +// A KEY FILE THAT NO LONGER OPENS THE SECRET MARKS THE HOOK. #715. +// +// The reachable path is ordinary: restore a backup taken on another machine, or +// rotate secret.key. The database is intact and every hook row is fine; only +// the sealed secrets are unreadable. +// +// This used to load the row with an EMPTY secret and say nothing, and +// dispatch.attempt skips the signature header on an empty secret -- so the +// consequence was every webhook silently going out unsigned. At the far end an +// unsigned delivery is indistinguishable from a forgery. +func TestAHookSealedWithAnotherKeyLoadsUnreadableRatherThanUnsigned(t *testing.T) { + d := testDB(t) + created, plaintext, err := d.CreateHook(testBox(t), validHook()) + if err != nil { + t.Fatalf("CreateHook: %v", err) + } + if plaintext == "" { + t.Fatal("no secret was sealed, so this fixture proves nothing") + } + + // The same database, a different key file. Nothing else changes. + otherBox, err := secrets.New(bytes.Repeat([]byte{0x5b}, 32)) + if err != nil { + t.Fatalf("secrets.New: %v", err) + } + + got, err := d.GetHook(otherBox, created.ID) + if err != nil { + t.Fatalf("GetHook must still return the row -- an operator whose key file "+ + "went missing needs a hooks page that loads and says what is wrong, "+ + "not a 500: %v", err) + } + if got.Name != "deploy" || got.URL == "" { + t.Errorf("the row did not survive intact: %+v", got) + } + if got.Secret != "" { + t.Error("a secret was produced from a ciphertext this key cannot open") + } + if got.SecretUnreadable == "" { + t.Fatal("the hook loads with no secret and no reason, which is exactly " + + "the state that posts unsigned: dispatch.attempt skips the signature " + + "header on an empty secret and the delivery goes out anyway") + } + if !strings.Contains(got.SecretUnreadable, "re-enter") { + t.Errorf("the reason does not name the fix, so an operator staring at a "+ + "hook that stopped firing has nothing to act on: %q", got.SecretUnreadable) + } + if err := got.Validate(); !errors.Is(err, hooks.ErrSecretUnreadable) { + t.Errorf("Validate = %v, want ErrSecretUnreadable -- this is what keeps "+ + "the dispatcher from starting a worker for it", err) + } + + // And it is a fact about the KEY FILE, not about the row: the right key + // still reads it, with no repair step and nothing to un-set. + back, err := d.GetHook(testBox(t), created.ID) + if err != nil { + t.Fatalf("GetHook with the right key: %v", err) + } + if back.SecretUnreadable != "" || back.Secret != plaintext { + t.Errorf("restoring the key file did not restore the hook by itself: "+ + "unreadable=%q secret ok=%v", back.SecretUnreadable, back.Secret == plaintext) + } + + // The list path too, since that is what the hooks page renders and what + // Dispatcher.reload reads. + all, err := d.ListHooks(otherBox) + if err != nil { + t.Fatalf("ListHooks: %v", err) + } + if len(all) != 1 || all[0].SecretUnreadable == "" { + t.Errorf("the list path does not carry the reason: %+v", all) + } +} diff --git a/internal/hooks/dispatch.go b/internal/hooks/dispatch.go index 65651348..5e9d5d21 100644 --- a/internal/hooks/dispatch.go +++ b/internal/hooks/dispatch.go @@ -422,7 +422,21 @@ func (d *Dispatcher) reload() { want := make(map[int64]Hook, len(rows)) for _, h := range rows { n := h.Normalized() - if n.Enabled && n.Validate() == nil { + if err := n.Validate(); err != nil { + // LOUD FOR THIS ONE, quiet for the rest. #715. An unreadable + // signing secret is a fact about the machine that an operator can + // fix and would otherwise learn only from a hook that stopped + // firing; every other refusal here is something they typed and were + // already told about at save time. + if n.Enabled && errors.Is(err, ErrSecretUnreadable) { + d.log.Error("a hook is not being delivered because its signing secret "+ + "could not be read on this machine; restore the key file or re-enter "+ + "the secret. Nothing is being sent unsigned.", + "hook", n.ID, "name", n.Name) + } + continue + } + if n.Enabled { want[n.ID] = n } } @@ -588,6 +602,20 @@ func (d *Dispatcher) attempt(ctx context.Context, h Hook, body []byte, env Envel defer cancel() reqCtx = withAllowPrivateTarget(reqCtx, h.AllowPrivateTarget) + // REFUSED HERE, AT THE ONE PLACE THE SIGNATURE IS DECIDED. #715. + // + // Both delivery paths -- the worker's deliver and the operator's Test -- + // go through attempt, so this is the point that makes an unsigned delivery + // UNREACHABLE rather than merely visible. Validate refuses the same hook + // earlier, which is what keeps a worker from existing; this is the guard + // under it, at the sink, for a hook that reached here another way. + // + // retry=false: no number of attempts will make the key file readable, and + // a retry loop over it would turn one silent hook into a log full of them. + if h.SecretUnreadable != "" { + return 0, "", false, fmt.Errorf("%w", ErrSecretUnreadable) + } + req, err := http.NewRequestWithContext(reqCtx, http.MethodPost, h.URL, bytes.NewReader(body)) if err != nil { return 0, "", false, err diff --git a/internal/hooks/hooks.go b/internal/hooks/hooks.go index 1666d0e8..6e1fed5c 100644 --- a/internal/hooks/hooks.go +++ b/internal/hooks/hooks.go @@ -211,8 +211,48 @@ type Hook struct { // hook to hit something on their own LAN sets this explicitly; a refusal // with no escape hatch would just get the whole feature disabled instead. AllowPrivateTarget bool `json:"allowPrivateTarget"` + // SecretUnreadable is the reason this hook's stored signing secret could + // not be decrypted on this machine, empty for every hook whose secret was + // read normally -- which is all of them on a healthy install. #715. + // + // It is set by db.scanHook and NEVER by a column: it is a fact about this + // process's key file, not about the row, so it is recomputed on every read + // rather than remembered. Restore the right key file and it goes away by + // itself, with no repair step and nothing to un-set. The same shape, and + // for the same reasons, as db.Destination.KeyUnreadable. + // + // WHEN IT IS SET, Secret IS EMPTY AND NOTHING IS DELIVERED. That is the + // whole point. The old behaviour was to load the row with an empty secret + // and go on posting, which signs with nothing and sends the delivery + // UNSIGNED -- and at the far end an unsigned delivery is indistinguishable + // from a forgery. The signing secret was the only thing that made the + // webhook trustworthy, and its absence is invisible to the receiver. + // + // The row itself is not touched. enabled is still 1 in the database, so + // this is reversible by restoring the key file rather than by re-enabling + // every hook by hand. + SecretUnreadable string `json:"secretUnreadable,omitempty"` } +// secretUnreadableReason is what the operator is shown. It names the fix, +// because "decryption failed" tells somebody staring at a hook that has stopped +// firing nothing they can act on, and the fix really is this small. +const secretUnreadableReason = "the signing secret could not be read on this machine — " + + "re-enter it to enable this hook" + +// SecretUnreadableReason is secretUnreadableReason for the storage layer, which +// is what discovers the condition and therefore what has to set it. +func SecretUnreadableReason() string { return secretUnreadableReason } + +// ErrSecretUnreadable is the sentinel behind Hook.SecretUnreadable. +// +// Deliberately never returned by the load path: a hook whose secret will not +// open must still appear in the list, with its name and endpoint intact, or an +// operator whose key file went missing opens the hooks page to an empty one and +// has nothing to act on. It is an error only so Validate has something to +// return and attempt has something to match on. +var ErrSecretUnreadable = errors.New(secretUnreadableReason) + // RedactedURL is what a response or a log line may show. func (h Hook) RedactedURL() string { return alerts.RedactWebhookURL(h.URL) } @@ -292,6 +332,17 @@ func (h Hook) Normalized() Hook { // the secret lives, and an error message is the first thing an operator pastes // into a bug report. func (h Hook) Validate() error { + // FIRST, and before the name check, because it is the one refusal here that + // is about the MACHINE rather than about what the operator typed. #715. + // + // reload() starts a worker only for a hook that validates, so this is what + // keeps an unsigned delivery from having a queue to sit in at all. The + // refusal at the moment of signing (Dispatcher.attempt) is the one that + // makes it unreachable; this one is what makes it VISIBLE, in the list and + // in the log, rather than a hook that quietly stopped firing. + if h.SecretUnreadable != "" { + return fmt.Errorf("hook %q: %w", h.Name, ErrSecretUnreadable) + } if h.Name == "" { return fmt.Errorf("hook needs a name") } diff --git a/internal/hooks/unsigned_delivery_test.go b/internal/hooks/unsigned_delivery_test.go new file mode 100644 index 00000000..61dd9ad4 --- /dev/null +++ b/internal/hooks/unsigned_delivery_test.go @@ -0,0 +1,104 @@ +package hooks + +import ( + "context" + "errors" + "testing" + "time" +) + +// A HOOK WHOSE SIGNING SECRET WILL NOT OPEN SENDS NOTHING. #715. +// +// It used to send everything, unsigned. db.scanHook loaded the row with an +// empty Secret when box.Open failed, and attempt skips the signature header on +// an empty secret -- so restoring a backup with a different secret.key, or +// rotating it, silently turned every webhook into an unauthenticated POST. +// +// At the far end that is indistinguishable from a forgery. The signing secret +// was the only thing that made the delivery trustworthy, and its absence is +// invisible to the receiver: an endpoint that verifies signatures rejects it, +// and one that does not now accepts anything anybody sends it. +func TestAHookWhoseSecretWillNotOpenDeliversNothingRatherThanSomethingUnsigned(t *testing.T) { + rec := &recorder{} + broken := Hook{ + ID: 1, Name: "deploy", Enabled: true, + URL: "https://example.com/h", + // What db.scanHook sets when box.Open fails: the row intact, the secret + // gone, and the reason carried alongside. + SecretUnreadable: SecretUnreadableReason(), + }.Normalized() + + d := NewDispatcher(testLogger(t), SourceFunc(func() ([]Hook, error) { + return []Hook{broken}, nil + }), WithDoer(rec), WithReloadInterval(10*time.Millisecond)) + runDispatcher(t, d) + + // No worker is started for it at all: Validate refuses it, which is what + // makes the queue it would otherwise sit in not exist. + time.Sleep(150 * time.Millisecond) + if d.HasHooks() { + t.Error("a hook with an unreadable secret has a live worker; reload " + + "accepted it, so anything published now is queued for delivery") + } + + for i := 0; i < 5; i++ { + d.Publish(Event{Trigger: TriggerIngestPublished, At: time.Now(), Source: SourceRef{ID: 1}}) + } + time.Sleep(150 * time.Millisecond) + if got := rec.seen(); len(got) != 0 { + t.Fatalf("%d delivery/deliveries went out for a hook whose secret could "+ + "not be read. Every one of them is unsigned, and the receiver cannot "+ + "tell it from a forgery: %q", len(got), got) + } +} + +// THE GUARD UNDER THE GUARD. attempt is the one place the signature is decided, +// and both delivery paths -- the worker's and the operator's Test button -- +// reach it. Refusing here is what makes an unsigned delivery unreachable rather +// than merely filtered out of reload's worker set. +// +// Driven through Test, because that path deliberately does NOT run Validate: +// an operator pressing "send test" on a hook must not be the way this hazard +// gets back in. +func TestTheTestButtonAlsoRefusesAHookWithNoReadableSecret(t *testing.T) { + rec := &recorder{} + d := NewDispatcher(testLogger(t), SourceFunc(func() ([]Hook, error) { return nil, nil }), + WithDoer(rec)) + + broken := Hook{ + ID: 2, Name: "manual", Enabled: true, + URL: "https://example.com/h", + SecretUnreadable: SecretUnreadableReason(), + } + res, err := d.Test(context.Background(), broken, TriggerIngestPublished) + if err == nil { + t.Fatal("Test reported success for a hook whose secret could not be read; " + + "an unsigned POST went out and the operator was told it worked") + } + if !errors.Is(err, ErrSecretUnreadable) { + // Not fatal: the redaction pass rewrites the text. What matters is that + // something was refused and the reason names the secret. + t.Logf("Test error does not wrap ErrSecretUnreadable (redaction rewrites "+ + "it): %v", err) + } + if res.Signature != "" { + t.Errorf("a signature was reported for a secret that could not be read: %q", + res.Signature) + } + if got := rec.seen(); len(got) != 0 { + t.Fatalf("the test delivery was sent anyway, unsigned: %q", got) + } +} + +// And the ordinary hook is untouched: a guard that also stops the working case +// is not a fix, it is an outage. +func TestAHookWithAReadableSecretStillDelivers(t *testing.T) { + rec := &recorder{} + d := NewDispatcher(testLogger(t), SourceFunc(func() ([]Hook, error) { return oneHook(), nil }), + WithDoer(rec), WithReloadInterval(10*time.Millisecond)) + runDispatcher(t, d) + waitFor(t, func() bool { return d.HasHooks() }) + + d.Publish(Event{Trigger: TriggerIngestPublished, At: time.Now(), Source: SourceRef{ID: 1}}) + waitFor(t, func() bool { return len(rec.seen()) > 0 }) +} From c6343ba2739c25f097f265d9df214a2526ffc0a6 Mon Sep 17 00:00:00 2001 From: Shannon Atkinson Date: Fri, 4 Sep 2026 16:55:30 -0700 Subject: [PATCH 5/8] fix(relay): a subscriber name already in use is refused instead of silently replacing the consumer Closes #711. Hub.SubscribeAddr was a bare map assignment: h.subs[name] = &subscriber{...} Registering two consumers under one name REPLACED the first. It kept running, kept a correct command line, kept a green card on the monitoring page -- and received nothing. Nothing about the process, its target URL or its status revealed it, and the hub logged "relay subscriber added" either way, so the log positively confirmed the wrong thing. Three devices already existed to avoid the collision and all three were rung zero: a naming convention (destinations.go's role suffix), a lock (engine.go's reconcileMu) and a comment (setup.go's note about the RTMP key variant). It had bitten twice. The sink itself accepted the collision without a word. Subscribe and SubscribeAddr now return (string, error) and refuse an occupied name with ErrSubscriberExists, logging at ERROR with BOTH addresses -- the whole difficulty of the old failure was that everything downstream looked healthy, so the one place it can be seen is the refusal itself. Thirteen production call sites change signature. Each one already had a release-and-bail path for the allocator refusing a port, and the subscription refusal takes the same path: release the port, and in the two places that record a subscription name before starting the child (the selector feed and the preview), clear it BEFORE the teardown can unsubscribe a name this consumer never took -- which would cut off whoever actually holds it. Unsubscribe is the mirror and was silent in the same way: delete() on an absent key is a no-op and the line said "removed" regardless, so a teardown naming the wrong subscriber read as successful cleanup. Not an error return -- every caller is a teardown path that would either ignore it or abandon the rest of its cleanup -- but it now says so at ERROR and removes nothing quietly. A test case asserted the hazard: "re-subscribing the same name replaces rather than duplicates". Replacing IS the failure. It now pins the refusal, that the FIRST consumer keeps the name, and that the name is free again after Unsubscribe. The new test asserts against the socket rather than the bookkeeping, because the failure was a consumer going quiet while looking healthy. Test fixtures across relay, engine and rtmpserver take a mustSubscribe helper rather than dropping the error: a fixture that silently fails to register would be asserting fan-out against a hub with no consumer on it. playout's fakeHub refuses collisions too, since a fake that accepts what production refuses hides the bug. Two mutations, each red: the bare map assignment restored, and Unsubscribe reporting a removal it did not make. Claude-Session: https://claude.ai/code/session_01A8N3W5ct9SZtHK9sCDD9cL --- internal/engine/dest_stop_test.go | 4 +- internal/engine/destinations.go | 20 +++- internal/engine/engine.go | 69 +++++++++++-- internal/engine/failover_test.go | 2 +- internal/engine/lifecycle_test.go | 30 ++++-- .../relayfeed_offset_integration_test.go | 2 +- internal/engine/seam_midstream_join_test.go | 2 +- internal/engine/selector.go | 10 +- internal/engine/shutdown_ports_test.go | 8 +- internal/engine/silence.go | 8 +- internal/playout/playout.go | 16 ++- internal/playout/playout_test.go | 9 +- internal/relay/concurrent_deliver_test.go | 2 +- internal/relay/hub_hop_test.go | 6 +- internal/relay/latejoin_probe_test.go | 2 +- internal/relay/listen_test.go | 10 +- internal/relay/name_collision_test.go | 98 +++++++++++++++++++ internal/relay/relay.go | 53 +++++++++- internal/relay/relay_test.go | 82 ++++++++++++---- internal/rtmpserver/ingest_udp_test.go | 20 +++- 20 files changed, 384 insertions(+), 69 deletions(-) create mode 100644 internal/relay/name_collision_test.go diff --git a/internal/engine/dest_stop_test.go b/internal/engine/dest_stop_test.go index 7b2ec8aa..12515029 100644 --- a/internal/engine/dest_stop_test.go +++ b/internal/engine/dest_stop_test.go @@ -39,8 +39,8 @@ func TestStopTakesTheBackupDownWithTheDestination(t *testing.T) { t.Fatalf("allocate backup: %v", err) } primarySub, backupSub := destSubName(row.ID, ""), destSubName(row.ID, destRoleBackup) - e.hub.Subscribe(primarySub, primaryPort) - e.hub.Subscribe(backupSub, backupPort) + mustSubscribe(t, e.hub, primarySub, primaryPort) + mustSubscribe(t, e.hub, backupSub, backupPort) e.dests[row.ID] = &destination{ row: row, hub: e.hub, spec: "spec", port: primaryPort, subName: primarySub, diff --git a/internal/engine/destinations.go b/internal/engine/destinations.go index 611d85f0..00b34df2 100644 --- a/internal/engine/destinations.go +++ b/internal/engine/destinations.go @@ -872,7 +872,14 @@ func (e *Engine) startDest(p destPlan, hub *relay.Hub, startDelay time.Duration) return err } subName := destSubName(row.ID, "") - url := hub.Subscribe(subName, port) + url, err := hub.Subscribe(subName, port) + if err != nil { + // #711. An occupied name means another consumer is reading under it; + // taking it would leave that one running, correct-looking and receiving + // nothing. Same release-and-bail shape as the port refusal above. + e.releasePort(port) + return err + } target := row.Target() if mt.Use { @@ -1314,7 +1321,16 @@ func (e *Engine) buildBackup(d *destination, compiled routing.Result, spec strin return } sub := destSubName(d.row.ID, destRoleBackup) - url := hub.Subscribe(sub, port) + url, err := hub.Subscribe(sub, port) + if err != nil { + // #711. Quietly, with a reason, exactly as the port refusal above does: + // the backup feed is the optional half and the primary is unaffected. + e.releasePort(port) + d.backupErr = "the backup feed's relay name is already in use" + e.log.Error("backup ingest could not subscribe; the primary is unaffected", + "dest", d.row.Name, "err", err) + return + } proc := supervisor.New(e.log, supervisor.Spec{ Name: sub, diff --git a/internal/engine/engine.go b/internal/engine/engine.go index dcb0ceda..883d941c 100644 --- a/internal/engine/engine.go +++ b/internal/engine/engine.go @@ -1814,7 +1814,15 @@ func (e *Engine) reconcileRecorder(s db.Settings) { e.log.Error("recorder: no relay port", "err", err) return } - url := e.hub.Subscribe("recorder", port) + url, err := e.hub.Subscribe("recorder", port) + if err != nil { + // #711. Same release-and-bail as the port refusal above. An occupied + // name means another consumer is reading under it, and taking it would + // leave that one running and receiving nothing. + e.releasePort(port) + e.log.Error("recorder: relay subscription refused", "err", err) + return + } pattern := filepath.Join(e.cfg.RecordingsDir(), "rec-%Y%m%d-%H%M%S.mkv") rs := ffmpeg.RecorderSpec{ @@ -2123,7 +2131,17 @@ func (e *Engine) startPreviewLocked(s db.Settings) { e.mu.Lock() e.previewHub = hub e.mu.Unlock() - url := hub.Subscribe("preview", port) + url, err := hub.Subscribe("preview", port) + if err != nil { + // #711. previewHub is cleared with it, or a later sweep unsubscribes a + // name this preview never took -- cutting off whoever actually holds it. + e.mu.Lock() + e.previewHub = nil + e.mu.Unlock() + e.releasePort(port) + e.log.Error("preview: relay subscription refused", "err", err) + return + } args := ffmpeg.PreviewArgs(ffmpeg.PreviewSpec{ RelayURL: url, @@ -2275,7 +2293,12 @@ func (e *Engine) reconcileMeters(s db.Settings) { return } meterHub := e.downstreamHub() - url := meterHub.Subscribe("meters", port) + url, err := meterHub.Subscribe("meters", port) + if err != nil { + e.releasePort(port) + e.log.Error("meters: relay subscription refused", "err", err) + return + } args := ffmpeg.MetersArgs(ffmpeg.MetersSpec{RelayURL: url, TrackChannels: channels}) @@ -3020,7 +3043,13 @@ func (e *Engine) startRendition(row *db.Rendition, spec string, sourceFPS float6 } subName := fmt.Sprintf("rendition:%d", row.ID) - in := upstream.Subscribe(subName, port) + in, err := upstream.Subscribe(subName, port) + if err != nil { + e.releasePort(port) + _ = hub.Close() + fail(err) + return + } rspec := renditionSpecOf(row, in, hub.InputURL(), sourceFPS, e.vaapiDevice(row), e.cfg.DataDir) // An FFmpeg with no drawtext filter must not be handed one. // @@ -3498,7 +3527,16 @@ func (e *Engine) probeOnce(ctx context.Context) bool { defer e.releasePort(port) name := "probe" - url := e.hub.Subscribe(name, port) + url, err := e.hub.Subscribe(name, port) + if err != nil { + // #711. Counted like an ffprobe failure, for the reason the port + // refusal above states: no layout was measured, and the reason is not + // something waiting longer will change. The deferred Unsubscribe is + // NOT armed, because this probe holds no subscription to remove and + // removing the name would cut off whoever does. + e.probeFailedNow(fmt.Errorf("the probe's relay name is already in use: %w", err)) + return false + } defer e.hub.Unsubscribe(name) // Captured BEFORE the read, checked before the write. Everything between is @@ -3956,7 +3994,12 @@ func (e *Engine) startLoudness(p loudnessPlan) { return } subName := loudnessSubPrefix + strconv.FormatInt(p.id, 10) - url := p.hub.Subscribe(subName, port) + url, err := p.hub.Subscribe(subName, port) + if err != nil { + e.releasePort(port) + fail(err) + return + } args := meters.Args(meters.Spec{ RelayURL: url, @@ -4154,7 +4197,12 @@ func (e *Engine) reconcileClips() { return } hub := e.downstreamHub() - url := hub.Subscribe(clipSubName, port) + url, err := hub.Subscribe(clipSubName, port) + if err != nil { + e.releasePort(port) + e.log.Error("clip buffer: relay subscription refused", "err", err) + return + } capt, err := clips.Open(e.log, cfg, url, func() { e.bus.Publish(events.TypeClips, nil) @@ -4509,7 +4557,12 @@ func (e *Engine) reconcileCaptions() { return } hub := e.downstreamHub() - url := hub.Subscribe(captSubName, port) + url, err := hub.Subscribe(captSubName, port) + if err != nil { + e.releasePort(port) + e.captionsFailed(fmt.Sprintf("live captions could not subscribe to the relay: %v", err)) + return + } // The sidecar lands in the playout directory by default so it sits beside // the HLS window it describes. It is a growing WebVTT file, not a diff --git a/internal/engine/failover_test.go b/internal/engine/failover_test.go index 410e0867..5d1ea911 100644 --- a/internal/engine/failover_test.go +++ b/internal/engine/failover_test.go @@ -636,7 +636,7 @@ func TestADestinationRidesAPrimaryDownSlateBackCycleWithoutRestarting(t *testing if err != nil { t.Fatalf("allocate: %v", err) } - hub.Subscribe("dest:1", port) + mustSubscribe(t, hub, "dest:1", port) dest := &destination{ row: &db.Destination{ID: 1, Name: "twitch"}, proc: proc, port: port, subName: "dest:1", hub: hub, spec: "unchanged", diff --git a/internal/engine/lifecycle_test.go b/internal/engine/lifecycle_test.go index 0af5599b..639b3a22 100644 --- a/internal/engine/lifecycle_test.go +++ b/internal/engine/lifecycle_test.go @@ -251,7 +251,7 @@ func TestAStartedRenditionPublishesTheWiringItsTeardownNeeds(t *testing.T) { t.Fatal("the fixture did not put a silence tier between the ingest and the renditions") } // A decoy of the name the rendition will use, on the hub it must NOT touch. - e.hub.Subscribe("rendition:1", freeUDPPort(t)) + mustSubscribe(t, e.hub, "rendition:1", freeUDPPort(t)) e.startRendition(lifeRendition(1, db.EncoderX264), "spec-a", 30, 2) @@ -308,11 +308,11 @@ func TestTeardownUnsubscribesFromTheHubTheEncodeActuallyRead(t *testing.T) { upstream := lifeHub(t) // stands in for the silence or selector tier's relay port := enginePort(t, e, "reserving the rendition's port") - upstream.Subscribe("rendition:1", port) + mustSubscribe(t, upstream, "rendition:1", port) // A decoy of the SAME NAME on the ingest hub. If teardown unsubscribes from // e.hub it will look like it worked unless something is watching that name // on both relays. - e.hub.Subscribe("rendition:1", port) + mustSubscribe(t, e.hub, "rendition:1", port) own := lifeHub(t) e.teardownRendition(&rendition{ @@ -389,7 +389,7 @@ func TestATeardownWithNoRecordedUpstreamFallsBackToTheIngestRatherThanPanicking( e := lifeEngine(t) e.alloc = oneSlotAllocator(t) port := enginePort(t, e, "reserving the rendition's port") - e.hub.Subscribe("rendition:1", port) + mustSubscribe(t, e.hub, "rendition:1", port) e.teardownRendition(&rendition{ row: lifeRendition(1, db.EncoderX264), port: port, subName: "rendition:1", @@ -406,7 +406,7 @@ func TestATeardownWithNoRecordedUpstreamFallsBackToTheIngestRatherThanPanicking( e := lifeEngine(t) e.alloc = oneSlotAllocator(t) port := enginePort(t, e, "reserving the analyser's port") - e.hub.Subscribe(loudnessSubPrefix+"7", port) + mustSubscribe(t, e.hub, loudnessSubPrefix+"7", port) e.teardownLoudness(&loudnessMon{port: port, subName: loudnessSubPrefix + "7"}) @@ -478,7 +478,7 @@ func TestStoppingOneAuxiliaryChildClearsOnlyItsOwnPortAndSignature(t *testing.T) ports := map[string]int{} for _, s := range slots { ports[s.aux.name] = enginePort(t, e, "reserving "+s.aux.name+"'s port") - e.hub.Subscribe(s.aux.name, ports[s.aux.name]) + mustSubscribe(t, e.hub, s.aux.name, ports[s.aux.name]) } e.recorder, e.preview, e.meters = loudTestProc(), loudTestProc(), loudTestProc() e.recorderPort, e.previewPort, e.metersPort = ports["recorder"], ports["preview"], ports["meters"] @@ -541,8 +541,8 @@ func TestTheMetersSidecarIsUnsubscribedFromTheHubItSubscribedTo(t *testing.T) { silenceHub := lifeHub(t) port := enginePort(t, e, "reserving the sidecar's port") - silenceHub.Subscribe("meters", port) - e.hub.Subscribe("meters", port) // decoy of the same name on the ingest + mustSubscribe(t, silenceHub, "meters", port) + mustSubscribe(t, e.hub, "meters", port) // decoy of the same name on the ingest e.meters, e.metersPort, e.metersSig, e.metersHub = loudTestProc(), port, "met-sig", silenceHub e.stopAux(auxMeters) @@ -912,7 +912,7 @@ func TestALoudnessMonitorRoundTripsItsPortAndSubscription(t *testing.T) { } // A decoy of the same name on the ingest hub, so unsubscribing from the // wrong relay cannot look like success. - e.hub.Subscribe(m.subName, m.port) + mustSubscribe(t, e.hub, m.subName, m.port) e.teardownLoudness(m) @@ -925,3 +925,15 @@ func TestALoudnessMonitorRoundTripsItsPortAndSubscription(t *testing.T) { } enginePort(t, e, "after an analyser was torn down") } + +// mustSubscribe is Subscribe for a test that is not about the refusal. #711 +// made an occupied name an error, and a fixture that drops it would be +// asserting against a hub that never registered the consumer. +func mustSubscribe(t testing.TB, h *relay.Hub, name string, port int) string { + t.Helper() + url, err := h.Subscribe(name, port) + if err != nil { + t.Fatalf("Subscribe(%q, %d): %v", name, port, err) + } + return url +} diff --git a/internal/engine/relayfeed_offset_integration_test.go b/internal/engine/relayfeed_offset_integration_test.go index bf0a3149..4ec24617 100644 --- a/internal/engine/relayfeed_offset_integration_test.go +++ b/internal/engine/relayfeed_offset_integration_test.go @@ -152,7 +152,7 @@ func runRelayHop(t *testing.T, ffmpegBin, fixture string, offset float64, paced // The feed reads the hub on a port of its own, exactly as startFeed gives it // one, and writes to the capture socket. subPort := freeUDPPort(t) - args := relayFeedArgs(hub.Subscribe("offsetbench", subPort), + args := relayFeedArgs(mustSubscribe(t, hub, "offsetbench", subPort), "udp://127.0.0.1:"+strconv.Itoa(sinkPort), offset) feed := exec.Command(ffmpegBin, args...) var feedErr strings.Builder diff --git a/internal/engine/seam_midstream_join_test.go b/internal/engine/seam_midstream_join_test.go index d5a8c77e..0b35c56e 100644 --- a/internal/engine/seam_midstream_join_test.go +++ b/internal/engine/seam_midstream_join_test.go @@ -202,7 +202,7 @@ func runJoinHop(t *testing.T, ffmpegBin string, hub *relay.Hub, dir string, h *j }() subPort := freeUDPPort(t) - args := relayFeedArgs(hub.Subscribe(h.name, subPort), + args := relayFeedArgs(mustSubscribe(t, hub, h.name, subPort), "udp://127.0.0.1:"+strconv.Itoa(sinkPort), h.offset) feed := exec.Command(ffmpegBin, args...) var feedErr strings.Builder diff --git a/internal/engine/selector.go b/internal/engine/selector.go index 2d442960..ac5c2c51 100644 --- a/internal/engine/selector.go +++ b/internal/engine/selector.go @@ -1552,8 +1552,16 @@ func (e *Engine) startFeed(s db.Settings, kind sourceKind, upstream, silenceSig if err != nil { return fail(err) } + url, serr := in.Subscribe(selectorSubName, port) + if serr != nil { + // #711. BEFORE feed.subName is recorded, so the teardown below does + // not unsubscribe a name this feed never took -- which would cut off + // whoever actually holds it. + e.releasePort(port) + return fail(serr) + } feed.in, feed.port, feed.subName = in, port, selectorSubName - args = relayFeedArgs(in.Subscribe(selectorSubName, port), out, offset) + args = relayFeedArgs(url, out, offset) default: // A fifth kind lands here, and lands here VISIBLY: nothing is started // and nothing is recorded as active, because a feed that cannot be built diff --git a/internal/engine/shutdown_ports_test.go b/internal/engine/shutdown_ports_test.go index 7b53a7e9..f650181b 100644 --- a/internal/engine/shutdown_ports_test.go +++ b/internal/engine/shutdown_ports_test.go @@ -39,15 +39,15 @@ func TestStopReturnsEveryPortTheAuxChildrenTook(t *testing.T) { e.recorderPort = enginePort(t, e, "recorder") e.previewPort = enginePort(t, e, "preview") e.metersPort = enginePort(t, e, "meters") - e.hub.Subscribe("recorder", e.recorderPort) - e.hub.Subscribe("preview", e.previewPort) - e.hub.Subscribe("meters", e.metersPort) + mustSubscribe(t, e.hub, "recorder", e.recorderPort) + mustSubscribe(t, e.hub, "preview", e.previewPort) + mustSubscribe(t, e.hub, "meters", e.metersPort) rp := enginePort(t, e, "rendition") e.rends = map[int64]*rendition{1: { proc: loudTestProc(), port: rp, subName: "rend:1", in: e.hub, }} - e.hub.Subscribe("rend:1", rp) + mustSubscribe(t, e.hub, "rend:1", rp) e.mu.Unlock() if got := e.heldPortCount(); got != span { diff --git a/internal/engine/silence.go b/internal/engine/silence.go index f8e924ac..5d7505b0 100644 --- a/internal/engine/silence.go +++ b/internal/engine/silence.go @@ -217,7 +217,13 @@ func (e *Engine) startSilence(spec string) { return } - in := e.hub.Subscribe(silenceSubName, port) + in, err := e.hub.Subscribe(silenceSubName, port) + if err != nil { + e.releasePort(port) + _ = hub.Close() + fail(err) + return + } args := ffmpeg.SilenceArgs(ffmpeg.SilenceSpec{ InRelayURL: in, OutRelayURL: hub.InputURL(), diff --git a/internal/playout/playout.go b/internal/playout/playout.go index ca248118..2ab00e2c 100644 --- a/internal/playout/playout.go +++ b/internal/playout/playout.go @@ -67,7 +67,7 @@ func DirIn(dataDir string) string { return filepath.Join(dataDir, DirName) } // somewhere to stop. Narrow because a variant may read the ingest hub or a // rendition's, and the manager must not care which. type Hub interface { - Subscribe(name string, port int) string + Subscribe(name string, port int) (string, error) Unsubscribe(name string) } @@ -384,7 +384,19 @@ func (m *Manager) start(s db.PlayoutSettings, v *variant) { } v.subName = "playout:" + v.cfg.Name - url := v.hub.Subscribe(v.subName, port) + url, err := v.hub.Subscribe(v.subName, port) + if err != nil { + // SAME SHAPE AS THE PORT REFUSAL ABOVE. #711. A name already registered + // means another consumer holds it; taking it would leave that one + // running and receiving nothing, which is invisible from its process, + // its command line and its card. + m.ports.Release(port) + v.subName = "" + v.spec, v.err = "", err.Error() + record() + m.log.Error("playout: relay subscription refused", "variant", v.cfg.Name, "err", err) + return + } args := VariantArgs(VariantSpec{ Name: v.cfg.Name, RelayURL: url, diff --git a/internal/playout/playout_test.go b/internal/playout/playout_test.go index 5d403294..2968e825 100644 --- a/internal/playout/playout_test.go +++ b/internal/playout/playout_test.go @@ -28,11 +28,16 @@ type fakeHub struct { func newHub(name string) *fakeHub { return &fakeHub{name: name, subs: map[string]int{}} } -func (h *fakeHub) Subscribe(name string, port int) string { +// Refuses an occupied name, like the real one. #711. A fake that accepts a +// collision the production hub refuses is a fake that hides the bug. +func (h *fakeHub) Subscribe(name string, port int) (string, error) { h.mu.Lock() defer h.mu.Unlock() + if _, taken := h.subs[name]; taken { + return "", fmt.Errorf("%q: %w", name, relay.ErrSubscriberExists) + } h.subs[name] = port - return fmt.Sprintf("udp://127.0.0.1:%d", port) + return fmt.Sprintf("udp://127.0.0.1:%d", port), nil } func (h *fakeHub) Unsubscribe(name string) { diff --git a/internal/relay/concurrent_deliver_test.go b/internal/relay/concurrent_deliver_test.go index 91721b0d..7cc37a4e 100644 --- a/internal/relay/concurrent_deliver_test.go +++ b/internal/relay/concurrent_deliver_test.go @@ -34,7 +34,7 @@ func TestConcurrentDeliverIsRaceFree(t *testing.T) { // A subscriber nothing is listening on, so every send fails and the // sendErrors counter -- the other unsynchronised write -- is exercised too. _, port := boundSubscriber(t) - h.Subscribe("ghost", port) + mustSubscribe(t, h, "ghost", port) var wg sync.WaitGroup for g := 0; g < 8; g++ { diff --git a/internal/relay/hub_hop_test.go b/internal/relay/hub_hop_test.go index a8c958a2..ca47a790 100644 --- a/internal/relay/hub_hop_test.go +++ b/internal/relay/hub_hop_test.go @@ -36,7 +36,7 @@ func TestASubscriberReceivesEveryByteTheHubReceived(t *testing.T) { } defer sub.Close() subPort := sub.LocalAddr().(*net.UDPAddr).Port - h.Subscribe("test-dest", subPort) + mustSubscribe(t, h, "test-dest", subPort) // Datagrams shaped like the relay's: 1316 bytes, seven 188-byte TS packets, // each carrying a recognisable PID so a dropped or reordered one shows. @@ -206,7 +206,7 @@ func TestFirstDeliveryIsLoggedOncePerSubscriber(t *testing.T) { t.Fatalf("subscriber socket: %v", err) } defer sub.Close() - h.Subscribe("dest:1", sub.LocalAddr().(*net.UDPAddr).Port) + mustSubscribe(t, h, "dest:1", sub.LocalAddr().(*net.UDPAddr).Port) pkt := make([]byte, 188) pkt[0] = 0x47 @@ -241,7 +241,7 @@ func TestASendToADepartedConsumerIsCounted(t *testing.T) { } port := gone.LocalAddr().(*net.UDPAddr).Port _ = gone.Close() - h.Subscribe("departed", port) + mustSubscribe(t, h, "departed", port) pkt := make([]byte, 188) pkt[0] = 0x47 diff --git a/internal/relay/latejoin_probe_test.go b/internal/relay/latejoin_probe_test.go index 00b5b9cf..6f52dcf1 100644 --- a/internal/relay/latejoin_probe_test.go +++ b/internal/relay/latejoin_probe_test.go @@ -92,7 +92,7 @@ func TestASubscriberJoiningMidStreamStartsReceivingImmediately(t *testing.T) { time.Sleep(150 * time.Millisecond) sub, port := boundSubscriber(t) - h.Subscribe("late", port) + mustSubscribe(t, h, "late", port) joined := time.Now() var total int diff --git a/internal/relay/listen_test.go b/internal/relay/listen_test.go index 2f2672b3..d2a7459f 100644 --- a/internal/relay/listen_test.go +++ b/internal/relay/listen_test.go @@ -74,7 +74,7 @@ func TestNewBindsTheRequestedFamily(t *testing.T) { if want := fmt.Sprintf("udp://%s:%d", tt.wantHost, h.Port()); h.InputURL() != want { t.Errorf("InputURL() = %q, want %q", h.InputURL(), want) } - got := h.Subscribe("sub", 9999) + got := mustSubscribe(t, h, "sub", 9999) if want := fmt.Sprintf("udp://%s:9999", tt.wantHost); got != want { t.Errorf("Subscribe() = %q, want %q", got, want) } @@ -85,10 +85,10 @@ func TestNewBindsTheRequestedFamily(t *testing.T) { func TestSubscribeAddrTargetsAnArbitraryHost(t *testing.T) { h := newTestHub(t) - if got, want := h.SubscribeAddr("remote", net.IPv4(192, 168, 1, 20), 5000), "udp://192.168.1.20:5000"; got != want { + if got, want := mustSubscribeAddr(t, h, "remote", net.IPv4(192, 168, 1, 20), 5000), "udp://192.168.1.20:5000"; got != want { t.Errorf("SubscribeAddr() = %q, want %q", got, want) } - if got, want := h.SubscribeAddr("remote6", net.ParseIP("2001:db8::1"), 5000), "udp://[2001:db8::1]:5000"; got != want { + if got, want := mustSubscribeAddr(t, h, "remote6", net.ParseIP("2001:db8::1"), 5000), "udp://[2001:db8::1]:5000"; got != want { t.Errorf("SubscribeAddr() = %q, want %q", got, want) } } @@ -110,8 +110,8 @@ func TestWildcardHubFansOutAcrossBothFamilies(t *testing.T) { } t.Cleanup(func() { _ = sub6.Close() }) - h.SubscribeAddr("v4", net.IPv4(127, 0, 0, 1), port4) - h.SubscribeAddr("v6", net.IPv6loopback, sub6.LocalAddr().(*net.UDPAddr).Port) + mustSubscribeAddr(t, h, "v4", net.IPv4(127, 0, 0, 1), port4) + mustSubscribeAddr(t, h, "v6", net.IPv6loopback, sub6.LocalAddr().(*net.UDPAddr).Port) payload := []byte("dual stack") publish(t, h, payload, 3) // publish dials IPv4 loopback diff --git a/internal/relay/name_collision_test.go b/internal/relay/name_collision_test.go new file mode 100644 index 00000000..64a1df76 --- /dev/null +++ b/internal/relay/name_collision_test.go @@ -0,0 +1,98 @@ +package relay + +import ( + "bytes" + "errors" + "log/slog" + "strings" + "testing" +) + +// A NAME ALREADY IN USE IS REFUSED, AND THE CONSUMER HOLDING IT KEEPS RECEIVING. +// #711. +// +// The map assignment used to be bare: `h.subs[name] = &subscriber{...}`. The +// replaced consumer keeps running, keeps a correct command line, and keeps a +// green card on the monitoring page — and receives nothing. Nothing about the +// process, its target URL or its status reveals it. +// +// Worse, the hub logged "relay subscriber added" either way, so the log +// positively confirmed the wrong thing. +// +// Three devices existed to avoid the collision and all three were rung zero: a +// naming convention in destinations.go, a lock in engine.go, and a comment in +// setup.go. It had bitten twice. This is the sink refusing. +func TestATakenNameIsRefusedAndTheConsumerHoldingItStillReceives(t *testing.T) { + h := newTestHub(t) + + first, firstPort := boundSubscriber(t) + mustSubscribe(t, h, "dest:1", firstPort) + + // The collision: a second consumer, a different port, the same name. + second, secondPort := boundSubscriber(t) + url, err := h.Subscribe("dest:1", secondPort) + if !errors.Is(err, ErrSubscriberExists) { + t.Fatalf("Subscribe under a live name = %q, %v; want ErrSubscriberExists", url, err) + } + if url != "" { + t.Errorf("a URL was handed out for a refused subscription: %q", url) + } + + // THE PROPERTY THAT MATTERS. Not the error -- the delivery. The whole + // failure was that the first consumer went quiet while looking healthy, so + // this asserts against the socket rather than against the bookkeeping. + payload := []byte("still yours") + publish(t, h, payload, 3) + waitForRx(t, h, 1) + assertDelivered(t, "the consumer that holds the name", first, payload, 3) + + // And the refused one got nothing, which is the other half: a refusal that + // still delivered would mean two processes reading one name. + if got := h.Subscribers(); len(got) != 1 || got[0] != "dest:1" { + t.Errorf("Subscribers() = %v, want exactly [dest:1]", got) + } + _ = second +} + +// Unsubscribe with a name this hub does not have removes nothing and no longer +// says it removed something. #711's mirror. +// +// delete() on an absent key is a no-op and the log line said "relay subscriber +// removed" regardless — so a teardown naming the wrong subscriber reported +// success while leaving the real one forwarding into a process that is gone. +func TestUnsubscribingANameTheHubDoesNotHaveLeavesTheOthersAlone(t *testing.T) { + // ITS OWN LOGGER, because the observable difference is the LOG LINE. Nothing + // else changes: delete() on an absent key is a no-op either way, so a test + // that only checks the subscriber set passes against the bug. + var logged bytes.Buffer + h, err := New(slog.New(slog.NewTextHandler(&logged, &slog.HandlerOptions{Level: slog.LevelDebug})), 0) + if err != nil { + t.Fatalf("New: %v", err) + } + t.Cleanup(func() { _ = h.Close() }) + + mustSubscribe(t, h, "dest:1", 5001) + logged.Reset() + + h.Unsubscribe("dest:2") // never subscribed + + line := logged.String() + if strings.Contains(line, "relay subscriber removed") { + t.Errorf("the hub reported removing a subscriber it never had. A teardown "+ + "naming the wrong subscriber then reads as successful cleanup while the "+ + "real one goes on forwarding into a process that is gone:\n%s", line) + } + if !strings.Contains(line, "does not have") { + t.Errorf("nothing was said about an Unsubscribe that removed nothing:\n%s", line) + } + + got := h.Subscribers() + if len(got) != 1 || got[0] != "dest:1" { + t.Fatalf("Subscribers() = %v, want [dest:1]", got) + } + // And the real one still goes when it is named. + h.Unsubscribe("dest:1") + if got := h.Subscribers(); len(got) != 0 { + t.Errorf("Subscribers() = %v, want none", got) + } +} diff --git a/internal/relay/relay.go b/internal/relay/relay.go index d1359742..d97040f0 100644 --- a/internal/relay/relay.go +++ b/internal/relay/relay.go @@ -22,6 +22,7 @@ package relay import ( + "errors" "fmt" "log/slog" "net" @@ -223,21 +224,52 @@ func (h *Hub) InputURL() string { return udpURL(h.advertise, h.port) } +// ErrSubscriberExists is returned when a name is already registered on this hub. +// +// #711. THE MAP ASSIGNMENT USED TO BE BARE. `h.subs[name] = ...` REPLACES the +// existing entry: the first consumer keeps running, keeps a correct command +// line and keeps a green card on the monitoring page -- and receives nothing. +// Worse, the hub logged "relay subscriber added" either way, so the log +// positively confirmed the wrong thing. +// +// Three devices already existed to avoid the collision and all three were rung +// zero: a naming convention in destinations.go, a lock in engine.go, and a +// comment in setup.go. It had bitten twice. The sink itself now refuses. +var ErrSubscriberExists = errors.New("a relay subscriber with that name is already registered on this hub") + // Subscribe registers a consumer and returns the URL it should read from. // // The consumer binds that port itself (FFmpeg does this when given a udp:// // input); the hub only sends to it. Subscribing before the consumer starts is // fine — datagrams to an unbound port are simply discarded by the kernel. -func (h *Hub) Subscribe(name string, port int) string { +// +// REFUSES AN OCCUPIED NAME (ErrSubscriberExists). Every caller already has a +// release-and-bail path for the allocator refusing a port, which is the same +// shape, and a caller that ignores this error is back to the silent replacement +// the error exists to prevent. +func (h *Hub) Subscribe(name string, port int) (string, error) { return h.SubscribeAddr(name, h.advertise, port) } // SubscribeAddr registers a consumer at an explicit address, for the case where // it is not on this host. The caller resolves any hostname itself so that // registration cannot block the engine on DNS. -func (h *Hub) SubscribeAddr(name string, ip net.IP, port int) string { +func (h *Hub) SubscribeAddr(name string, ip net.IP, port int) (string, error) { h.mu.Lock() defer h.mu.Unlock() + if prev, taken := h.subs[name]; taken { + // AT ERROR AND BEFORE THE STORE, so the log says what happened rather + // than confirming an add that is not going to happen. Both addresses go + // in the line: the whole difficulty of the old failure was that + // everything downstream looked healthy, so the one place it can be seen + // is here, naming the consumer that would have been cut off. + h.log.Error("refusing a relay subscription: that name is already registered on "+ + "this hub, and taking it would leave the consumer holding it running and "+ + "receiving nothing", + "name", name, "hubPort", h.port, + "heldBy", prev.addr.String(), "refused", (&net.UDPAddr{IP: ip, Port: port}).String()) + return "", fmt.Errorf("%q on hub port %d: %w", name, h.port, ErrSubscriberExists) + } h.subs[name] = &subscriber{ name: name, addr: &net.UDPAddr{IP: ip, Port: port}, @@ -253,13 +285,28 @@ func (h *Hub) SubscribeAddr(name string, ip net.IP, port int) string { // said nothing, because the acceptance suite never shows Debug. h.log.Info("relay subscriber added", "name", name, "hubPort", h.port, "subscriberPort", port, "total", len(h.subs)) - return udpURL(ip, port) + return udpURL(ip, port), nil } // Unsubscribe removes a consumer. func (h *Hub) Unsubscribe(name string) { h.mu.Lock() defer h.mu.Unlock() + // THE MIRROR OF THE COLLISION, and it was silent in the same way. #711. + // delete() on an absent key is a no-op, and the line below said "removed" + // regardless -- so a mismatched name removed nothing and reported success, + // which is exactly how a subscription outlives the process that owned it. + // + // Not an error return: every caller is a teardown path, and a teardown that + // has to branch on this would either ignore it or abandon the rest of its + // cleanup. Reported instead, at the level that gets read. + if _, had := h.subs[name]; !had { + h.log.Error("asked to remove a relay subscriber this hub does not have; "+ + "nothing was removed. A teardown naming the wrong subscriber leaves the "+ + "real one forwarding into a process that is gone", + "name", name, "hubPort", h.port, "total", len(h.subs)) + return + } delete(h.subs, name) h.rebuildTargets() // AT INFO, for the same reason as "added". #674: a destination subscribed at diff --git a/internal/relay/relay_test.go b/internal/relay/relay_test.go index 75898e3d..7d471c91 100644 --- a/internal/relay/relay_test.go +++ b/internal/relay/relay_test.go @@ -2,6 +2,7 @@ package relay import ( "bytes" + "errors" "fmt" "io" "log/slog" @@ -203,24 +204,48 @@ func TestSubscriberBookkeeping(t *testing.T) { { name: "subscribe registers by name", act: func(h *Hub) { - h.Subscribe("rec", 5001) - h.Subscribe("hls", 5002) + mustSubscribe(t, h, "rec", 5001) + mustSubscribe(t, h, "hls", 5002) }, want: []string{"hls", "rec"}, }, { - name: "re-subscribing the same name replaces rather than duplicates", + // THIS CASE USED TO ASSERT THE HAZARD. It read "re-subscribing the + // same name replaces rather than duplicates", and replacing is + // precisely the failure #711 records: the first consumer keeps + // running, keeps a correct command line and keeps a green card, and + // receives nothing. The second subscribe is now refused and the + // FIRST consumer is the one still registered. + name: "a second subscribe under a live name is refused, and the first keeps the name", act: func(h *Hub) { - h.Subscribe("rec", 5001) - h.Subscribe("rec", 5009) + mustSubscribe(t, h, "rec", 5001) + if _, err := h.Subscribe("rec", 5009); !errors.Is(err, ErrSubscriberExists) { + t.Fatalf("second Subscribe = %v, want ErrSubscriberExists; a bare "+ + "map assignment here silently cuts off the consumer on 5001", err) + } + if got := h.subs["rec"].addr.Port; got != 5001 { + t.Errorf("the name now points at port %d, want the original 5001: "+ + "the refusal did not leave the first consumer in place", got) + } + }, + want: []string{"rec"}, + }, + { + // And the name is free again once it is given up, or a restart + // would be a permanent refusal. + name: "a name released by Unsubscribe can be taken again", + act: func(h *Hub) { + mustSubscribe(t, h, "rec", 5001) + h.Unsubscribe("rec") + mustSubscribe(t, h, "rec", 5009) }, want: []string{"rec"}, }, { name: "unsubscribe removes only the named consumer", act: func(h *Hub) { - h.Subscribe("rec", 5001) - h.Subscribe("hls", 5002) + mustSubscribe(t, h, "rec", 5001) + mustSubscribe(t, h, "hls", 5002) h.Unsubscribe("rec") }, want: []string{"hls"}, @@ -228,7 +253,7 @@ func TestSubscriberBookkeeping(t *testing.T) { { name: "unsubscribing an unknown name is a no-op", act: func(h *Hub) { - h.Subscribe("hls", 5002) + mustSubscribe(t, h, "hls", 5002) h.Unsubscribe("nobody") }, want: []string{"hls"}, @@ -257,7 +282,7 @@ func TestSubscriberBookkeeping(t *testing.T) { func TestSubscribeReturnsTheConsumerReadURL(t *testing.T) { h := newTestHub(t) - if got, want := h.Subscribe("rec", 41234), "udp://127.0.0.1:41234"; got != want { + if got, want := mustSubscribe(t, h, "rec", 41234), "udp://127.0.0.1:41234"; got != want { t.Errorf("Subscribe() = %q, want %q", got, want) } } @@ -279,8 +304,8 @@ func TestFanoutDeliversEachDatagramToEverySubscriber(t *testing.T) { h := newTestHub(t) connA, portA := boundSubscriber(t) connB, portB := boundSubscriber(t) - h.Subscribe("a", portA) - h.Subscribe("b", portB) + mustSubscribe(t, h, "a", portA) + mustSubscribe(t, h, "b", portB) const sends = 3 publish(t, h, tt.payload, sends) @@ -295,8 +320,8 @@ func TestFanoutSkipsAnUnsubscribedConsumer(t *testing.T) { h := newTestHub(t) connA, portA := boundSubscriber(t) connB, portB := boundSubscriber(t) - h.Subscribe("a", portA) - h.Subscribe("b", portB) + mustSubscribe(t, h, "a", portA) + mustSubscribe(t, h, "b", portB) h.Unsubscribe("b") payload := []byte("only a") @@ -315,8 +340,8 @@ func TestFanoutSkipsAnUnsubscribedConsumer(t *testing.T) { func TestDeadSubscriberDoesNotStarveALiveOne(t *testing.T) { h := newTestHub(t) live, livePort := boundSubscriber(t) - h.Subscribe("dead", unboundPort(t)) - h.Subscribe("live", livePort) + mustSubscribe(t, h, "dead", unboundPort(t)) + mustSubscribe(t, h, "live", livePort) payload := tsDatagram(0x22) const sends = 5 @@ -332,8 +357,8 @@ func TestStatsCountsReceiveAndTransmit(t *testing.T) { h := newTestHub(t) connA, portA := boundSubscriber(t) connB, portB := boundSubscriber(t) - h.Subscribe("a", portA) - h.Subscribe("b", portB) + mustSubscribe(t, h, "a", portA) + mustSubscribe(t, h, "b", portB) payload := tsDatagram(0x33) const sends = 4 @@ -396,7 +421,7 @@ func TestCloseStopsTheReader(t *testing.T) { t.Fatalf("New: %v", err) } sub, subPort := boundSubscriber(t) - h.Subscribe("a", subPort) + mustSubscribe(t, h, "a", subPort) port := h.Port() publish(t, h, []byte("before close"), 1) @@ -535,3 +560,24 @@ func TestPortAllocatorSkipsAPortSomethingElseIsUsing(t *testing.T) { t.Errorf("Allocate = %d, want %d (port %d is in use)", got, base+1, base) } } + +// mustSubscribe is Subscribe for a test that is not about the refusal. #711 +// made an occupied name an error, and a test that drops it would go on +// asserting fan-out against a hub that never registered the consumer. +func mustSubscribe(t testing.TB, h *Hub, name string, port int) string { + t.Helper() + url, err := h.Subscribe(name, port) + if err != nil { + t.Fatalf("Subscribe(%q, %d): %v", name, port, err) + } + return url +} + +func mustSubscribeAddr(t testing.TB, h *Hub, name string, ip net.IP, port int) string { + t.Helper() + url, err := h.SubscribeAddr(name, ip, port) + if err != nil { + t.Fatalf("SubscribeAddr(%q, %v, %d): %v", name, ip, port, err) + } + return url +} diff --git a/internal/rtmpserver/ingest_udp_test.go b/internal/rtmpserver/ingest_udp_test.go index 2411d711..4a61582a 100644 --- a/internal/rtmpserver/ingest_udp_test.go +++ b/internal/rtmpserver/ingest_udp_test.go @@ -487,7 +487,7 @@ func TestTheWholeChainThroughARealHubCarriesTheRoutedAudio(t *testing.T) { } subPort := subPC.LocalAddr().(*net.UDPAddr).Port _ = subPC.Close() // the reader binds it - subURL := hub.Subscribe("dest:test", subPort) + subURL := mustSubscribe(t, hub, "dest:test", subPort) defer hub.Unsubscribe("dest:test") pubCtx, stopPub := context.WithCancel(context.Background()) @@ -664,7 +664,7 @@ func TestAReaderJoiningBetweenTwoPublishesResolvesTheSecondOnesAudio(t *testing. } subPort := subPC.LocalAddr().(*net.UDPAddr).Port _ = subPC.Close() - subURL := hub.Subscribe("dest:test", subPort) + subURL := mustSubscribe(t, hub, "dest:test", subPort) defer hub.Unsubscribe("dest:test") tsPath := filepath.Join(t.TempDir(), "gap.ts") @@ -821,7 +821,7 @@ func TestADestinationStillResolvesItsAudioBesideEightOtherSubscribers(t *testing op := pc.LocalAddr().(*net.UDPAddr).Port _ = pc.Close() name := fmt.Sprintf("other:%d", i) - ou := hub.Subscribe(name, op) + ou := mustSubscribe(t, hub, name, op) defer hub.Unsubscribe(name) oa := append([]string{"-nostdin", "-hide_banner", "-loglevel", "error"}, ffmpeg.RelayInputArgs()...) @@ -843,7 +843,7 @@ func TestADestinationStillResolvesItsAudioBesideEightOtherSubscribers(t *testing } subPort := subPC.LocalAddr().(*net.UDPAddr).Port _ = subPC.Close() - subURL := hub.Subscribe("dest:test", subPort) + subURL := mustSubscribe(t, hub, "dest:test", subPort) defer hub.Unsubscribe("dest:test") tsPath := filepath.Join(t.TempDir(), "crowded.ts") @@ -928,3 +928,15 @@ func requireShippedFFmpeg(t *testing.T) (ffmpegBin, ffprobeBin string) { } return ffmpegBin, ffprobeBin } + +// mustSubscribe is Subscribe for a test that is not about the refusal. #711 +// made an occupied name an error; dropping it here would leave a test asserting +// delivery against a consumer the hub never registered. +func mustSubscribe(t testing.TB, h *relay.Hub, name string, port int) string { + t.Helper() + url, err := h.Subscribe(name, port) + if err != nil { + t.Fatalf("Subscribe(%q, %d): %v", name, port, err) + } + return url +} From e8ae778fac48af60c3427abf8e1e1e9f836255e7 Mon Sep 17 00:00:00 2001 From: Shannon Atkinson Date: Fri, 4 Sep 2026 17:14:09 -0700 Subject: [PATCH 6/8] fix(census): every spawner is enrolled or explained, and the clean report says what it covered Closes #717. The census was added inside internal/supervisor with unexported enrol/discharge, so exactly ONE of the roughly twenty spawn sites in this repository could use it -- and internal/ffmpeg could not have used it even if it wanted to, because supervisor imports ffmpeg and the import would have been a cycle. Its own comment framed it as "WHAT HAVE WE ACTUALLY SPAWNED?" and the shutdown report claimed it "would have said it on the first occurrence" of #631. Both were true only for supervisor children. A transcode or a whisper child surviving shutdown produced exactly the silence #631 produced -- while the shutdown log actively reported that nothing was wrong. A detection device that under-reports is worse than none, because its green is read as an all-clear. Three parts: - internal/childcensus, a leaf package importing nothing from this module, so every spawner can reach it. Enrol and Discharge are exported. - The spawners that can outlive a call now enrol: media.Exec (every transcode and derivative encode), the live-caption whisper and audio tap, and the transcription extract and whisper workers. Discharge is paired at the Wait, which is the only moment the pid is genuinely gone. - TestEverySpawnSiteIsAccountedFor walks every non-test .go file in the tree and requires each package calling exec.Command to be either a package that enrols, or one listed WITH A REASON saying what bounds its child's life. Seven silent omissions become seven stated decisions and the twenty-first spawner fails the build. The excuses are themselves checked: a reason under 40 characters, or one containing TODO, fails. An entry for a package that no longer spawns anything fails too, so the list cannot rot into a standing excuse nobody re-earns. The walker skips every dot-directory, not just .git: .claude/worktrees holds checkouts of this same repository, and walking them reported every spawn site three times under a path nobody can act on. reportSurvivingChildren now says so on a clean shutdown, and names its scope. Its test asserted the opposite -- "a line here on every clean stop would teach operators to skim past the one that matters" -- and that reasoning was sound when the scope was narrow enough to make silence ambiguous. It now pins the new property and records why it changed. Control is not available: nothing in Go stops a package calling exec.Command. This is Warning, raised when the code is written rather than when a child is found on a host. Also: coverage for the #711 refusal paths, which are the ones that had none. Every aux consumer, the destination and its backup, the silence tier and a playout variant, each driven into a taken name and each asserted on both halves -- nothing started, and the port came back. Closing the collision hazard must not open the leak hazard #707 was about. Three mutations, each red: a spawner that stops enrolling, an excuse reduced to a placeholder, and the clean shutdown going back to saying nothing. Claude-Session: https://claude.ai/code/session_01A8N3W5ct9SZtHK9sCDD9cL --- cmd/polyemesis/main.go | 22 +- cmd/polyemesis/surviving_children_test.go | 40 +++- .../{supervisor => childcensus}/census.go | 35 ++- internal/childcensus/census_test.go | 53 +++++ internal/childcensus/spawn_sites_test.go | 225 ++++++++++++++++++ internal/engine/subscribe_refusal_test.go | 223 +++++++++++++++++ internal/media/exec.go | 11 + internal/playout/subscribe_refusal_test.go | 50 ++++ internal/supervisor/census_test.go | 71 +----- internal/supervisor/supervisor.go | 5 +- internal/transcribe/live.go | 8 + internal/transcribe/worker.go | 8 + 12 files changed, 675 insertions(+), 76 deletions(-) rename internal/{supervisor => childcensus}/census.go (72%) create mode 100644 internal/childcensus/census_test.go create mode 100644 internal/childcensus/spawn_sites_test.go create mode 100644 internal/engine/subscribe_refusal_test.go create mode 100644 internal/playout/subscribe_refusal_test.go diff --git a/cmd/polyemesis/main.go b/cmd/polyemesis/main.go index fe3687ba..0b872092 100644 --- a/cmd/polyemesis/main.go +++ b/cmd/polyemesis/main.go @@ -20,6 +20,7 @@ import ( "github.com/rainmanjam/polyemesis/internal/api" "github.com/rainmanjam/polyemesis/internal/automod" "github.com/rainmanjam/polyemesis/internal/chat" + "github.com/rainmanjam/polyemesis/internal/childcensus" "github.com/rainmanjam/polyemesis/internal/config" "github.com/rainmanjam/polyemesis/internal/db" "github.com/rainmanjam/polyemesis/internal/diag" @@ -27,7 +28,6 @@ import ( "github.com/rainmanjam/polyemesis/internal/events" "github.com/rainmanjam/polyemesis/internal/ffmpeg" "github.com/rainmanjam/polyemesis/internal/logtz" - "github.com/rainmanjam/polyemesis/internal/supervisor" // Aliased: main.go already has a `hooks` type for the service lifecycle // callbacks, and that name is the older claim on it. webhooks "github.com/rainmanjam/polyemesis/internal/hooks" @@ -496,7 +496,7 @@ func run(h *hooks) error { srv.DrainLifecycleWithin(shutdownCtx) eng.StopWithin(shutdownCtx) warnIfShutdownOverran(shutdownCtx, log) - reportSurvivingChildren(log, supervisor.Live()) + reportSurvivingChildren(log, childcensus.Live()) log.Info("goodbye") return nil } @@ -1029,8 +1029,24 @@ func verifyBackup(dir string, out io.Writer) error { // the whole budget rather than merely being slow. // Takes the census rather than reading it, so the reporting can be tested // without spawning a process to be reported ON. -func reportSurvivingChildren(log *slog.Logger, live []supervisor.Child) { +func reportSurvivingChildren(log *slog.Logger, live []childcensus.Child) { if len(live) == 0 { + // SAYS SO, RATHER THAN SAYING NOTHING. #717. + // + // Silence here was read as an all-clear, and for most of this program's + // life it could not have been one: the census covered supervisor + // children only, so a transcode or a whisper child outliving the + // shutdown produced exactly the silence #631 produced -- while this + // function said nothing and the operator concluded the teardown was + // clean. + // + // It now covers every spawner that can outlive a call, and + // TestEverySpawnSiteIsAccountedFor is what keeps that true: a package + // that spawns without enrolling, and without a stated reason, fails the + // build. The line below is the claim; that test is what backs it. + log.Info("no child outlived the shutdown", + "scope", "every OS child this process spawned and enrolled: supervisor "+ + "children, media transcodes, and the transcription and live-caption workers") return } // Warn rather than Error: on a SIGKILLed child the census clears when the diff --git a/cmd/polyemesis/surviving_children_test.go b/cmd/polyemesis/surviving_children_test.go index 55b11e2a..960f38f0 100644 --- a/cmd/polyemesis/surviving_children_test.go +++ b/cmd/polyemesis/surviving_children_test.go @@ -1,11 +1,10 @@ package main import ( + "github.com/rainmanjam/polyemesis/internal/childcensus" "strings" "testing" "time" - - "github.com/rainmanjam/polyemesis/internal/supervisor" ) // #631 was found by somebody running `ps` on a production host and noticing an @@ -23,19 +22,44 @@ import ( // capture lives in shutdown_warn_test.go, which reports the other half of this // same moment: that the budget ran out. This says WHICH children it ran out on. -func TestAQuietShutdownSaysNothing(t *testing.T) { - // The common case by an enormous margin, and a line here on every clean - // stop would teach operators to skim past the one that matters. +// THIS TEST USED TO ASSERT SILENCE, and the reasoning was sound at the time: +// "the common case by an enormous margin, and a line here on every clean stop +// would teach operators to skim past the one that matters." +// +// #717 is why it changed. The census covered SUPERVISOR CHILDREN ONLY, so the +// silence this test pinned was being produced in two very different situations +// that looked identical from the log: a genuinely clean teardown, and a whisper +// or transcode child still running that this function could not see. A +// detection device that under-reports is worse than none, because its green is +// read as an all-clear. +// +// The scope is now broad -- every spawner that can outlive a call enrols -- and +// TestEverySpawnSiteIsAccountedFor is what keeps it broad. So the clean case +// says so, and says what "clean" covers. One line at the end of a shutdown that +// already logs "goodbye" is not a habit; a green nobody can size is. +func TestAQuietShutdownSaysWhatItCovered(t *testing.T) { log, buf := capture(t) reportSurvivingChildren(log, nil) - if buf.Len() != 0 { - t.Fatalf("a shutdown that left nothing behind logged %q", buf.String()) + + out := buf.String() + if out == "" { + t.Fatal("a clean shutdown said nothing at all. Silence here is produced " + + "both by a teardown that reaped everything and by one whose survivors " + + "are outside the census, and an operator cannot tell those apart") + } + if strings.Contains(strings.ToLower(out), "warn") || strings.Contains(out, "ERROR") { + t.Errorf("the clean case is reported at warning level or worse, which is how "+ + "an operator learns to skim the line that matters:\n%s", out) + } + if !strings.Contains(out, "scope") { + t.Errorf("the clean report does not say what it covered, so it can still be "+ + "read as more than it is:\n%s", out) } } func TestASurvivingChildIsNamedWithItsPID(t *testing.T) { log, buf := capture(t) - reportSurvivingChildren(log, []supervisor.Child{ + reportSurvivingChildren(log, []childcensus.Child{ {PID: 5216, Name: "meters", Kind: "meters", Since: time.Now().Add(-90 * time.Second)}, {PID: 5217, Name: "dest:studio-a", Kind: "destination", Since: time.Now().Add(-30 * time.Second)}, }) diff --git a/internal/supervisor/census.go b/internal/childcensus/census.go similarity index 72% rename from internal/supervisor/census.go rename to internal/childcensus/census.go index f14c0552..421eccbe 100644 --- a/internal/supervisor/census.go +++ b/internal/childcensus/census.go @@ -1,4 +1,20 @@ -package supervisor +// Package childcensus counts the OS children this process has spawned and not +// yet reaped. +// +// A LEAF PACKAGE ON PURPOSE, and that is the whole of #717. It began inside +// internal/supervisor with unexported enrol/discharge, which meant exactly one +// of the roughly twenty spawn sites in this repository could use it -- and +// internal/ffmpeg could not have used it even if it wanted to, because +// supervisor imports ffmpeg and the import would have been a cycle. So it lives +// here, importing nothing from this module, and every spawner can reach it. +// +// WHY THE SCOPE MATTERED ENOUGH TO MOVE THE PACKAGE. The report built on this +// says "nothing outlived the shutdown" by saying nothing at all, and a +// detection device that under-reports is worse than none, because its green is +// read as an all-clear. A transcode or a whisper child surviving shutdown +// produced exactly the silence #631 produced, while the shutdown log actively +// reported that all was well. +package childcensus import ( "fmt" @@ -64,10 +80,15 @@ var census struct { live map[int]Child } -// enrol records a child that has just been spawned. Called with the pid from a +// Enrol records a child that has just been spawned. Called with the pid from a // successful cmd.Start(), because before that there is nothing to enrol and // after a failed start there never was. -func enrol(pid int, name, kind string) { +// +// EVERY SPAWNER IS EXPECTED TO CALL IT. TestEverySpawnSiteIsAccountedFor makes +// that a build-time check rather than a habit: a package that calls +// exec.Command without enrolling, and without a stated reason for not needing +// to, fails. +func Enrol(pid int, name, kind string) { if pid <= 0 { return } @@ -79,10 +100,14 @@ func enrol(pid int, name, kind string) { census.live[pid] = Child{PID: pid, Name: name, Kind: kind, Since: time.Now()} } -// discharge records that a child has been reaped. Called where cmd.Wait() +// Discharge records that a child has been reaped. Called where cmd.Wait() // returns, which is the only moment the pid is genuinely gone -- signalling it // is not, because a child that ignores SIGTERM is still very much a child. -func discharge(pid int) { +// +// SAFE TO DEFER IMMEDIATELY AFTER Enrol. Discharging a pid that was never +// enrolled is a no-op, so a spawner that pairs them at the same lexical level +// cannot leave an entry behind on an early return. +func Discharge(pid int) { if pid <= 0 { return } diff --git a/internal/childcensus/census_test.go b/internal/childcensus/census_test.go new file mode 100644 index 00000000..f2194dfa --- /dev/null +++ b/internal/childcensus/census_test.go @@ -0,0 +1,53 @@ +package childcensus + +import ( + "testing" + "time" +) + +func TestTheCensusRefusesAPIDThatIsNotOne(t *testing.T) { + // cmd.Process.Pid is only meaningful after a successful Start. A zero here + // would be a permanent entry for a child that never existed, and a census + // with a phantom in it is one nobody trusts the rest of. + before := LiveCount() + Enrol(0, "ghost", "ghost") + Enrol(-1, "ghost", "ghost") + if LiveCount() != before { + t.Fatalf("a non-pid was enrolled: count went %d -> %d", before, LiveCount()) + } + Discharge(0) + Discharge(-1) + if LiveCount() != before { + t.Fatalf("discharging a non-pid disturbed the census: %d -> %d", before, LiveCount()) + } +} + +func TestTheOldestSurvivorIsReportedFirst(t *testing.T) { + // A report leads with the child that has been wrong for longest, because + // that is the one whose cause is furthest back and least likely to be the + // thing the operator is currently looking at. + before := len(Live()) + now := time.Now() + census.mu.Lock() + if census.live == nil { + census.live = map[int]Child{} + } + census.live[900001] = Child{PID: 900001, Name: "newer", Since: now} + census.live[900002] = Child{PID: 900002, Name: "older", Since: now.Add(-time.Hour)} + census.mu.Unlock() + t.Cleanup(func() { Discharge(900001); Discharge(900002) }) + + got := Live() + if len(got) != before+2 { + t.Fatalf("expected %d entries, got %d", before+2, len(got)) + } + var names []string + for _, c := range got { + if c.PID == 900001 || c.PID == 900002 { + names = append(names, c.Name) + } + } + if len(names) != 2 || names[0] != "older" { + t.Fatalf("Live() ordered the survivors %v; oldest must come first", names) + } +} diff --git a/internal/childcensus/spawn_sites_test.go b/internal/childcensus/spawn_sites_test.go new file mode 100644 index 00000000..0bb72254 --- /dev/null +++ b/internal/childcensus/spawn_sites_test.go @@ -0,0 +1,225 @@ +package childcensus + +import ( + "go/ast" + "go/parser" + "go/token" + "os" + "path/filepath" + "sort" + "strings" + "testing" +) + +// EVERY SPAWN SITE IS EITHER ENROLLED OR EXPLAINED. #717. +// +// The census was added with unexported enrol/discharge inside internal/ +// supervisor, so exactly one of the roughly twenty spawn sites in this +// repository could use it. Its own comment framed it as "WHAT HAVE WE ACTUALLY +// SPAWNED?" and the shutdown report said "it would have said it on the first +// occurrence of #631" -- both true only for supervisor children. A transcode or +// a whisper child surviving shutdown produced exactly the silence #631 produced, +// while the shutdown log actively reported that nothing was wrong. +// +// A DETECTION DEVICE THAT UNDER-REPORTS IS WORSE THAN NONE, because its green is +// read as an all-clear. So the scope is no longer a thing somebody remembers: +// every package that calls exec.Command or exec.CommandContext is either a +// package that enrols, or a package on the list below WITH A REASON. +// +// Control is not available -- nothing in Go stops a package calling +// exec.Command -- so this is Warning, at the earliest moment it can be raised: +// when the code is written, not when a child is found on a host. +// +// A new spawner fails this test until somebody decides which it is. That is the +// whole device: the decision is forced, and it is recorded where the next reader +// will find it. +var spawnersThatNeedNoCensus = map[string]string{ + "internal/ffmpeg": "capability probes and duration counts: every one collects its " + + "output and returns, is bounded by a context deadline with WaitDelay set, and " + + "cannot outlive the call that made it, let alone the process", + "internal/clipper": "one ffprobe keyframe scan, output-collected, killed with its " + + "context; the clip ENCODE is a supervisor child and is enrolled there", + "internal/playlistmedia": "the probe helper only; every encode in this package goes " + + "through media.Exec, which enrols", + "internal/recording": "a single ffprobe for a finished file's duration, output-collected", + "internal/api": "two short output-collected runs -- the playout poster frame and the " + + "expert dry-run, the latter bounded by both a context deadline and WaitDelay. " + + "Neither can survive the handler, so neither can survive the shutdown", + "internal/testenv": "test scaffolding: netstat and lsof, to find a free UDP port", + "scripts/cmd/gotest": "a build-time wrapper that shells out to `go test`; it is not " + + "part of the server binary and its child is the test run itself", + "scripts": "the acceptance drivers, which are built and run by the suites in " + + "scripts/ and never linked into the server binary; their children die with " + + "the driver process and there is no shutdown report for them to be missing from", + "internal/supervisor": "enrols through childcensus at spawn and discharges at reap; " + + "listed here because its exec.Command call is in the same function as the Enrol " + + "and the walker below matches on package, not on line", +} + +// A REASON THAT SAYS NOTHING IS NOT A REASON. The failure mode this guards +// against is somebody silencing the test with "n/a" and moving on, which puts +// the scope back where it was: a thing nobody can see. +const minReasonLen = 40 + +func TestEverySpawnSiteIsAccountedFor(t *testing.T) { + root := repoRoot(t) + fset := token.NewFileSet() + + spawners := map[string][]string{} // package dir -> call sites + enrollers := map[string]bool{} // package dir -> calls childcensus.Enrol + + err := filepath.Walk(root, func(path string, info os.FileInfo, err error) error { + if err != nil { + return err + } + if info.IsDir() { + // EVERY DOT-DIRECTORY, not just .git. .claude/worktrees holds + // checkouts of this same repository, and walking them made the + // report list every spawn site three times under a path nobody can + // act on -- and would have kept a stale copy failing this test long + // after the branch it came from was merged. + if strings.HasPrefix(info.Name(), ".") && info.Name() != "." { + return filepath.SkipDir + } + switch info.Name() { + case "node_modules", "web", "ui", "dist", "vendor", "testdata": + return filepath.SkipDir + } + return nil + } + if !strings.HasSuffix(path, ".go") || strings.HasSuffix(path, "_test.go") { + return nil + } + f, perr := parser.ParseFile(fset, path, nil, 0) + if perr != nil { + return nil // not our business to fail on unparseable Go; the build does that + } + rel, _ := filepath.Rel(root, path) + pkg := filepath.ToSlash(filepath.Dir(rel)) + + ast.Inspect(f, func(n ast.Node) bool { + call, ok := n.(*ast.CallExpr) + if !ok { + return true + } + sel, ok := call.Fun.(*ast.SelectorExpr) + if !ok { + return true + } + ident, ok := sel.X.(*ast.Ident) + if !ok { + return true + } + switch { + case ident.Name == "exec" && strings.HasPrefix(sel.Sel.Name, "Command"): + spawners[pkg] = append(spawners[pkg], + filepath.ToSlash(rel)+":"+fsetLine(fset, call.Pos())) + case ident.Name == "childcensus" && sel.Sel.Name == "Enrol": + enrollers[pkg] = true + } + return true + }) + return nil + }) + if err != nil { + t.Fatalf("walking the tree: %v", err) + } + + // THE WALKER MUST ACTUALLY FIND THINGS. A test that walks nothing passes + // every assertion below and reports a scope it never checked, which is the + // same failure as the census it is here to bound. + if len(spawners) < 5 { + t.Fatalf("only found spawn sites in %d package(s) under %s; the walker is "+ + "broken and this test is asserting nothing", len(spawners), root) + } + if !enrollers["internal/supervisor"] && !enrollers["internal/media"] { + t.Fatal("found no package calling childcensus.Enrol; the walker cannot tell " + + "an enrolling package from a silent one, so its verdict is worthless") + } + + var unaccounted []string + for pkg, sites := range spawners { + if pkg == "internal/childcensus" || enrollers[pkg] { + continue + } + if _, excused := spawnersThatNeedNoCensus[pkg]; excused { + continue + } + unaccounted = append(unaccounted, pkg+" ("+strings.Join(sites, ", ")+")") + } + sort.Strings(unaccounted) + if len(unaccounted) > 0 { + t.Errorf("these packages spawn OS children, do not enrol them in the census, "+ + "and give no reason:\n %s\n\n"+ + "A child nobody enrolled is invisible from inside the program: absent from "+ + "every map, every status page and every log line, and present only in the "+ + "process table. That is the exact shape of #631, which took three weeks and "+ + "53 escalations to notice.\n\n"+ + "Either call childcensus.Enrol after Start and Discharge after Wait, or add "+ + "the package to spawnersThatNeedNoCensus with a reason saying why its child "+ + "cannot outlive the call.", strings.Join(unaccounted, "\n ")) + } + + // AND THE LIST MUST NOT ROT. An entry for a package that no longer spawns + // anything is a standing excuse nobody re-earns. + for pkg := range spawnersThatNeedNoCensus { + if len(spawners[pkg]) == 0 { + t.Errorf("spawnersThatNeedNoCensus lists %q, which no longer calls "+ + "exec.Command. Remove the entry rather than leaving an excuse in "+ + "place for whatever is written there next.", pkg) + } + } +} + +// The reasons have to be reasons, or the list becomes a way to silence the test. +func TestTheCensusExcusesExplainThemselves(t *testing.T) { + for pkg, why := range spawnersThatNeedNoCensus { + if len(why) < minReasonLen { + t.Errorf("%s is excused from the census with %q (%d chars). Say what "+ + "bounds the child's life -- an output-collected run, a context "+ + "deadline, a WaitDelay -- because the next reader has to decide "+ + "whether it is still true.", pkg, why, len(why)) + } + if strings.Contains(strings.ToLower(why), "tbd") || strings.Contains(why, "TODO") { + t.Errorf("%s: %q is a placeholder, not a reason", pkg, why) + } + } +} + +func fsetLine(fset *token.FileSet, p token.Pos) string { + return itoa(fset.Position(p).Line) +} + +func itoa(n int) string { + if n == 0 { + return "0" + } + var b []byte + for n > 0 { + b = append([]byte{byte('0' + n%10)}, b...) + n /= 10 + } + return string(b) +} + +// repoRoot walks up from the test's working directory to the module root, so +// this runs the same from `go test ./...` and from an IDE. +func repoRoot(t *testing.T) string { + t.Helper() + dir, err := os.Getwd() + if err != nil { + t.Fatalf("getwd: %v", err) + } + for i := 0; i < 8; i++ { + if _, err := os.Stat(filepath.Join(dir, "go.mod")); err == nil { + return dir + } + parent := filepath.Dir(dir) + if parent == dir { + break + } + dir = parent + } + t.Fatal("could not find go.mod above the test's working directory") + return "" +} diff --git a/internal/engine/subscribe_refusal_test.go b/internal/engine/subscribe_refusal_test.go new file mode 100644 index 00000000..08666aad --- /dev/null +++ b/internal/engine/subscribe_refusal_test.go @@ -0,0 +1,223 @@ +package engine + +import ( + "testing" + + "github.com/rainmanjam/polyemesis/internal/clips" + "github.com/rainmanjam/polyemesis/internal/db" + "github.com/rainmanjam/polyemesis/internal/routing" +) + +// A RELAY NAME ALREADY IN USE STOPS THE CHILD AND GIVES THE PORT BACK. #711/#707. +// +// Every aux consumer takes a port and then a name, and until #711 the name was +// a bare map assignment that could not fail. Now it can, and the refusal has to +// take the same release-and-bail path the port refusal beside it already took — +// otherwise closing the collision hazard would open the leak hazard, on the +// exact code #707 was about. +// +// So the assertion here is BOTH halves at once: nothing started, and the pool +// is exactly as full as it was. The incumbent keeping its subscription is +// checked too, because that is the property the whole refusal exists for. +func TestAnAuxConsumerRefusedItsRelayNameStartsNothingAndKeepsNoPort(t *testing.T) { + // Table over the production consumers rather than one test each: they are + // the same hazard reached through five doors, and a table makes a sixth + // door's omission visible as a missing row. + for _, tc := range []struct { + name string + subName string + drive func(t *testing.T, e *Engine) + live func(e *Engine) bool + }{ + { + name: "meters", + subName: "meters", + drive: func(t *testing.T, e *Engine) { + e.mu.Lock() + e.source = routing.Source{Tracks: []routing.Track{{Channels: 2}}} + e.measured, e.probed = true, true + e.mu.Unlock() + s := db.DefaultSettings() + s.Meters.Enabled = true + e.reconcileMeters(s) + }, + live: func(e *Engine) bool { e.mu.RLock(); defer e.mu.RUnlock(); return e.meters != nil }, + }, + { + name: "recorder", + subName: "recorder", + drive: func(t *testing.T, e *Engine) { + s := db.DefaultSettings() + s.Recording.Enabled = true + e.reconcileRecorder(s) + }, + live: func(e *Engine) bool { e.mu.RLock(); defer e.mu.RUnlock(); return e.recorder != nil }, + }, + { + name: "preview", + subName: "preview", + drive: func(t *testing.T, e *Engine) { + s := db.DefaultSettings() + s.Preview.Enabled = true + markPreviewFlowing(e) + e.reconcilePreview(s) + }, + live: func(e *Engine) bool { e.mu.RLock(); defer e.mu.RUnlock(); return e.preview != nil }, + }, + { + name: "clip buffer", + subName: clipSubName, + drive: func(t *testing.T, e *Engine) { + e.mu.Lock() + e.clipOn, e.clipCfg = true, clips.Config{WindowSeconds: 30, MaxRingBytes: 1 << 20} + e.mu.Unlock() + e.reconcileClips() + }, + live: func(e *Engine) bool { e.mu.RLock(); defer e.mu.RUnlock(); return e.clipCap != nil }, + }, + } { + t.Run(tc.name, func(t *testing.T) { + e, _ := storeEngine(t) + + // THE INCUMBENT. A real consumer already reading under this name, + // which is the only state that makes a second subscribe wrong. + held := enginePort(t, e, "the incumbent consumer") + hub := e.downstreamHub() + if hub == nil { + t.Fatal("no downstream hub on a fresh engine") + } + if _, err := hub.Subscribe(tc.subName, held); err != nil { + t.Fatalf("the incumbent could not subscribe: %v", err) + } + // The ingest hub too, for the consumers that read it rather than + // the downstream one; on a fresh engine they are the same object, + // and this keeps the row honest if they stop being. + if e.hub != hub { + if _, err := e.hub.Subscribe(tc.subName, held); err != nil { + t.Fatalf("the incumbent could not subscribe to the ingest hub: %v", err) + } + } + + before := e.heldPortCount() + tc.drive(t, e) + + if tc.live(e) { + t.Errorf("the %s started even though its relay name was taken. It is "+ + "subscribed to nothing, so it runs with a correct command line and "+ + "a healthy card while receiving no packets at all -- and it has "+ + "replaced the consumer that was reading under that name", tc.name) + } + if got := e.heldPortCount(); got != before { + t.Errorf("the engine holds %d port(s), was %d: a refusal that keeps the "+ + "port burns one of the 500 shared across every engine, permanently "+ + "and silently", got, before) + } + if !hasSubscriber(hub, tc.subName) { + t.Errorf("%q is no longer on the hub: the refusal removed the "+ + "incumbent's subscription, which is the exact outcome it exists "+ + "to prevent", tc.subName) + } + }) + } +} + +// The silence tier takes the same path and is worth its own case: it also opens +// a relay hub of its own before subscribing, so its refusal has three things to +// give back rather than two. +func TestASilenceTierRefusedItsRelayNameLeavesNoPortAndNoHub(t *testing.T) { + e, _ := storeEngine(t) + + held := enginePort(t, e, "the incumbent consumer") + if _, err := e.hub.Subscribe(silenceSubName, held); err != nil { + t.Fatalf("the incumbent could not subscribe: %v", err) + } + before := e.heldPortCount() + + e.startSilence("silence|stereo|48000") + + e.mu.RLock() + tier := e.silence + e.mu.RUnlock() + // startSilence records a FAILED tier rather than returning: the destinations + // downstream have to be told why no bed is coming, and the next reconcile + // retries. So the property is not "nothing was recorded" -- it is that + // nothing was STARTED and the reason is carried. + if tier == nil { + t.Fatal("the refusal recorded nothing at all; the destinations downstream " + + "are never told why no silent bed arrived") + } + if tier.proc != nil || tier.hub != nil || tier.port != 0 { + t.Errorf("the silence tier published itself despite being refused its relay "+ + "name (%+v), so reconcile believes a bed is on air that receives nothing", tier) + } + if tier.err == "" { + t.Error("the failed tier carries no reason, so the status page says the bed " + + "is absent without saying why") + } + if got := e.heldPortCount(); got != before { + t.Errorf("the engine holds %d port(s), was %d", got, before) + } + if !hasSubscriber(e.hub, silenceSubName) { + t.Error("the incumbent's subscription was removed by the refusal") + } +} + +// The destination path, primary and backup, and they fail differently on +// purpose: a destination that cannot start is an error the caller reports, +// while a backup that cannot start is recorded and the primary carries on. +// #711 has to preserve both, or closing the collision would either take a live +// destination down or turn its optional half into a hard failure. +func TestADestinationRefusedItsRelayNameFailsAndReturnsThePort(t *testing.T) { + e, _ := storeEngine(t) + row := backupRow() + + held := enginePort(t, e, "the incumbent consumer") + if _, err := e.hub.Subscribe(destSubName(row.ID, ""), held); err != nil { + t.Fatalf("the incumbent could not subscribe: %v", err) + } + before := e.heldPortCount() + + err := e.startDest(destPlan{row: row, spec: "spec", compiled: routing.Result{}}, e.hub, 0) + if err == nil { + t.Error("startDest reported success while subscribed to nothing. The " + + "destination would show a healthy card and a correct command line and " + + "publish an empty stream, and the consumer that held the name is cut off") + } + if got := e.heldPortCount(); got != before { + t.Errorf("the engine holds %d port(s), was %d: a destination that refuses to "+ + "start must give its port back", got, before) + } +} + +func TestABackupRefusedItsRelayNameIsRecordedAndLeavesThePrimaryAlone(t *testing.T) { + e, _ := storeEngine(t) + row := backupRow() + + held := enginePort(t, e, "the incumbent consumer") + backupSub := destSubName(row.ID, destRoleBackup) + if _, err := e.hub.Subscribe(backupSub, held); err != nil { + t.Fatalf("the incumbent could not subscribe: %v", err) + } + before := e.heldPortCount() + + d := &destination{row: row, hub: e.hub, spec: "spec"} + e.buildBackup(d, routing.Result{}, "spec") + + if d.backup != nil || d.backupPort != 0 || d.backupSub != "" { + t.Errorf("the backup published itself despite being refused its relay name: "+ + "proc=%v port=%d sub=%q", d.backup != nil, d.backupPort, d.backupSub) + } + if d.backupErr == "" { + t.Error("the backup failed silently. Its whole card says 'redundant feed " + + "running' or says why it is not, and this leaves it saying neither") + } + if got := e.heldPortCount(); got != before { + t.Errorf("the engine holds %d port(s), was %d", got, before) + } + // AND THE PRIMARY IS UNTOUCHED. A backup that cannot start is not a reason + // to take a live destination off the air, which is why this path records a + // reason rather than returning an error. + if !hasSubscriber(e.hub, backupSub) { + t.Error("the refusal removed the incumbent's subscription") + } +} diff --git a/internal/media/exec.go b/internal/media/exec.go index 9b999043..1984e927 100644 --- a/internal/media/exec.go +++ b/internal/media/exec.go @@ -11,6 +11,8 @@ import ( "time" "github.com/rainmanjam/polyemesis/internal/ffmpeg" + + "github.com/rainmanjam/polyemesis/internal/childcensus" ) // Command is one child process to run. @@ -76,6 +78,15 @@ func Exec(ctx context.Context, cmd Command, sink Sink) error { if err := c.Start(); err != nil { return fmt.Errorf("start %s: %w", cmd.Name, err) } + // ENROLLED FOR AS LONG AS IT RUNS. #717. Before this, the census covered + // supervisor children only, and a transcode that outlived the shutdown + // produced exactly the silence #631 produced -- while the shutdown log + // reported that nothing was wrong. + // + // Discharged where Wait returns, which is the only moment the pid is + // genuinely gone; a child that ignores the kill is still very much a child. + childcensus.Enrol(c.Process.Pid, cmd.Name, "media") + defer childcensus.Discharge(c.Process.Pid) var ( mu sync.Mutex diff --git a/internal/playout/subscribe_refusal_test.go b/internal/playout/subscribe_refusal_test.go new file mode 100644 index 00000000..170ae550 --- /dev/null +++ b/internal/playout/subscribe_refusal_test.go @@ -0,0 +1,50 @@ +package playout + +import ( + "testing" + + "github.com/rainmanjam/polyemesis/internal/db" +) + +// A VARIANT REFUSED ITS RELAY NAME STARTS NOTHING AND GIVES ITS PORT BACK. #711. +// +// Hub.Subscribe used to be a bare map assignment that could not fail, so this +// path did not exist. Now it can fail, and it has to take the same +// release-and-bail path the port refusal beside it already takes -- otherwise +// closing the name collision opens a port leak on the pool of 500 shared across +// every engine. +// +// The refusal is recorded rather than returned, exactly as a failed port +// allocation is: the other variants in the ladder go on running, and the +// operator is told which one is missing and why. +func TestAVariantRefusedItsRelayNameLeavesNoPortBehind(t *testing.T) { + h := newHarness(t) + + // The incumbent: something already reading under the name this variant + // will ask for. That is the only state in which a second subscribe is + // wrong, and before #711 it was silently granted. + name := "hd" + if _, err := h.hub.Subscribe("playout:"+name, 20999); err != nil { + t.Fatalf("the incumbent could not subscribe: %v", err) + } + before := h.ports.leaked() + + if err := h.Reconcile(baseSettings(db.PlayoutVariant{Name: name, Enabled: true}), h.resolve); err != nil { + t.Fatalf("Reconcile: %v", err) + } + + if n := len(h.spawns.all()); n != 0 { + t.Errorf("%d variant process(es) were spawned despite the relay name being "+ + "taken. Each one runs with a correct command line, writes an empty "+ + "playlist, and receives no packets at all", n) + } + if got := h.ports.leaked(); got != before { + t.Errorf("%d port(s) held, was %d: a variant that refuses to start must give "+ + "its port back, or every reconcile against a taken name burns one of the "+ + "500 shared across all engines", got, before) + } + if h.hub.count() != 1 { + t.Errorf("the hub holds %d subscriber(s): the refusal disturbed the "+ + "incumbent, which is the outcome it exists to prevent", h.hub.count()) + } +} diff --git a/internal/supervisor/census_test.go b/internal/supervisor/census_test.go index 1f3a5aa2..d7851b9e 100644 --- a/internal/supervisor/census_test.go +++ b/internal/supervisor/census_test.go @@ -9,6 +9,8 @@ import ( "strings" "testing" "time" + + "github.com/rainmanjam/polyemesis/internal/childcensus" ) /* The census exists because #631 could not be answered from inside the program. @@ -29,13 +31,13 @@ import ( // liveByPID finds this test's own child rather than asserting on the global // count. The census is package-level by design, and a sibling test's cleanup // goroutine may still be reaping when this one starts. -func liveByPID(pid int) (Child, bool) { - for _, c := range Live() { +func liveByPID(pid int) (childcensus.Child, bool) { + for _, c := range childcensus.Live() { if c.PID == pid { return c, true } } - return Child{}, false + return childcensus.Child{}, false } func TestASpawnedChildIsCountedAndAReapedOneIsNot(t *testing.T) { @@ -132,13 +134,13 @@ func TestTheCensusCountsReapedRatherThanSignalled(t *testing.T) { func TestTheCensusIsNotVacuous(t *testing.T) { // A census that never enrolled anything would pass both tests above by // reporting nothing at every point they look. This one asserts the - // positive: with a child up, Live() is non-empty and LiveCount() agrees + // positive: with a child up, childcensus.Live() is non-empty and childcensus.LiveCount() agrees // with it. p := testProcess(t, fakeSleep(30*time.Second), Spec{Name: "ingest", Kind: "ingest"}) p.Start() - waitFor(t, "a non-empty census", func() bool { return LiveCount() > 0 }) - if n, l := LiveCount(), len(Live()); n != l { - t.Fatalf("LiveCount()=%d but len(Live())=%d; the cheap path and the reporting "+ + waitFor(t, "a non-empty census", func() bool { return childcensus.LiveCount() > 0 }) + if n, l := childcensus.LiveCount(), len(childcensus.Live()); n != l { + t.Fatalf("childcensus.LiveCount()=%d but len(childcensus.Live())=%d; the cheap path and the reporting "+ "path disagree, so one of them is lying to somebody", n, l) } } @@ -147,7 +149,7 @@ func TestACensusEntryReadsAsSomethingAnOperatorCanActotOn(t *testing.T) { // The String is what lands in a report, and a report that omits the pid // tells an operator there is a problem without telling them how to find it // -- which is where #631 started, with somebody reading `ps` output by eye. - c := Child{PID: 5216, Name: "meters", Kind: "meters", Since: time.Now().Add(-90 * time.Second)} + c := childcensus.Child{PID: 5216, Name: "meters", Kind: "meters", Since: time.Now().Add(-90 * time.Second)} got := c.String() for _, want := range []string{"5216", "meters"} { if !strings.Contains(got, want) { @@ -161,53 +163,6 @@ func TestACensusEntryReadsAsSomethingAnOperatorCanActotOn(t *testing.T) { } } -func TestTheCensusRefusesAPIDThatIsNotOne(t *testing.T) { - // cmd.Process.Pid is only meaningful after a successful Start. A zero here - // would be a permanent entry for a child that never existed, and a census - // with a phantom in it is one nobody trusts the rest of. - before := LiveCount() - enrol(0, "ghost", "ghost") - enrol(-1, "ghost", "ghost") - if LiveCount() != before { - t.Fatalf("a non-pid was enrolled: count went %d -> %d", before, LiveCount()) - } - discharge(0) - discharge(-1) - if LiveCount() != before { - t.Fatalf("discharging a non-pid disturbed the census: %d -> %d", before, LiveCount()) - } -} - -func TestTheOldestSurvivorIsReportedFirst(t *testing.T) { - // A report leads with the child that has been wrong for longest, because - // that is the one whose cause is furthest back and least likely to be the - // thing the operator is currently looking at. - before := len(Live()) - now := time.Now() - census.mu.Lock() - if census.live == nil { - census.live = map[int]Child{} - } - census.live[900001] = Child{PID: 900001, Name: "newer", Since: now} - census.live[900002] = Child{PID: 900002, Name: "older", Since: now.Add(-time.Hour)} - census.mu.Unlock() - t.Cleanup(func() { discharge(900001); discharge(900002) }) - - got := Live() - if len(got) != before+2 { - t.Fatalf("expected %d entries, got %d", before+2, len(got)) - } - var names []string - for _, c := range got { - if c.PID == 900001 || c.PID == 900002 { - names = append(names, c.Name) - } - } - if len(names) != 2 || names[0] != "older" { - t.Fatalf("Live() ordered the survivors %v; oldest must come first", names) - } -} - func TestASpawnThatFailedEnrolsNothing(t *testing.T) { // The one way this census could report a child that never existed, and the // reason enrol sits inside `if startErr == nil` rather than after it. @@ -216,7 +171,7 @@ func TestASpawnThatFailedEnrolsNothing(t *testing.T) { // at the end of every shutdown, so a phantom here is a warning line naming // a pid that was never a process -- on the very report whose job is to be // believed the one time it fires. - before := LiveCount() + before := childcensus.LiveCount() p := testProcess(t, fake{bin: filepath.Join(t.TempDir(), "no-such-binary")}, Spec{Name: "ghost", Kind: "ghost"}) p.Start() @@ -227,8 +182,8 @@ func TestASpawnThatFailedEnrolsNothing(t *testing.T) { // AutoRestart is off in this Spec, so there is no second attempt to race. deadline := time.Now().Add(750 * time.Millisecond) for time.Now().Before(deadline) { - if got := LiveCount(); got > before { - for _, c := range Live() { + if got := childcensus.LiveCount(); got > before { + for _, c := range childcensus.Live() { t.Logf(" census entry: %s", c) } t.Fatalf("a spawn that never happened put the census at %d, was %d", got, before) diff --git a/internal/supervisor/supervisor.go b/internal/supervisor/supervisor.go index 08724f34..81caf92b 100644 --- a/internal/supervisor/supervisor.go +++ b/internal/supervisor/supervisor.go @@ -20,6 +20,7 @@ import ( "time" "github.com/rainmanjam/polyemesis/internal/alerts" + "github.com/rainmanjam/polyemesis/internal/childcensus" "github.com/rainmanjam/polyemesis/internal/ffmpeg" ) @@ -859,7 +860,7 @@ func (p *Process) runOnce(ctx context.Context) error { // entry keyed on a pid survives its Process being dropped on the floor, // and an entry keyed on the Process would not. This line and the // discharge after cmd.Wait() are the census's only two writers. - enrol(cmd.Process.Pid, p.spec.Name, p.spec.Kind) + childcensus.Enrol(cmd.Process.Pid, p.spec.Name, p.spec.Kind) } // The parent's copies of the write ends, closed unconditionally: the child // has inherited its own, and while the parent holds one the pipe cannot reach @@ -976,7 +977,7 @@ func (p *Process) runOnce(ctx context.Context) error { // Reaped, so the census is now wrong until this line runs. Paired with the // enrol after cmd.Start(); deliberately NOT in the drain below, which waits // on descendants this process never started and can outlive the child. - discharge(cmd.Process.Pid) + childcensus.Discharge(cmd.Process.Pid) // Announce the reap before the drain, because that is what terminate()'s // escalation is asking about: a child that has been reaped needs no SIGKILL, // whether or not its grandchild is still writing. diff --git a/internal/transcribe/live.go b/internal/transcribe/live.go index cb91e4af..2edee37c 100644 --- a/internal/transcribe/live.go +++ b/internal/transcribe/live.go @@ -18,6 +18,8 @@ import ( "github.com/rainmanjam/polyemesis/internal/ffmpeg" "github.com/rainmanjam/polyemesis/internal/routing" + + "github.com/rainmanjam/polyemesis/internal/childcensus" ) // Realtime captions: the one job in this workstream that deliberately competes @@ -1022,6 +1024,10 @@ func (w *whisperLive) Transcribe(ctx context.Context, pcm []byte) ([]Segment, er if err := cmd.Start(); err != nil { return nil, fmt.Errorf("live captions: start whisper: %w", err) } + // #717. Runs for the length of a broadcast, so it is exactly the shape that + // can outlive a shutdown unseen. + childcensus.Enrol(cmd.Process.Pid, "live-captions-whisper", "transcribe") + defer childcensus.Discharge(cmd.Process.Pid) var ( wg sync.WaitGroup @@ -1185,6 +1191,7 @@ func (c *LiveCaptioner) Start(ctx context.Context, relayURL, modelPath, workDir cancel() return fmt.Errorf("live captions: start audio tap: %w", err) } + childcensus.Enrol(cmd.Process.Pid, "live-captions-audio-tap", "transcribe") // #717 tr := &whisperLive{ tools: c.whisper, @@ -1218,6 +1225,7 @@ func (c *LiveCaptioner) Start(ctx context.Context, relayURL, modelPath, workDir // captioner that leaves an FFmpeg child behind on every stop would // accumulate one per toggle, each still decoding the relay. _ = cmd.Wait() + childcensus.Discharge(cmd.Process.Pid) // #717: paired with the Enrol after Start c.mu.Lock() c.last = sess.Stats() diff --git a/internal/transcribe/worker.go b/internal/transcribe/worker.go index a67d6f15..1b224243 100644 --- a/internal/transcribe/worker.go +++ b/internal/transcribe/worker.go @@ -19,6 +19,8 @@ import ( "github.com/rainmanjam/polyemesis/internal/ffmpeg" "github.com/rainmanjam/polyemesis/internal/jobs" "github.com/rainmanjam/polyemesis/internal/routing" + + "github.com/rainmanjam/polyemesis/internal/childcensus" ) // The queue processor. @@ -430,6 +432,9 @@ func (p *Processor) extract(ctx context.Context, spec ExtractSpec, progress func if err := cmd.Start(); err != nil { return fmt.Errorf("start ffmpeg: %w", err) } + // #717. A transcription extract runs for as long as the recording is long. + childcensus.Enrol(cmd.Process.Pid, "transcribe-extract", "transcribe") + defer childcensus.Discharge(cmd.Process.Pid) var wg sync.WaitGroup wg.Add(1) go func() { @@ -504,6 +509,9 @@ func (p *Processor) whisperRun(ctx context.Context, spec WhisperSpec, rep jobs.R if err := cmd.Start(); err != nil { return nil, "", fmt.Errorf("start whisper: %w", err) } + // #717. Whisper on a long recording runs for minutes to hours. + childcensus.Enrol(cmd.Process.Pid, "transcribe-whisper", "transcribe") + defer childcensus.Discharge(cmd.Process.Pid) err := cmd.Wait() // A child killed mid-line still has something to say, and when the failure From d0dcfb19edc5f5eb6762a30dc58c61dc4074375d Mon Sep 17 00:00:00 2001 From: Shannon Atkinson Date: Fri, 4 Sep 2026 17:35:32 -0700 Subject: [PATCH 7/8] fix(api): a mutation whose reconcile failed no longer answers with a plain success Closes #709. Sixteen handlers called s.reconcile() and TWO SPELLINGS lived side by side in one package: three turned the error into a 500, twelve logged it at Warn and returned success. Nothing in the signature said which was right, so a handler written by copying its nearest neighbour got whichever that neighbour was. The silent spelling is worse than it looks. Engine.Reconcile returns early on a reconcileOutputs error, so preview, clips, captions and loudness are skipped with it; Manager.Reconcile returns firstErr. And reconcile is EVENT-DRIVEN WITH NO TICKER -- engine.go says so in as many words -- so the failure is never retried. Stored state and the running FFmpeg diverge until the next successful mutation or a restart, while the response said 200 and the UI raised a green toast. The worst case was invisible: handleDeleteDestination returned {"status": "deleted"}, the row left the list, and the FFmpeg child kept publishing to a destination the console no longer draws. ONE SPELLING. Server.reconcileNow is the only caller of s.reconcile() and returns the sentence to hand the operator, empty on success. The three loud sites turn a non-empty result into their 500; the rest attach it. What is gone is the per-site choice about whether the failure is reported at all. writeMutation folds the sentence into the response THROUGH THE MARSHALLED FORM rather than a field on each of a dozen response types -- adding a field per type is exactly the per-site decision being removed. It appends to `warnings`, which two handlers already build and the SPA already renders, rather than inventing a second array meaning the same thing, and sets reconcileFailed so the UI branches on a flag rather than on an English sentence. writeMutationNoContent handles the 204 routes: a 204 has no body, so a failed reconcile becomes a 200 that can say something rather than an empty success. expert.go was the sharpest instance and is fixed as such. Applied shipped as a hardcoded `true`, and a comment claimed "the command shown back is the one the reconcile above just started" -- false on exactly the branch that swallowed the error. Applied is now `rw == ""` and Warning carries the reason, which MonitoringPage already renders. scheduler.Result gains ReconcileErr, set on every schedule that FIRED in a sweep whose reconcile failed. On every one, because the reconcile is a single call for the batch: which of them took effect is not knowable, and saying so on each is honest where attributing it to one would not be. THE UI HALF IS IN THE TRANSPORT, not at the call sites. api.ts's request() raises the amber toast when it sees reconcileFailed, so all fifteen routes and every route added later are covered without being told. It reads the FLAG rather than the array, so a warning the server attached for another reason -- a DestinationDialog platform note -- is not doubled. TestReconcileHasOneSpellingAndItsResultCannotBeDropped enforces both rules at build time: s.reconcile() must have exactly one caller, and a bare `s.reconcileNow(...)` statement fails, because Go will happily let you discard the returned string and discarding it is precisely the mistake. Warning rather than Control, deliberately: refusing the write would be wrong. The row genuinely was saved, and a 500 invites a retry that re-POSTs a destination. The honest ceiling is that the response states what did not happen. Six mutations, each red: a handler dropping the warning, a second s.reconcile() spelling reappearing, writeMutation dropping it, an existing warnings array being overwritten, the transport not reading the flag, and the transport reading the array instead of the flag. Claude-Session: https://claude.ai/code/session_01A8N3W5ct9SZtHK9sCDD9cL --- internal/api/api.go | 119 ++++++++++++++++- internal/api/expert.go | 27 ++-- internal/api/handlers.go | 34 +++-- internal/api/media.go | 4 +- internal/api/oauth_handlers.go | 6 +- internal/api/reconcile_reporting_test.go | 147 +++++++++++++++++++++ internal/api/reconcile_warning_test.go | 157 +++++++++++++++++++++++ internal/api/renditions.go | 18 +-- internal/api/sources.go | 17 +-- internal/scheduler/runner.go | 27 +++- ui/src/lib/api.ts | 33 +++++ ui/src/lib/reconcile-warning.test.ts | 79 ++++++++++++ 12 files changed, 604 insertions(+), 64 deletions(-) create mode 100644 internal/api/reconcile_reporting_test.go create mode 100644 internal/api/reconcile_warning_test.go create mode 100644 ui/src/lib/reconcile-warning.test.ts diff --git a/internal/api/api.go b/internal/api/api.go index e7a6be5f..dfb9da0a 100644 --- a/internal/api/api.go +++ b/internal/api/api.go @@ -111,10 +111,12 @@ func (s *Server) engOrNil() *engine.Engine { // // A nil manager is not an error. Every server in this package's unit tests has // one, and the caller's question -- "is what is running what is stored" -- is -// answered by "nothing is running" rather than by a failure. The callers that -// only warn keep warning and the callers that return 500 keep returning 500; -// what changes is which engines were reconciled, not how a failure is -// reported. +// answered by "nothing is running" rather than by a failure. +// +// ONE CALLER, AND IT IS reconcileNow. #709 collapsed sixteen call sites onto +// that helper because two spellings of the failure handling lived here side by +// side; TestReconcileHasOneSpellingAndItsResultCannotBeDropped is what keeps +// this from growing a second one. func (s *Server) reconcile() error { if s.mgr == nil { return nil @@ -122,6 +124,115 @@ func (s *Server) reconcile() error { return s.mgr.Reconcile() } +// reconcileNow is the ONLY spelling of "apply this mutation to the pipeline". +// It returns the sentence to hand the operator, empty when the reconcile +// succeeded. #709. +// +// THE MISTAKE IT REMOVES. Sixteen handlers called s.reconcile() and two +// spellings lived in the same package: three turned the error into a 500, and +// twelve logged it at Warn and returned success. Nothing in the signature said +// which was right, so a new handler written by copying its nearest neighbour +// got whichever one that neighbour happened to be. +// +// WHY THE SILENT SPELLING IS WORSE THAN IT LOOKS. Engine.Reconcile returns +// early on a reconcileOutputs error, so preview, clips, captions and loudness +// are skipped with it; Manager.Reconcile returns firstErr. And reconcile is +// EVENT-DRIVEN WITH NO TICKER -- engine.go says so in as many words -- so a +// failure is never retried. Stored state and the running FFmpeg diverge until +// the next successful mutation or a restart, while the response said 200 and +// the UI raised a green toast. +// +// The worst case is invisible: a destination delete returned {"status": +// "deleted"}, the row left the list, and the FFmpeg child kept publishing to a +// destination the console no longer draws. +// +// WARNING RATHER THAN CONTROL, deliberately. Refusing the write would be wrong: +// the row genuinely was saved, and a 500 invites a retry that re-POSTs a +// destination. The honest ceiling is that the response states what did not +// happen. +// +// AT ERROR, NOT WARN. Nothing retries this, so it is not a transient to be +// noted -- it is a divergence that persists until somebody acts. +func (s *Server) reconcileNow(action string) string { + err := s.reconcile() + if err == nil { + return "" + } + s.log.Error("the pipeline was not reconciled after a change was saved; "+ + "stored state and the running processes have diverged and nothing retries this", + "action", action, "err", err) + return action + " was saved, but the running pipeline could not be updated to " + + "match it: " + err.Error() + ". Nothing retries this automatically; the change " + + "takes effect on the next successful save or a restart." +} + +// writeMutation writes a mutation's response with the reconcile warning folded +// in, under the key the SPA already reads for a partial success. #709. +// +// THROUGH THE MARSHALLED FORM rather than a field on every response type, +// because the payloads here are a mix of maps and a dozen typed structs and +// adding a field to each is exactly the per-site decision this is removing. +// The shape is preserved exactly; one key is added, and only when there is +// something to say. +// +// A payload that is not a JSON object -- an array, a bare string -- cannot +// carry the key, so it is written unchanged and the warning is logged. No +// mutation response in this package has that shape today, and the guard test +// TestEveryReconcileGoesThroughTheHelper is what keeps a new one from arriving +// unnoticed. +func writeMutation(w http.ResponseWriter, status int, warning string, v any) { + if warning == "" { + writeJSON(w, status, v) + return + } + raw, err := json.Marshal(v) + if err != nil { + writeJSON(w, status, v) + return + } + var obj map[string]json.RawMessage + if err := json.Unmarshal(raw, &obj); err != nil || obj == nil { + writeJSON(w, status, v) + return + } + msg, err := json.Marshal([]string{warning}) + if err != nil { + writeJSON(w, status, v) + return + } + // APPENDED TO warnings RATHER THAN A KEY OF ITS OWN, because two handlers + // already build that array and the SPA already renders it. A second array + // meaning the same thing is a second thing for the next reader to miss. + if existing, ok := obj["warnings"]; ok { + var list []string + if err := json.Unmarshal(existing, &list); err == nil { + list = append(list, warning) + if merged, err := json.Marshal(list); err == nil { + msg = merged + } + } + } + obj["warnings"] = msg + obj["reconcileFailed"] = json.RawMessage("true") + writeJSON(w, status, obj) +} + +// writeMutationNoContent is writeMutation for a handler whose success is 204. +// +// A 204 has no body to put a warning in, so a reconcile that failed must change +// the STATUS: 200 with the warning, rather than a silent 204 that says the +// whole operation succeeded. +func writeMutationNoContent(w http.ResponseWriter, warning string) { + if warning == "" { + w.WriteHeader(http.StatusNoContent) + return + } + writeJSON(w, http.StatusOK, map[string]any{ + "warnings": []string{warning}, + "reconcileFailed": true, + }) +} + // tools is the FFmpeg this install detected. // // OFF THE MANAGER, NOT OFF AN ENGINE, and that is the whole point of it having diff --git a/internal/api/expert.go b/internal/api/expert.go index 4e1cd369..29249346 100644 --- a/internal/api/expert.go +++ b/internal/api/expert.go @@ -871,12 +871,14 @@ func (s *Server) handlePutExpert(w http.ResponseWriter, r *http.Request) { // running state are never allowed to drift. The arguments ride in the // destination's restart signature, so this is what actually applies them — // the destination is torn down and respawned with the new command line. - if err := s.reconcile(); err != nil { - s.log.Warn("reconcile after expert args update", "err", err) - } - - // Resolved against the row that was written, so the command shown back is - // the one the reconcile above just started. + rw := s.reconcileNow("the expert arguments") + + // Resolved against the row that was WRITTEN, which is not necessarily the + // row that is RUNNING. #709: the previous comment here said "the command + // shown back is the one the reconcile above just started", and on the + // branch where the reconcile failed that sentence was false -- while + // Applied shipped as a hardcoded `true` and the UI answered "Saved." and + // rendered the new command back as though FFmpeg were running it. cmd, cerr := s.resolveExpertCommand(updated, in, out) if cerr != nil { writeExpertCommandError(w, cerr) @@ -889,7 +891,11 @@ func (s *Server) handlePutExpert(w http.ResponseWriter, r *http.Request) { Command: cmd, Guards: guards, Passthrough: updated.RenditionID == nil, - Applied: true, + // APPLIED IS NOW A FACT RATHER THAN A LITERAL. The field's own comment + // says it is "true on a read or a successful write"; a write whose + // reconcile failed is not a successful one, and Warning says why. + Applied: rw == "", + Warning: rw, }) } @@ -906,13 +912,12 @@ func (s *Server) handleDeleteExpert(w http.ResponseWriter, r *http.Request) { writeStoreError(w, err) return } - if err := s.reconcile(); err != nil { - s.log.Warn("reconcile after expert args delete", "err", err) - } + rw := s.reconcileNow("clearing the expert arguments") resp := expertResponse{ DestinationID: id, Passthrough: cleared.RenditionID == nil, - Applied: true, + Applied: rw == "", + Warning: rw, } if cmd, err := s.resolveExpertCommand(cleared, nil, nil); err == nil { resp.Command = cmd diff --git a/internal/api/handlers.go b/internal/api/handlers.go index a9f533fe..8143822d 100644 --- a/internal/api/handlers.go +++ b/internal/api/handlers.go @@ -1007,8 +1007,8 @@ func (s *Server) handlePutAnnotations(w http.ResponseWriter, r *http.Request) { s.log.Warn("annotations saved to the source but not mirrored to settings", "err", err) } } - if err := s.reconcile(); err != nil { - writeError(w, http.StatusInternalServerError, "annotations saved but reconcile failed: "+err.Error()) + if rw := s.reconcileNow("the annotations"); rw != "" { + writeError(w, http.StatusInternalServerError, rw) return } writeJSON(w, http.StatusOK, eng.SourceInfo()) @@ -1638,8 +1638,8 @@ func (s *Server) handlePutSettings(w http.ResponseWriter, r *http.Request) { // default engine saved the setting and changed nothing: enabling shared // ingest returned 200 while no listener ever bound, which is exactly the // kind of silent no-op that is worse than an error. - if err := s.reconcile(); err != nil { - writeError(w, http.StatusInternalServerError, "settings saved but reconcile failed: "+err.Error()) + if rw := s.reconcileNow("the settings"); rw != "" { + writeError(w, http.StatusInternalServerError, rw) return } // Chat retention is not the manager's to reconcile -- the Hub owns it -- and @@ -2145,14 +2145,12 @@ func (s *Server) handleCreateDestination(w http.ResponseWriter, r *http.Request) writeCreateError(w, err) return } - if err := s.reconcile(); err != nil { - s.log.Warn("reconcile after destination create", "err", err) - } + rw := s.reconcileNow("the destination") resp := map[string]any{"destination": created} if len(warnings) > 0 { resp["warnings"] = warnings } - writeJSON(w, http.StatusCreated, resp) + writeMutation(w, http.StatusCreated, rw, resp) } func (s *Server) handleUpdateDestination(w http.ResponseWriter, r *http.Request) { @@ -2203,9 +2201,7 @@ func (s *Server) handleUpdateDestination(w http.ResponseWriter, r *http.Request) } // Reconcile restarts only this destination, and only if the change // actually affects its command line. - if err := s.reconcile(); err != nil { - s.log.Warn("reconcile after destination update", "err", err) - } + rw := s.reconcileNow("the destination") resp := map[string]any{"destination": updated} updSrc, updKnown := s.sourceForDestination(updated.SourceID) @@ -2218,7 +2214,7 @@ func (s *Server) handleUpdateDestination(w http.ResponseWriter, r *http.Request) if len(warnings) > 0 { resp["warnings"] = warnings } - writeJSON(w, http.StatusOK, resp) + writeMutation(w, http.StatusOK, rw, resp) } // handleReorderDestinations persists dashboard order. It deliberately does not @@ -2267,10 +2263,12 @@ func (s *Server) handleDeleteDestination(w http.ResponseWriter, r *http.Request) writeStoreError(w, err) return } - if err := s.reconcile(); err != nil { - s.log.Warn("reconcile after destination delete", "err", err) - } - writeJSON(w, http.StatusOK, map[string]string{"status": "deleted"}) + // THE WORST CASE IN #709, and the reason this one is worth reading twice. + // The row leaves the list and the response says "deleted" -- while the + // FFmpeg child keeps publishing to a destination the console no longer + // draws. Nothing else in the product could ever mention it again. + rw := s.reconcileNow("the destination delete") + writeMutation(w, http.StatusOK, rw, map[string]string{"status": "deleted"}) } // destEffect is what one press of start or stop actually did to one row: the @@ -2323,8 +2321,8 @@ func (s *Server) applyDestinationEnabled(id int64, enabled bool) destControl { if err := s.store.SetDestinationEnabled(id, enabled); err != nil { return destControl{StoreErr: err} } - if err := s.reconcile(); err != nil { - return destControl{ReconcileErr: err} + if rw := s.reconcileNow("the destination"); rw != "" { + return destControl{ReconcileErr: errors.New(rw)} } // The EFFECT, not just the intent. // diff --git a/internal/api/media.go b/internal/api/media.go index 11531cfb..adf6edeb 100644 --- a/internal/api/media.go +++ b/internal/api/media.go @@ -657,8 +657,8 @@ func (s *Server) handleDeleteMedia(w http.ResponseWriter, r *http.Request) { // file (see testServer's comment). A running server always has one, and the // nil-manager check that used to stand here is inside Server.reconcile now, // where every caller gets it. - if err := s.reconcile(); err != nil { - writeError(w, http.StatusInternalServerError, "media deleted but reconcile failed: "+err.Error()) + if rw := s.reconcileNow("the media delete"); rw != "" { + writeError(w, http.StatusInternalServerError, rw) return } w.WriteHeader(http.StatusNoContent) diff --git a/internal/api/oauth_handlers.go b/internal/api/oauth_handlers.go index 2e019386..df518b82 100644 --- a/internal/api/oauth_handlers.go +++ b/internal/api/oauth_handlers.go @@ -524,14 +524,12 @@ func (s *Server) handleRefreshKey(w http.ResponseWriter, r *http.Request) { writeError(w, http.StatusBadRequest, err.Error()) return } - if err := s.reconcile(); err != nil { - s.log.Warn("reconcile after key refresh", "err", err) - } + rw := s.reconcileNow("the refreshed stream key") resp := map[string]any{"destination": updated} if len(warnings) > 0 { resp["warnings"] = warnings } - writeJSON(w, http.StatusOK, resp) + writeMutation(w, http.StatusOK, rw, resp) } // firstBackup is the secondary ingest a destination will publish to, or empty. diff --git a/internal/api/reconcile_reporting_test.go b/internal/api/reconcile_reporting_test.go new file mode 100644 index 00000000..ae92197b --- /dev/null +++ b/internal/api/reconcile_reporting_test.go @@ -0,0 +1,147 @@ +package api + +import ( + "go/ast" + "go/parser" + "go/token" + "os" + "path/filepath" + "sort" + "strings" + "testing" +) + +// THERE IS ONE SPELLING OF "APPLY THIS MUTATION", AND IT CANNOT BE DROPPED. #709. +// +// Sixteen handlers called s.reconcile() and two spellings lived side by side in +// this package: three turned the error into a 500, twelve logged it at Warn and +// returned success. Nothing in the signature said which was right, so a handler +// written by copying its nearest neighbour got whichever that neighbour was. +// +// The silent spelling is worse than it looks. Engine.Reconcile returns early on +// a reconcileOutputs error, so preview, clips, captions and loudness are skipped +// with it, and reconcile is EVENT-DRIVEN WITH NO TICKER -- so the failure is +// never retried. Stored state and the running FFmpeg diverge until the next +// successful mutation or a restart, while the response said 200 and the UI +// raised a green toast. The worst case was a destination delete: the row left +// the list, the response said "deleted", and the child kept publishing. +// +// Two rules, both checkable at build time, and together they remove the choice: +// +// 1. s.reconcile() has exactly one caller, reconcileNow. There is no second +// spelling left to copy. +// 2. A bare `s.reconcileNow(...)` STATEMENT fails. Go will let you discard a +// returned string, and discarding this one is precisely the mistake -- so +// the call must appear in an assignment or a condition, which forces the +// author to say what happens to it. +func TestReconcileHasOneSpellingAndItsResultCannotBeDropped(t *testing.T) { + root := packageRoot(t) + fset := token.NewFileSet() + + var ( + rawCallers []string // functions calling s.reconcile() directly + dropped []string // bare `s.reconcileNow(...)` statements + users int // calls whose result is used + ) + + entries, err := os.ReadDir(root) + if err != nil { + t.Fatalf("reading %s: %v", root, err) + } + for _, e := range entries { + if e.IsDir() || !strings.HasSuffix(e.Name(), ".go") || strings.HasSuffix(e.Name(), "_test.go") { + continue + } + path := filepath.Join(root, e.Name()) + f, perr := parser.ParseFile(fset, path, nil, 0) + if perr != nil { + t.Fatalf("parsing %s: %v", path, perr) + } + + var fnName string + ast.Inspect(f, func(n ast.Node) bool { + switch node := n.(type) { + case *ast.FuncDecl: + fnName = node.Name.Name + case *ast.ExprStmt: + // A CALL AS A STATEMENT is a discarded result. This is the only + // shape that drops the warning, and it is the whole rule. + if isServerCall(node.X, "reconcileNow") { + dropped = append(dropped, + e.Name()+":"+itoaLine(fset, node.Pos())+" in "+fnName) + } + case *ast.CallExpr: + if isServerCall(node, "reconcile") { + rawCallers = append(rawCallers, e.Name()+":"+itoaLine(fset, node.Pos())+" in "+fnName) + } + if isServerCall(node, "reconcileNow") { + users++ + } + } + return true + }) + } + + // THE WALKER MUST FIND THINGS, or every assertion below passes over an + // empty set and reports a rule it never checked. + if users < 10 { + t.Fatalf("found only %d call(s) to reconcileNow in %s; the walker is broken "+ + "and this test is asserting nothing", users, root) + } + + sort.Strings(rawCallers) + if len(rawCallers) != 1 || !strings.Contains(rawCallers[0], "reconcileNow") { + t.Errorf("s.reconcile() has %d caller(s) and should have exactly one, "+ + "reconcileNow:\n %s\n\n"+ + "A second caller is a second spelling, and the difference between them "+ + "-- 500 or a silent 200 -- is invisible in the signature. Call "+ + "reconcileNow and decide what to do with the sentence it returns.", + len(rawCallers), strings.Join(rawCallers, "\n ")) + } + + sort.Strings(dropped) + if len(dropped) > 0 { + t.Errorf("these calls discard the reconcile warning:\n %s\n\n"+ + "A discarded warning is a handler that answers 200 for a change that did "+ + "not take effect. Nothing retries the reconcile, so the divergence lasts "+ + "until the next successful save or a restart. Pass the result to "+ + "writeMutation, writeMutationNoContent, or a writeError.", + strings.Join(dropped, "\n ")) + } +} + +// isServerCall reports whether call is `.(...)`. +func isServerCall(n ast.Node, name string) bool { + call, ok := n.(*ast.CallExpr) + if !ok { + return false + } + sel, ok := call.Fun.(*ast.SelectorExpr) + if !ok || sel.Sel.Name != name { + return false + } + ident, ok := sel.X.(*ast.Ident) + return ok && ident.Name == "s" +} + +func itoaLine(fset *token.FileSet, p token.Pos) string { + n := fset.Position(p).Line + if n == 0 { + return "0" + } + var b []byte + for n > 0 { + b = append([]byte{byte('0' + n%10)}, b...) + n /= 10 + } + return string(b) +} + +func packageRoot(t *testing.T) string { + t.Helper() + dir, err := os.Getwd() + if err != nil { + t.Fatalf("getwd: %v", err) + } + return dir +} diff --git a/internal/api/reconcile_warning_test.go b/internal/api/reconcile_warning_test.go new file mode 100644 index 00000000..02bf3f77 --- /dev/null +++ b/internal/api/reconcile_warning_test.go @@ -0,0 +1,157 @@ +package api + +import ( + "encoding/json" + "net/http" + "net/http/httptest" + "testing" + + "github.com/rainmanjam/polyemesis/internal/config" +) + +// A MUTATION WHOSE RECONCILE FAILED SAYS SO IN THE RESPONSE. #709. +// +// The change was really saved, so the status stays a success -- refusing the +// write would be wrong, and a 500 invites a retry that re-POSTs a destination. +// What must not happen is the previous behaviour: a bare 200 with the failure +// in a log line nothing in the product reads, while the UI raises a green toast +// and renders the new state as though it were running. +func TestAFailedReconcileIsCarriedIntoEveryMutationShape(t *testing.T) { + const warning = "the destination was saved, but the running pipeline could not be updated" + + type payload struct { + Status string `json:"status"` + } + + for _, tc := range []struct { + name string + body any + // wantWarnings is what the response's warnings array must end up + // holding, in order. + wantWarnings []string + keep map[string]any // fields that must survive untouched + }{ + { + name: "a map payload", + body: map[string]any{"status": "deleted"}, + wantWarnings: []string{warning}, + keep: map[string]any{"status": "deleted"}, + }, + { + name: "a typed struct payload", + body: payload{Status: "created"}, + wantWarnings: []string{warning}, + keep: map[string]any{"status": "created"}, + }, + { + // APPENDED, NOT REPLACED. Two handlers already build a warnings + // array -- a destination create carries its own validation notes -- + // and losing those to make room for this one would trade one silent + // failure for another. + name: "a payload that already carries warnings", + body: map[string]any{"status": "ok", "warnings": []string{"the stream key looks short"}}, + wantWarnings: []string{"the stream key looks short", warning}, + keep: map[string]any{"status": "ok"}, + }, + } { + t.Run(tc.name, func(t *testing.T) { + w := httptest.NewRecorder() + writeMutation(w, http.StatusOK, warning, tc.body) + + if w.Code != http.StatusOK { + t.Errorf("status = %d, want 200: the row really was saved, and a 5xx "+ + "invites a retry that re-POSTs it", w.Code) + } + var got map[string]any + if err := json.Unmarshal(w.Body.Bytes(), &got); err != nil { + t.Fatalf("response is not a JSON object: %v\n%s", err, w.Body.String()) + } + for k, want := range tc.keep { + if got[k] != want { + t.Errorf("%q = %v, want %v: the payload's own shape must survive", k, got[k], want) + } + } + if got["reconcileFailed"] != true { + t.Errorf("reconcileFailed is %v, want true. The SPA needs a "+ + "machine-readable flag; matching on the English sentence breaks "+ + "the day it is reworded", got["reconcileFailed"]) + } + raw, _ := json.Marshal(got["warnings"]) + var list []string + if err := json.Unmarshal(raw, &list); err != nil { + t.Fatalf("warnings is not a string array: %s", raw) + } + if len(list) != len(tc.wantWarnings) { + t.Fatalf("warnings = %q, want %q", list, tc.wantWarnings) + } + for i := range list { + if list[i] != tc.wantWarnings[i] { + t.Errorf("warnings[%d] = %q, want %q", i, list[i], tc.wantWarnings[i]) + } + } + }) + } +} + +// A SUCCESSFUL RECONCILE ADDS NOTHING. A flag that is always present is a flag +// the UI stops reading, and a warnings array that is always non-empty trains an +// operator to skim it. +func TestASuccessfulReconcileLeavesTheResponseExactlyAsItWas(t *testing.T) { + w := httptest.NewRecorder() + writeMutation(w, http.StatusCreated, "", map[string]any{"destination": "one"}) + + if w.Code != http.StatusCreated { + t.Errorf("status = %d, want 201", w.Code) + } + var got map[string]any + if err := json.Unmarshal(w.Body.Bytes(), &got); err != nil { + t.Fatalf("unmarshal: %v", err) + } + if _, ok := got["warnings"]; ok { + t.Errorf("a clean mutation carried a warnings array: %v", got) + } + if _, ok := got["reconcileFailed"]; ok { + t.Errorf("a clean mutation carried reconcileFailed: %v", got) + } + if got["destination"] != "one" { + t.Errorf("the payload did not survive: %v", got) + } +} + +// A 204 HAS NOWHERE TO PUT A WARNING, so a reconcile that failed must change the +// status rather than send an empty body that says the whole operation worked. +func TestANoContentMutationBecomesA200WhenTheReconcileFailed(t *testing.T) { + clean := httptest.NewRecorder() + writeMutationNoContent(clean, "") + if clean.Code != http.StatusNoContent { + t.Errorf("clean status = %d, want 204", clean.Code) + } + if clean.Body.Len() != 0 { + t.Errorf("a clean 204 has a body: %s", clean.Body.String()) + } + + failed := httptest.NewRecorder() + writeMutationNoContent(failed, "the programme delete did not reach the pipeline") + if failed.Code == http.StatusNoContent { + t.Fatal("a failed reconcile still answered 204. A 204 has no body, so the " + + "only way to say anything at all is to stop claiming complete success") + } + var got map[string]any + if err := json.Unmarshal(failed.Body.Bytes(), &got); err != nil { + t.Fatalf("unmarshal: %v", err) + } + if got["reconcileFailed"] != true { + t.Errorf("reconcileFailed = %v, want true", got["reconcileFailed"]) + } +} + +// reconcileNow says nothing when there is nothing to say, and every unit-test +// server in this package has a nil manager -- so a helper that warned on nil +// would put a false failure on every mutation response in the suite. +func TestReconcileNowIsSilentWithNoManager(t *testing.T) { + s, _, _ := testServer(t, config.Config{}) + if got := s.reconcileNow("the destination"); got != "" { + t.Errorf("reconcileNow with no manager = %q, want empty: nothing is running, "+ + "so nothing has diverged from what is stored", got) + } +} diff --git a/internal/api/renditions.go b/internal/api/renditions.go index d858e08e..cb70f4b5 100644 --- a/internal/api/renditions.go +++ b/internal/api/renditions.go @@ -117,10 +117,8 @@ func (s *Server) handleCreateRendition(w http.ResponseWriter, r *http.Request) { // Nothing selects a brand-new rendition yet, so this starts no encode; it // runs for the same reason every other mutation reconciles, which is that // the saved state and the running state are never allowed to drift. - if err := s.reconcile(); err != nil { - s.log.Warn("reconcile after rendition create", "err", err) - } - writeJSON(w, http.StatusCreated, map[string]any{"rendition": created}) + rw := s.reconcileNow("the rendition") + writeMutation(w, http.StatusCreated, rw, map[string]any{"rendition": created}) } // renditionKeepsItsSource refuses an update that would move a rendition from @@ -212,10 +210,8 @@ func (s *Server) handleUpdateRendition(w http.ResponseWriter, r *http.Request) { // The rendition's signature rides in each downstream destination's, so this // restarts the encode and exactly the destinations reading it, and nothing // else. - if err := s.reconcile(); err != nil { - s.log.Warn("reconcile after rendition update", "err", err) - } - writeJSON(w, http.StatusOK, map[string]any{"rendition": updated}) + rw := s.reconcileNow("the rendition") + writeMutation(w, http.StatusOK, rw, map[string]any{"rendition": updated}) } // handleDeleteRendition removes a rendition and reports what that cost. @@ -242,9 +238,7 @@ func (s *Server) handleDeleteRendition(w http.ResponseWriter, r *http.Request) { writeStoreError(w, err) return } - if err := s.reconcile(); err != nil { - s.log.Warn("reconcile after rendition delete", "err", err) - } + rw := s.reconcileNow("the rendition delete") resp := map[string]any{ "status": "deleted", @@ -254,7 +248,7 @@ func (s *Server) handleDeleteRendition(w http.ResponseWriter, r *http.Request) { if n := total[id]; n > 0 { resp["warning"] = renditionDeleteWarning(n, enabled[id]) } - writeJSON(w, http.StatusOK, resp) + writeMutation(w, http.StatusOK, rw, resp) } func renditionDeleteWarning(total, enabled int) string { diff --git a/internal/api/sources.go b/internal/api/sources.go index df766744..02d0ea14 100644 --- a/internal/api/sources.go +++ b/internal/api/sources.go @@ -469,11 +469,9 @@ func (s *Server) handleCreateSource(w http.ResponseWriter, r *http.Request) { } // Through the manager: a new source needs an engine built for it, which // only Sync does. - if err := s.reconcile(); err != nil { - s.log.Warn("reconcile after source create", "err", err) - } + rw := s.reconcileNow("the programme") defaultID, _ := s.store.DefaultSourceID() - writeJSON(w, http.StatusCreated, s.viewSource(r, &row, defaultID)) + writeMutation(w, http.StatusCreated, rw, s.viewSource(r, &row, defaultID)) } func (s *Server) handleUpdateSource(w http.ResponseWriter, r *http.Request) { @@ -506,11 +504,9 @@ func (s *Server) handleUpdateSource(w http.ResponseWriter, r *http.Request) { writeError(w, sourceStatus(err), err.Error()) return } - if err := s.reconcile(); err != nil { - s.log.Warn("reconcile after source update", "err", err) - } + rw := s.reconcileNow("the programme") defaultID, _ := s.store.DefaultSourceID() - writeJSON(w, http.StatusOK, s.viewSource(r, &row, defaultID)) + writeMutation(w, http.StatusOK, rw, s.viewSource(r, &row, defaultID)) } func (s *Server) handleDeleteSource(w http.ResponseWriter, r *http.Request) { @@ -525,10 +521,7 @@ func (s *Server) handleDeleteSource(w http.ResponseWriter, r *http.Request) { writeError(w, sourceStatus(err), err.Error()) return } - if err := s.reconcile(); err != nil { - s.log.Warn("reconcile after source delete", "err", err) - } - w.WriteHeader(http.StatusNoContent) + writeMutationNoContent(w, s.reconcileNow("the programme delete")) } // handleRotateSourceToken issues a new publish secret. diff --git a/internal/scheduler/runner.go b/internal/scheduler/runner.go index f9c14faa..499318fd 100644 --- a/internal/scheduler/runner.go +++ b/internal/scheduler/runner.go @@ -52,6 +52,13 @@ type Result struct { Reason string `json:"reason"` Targets []int64 `json:"targets,omitempty"` Err string `json:"error,omitempty"` + // ReconcileErr is set when the schedule fired and was saved but the + // pipeline could not be brought into line with it. #709. + // + // SEPARATE FROM Err, which is this schedule's own failure to act. This one + // says the action succeeded and did not take effect -- a different fact, + // and the one that used to exist only in a log line nothing reads. + ReconcileErr string `json:"reconcileError,omitempty"` } // Option configures a Runner. @@ -241,8 +248,26 @@ func (r *Runner) Tick(now time.Time) []Result { } if changed { + // #709. A schedule that fired, wrote its intent and could not reconcile + // has changed the database and not the running pipeline -- and nothing + // retries it, because Reconcile is event-driven with no ticker. The log + // line alone left /schedules reporting every occurrence as fired. + // + // The reason rides on EVERY result in this sweep, because the reconcile + // is one call for the whole batch: it is not knowable which of the + // schedules that fired took effect, and saying so on each is honest + // where attributing it to one would not be. if err := r.act.Reconcile(); err != nil { - r.log.Error("schedule reconcile failed", "err", err) + r.log.Error("a schedule fired but the pipeline was not reconciled; "+ + "the stored intent and the running processes have diverged and "+ + "nothing retries this", "err", err) + for i := range out { + if !out[i].Fired { + continue + } + out[i].ReconcileErr = "the schedule fired and was saved, but the running " + + "pipeline could not be updated to match it: " + err.Error() + } } } if len(out) > 0 { diff --git a/ui/src/lib/api.ts b/ui/src/lib/api.ts index cedd1f0d..a4955a1f 100644 --- a/ui/src/lib/api.ts +++ b/ui/src/lib/api.ts @@ -185,9 +185,42 @@ async function request( : ""; throw new ApiError(resp.status, msg, code); } + reportReconcileFailure(body); return body as T; } +/** Raise the amber toast for a mutation the server saved but could not apply. + * + * #709. Sixteen handlers used to log a failed reconcile and answer 200, so the + * dashboard raised a green toast for a change that had not taken effect — + * worst of all on a destination delete, where the row left the list while the + * FFmpeg child kept publishing. The server now says `reconcileFailed: true` + * and puts the sentence in `warnings`. + * + * IN THE TRANSPORT, NOT AT THE CALL SITES, and that is the point. The + * alternative is fifteen call sites each deciding whether to read the flag, + * which is the same per-site choice the server change removed — and the next + * mutation added would get whichever one its neighbour happened to be. Here it + * is one decision, and a route added tomorrow is covered without being told. + * + * A DestinationDialog-style caller that already renders `warnings` itself + * keeps doing so; the flag is what this reads, so a warning the server + * attached for another reason is not doubled. */ +function reportReconcileFailure(body: unknown): void { + if (!body || typeof body !== "object") return; + const b = body as { reconcileFailed?: unknown; warnings?: unknown }; + if (b.reconcileFailed !== true) return; + const lines = Array.isArray(b.warnings) ? b.warnings.filter((w) => typeof w === "string") : []; + const msg = + lines.length > 0 + ? (lines[lines.length - 1] as string) + : "The change was saved but the running pipeline could not be updated to match it."; + // Long, because this one is not a status update: nothing retries the + // reconcile, so an operator who misses it is looking at a console that + // disagrees with the processes until the next successful save or a restart. + void import("sonner").then(({ toast }) => toast.warning(msg, { duration: 15000 })); +} + const get = (p: string) => request(p); const post = (p: string, body?: unknown) => request(p, { method: "POST", body: body ? JSON.stringify(body) : undefined }); diff --git a/ui/src/lib/reconcile-warning.test.ts b/ui/src/lib/reconcile-warning.test.ts new file mode 100644 index 00000000..a2fd5bde --- /dev/null +++ b/ui/src/lib/reconcile-warning.test.ts @@ -0,0 +1,79 @@ +// @vitest-environment jsdom +import { describe, it, expect, vi, beforeEach, afterEach } from "vitest"; + +// A MUTATION THE SERVER SAVED BUT COULD NOT APPLY RAISES A WARNING. #709. +// +// The server used to log a failed reconcile and answer 200, so the dashboard +// raised a GREEN toast for a change that had not taken effect. The worst case +// was a destination delete: the row left the list, the response said "deleted", +// and the FFmpeg child kept publishing to a destination the console no longer +// drew. +// +// This is read in the transport rather than at the call sites, so the assertion +// is about the transport: a body carrying the flag must produce the amber +// toast, and one without it must not. + +const toast = { warning: vi.fn(), success: vi.fn(), error: vi.fn() }; +vi.mock("sonner", () => ({ toast })); + +async function respondWith(status: number, body: unknown) { + vi.stubGlobal( + "fetch", + vi.fn(async () => ({ + ok: status < 400, + status, + text: async () => (body === undefined ? "" : JSON.stringify(body)), + })), + ); + const { api } = await import("./api"); + return api; +} + +describe("a reconcile the server could not perform", () => { + beforeEach(() => { + vi.resetModules(); + toast.warning.mockClear(); + }); + afterEach(() => vi.unstubAllGlobals()); + + it("warns, with the server's own sentence", async () => { + const sentence = + "the destination delete was saved, but the running pipeline could not be updated to match it"; + const api = await respondWith(200, { + status: "deleted", + reconcileFailed: true, + warnings: [sentence], + }); + + await api.deleteDestination(7 as never); + await new Promise((r) => setTimeout(r, 0)); + + expect(toast.warning).toHaveBeenCalledTimes(1); + expect(toast.warning.mock.calls[0][0]).toBe(sentence); + }); + + it("says nothing when the reconcile succeeded", async () => { + const api = await respondWith(200, { status: "deleted" }); + + await api.deleteDestination(7 as never); + await new Promise((r) => setTimeout(r, 0)); + + // A warning on every mutation is a warning an operator stops reading, which + // is the same silence by a different route. + expect(toast.warning).not.toHaveBeenCalled(); + }); + + it("reads the flag, not the array, so an unrelated warning is not doubled", async () => { + // DestinationDialog renders `warnings` itself. If this warned on the array + // alone, a platform-settings note would appear twice on every create. + const api = await respondWith(200, { + destination: { id: 1 }, + warnings: ["the stream key looks short"], + }); + + await api.createDestination({} as never); + await new Promise((r) => setTimeout(r, 0)); + + expect(toast.warning).not.toHaveBeenCalled(); + }); +}); From bd7975b1bd883e91f6ff255e0402d4688e7e0c20 Mon Sep 17 00:00:00 2001 From: Shannon Atkinson Date: Fri, 4 Sep 2026 17:41:39 -0700 Subject: [PATCH 8/8] fix(ui): a failed read no longer renders as an empty result that tells the operator to act Closes #719. lib/readState.ts exists to make `.catch(() => setX([]))` unwriteable, and its header calls itself "a CONTROL rather than a warning" because mayClaim is a type guard. DestinationDialog.tsx never imported it and had FIVE of them. Two of the five drove the operator to act on a claim the server never made: - a failed listRenditions() rendered "No shared encodes yet. Create one on the Renditions page first." and disabled the shared-encode radio, sending them to build a second real encode they already have; - a failed listAccounts() replaced the account picker with "Connect {platform} account" -- a re-authorisation for an account that is very likely already linked, and following it navigates away and discards the half-filled dialog. All five reads now carry a ReadState. The arrays are derived with rowsOf, so every consumer that only wants rows is untouched; mayClaim guards the two places that say something, and readFailed gives each a sentence that distinguishes "we could not ask" from "there are none". WHAT ENFORCED THE RULE WAS A LIST OF FILENAMES. readState.test.ts asserted that specific source strings were absent from SettingsPage.tsx and AutomationPage.tsx -- three files, hand-maintained. That is training, not a device, and it did not know DestinationDialog.tsx existed. readState.shape.test.ts walks every .ts/.tsx under ui/src and matches on the SHAPE instead, so the file added tomorrow is covered without being listed. It found nine more instances the audit never named. Each is now a STATED decision in an excuse map keyed by file AND setter -- a file-level key would have covered DestinationDialog's other three by accident, which is exactly how the previous enforcement missed it. Most turn out to be `null` used as a genuine third state with the consumer already branching on it; those carry the reason, and the reasons are themselves checked for length and placeholders, and for still matching a read that exists. One was a real bug. Dashboard's metadata composer holds `MetaTarget[] | null` and `if (targets === null) return null` hides it entirely -- but the catch stored [], so a failed read rendered the composer with ZERO platforms. That is a positive claim that this broadcast has nowhere to push metadata. It is null now. The guard bans okRead([]) inside a catch as well as a bare [], because adopting ReadState and then storing a successful-looking empty read is the same mistake wearing the fix, and the type no longer objects to it. Found by mutation: the first version of the guard passed that spelling. Comments are blanked before matching, with newlines preserved so reported line numbers still point at the file: a guard that fires on prose describing the hazard is a guard people delete rather than obey. It also carries positive and negative controls over the pattern itself, because the regex IS the device and one that quietly stopped matching would leave every assertion passing over nothing. Warning rather than Control: nothing in TypeScript stops a component holding a bare array and assigning [] in a catch. The earliest a device can speak is when the code is written. Four mutations, each red: a dialog read storing [] again, the same read storing okRead([]), an excuse reduced to a placeholder, and an excuse outliving the read it excused. Claude-Session: https://claude.ai/code/session_01A8N3W5ct9SZtHK9sCDD9cL --- ui/src/components/DestinationDialog.tsx | 94 +++++++++--- ui/src/lib/readState.shape.test.ts | 188 ++++++++++++++++++++++++ ui/src/lib/readState.test.ts | 13 +- ui/src/pages/Dashboard.tsx | 8 +- 4 files changed, 284 insertions(+), 19 deletions(-) create mode 100644 ui/src/lib/readState.shape.test.ts diff --git a/ui/src/components/DestinationDialog.tsx b/ui/src/components/DestinationDialog.tsx index 2c801666..69fce58c 100644 --- a/ui/src/components/DestinationDialog.tsx +++ b/ui/src/components/DestinationDialog.tsx @@ -33,6 +33,15 @@ import { } from "@/lib/destinationSource"; import { FACEBOOK_PRIVACIES } from "@/lib/facebookPrivacy"; import { useT } from "@/lib/i18n"; +import { + failedRead, + mayClaim, + okRead, + pendingRead, + readFailed, + rowsOf, + type ReadState, +} from "@/lib/readState"; import { computeLeaving, joinConsequence, leaveConsequence } from "@/lib/rendition-consequence"; import { Switch } from "@/components/ui/switch"; // The capability matrix this dialog renders inline. Data, not a component, and @@ -661,21 +670,37 @@ export function DestinationDialog({ open, onOpenChange, destination, onSaved }: // db.Destination.Multitrack. const [multitrack, setMultitrack] = useState(false); const [accountId, setAccountId] = useState("none"); - const [accounts, setAccounts] = useState([]); + // READ STATES, NOT BARE ARRAYS. #719. + // + // These were `.then(setX).catch(() => setX([]))`, which stores a FAILED read + // as the same value as a successful empty one -- and this dialog turns both + // into positive claims that drive the operator to act: "No shared encodes + // yet. Create one on the Renditions page first." sends them to build a second + // real encode they already have, and a missing account list replaces the + // picker with "Connect account", a re-authorisation for an account that is + // already linked which also discards the half-filled dialog. + // + // lib/readState exists to make that unwriteable and this file never imported + // it. The arrays below are derived with rowsOf, so every consumer that only + // wants rows is unchanged; mayClaim guards the two places that say something. + const [accountsRead, setAccountsRead] = useState>(pendingRead); + const accounts = rowsOf(accountsRead); const [renditionId, setRenditionId] = useState(PASSTHROUGH); // RenditionView, not Rendition. The view carries `destinations` and // `enabledDestinations`, and this used to strip them off one line after they // arrived — throwing away the only data that can tell an operator whether // picking an encode starts a new one or joins a running one. That fact is // the entire argument for renditions existing, and the UI could not state it. - const [renditions, setRenditions] = useState([]); + const [renditionsRead, setRenditionsRead] = useState>(pendingRead); + const renditions = rowsOf(renditionsRead); /** #661: how the chosen rendition sits against the chosen platform's published * figures. Fetched rather than computed — the comparison reads researched, * dated numbers out of internal/db/platforms.go, and a second copy here would * drift from that file exactly as the marketing site's hand-copied figures * once did. */ const [concerns, setConcerns] = useState([]); - const [sources, setSources] = useState([]); + const [sourcesRead, setSourcesRead] = useState>(pendingRead); + const sources = rowsOf(sourcesRead); // Which programme this destination carries. A string because that is what the // Select speaks; "" means nobody has chosen yet, which is a state the save // button reads rather than a value it sends. @@ -690,8 +715,10 @@ export function DestinationDialog({ open, onOpenChange, destination, onSaved }: if (!open || choices.length === 0) return; setSourceId((current) => (current === "" ? initialSourceValue(destination, choices) : current)); }, [open, choices, destination]); - const [guidance, setGuidance] = useState([]); - const [services, setServices] = useState([]); + const [guidanceRead, setGuidanceRead] = useState>(pendingRead); + const guidance = rowsOf(guidanceRead); + const [servicesRead, setServicesRead] = useState>(pendingRead); + const services = rowsOf(servicesRead); /** The registry entry for whatever platform is selected, or null for a * custom destination — which the registry has no opinion about, and must @@ -724,12 +751,18 @@ export function DestinationDialog({ open, onOpenChange, destination, onSaved }: useEffect(() => { if (!open) return; - api.listAccounts().then(setAccounts).catch(() => setAccounts([])); + api + .listAccounts() + .then((r) => setAccountsRead(okRead(r))) + .catch(() => setAccountsRead(failedRead())); api .listRenditions() - .then(setRenditions) - .catch(() => setRenditions([])); - api.listSources().then(setSources).catch(() => setSources([])); + .then((r) => setRenditionsRead(okRead(r))) + .catch(() => setRenditionsRead(failedRead())); + api + .listSources() + .then((r) => setSourcesRead(okRead(r))) + .catch(() => setSourcesRead(failedRead())); // Fetched, not mirrored. The UI keeps its own preset list so the picker // renders before any request resolves, but the researched numbers carry a // source and a date and a second copy of them here would drift silently — @@ -737,16 +770,16 @@ export function DestinationDialog({ open, onOpenChange, destination, onSaved }: // and nothing surfaced them. api .platformPresets() - .then((r) => setGuidance(r.presets)) - .catch(() => setGuidance([])); + .then((r) => setGuidanceRead(okRead(r.presets))) + .catch(() => setGuidanceRead(failedRead())); // The ingest servers and the platform's own encoder ceilings. Fetched for // the same reason the guidance is: these are other people's published // figures and a second copy in the bundle would drift from the one the // server serves. api .listServices() - .then((r) => setServices(r.services)) - .catch(() => setServices([])); + .then((r) => setServicesRead(okRead(r.services))) + .catch(() => setServicesRead(failedRead())); setPickerOpen(false); setQuery(""); @@ -1287,6 +1320,12 @@ export function DestinationDialog({ open, onOpenChange, destination, onSaved }: {showOAuth && caps?.connect && (
+ {/* #719. A failed listAccounts() used to replace the picker with + "Connect {platform} account", which is a re-authorisation for + an account that is very likely already linked -- and following + it navigates away and discards this half-filled dialog. The + connect path is offered only when the server actually + answered. */} {platformAccounts.length > 0 ? ( + ) : readFailed(accountsRead) ? ( +

+ The connected accounts could not be read, so this cannot say whether{" "} + {caps.name} is already linked. Reopen this dialog once the connection is + back rather than reconnecting — following that link leaves this form. +

+ ) : !mayClaim(accountsRead) ? ( +

Checking for a linked account…

) : (
@@ -1700,7 +1760,7 @@ export function DestinationDialog({ open, onOpenChange, destination, onSaved }: fps: num(variantFps), } as Partial); const rows = await api.listRenditions(); - setRenditions(rows); + setRenditionsRead(okRead(rows)); setRenditionId(String(made.rendition.id)); setVariantOpen(false); } catch (e) { diff --git a/ui/src/lib/readState.shape.test.ts b/ui/src/lib/readState.shape.test.ts new file mode 100644 index 00000000..3264fd95 --- /dev/null +++ b/ui/src/lib/readState.shape.test.ts @@ -0,0 +1,188 @@ +import { describe, it, expect } from "vitest"; +import { readFileSync, readdirSync, statSync } from "node:fs"; +import { join } from "node:path"; + +/* NO READ IN THIS APP STORES ITS FAILURE AS AN EMPTY RESULT. #719. + * + * readState.ts has existed to make `.catch(() => setX([]))` unwriteable since + * the three cards in SettingsPage and AutomationPage were fixed. What enforced + * it was a list of FILENAMES with specific source strings asserted absent from + * each -- and a list of filenames does not know about the file added tomorrow. + * It did not know DestinationDialog.tsx existed, and DestinationDialog.tsx had + * five of them. + * + * That is training, not a device. This walks every file instead and matches on + * the SHAPE, so the next one fails on the day it is written. + * + * Warning rather than Control: nothing in TypeScript stops a component holding + * a bare array and assigning [] in a catch. The earliest a device can speak is + * when the code is written, which is here. + * + * WHY THE EMPTY VALUE IS THE PROBLEM AND NOT THE CATCH. A failed read stored as + * [] or null is indistinguishable from a successful empty one, and an empty + * state is a POSITIVE CLAIM: it says the server answered and there is nothing + * there. Every instance found so far went further and drove the operator to + * act -- regenerate a working client secret, connect an account already + * connected, build a second encode they already had. */ + +const ROOT = new URL("../../../", import.meta.url).pathname; +const UI_SRC = join(ROOT, "ui/src"); + +/* Reads whose empty-on-failure value is NOT a claim, with the reason. + * + * KEYED BY FILE AND SETTER, not by file. A page holds several reads and they + * are not all the same decision -- DestinationDialog had five and two of them + * drove the operator to act. A file-level excuse would have covered the other + * three by accident, which is how the previous enforcement missed this file + * entirely. + * + * An entry here is a decision somebody made and can be argued with; an omission + * is a hazard nobody saw. Note what most of them have in common: `null` is + * being used as a genuine third state, and the consumer already branches on it. + * That is the same distinction readState.ts draws, spelled without the type. */ +const notAClaim: Record = { + "ui/src/pages/ClipEditor.tsx:setKeyframes": + "null is the UNKNOWN state and the timeline draws it as unknown rather than as " + + "'this recording has no keyframes'; failing the page over a probe would be worse", + "ui/src/pages/ClipEditor.tsx:setPlan": + "the same catch sets planError from the failure, so the empty plan is never on " + + "screen without the reason it is empty beside it", + "ui/src/pages/Dashboard.tsx:setTargets": + "null is the unknown state and `if (targets === null) return null` hides the " + + "metadata composer entirely; this was [] until #719, which rendered the composer " + + "with zero platforms -- a claim that this broadcast has nowhere to push metadata", + "ui/src/pages/Dashboard.tsx:setSources": + "the programme badge is drawn only when there is MORE THAN ONE source, so an " + + "empty list hides a badge rather than asserting that no programmes exist", + "ui/src/pages/Dashboard.tsx:setFeatureEnabled": + "null is the unknown state and the recording/meters notice stays silent on it, " + + "which the catch's own comment says: it must not claim an exposure it could not verify", + "ui/src/pages/RenditionsPage.tsx:setCaps": + "null is unknown; the encoder picker falls back to offering every encoder rather " + + "than claiming this machine supports none, which would hide working hardware", + "ui/src/pages/RenditionsPage.tsx:setFonts": + "null is unknown; the overlay editor keeps the font field open rather than claiming " + + "the data directory contains no fonts", + "ui/src/pages/SettingsPage.tsx:setSourceCount": + "explicitly NOT 0 -- claiming zero sources on a failed read would replace the ingest " + + "form with 'create a source' on an install that has several. Unknown leaves every " + + "branch on its pre-existing behaviour", + "ui/src/pages/SettingsPage.tsx:setSystem": + "null is unknown and the page says the system read failed rather than rendering an " + + "install with no FFmpeg, which is the widest read on the page and the one most " + + "likely to fail on a machine that is otherwise fine", +}; + +/* `.catch(...)` whose body assigns an empty collection: the exact shape. + * + * Deliberately narrow. It matches the assignment of a literal [], null or {} + * inside a catch and nothing else, because a catch that sets an error message, + * or retries, or assigns a real fallback value, is not this mistake. */ +const EMPTY_ON_FAILURE = + /\.catch\(\s*\([^)]*\)\s*=>\s*(?:\{\s*)?set[A-Za-z0-9_]*\(\s*(?:okRead\(\s*)?(?:\[\s*\]|null|\{\s*\})\s*\)/g; + +/* Blanks comment bodies while PRESERVING NEWLINES, so the line numbers in a + * failure still point at the file. A guard whose report sends the reader to the + * wrong line costs more than it saves. */ +function stripComments(src: string): string { + const blank = (m: string) => m.replace(/[^\n]/g, " "); + return src.replace(/\/\*[\s\S]*?\*\//g, blank).replace(/(^|[^:])\/\/[^\n]*/g, (m, p1) => p1 + blank(m.slice(p1.length))); +} + +function walk(dir: string): string[] { + const out: string[] = []; + for (const name of readdirSync(dir)) { + const p = join(dir, name); + if (statSync(p).isDirectory()) { + if (name === "node_modules" || name === "components/ui") continue; + out.push(...walk(p)); + continue; + } + if (!/\.(ts|tsx)$/.test(name) || /\.test\.tsx?$/.test(name)) continue; + out.push(p); + } + return out; +} + +describe("a read that failed is never stored as an empty result", () => { + const files = walk(UI_SRC); + + it("finds files to check, so a pass means something", () => { + // A walker that resolves nothing passes the assertion below and reports a + // rule it never applied -- the same "a check that does not run looks like + // one that passed" this whole file is about. + expect(files.length).toBeGreaterThan(80); + }); + + it("has no `.catch(() => setX([]))` anywhere in ui/src", () => { + const hits: string[] = []; + for (const file of files) { + const rel = file.slice(ROOT.length); + // COMMENTS STRIPPED FIRST. This file's own explanation quotes the + // banned shape, and a guard that fires on prose describing the hazard is + // a guard people delete rather than obey. + const src = stripComments(readFileSync(file, "utf8")); + for (const m of src.matchAll(EMPTY_ON_FAILURE)) { + const setter = /set[A-Za-z0-9_]*/.exec(m[0])?.[0] ?? ""; + if (`${rel}:${setter}` in notAClaim) continue; + const line = src.slice(0, m.index ?? 0).split("\n").length; + hits.push(`${rel}:${line} — ${m[0].replace(/\s+/g, " ")}`); + } + } + expect( + hits, + "A failed read stored as an empty value is indistinguishable from a successful " + + "empty one, and every empty state in this app is a positive claim: it says the " + + "server answered and there is nothing there. Use ReadState from @/lib/readState " + + "— failedRead() in the catch, mayClaim() before any sentence that asserts what " + + "came back — or add the file to notAClaim with a reason saying why its empty " + + "value asserts nothing.\n\n" + + hits.join("\n"), + ).toEqual([]); + }); + + it("keeps the excuse list honest", () => { + for (const [key, why] of Object.entries(notAClaim)) { + // A reason that says nothing is how a rule becomes something people learn + // to silence, so the length is checked and placeholders are refused. + expect(why.length, `${key} is excused with too little to argue with`).toBeGreaterThan(60); + expect(/TODO|TBD|n\/a/i.test(why), `${key} is excused with a placeholder`).toBe(false); + + // AND THE ENTRY MUST STILL APPLY. An excuse for a read that no longer + // exists is a standing permission nobody re-earned, sitting there for + // whatever is written next under the same setter name. + const [file, setter] = key.split(":"); + const src = stripComments(readFileSync(join(ROOT, file), "utf8")); + expect( + new RegExp(`\\.catch\\([^)]*\\)\\s*=>\\s*(?:\\{\\s*)?${setter}\\(`).test(src), + `${key} is excused but no longer matches the shape — remove the entry`, + ).toBe(true); + } + }); + + it("the guard can actually see the shape it bans", () => { + // A POSITIVE CONTROL. The regex is the whole device, and a regex that + // silently stopped matching would leave every assertion above passing over + // nothing. These are the spellings found in the tree before the fix. + for (const s of [ + "api.listAccounts().then(setAccounts).catch(() => setAccounts([]))", + ".catch(() => setRenditions([]))", + ".catch(() => { setCreds(null) })", + ".catch((e) => setRows([]))", + // okRead([]) IS THE SAME MISTAKE WEARING THE FIX. Adopting ReadState and + // then storing a successful-looking empty read in the catch puts the two + // states back together, and the type no longer objects. + ".catch(() => setRenditionsRead(okRead([])))", + ]) { + expect(new RegExp(EMPTY_ON_FAILURE.source).test(s), `not matched: ${s}`).toBe(true); + } + // And what it must NOT match, or it becomes a rule people learn to silence. + for (const s of [ + '.catch(() => setError("could not load"))', + ".catch(() => setRead(failedRead()))", + ".catch(() => setRows(CACHED_DEFAULTS))", + ]) { + expect(new RegExp(EMPTY_ON_FAILURE.source).test(s), `wrongly matched: ${s}`).toBe(false); + } + }); +}); diff --git a/ui/src/lib/readState.test.ts b/ui/src/lib/readState.test.ts index 48f9030e..6cde9d5b 100644 --- a/ui/src/lib/readState.test.ts +++ b/ui/src/lib/readState.test.ts @@ -37,7 +37,18 @@ describe("rowsOf / readFailed", () => { }); }); -/* AND THAT THE THREE CARDS ACTUALLY ASK. */ +/* AND THAT THE THREE CARDS ACTUALLY ASK. + * + * THESE ARE PER-CARD ASSERTIONS ABOUT WHAT IS RENDERED, and they are worth + * keeping as such: each one names the sentence an operator sees on a failed + * read, which no shape rule can check. + * + * What they are NO LONGER doing is enforcing the rule. #719: a hand-maintained + * list of three filenames with specific source strings asserted absent from + * each is training, not a device -- it did not know DestinationDialog.tsx + * existed, and DestinationDialog.tsx had five instances, two of which drove the + * operator to act. readState.shape.test.ts walks every file and matches on the + * shape, so the file added tomorrow is covered without being listed. */ const ROOT = new URL("../../../", import.meta.url).pathname; const read = (p: string) => readFileSync(join(ROOT, p), "utf8"); diff --git a/ui/src/pages/Dashboard.tsx b/ui/src/pages/Dashboard.tsx index 5633afbe..4fc3f1f3 100644 --- a/ui/src/pages/Dashboard.tsx +++ b/ui/src/pages/Dashboard.tsx @@ -213,7 +213,13 @@ function GoLiveComposer() { setCategory(data.last.metadata.category); } }) - .catch(() => setTargets([])); + // NULL, NOT []. #719. `targets` is `MetaTarget[] | null` and null is the + // unknown state -- `if (targets === null) return null` hides the composer + // entirely. Storing [] here made a failed read render the composer with + // ZERO platforms, which is a positive claim: it says the server answered + // and this broadcast has nowhere to push metadata. Unknown keeps it + // hidden, which is what it was before the request. + .catch(() => setTargets(null)); // What is still editable, read once when the composer opens. Deliberately // not polled: each row is a live platform call, and a broadcast that goes // live mid-edit is caught by the write's own 403 rather than by a timer.