diff --git a/cmd/polyemesis/main.go b/cmd/polyemesis/main.go index 07071074..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" @@ -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 @@ -489,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 } @@ -1022,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/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..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() @@ -40,7 +75,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 +107,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 +156,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 +198,154 @@ 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) + } +} + +// 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/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/api/api.go b/internal/api/api.go index 0e42ffe1..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 @@ -402,49 +513,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: + // revokedMu guards wsPingEvery. // - // 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. - // - // 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 +694,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 +1490,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. +// +// 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. // -// 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 { +// 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 +1788,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/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/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/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/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/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/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/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/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..12515029 100644 --- a/internal/engine/dest_stop_test.go +++ b/internal/engine/dest_stop_test.go @@ -30,17 +30,17 @@ 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) } 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 cdb52197..00b34df2 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 } } @@ -850,12 +867,19 @@ 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 } 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 { @@ -881,7 +905,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 @@ -981,7 +1005,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{ @@ -1077,7 +1101,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) } @@ -1289,7 +1313,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", @@ -1297,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, @@ -1350,7 +1383,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 0c536b17..883d941c 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") } @@ -1731,7 +1790,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,19 +1802,27 @@ 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 { 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 } - 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{ @@ -1792,7 +1859,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 +2108,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 @@ -2064,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, @@ -2092,7 +2169,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 @@ -2105,7 +2182,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 +2266,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,16 +2284,21 @@ func (e *Engine) reconcileMeters(s db.Settings) { return } if cur != nil { - e.stopAux(&e.meters, "meters") + 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 } 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}) @@ -2257,7 +2339,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 +3007,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 +3016,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 +3028,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 @@ -2961,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. // @@ -3004,7 +3092,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 +3128,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 { @@ -3048,8 +3136,159 @@ 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 }, + } +) + +// 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) proc := *slot *slot = nil var port int @@ -3058,21 +3297,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,9 +3314,9 @@ 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) + e.releasePort(port) } } @@ -3272,7 +3504,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 @@ -3292,10 +3524,19 @@ 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) + 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 @@ -3747,13 +3988,18 @@ 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 } 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, @@ -3805,7 +4051,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} @@ -3834,7 +4080,7 @@ func (e *Engine) teardownLoudness(m *loudnessMon) { hub.Unsubscribe(m.subName) } if m.port != 0 { - e.alloc.Release(m.port) + e.releasePort(m.port) } } @@ -3945,20 +4191,25 @@ 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 } 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) }) if err != nil { hub.Unsubscribe(clipSubName) - e.alloc.Release(port) + e.releasePort(port) e.log.Error("clip buffer", "err", err) return } @@ -3968,7 +4219,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 @@ -3990,7 +4241,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") } @@ -4300,13 +4551,18 @@ 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 } 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 @@ -4338,7 +4594,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 @@ -4350,7 +4606,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 @@ -4432,7 +4688,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/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 2d3b606d..639b3a22 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 @@ -229,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) @@ -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,12 +307,12 @@ 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") - upstream.Subscribe("rendition:1", port) + port := enginePort(t, e, "reserving the rendition's 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{ @@ -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,8 +388,8 @@ 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") - e.hub.Subscribe("rendition:1", port) + port := enginePort(t, e, "reserving the rendition's port") + mustSubscribe(t, e.hub, "rendition:1", port) e.teardownRendition(&rendition{ row: lifeRendition(1, db.EncoderX264), port: port, subName: "rendition:1", @@ -377,14 +399,14 @@ 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") - e.hub.Subscribe(loudnessSubPrefix+"7", port) + port := enginePort(t, e, "reserving the analyser's port") + mustSubscribe(t, e.hub, 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") }) } @@ -417,22 +439,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 +477,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] = enginePort(t, e, "reserving "+s.aux.name+"'s port") + 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"] 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 := 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.name]) + got, ports[stopping.aux.name]) } }) } @@ -515,12 +540,12 @@ func TestTheMetersSidecarIsUnsubscribedFromTheHubItSubscribedTo(t *testing.T) { e.alloc = oneSlotAllocator(t) silenceHub := lifeHub(t) - port := mustAllocate(t, e.alloc, "reserving the sidecar's port") - silenceHub.Subscribe("meters", port) - e.hub.Subscribe("meters", port) // decoy of the same name on the ingest + port := enginePort(t, e, "reserving the sidecar's port") + 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(&e.meters, "meters") + e.stopAux(auxMeters) if hasSubscriber(silenceHub, "meters") { t.Error("the sidecar was not unsubscribed from the relay it was actually reading; " + @@ -533,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 @@ -702,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 @@ -736,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 @@ -780,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") }) } } @@ -856,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 @@ -887,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) @@ -898,5 +923,17 @@ 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") +} + +// 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/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/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 2aa5ff4f..ac5c2c51 100644 --- a/internal/engine/selector.go +++ b/internal/engine/selector.go @@ -1548,12 +1548,20 @@ 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) } + 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 @@ -1662,7 +1670,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..f650181b --- /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") + 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, + }} + mustSubscribe(t, e.hub, "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..5d7505b0 100644 --- a/internal/engine/silence.go +++ b/internal/engine/silence.go @@ -205,19 +205,25 @@ 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 } - 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(), @@ -237,7 +243,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 +270,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/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/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/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 }) +} 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/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/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/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/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/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 +} 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) +} 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/internal/supervisor/census_test.go b/internal/supervisor/census_test.go index 2290ae81..d7851b9e 100644 --- a/internal/supervisor/census_test.go +++ b/internal/supervisor/census_test.go @@ -2,10 +2,15 @@ package supervisor import ( "context" + "io" + "log/slog" + "os/exec" "path/filepath" "strings" "testing" "time" + + "github.com/rainmanjam/polyemesis/internal/childcensus" ) /* The census exists because #631 could not be answered from inside the program. @@ -26,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) { @@ -129,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) } } @@ -144,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) { @@ -158,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. @@ -213,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() @@ -224,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) @@ -233,3 +191,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() +} diff --git a/internal/supervisor/supervisor.go b/internal/supervisor/supervisor.go index 419e1174..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. @@ -1117,13 +1118,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) { 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 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/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/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/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(); + }); +}); 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.