diff --git a/cmd/agent/bootstrap.go b/cmd/agent/bootstrap.go index dae77e63..cc7340bd 100644 --- a/cmd/agent/bootstrap.go +++ b/cmd/agent/bootstrap.go @@ -75,12 +75,64 @@ func repairTrustStoreWhenBootstrapIsDone(ctx context.Context, caDir string, logg case <-time.After(delay): } results := tlsgen.RepairTrustStore(tlsgen.ReadRootCAPEM(caDir), logger) + if anyStoreRepaired(results) { + restartForRepairedTrustStore(logger) + return + } if trustStoresHealthy(results) { return } } } +// trustRestartStamp marks that this boot has already restarted for a repair. +// On tmpfs: it must not survive a reboot, because a fresh boot rebuilds the +// broken overlay and legitimately earns another restart. +const trustRestartStamp = "/tmp/streborn-trust-restarted" + +// restartForRepairedTrustStore exits so the boot script's watchdog respawns +// the agent, and with it the Spotify engine. +// +// Repairing the FILES is not enough, which a field bundle proved: the fixed +// build reported both stores healthy and the speaker still failed every +// handshake. Go reads the system trust store once per process and caches it, +// so the agent and go-librespot were both started by a boot script that had +// already mounted the broken overlay, and both went on using the poisoned copy +// they had cached long before the repair touched the file. Nothing re-reads it, +// so nothing changes until the processes are new. +// +// Restarting is safe here in a way it would not be normally: a box that +// reaches this path trusts nothing, so no stream is playing to interrupt. +// Guarded to once per boot, because a restart that keeps repeating is worse +// than a speaker that trusts nothing. +func restartForRepairedTrustStore(logger *slog.Logger) { + if _, err := os.Stat(trustRestartStamp); err == nil { + logger.Warn("trust store repaired again after a restart this boot, not restarting a second time (the boot script is rebuilding it)") + return + } + if err := os.WriteFile(trustRestartStamp, []byte(time.Now().Format(time.RFC3339)+"\n"), 0o644); err != nil { + logger.Warn("trust store repair: cannot write the restart guard, staying up rather than risking a restart loop", "err", err) + return + } + logger.Warn("trust store repaired, restarting so this process and the Spotify engine read the fixed store (Go caches it once per process)") + // Flush before pulling the rug out, the same way every other exit path + // here does. + _ = exec.Command("sync").Run() + time.Sleep(500 * time.Millisecond) + os.Exit(0) +} + +// anyStoreRepaired reports whether the pass actually rebuilt something, which +// is what makes the cached-pool restart necessary. +func anyStoreRepaired(results []tlsgen.TrustRepairResult) bool { + for _, r := range results { + if r.Outcome == tlsgen.TrustRepairRepaired { + return true + } + } + return false +} + // trustStoresHealthy reports whether every store either carries public roots // or does not exist on this chassis. A store we could not fix keeps the // retry alive; one we did fix ends it. diff --git a/cmd/agent/crashforensics.go b/cmd/agent/crashforensics.go new file mode 100644 index 00000000..6fa04184 --- /dev/null +++ b/cmd/agent/crashforensics.go @@ -0,0 +1,217 @@ +// Crash forensics: why the previous agent process stopped. +// +// The agent can vanish and be respawned by the boot script's watchdog without +// leaving a single line about it. A live Portable did exactly that on +// 2026-08-14: a healthy Spotify session (156 s attached, 3049 KB forwarded), +// then nothing for 76 seconds, then "streborn starting" with +// bootReason="agent-respawn (box already up 2h19m)". Spotify never recovered +// afterwards, and the log could not say whether the process had panicked, been +// killed for memory, or been stopped deliberately. +// +// One thing it could already say by omission: a deliberate stop logs "shutdown +// signal received" from the SIGTERM handler, and there was no such line. So the +// process was killed rather than asked to stop. That is inference from an +// absence, which is exactly the kind of reasoning this file exists to replace. +// +// Two cheap measurements make the next one answerable: +// +// - A heartbeat in /tmp, so the next start knows what the previous run looked +// like moments before it died: free memory, the agent's own footprint, +// thread count and whether Spotify was streaming. /tmp is tmpfs, so it +// costs no NAND and it survives an agent respawn while a box reboot clears +// it, which is the same distinction bootReason draws. +// - The kernel's own verdict. The OOM killer names its victim in the ring +// buffer, and that line settles "killed for memory" outright. + +package main + +import ( + "encoding/json" + "log/slog" + "os" + "os/exec" + "strings" + "sync" + "time" +) + +// heartbeatPath lives on tmpfs deliberately: no NAND wear, and it disappears +// on a box reboot, so a heartbeat that IS there always belongs to the process +// that just died on a box which stayed up. +const heartbeatPath = "/tmp/streborn-agent-heartbeat.json" + +// heartbeatEvery is a compromise between resolution and pointless writes. The +// interesting window is the last minute before a kill, and half a minute of +// granularity places the death inside it without writing constantly. +const heartbeatEvery = 30 * time.Second + +// agentHeartbeat is the state of a running agent at one moment. +type agentHeartbeat struct { + At string `json:"at"` + UptimeSec int64 `json:"boxUptimeSec"` + MemAvailKB int64 `json:"memAvailableKB"` + MemTotalKB int64 `json:"memTotalKB"` + AgentRSSKB int64 `json:"agentRSSKB"` + AgentThreads int64 `json:"agentThreads"` + SpotifyStreaming bool `json:"spotifyStreaming"` +} + +// lastExitReport is what the previous run left behind, assembled once at start. +type lastExitReport struct { + // BootReason is the same string the box-write ledger is armed with. + BootReason string `json:"bootReason"` + // Previous is the last heartbeat the dead process wrote, absent when this + // is a box boot (tmpfs cleared) or the first run after an update. + Previous *agentHeartbeat `json:"previousRun,omitempty"` + // GapSec is how long between that heartbeat and this start. A gap close to + // heartbeatEvery means the process died right after it; a much larger one + // means it was already wedged and not writing. + GapSec int64 `json:"gapSec,omitempty"` + // OOMKill carries the kernel's own line when the OOM killer took the agent. + // Empty means the ring buffer holds no such verdict, which on this kernel + // is evidence rather than silence: the OOM killer always logs its victim. + OOMKill string `json:"oomKill,omitempty"` + // DmesgTail is the last few kernel lines, for the cases the OOM matcher + // does not cover (a watchdog, a segfault, a filesystem going read only). + DmesgTail string `json:"dmesgTail,omitempty"` +} + +var ( + lastExitMu sync.RWMutex + lastExit lastExitReport +) + +// LastExit returns the assembled report for /api/debug/state. +func lastExitSnapshot() any { + lastExitMu.RLock() + defer lastExitMu.RUnlock() + return lastExit +} + +// noteAgentStart reads whatever the previous run left behind and logs it. Call +// once, early, BEFORE the new heartbeat overwrites the old file. +// +// It never fails the start: every input here is best effort, and an agent that +// cannot explain its predecessor's death still has to run. +func noteAgentStart(bootReason string, logger *slog.Logger) { + rep := lastExitReport{BootReason: bootReason} + + if prev, err := readHeartbeat(); err == nil { + rep.Previous = prev + if t, perr := time.Parse(time.RFC3339Nano, prev.At); perr == nil { + rep.GapSec = int64(time.Since(t).Seconds()) + } + } + rep.OOMKill, rep.DmesgTail = scanKernelForKill() + + lastExitMu.Lock() + lastExit = rep + lastExitMu.Unlock() + + // Only say something when there is something to say. A box boot with no + // heartbeat and no OOM line is the normal case and deserves no NAND. + switch { + case rep.OOMKill != "": + logger.Warn("previous agent run was killed for memory by the kernel", + "bootReason", bootReason, "oom", rep.OOMKill, "gapSec", rep.GapSec) + case rep.Previous != nil: + logger.Warn("previous agent run ended without a shutdown signal, here is its last heartbeat", + "bootReason", bootReason, + "gapSec", rep.GapSec, + "memAvailableKB", rep.Previous.MemAvailKB, + "agentRSSKB", rep.Previous.AgentRSSKB, + "agentThreads", rep.Previous.AgentThreads, + "spotifyStreaming", rep.Previous.SpotifyStreaming) + } +} + +// runHeartbeat writes the state file until ctx is done. streaming reports +// whether Spotify is currently forwarding; nil when Spotify is not configured. +func runHeartbeat(stop <-chan struct{}, streaming func() bool, logger *slog.Logger) { + write := func() { + avail, total := readMemKB() + rss, threads := readSelfRSS() + hb := agentHeartbeat{ + At: time.Now().Format(time.RFC3339Nano), + UptimeSec: readUptimeSec(), + MemAvailKB: avail, + MemTotalKB: total, + AgentRSSKB: rss, + AgentThreads: threads, + } + if streaming != nil { + hb.SpotifyStreaming = streaming() + } + b, err := json.Marshal(hb) + if err != nil { + return + } + // Write in place rather than via a temp + rename: the file is tiny, a + // torn write only costs one sample, and a rename dance on tmpfs buys + // nothing while leaving stale temps behind if we are killed mid-way. + if err := os.WriteFile(heartbeatPath, b, 0o644); err != nil { + logger.Debug("heartbeat write failed", "err", err) + } + } + write() // one immediately, so a process that dies inside the first interval still leaves a mark + t := time.NewTicker(heartbeatEvery) + defer t.Stop() + for { + select { + case <-stop: + return + case <-t.C: + write() + } + } +} + +func readHeartbeat() (*agentHeartbeat, error) { + b, err := os.ReadFile(heartbeatPath) + if err != nil { + return nil, err + } + var hb agentHeartbeat + if err := json.Unmarshal(b, &hb); err != nil { + return nil, err + } + return &hb, nil +} + +// oomMarkers are how this kernel announces a kill. Matching several keeps the +// check honest across the wording differences between kernel versions. +var oomMarkers = []string{"Out of memory", "oom-kill", "oom_reaper", "Killed process"} + +// scanKernelForKill returns the OOM line naming our binary, plus a short tail +// of the kernel ring buffer for anything the matcher does not know about. +// +// dmesg is read through the command rather than /dev/kmsg because the ring +// buffer needs no privileges this way on the box, and because a missing dmesg +// then simply yields nothing instead of an error path nobody reads. +func scanKernelForKill() (oom, tail string) { + out, err := exec.Command("dmesg").Output() + if err != nil { + return "", "" + } + lines := strings.Split(strings.TrimRight(string(out), "\n"), "\n") + for i := len(lines) - 1; i >= 0; i-- { + l := lines[i] + if !strings.Contains(l, "streborn") { + continue + } + for _, m := range oomMarkers { + if strings.Contains(l, m) { + oom = strings.TrimSpace(l) + break + } + } + if oom != "" { + break + } + } + const keep = 12 + if len(lines) > keep { + lines = lines[len(lines)-keep:] + } + return oom, strings.Join(lines, "\n") +} diff --git a/cmd/agent/main.go b/cmd/agent/main.go index 20f50563..0debbad0 100644 --- a/cmd/agent/main.go +++ b/cmd/agent/main.go @@ -422,6 +422,13 @@ func run() error { "totals": boxwrites.Totals(), } }) + // Why the PREVIOUS run stopped. Read before the new heartbeat overwrites + // what the dead process left, and before anything else can crash. An agent + // that vanishes and is respawned by the watchdog otherwise leaves no trace + // at all: a live Portable did exactly that mid-Spotify on 2026-08-14 and + // the log could only say the process was gone. See crashforensics.go. + noteAgentStart(bootReason, logger) + webui.RegisterDebugSection("last_exit", lastExitSnapshot) go func() { for { time.Sleep(time.Hour) @@ -848,6 +855,25 @@ func run() error { // stamp the same classifier. renderer.OnTransportCommand = wsClient.NoteOwnTransportCommand webuiSrv.SetTransportCommandHook(wsClient.NoteOwnTransportCommand) + // bmx_adapter answers the two questions a failed hardware preset press + // raises and no bundle could answer before (#600): what the speaker itself + // complained about and what it was acting on at the time, and whether it + // ever fetched the service list that tells it where STR's adapters live. + // A native radio preset's location is RELATIVE to the baseUrl in that + // list, so registryFetches=0 means the speaker cannot resolve a press at + // all, however healthy everything else looks. + webui.RegisterDebugSection("bmx_adapter", func() any { + fetches, last := margeSrv.RegistryFetches() + lastStr := "" + if !last.IsZero() { + lastStr = last.Format(time.RFC3339) + } + return map[string]any{ + "registryFetches": fetches, + "lastRegistryFetch": lastStr, + "boxErrors": wsClient.BoxErrors(), + } + }) // The standby classifier reads the same stamp: a source flip right after // STR's own push (a wake-resume/recall the firmware rejects) must not be // classified as a user power-off. @@ -970,6 +996,15 @@ func run() error { // makes the RAM/load trend before a freeze visible in the on-box log // for post-mortem. Negligible NAND traffic (12 lines/hour), now that // the per-second connectionState spam is gone. + // The heartbeat rides alongside the health loop but at its own cadence: the + // health log answers "is this box trending toward trouble", the heartbeat + // answers "what did the process look like in the half minute before it was + // killed", and only the second one survives the kill. + wg.Add(1) + go func() { + defer wg.Done() + runHeartbeat(ctx.Done(), spotifyMgr.Streaming, logger) + }() wg.Add(1) go func() { defer wg.Done() diff --git a/internal/boxws/client.go b/internal/boxws/client.go index 465eceb2..7ae312a1 100644 --- a/internal/boxws/client.go +++ b/internal/boxws/client.go @@ -45,6 +45,21 @@ type Client struct { // storm so bundles can correlate it with the boot clock and marge trail. err1036Times []time.Time lastStormLogAt time.Time + // boxErrors is a small ring of the errors the BOX reported, newest last. + // The log already carries each one, but a bundle then needs someone to + // find them by eye among thousands of lines, and the code alone does not + // say what the box was doing at the time. A hardware preset press that + // dies on 4502 BMX_JSON_PARSE_ERROR (issue #600) is the case in point: + // the speaker activated a native radio preset, failed to parse whatever + // came back, and dropped to INVALID_SOURCE, and answering "what did it + // fetch, and had it ever fetched the service registry?" from the log was + // impossible. Pairing each error with the location the box was acting on + // makes the next bundle say it directly. + boxErrors []BoxErrorNote + // lastSelectionLoc / lastSelectionAt are the location and moment of the + // last preset the box selected, used to attribute an error to a press. + lastSelectionLoc string + lastSelectionAt time.Time // prevEndedIdle marks that the previous WS session ended in a plain idle // read timeout, so the next "connected" phase marker logs at Debug instead // of churning the NAND log. Only touched from the Run loop goroutine. @@ -321,6 +336,63 @@ const ( // hangs off it): it timestamps the storm START so bundles can correlate it // with the boot clock state (plug-pull RTC loss poisons the firmware, #419 // Finding 4), TLS handshake failures on marge-tls, and the marge trail. +// BoxErrorNote is one error the box reported over its WebSocket, kept with +// the preset location the box was acting on so a bundle can tell a failure +// that followed a preset press apart from one that came out of nowhere. +type BoxErrorNote struct { + When string `json:"when"` + Value string `json:"value"` + Name string `json:"name"` + Detail string `json:"detail,omitempty"` + // ActingOn is the location of the last preset the box selected before this + // error, empty when the error did not follow a selection. + ActingOn string `json:"actingOn,omitempty"` + // SinceSelectionMs is how long after that selection the error arrived. + SinceSelectionMs int64 `json:"sinceSelectionMs,omitempty"` +} + +// maxBoxErrors bounds the ring. These are rare on a healthy speaker and the +// interesting ones cluster around a single press, so a short tail is enough +// and cannot grow the debug payload without limit on a box that storms. +const maxBoxErrors = 12 + +// noteBoxError records a box-reported error next to what the box was doing. +func (c *Client) noteBoxError(value, name, detail string) { + now := time.Now() + c.mu.Lock() + defer c.mu.Unlock() + n := BoxErrorNote{ + When: now.Format(time.RFC3339Nano), + Value: value, + Name: name, + Detail: detail, + } + if !c.lastSelectionAt.IsZero() { + n.ActingOn = c.lastSelectionLoc + n.SinceSelectionMs = now.Sub(c.lastSelectionAt).Milliseconds() + } + c.boxErrors = append(c.boxErrors, n) + if len(c.boxErrors) > maxBoxErrors { + c.boxErrors = c.boxErrors[len(c.boxErrors)-maxBoxErrors:] + } +} + +// BoxErrors returns a copy of the recorded box errors, oldest first. +func (c *Client) BoxErrors() []BoxErrorNote { + c.mu.Lock() + defer c.mu.Unlock() + return append([]BoxErrorNote(nil), c.boxErrors...) +} + +// NoteSelection records the preset location the box just selected, so an error +// arriving milliseconds later can be attributed to it. +func (c *Client) NoteSelection(loc string) { + c.mu.Lock() + defer c.mu.Unlock() + c.lastSelectionLoc = loc + c.lastSelectionAt = time.Now() +} + func (c *Client) note1036() { now := time.Now() c.mu.Lock() diff --git a/internal/boxws/client_test.go b/internal/boxws/client_test.go new file mode 100644 index 00000000..5154c685 --- /dev/null +++ b/internal/boxws/client_test.go @@ -0,0 +1,59 @@ +package boxws + +import ( + "io" + "log/slog" + "testing" +) + +func quietTestLogger() *slog.Logger { + return slog.New(slog.NewTextHandler(io.Discard, nil)) +} + +// A box error that follows a preset selection must be recorded WITH what the +// box was acting on. Issue #600: a hardware press activated a native radio +// preset and the speaker answered 4502 BMX_JSON_PARSE_ERROR 700 ms later, and +// the bundle could not connect the two. +func TestBoxErrorIsRecordedAgainstTheSelectionItFollowed(t *testing.T) { + c := &Client{logger: quietTestLogger()} + + c.NoteSelection("/station?data=eyJuYW1lIjoiUmFkaW8gTm9vcmQifQ") + c.noteBoxError("4502", "BMX_JSON_PARSE_ERROR", "Json parse error: Line 1, Column 12") + + got := c.BoxErrors() + if len(got) != 1 { + t.Fatalf("want one recorded error, got %d", len(got)) + } + if got[0].Value != "4502" || got[0].Name != "BMX_JSON_PARSE_ERROR" { + t.Errorf("error mis-recorded: %+v", got[0]) + } + if got[0].ActingOn == "" { + t.Error("the error must carry the location the box was acting on") + } + if got[0].SinceSelectionMs < 0 { + t.Errorf("SinceSelectionMs = %d, want the gap to the selection", got[0].SinceSelectionMs) + } +} + +// An error with no preset press before it must not invent an attribution. +func TestBoxErrorWithoutASelectionCarriesNoAttribution(t *testing.T) { + c := &Client{logger: quietTestLogger()} + + c.noteBoxError("3101", "AUDIO_ERROR_BAD_URL", "") + + got := c.BoxErrors() + if len(got) != 1 || got[0].ActingOn != "" { + t.Errorf("unattributed error should stay unattributed: %+v", got) + } +} + +// The ring is bounded so a storming speaker cannot grow the debug payload. +func TestBoxErrorRingIsBounded(t *testing.T) { + c := &Client{logger: quietTestLogger()} + for i := 0; i < maxBoxErrors*3; i++ { + c.noteBoxError("1036", "UNABLE_TO_PROCESS_NOT_LOGGED_IN", "") + } + if n := len(c.BoxErrors()); n != maxBoxErrors { + t.Errorf("ring holds %d entries, want it capped at %d", n, maxBoxErrors) + } +} diff --git a/internal/boxws/dispatch.go b/internal/boxws/dispatch.go index 414d03a0..5969e87c 100644 --- a/internal/boxws/dispatch.go +++ b/internal/boxws/dispatch.go @@ -399,6 +399,9 @@ func (c *Client) handleMessage(ctx context.Context, data []byte) { if v, name, sev, detail := parseBoxError(s); v != "" { c.logger.Warn("box ws: box reported error", "value", v, "name", name, "severity", sev, "detail", detail) + // Also keep it with what the box was acting on, so a bundle + // does not need the reader to find these by eye (#600). + c.noteBoxError(v, name, detail) if v == "1036" { c.note1036() } @@ -547,6 +550,9 @@ func (c *Client) handleMessage(ctx context.Context, data []byte) { "source", pe.ContentItem.Source, "title", pe.ContentItem.ItemName, ) + // Remember what the box is acting on, so an error frame arriving a moment + // later is recorded against this selection instead of standing alone (#600). + c.NoteSelection(pe.ContentItem.Location) // Stamp the press so the STOP_STATE this switch teardown emits a moment later // is recognised as teardown, not a user stop (see stopStateIsTeardown). c.mu.Lock() diff --git a/internal/marge/marge.go b/internal/marge/marge.go index fd542df9..4e6ae906 100644 --- a/internal/marge/marge.go +++ b/internal/marge/marge.go @@ -56,6 +56,11 @@ type Server struct { requestLog []SpyEntry requestLogMax int + // registryFetches / lastRegistryFetch count the box's own requests for the + // BMX service list (see spy.go). + registryFetches int + lastRegistryFetch time.Time + // group holds the stereo-pair (L/R) record the ST10 firmware created "on // marge" via POST /streaming/account//group/, the cloud half of the // box's /addGroup. nil means no pair. diff --git a/internal/marge/responses.go b/internal/marge/responses.go index 6b1b5955..e82c4b1b 100644 --- a/internal/marge/responses.go +++ b/internal/marge/responses.go @@ -54,6 +54,12 @@ func (s *Server) respondBmxRegistry(w http.ResponseWriter, r *http.Request) { // resolve a station. base := "http://127.0.0.1:8888" _ = r + // Count it. This response is what tells the box where the BMX adapters + // live, and a native radio preset carries a location RELATIVE to that + // baseUrl, so a box that never asks for this list cannot resolve a preset + // press at all. Issue #600 turned on exactly that question and the bundle + // could only answer it by inference from an empty request trail. + s.noteRegistryFetch() body := strings.ReplaceAll(bmxServicesJSON, "{BMX_SERVER}", base) body = strings.ReplaceAll(body, "{MEDIA_SERVER}", base+"/media") w.Header().Set("Content-Type", "application/json; charset=utf-8") diff --git a/internal/marge/spy.go b/internal/marge/spy.go index a33c9121..658a8fa6 100644 --- a/internal/marge/spy.go +++ b/internal/marge/spy.go @@ -111,3 +111,28 @@ func (s *Server) handleSpyLog(w http.ResponseWriter, _ *http.Request) { fmt.Fprintln(w, "----------------------------------------") } } + +// --- BMX registry fetch counter --------------------------------------------- +// +// The registry response carries the baseUrl the box resolves a native radio +// preset's relative location against. A box that never fetches it cannot +// resolve a preset press, and the failure surfaces far away from the cause: +// the speaker reports a JSON parse error and drops to INVALID_SOURCE, which +// reads like a broken station (#600). One counter and one timestamp turn that +// into a fact a bundle states outright. + +// noteRegistryFetch records that the box asked for the BMX service list. +func (s *Server) noteRegistryFetch() { + s.mu.Lock() + defer s.mu.Unlock() + s.registryFetches++ + s.lastRegistryFetch = time.Now() +} + +// RegistryFetches reports how often the box has asked for the BMX service list +// since this agent started, and when it last did. count 0 means never. +func (s *Server) RegistryFetches() (count int, last time.Time) { + s.mu.RLock() + defer s.mu.RUnlock() + return s.registryFetches, s.lastRegistryFetch +} diff --git a/internal/tlsgen/trustrepair.go b/internal/tlsgen/trustrepair.go index 5f3cc7a5..8d8c1a60 100644 --- a/internal/tlsgen/trustrepair.go +++ b/internal/tlsgen/trustrepair.go @@ -152,7 +152,7 @@ func repairOne(path string, slot int, rootCAPEM []byte, ops mountOps, logger *sl } res.RootsBefore = publicRootCount(before, rootCAPEM) res.RootsAfter = res.RootsBefore - if res.RootsBefore > 0 { + if res.RootsBefore >= minPlausiblePublicRoots { res.Outcome = TrustRepairHealthy return res } @@ -187,7 +187,7 @@ func repairOne(path string, slot int, rootCAPEM []byte, ops mountOps, logger *sl return res } res.FirmwareRoots = strings.Count(string(firmware), pemCertHeader) - if publicRootCount(firmware, rootCAPEM) == 0 { + if publicRootCount(firmware, rootCAPEM) < minPlausiblePublicRoots { // Nothing to rebuild from. The broken overlay at least carried our // root, so put it back rather than leave the speaker with less than // it started with. @@ -223,7 +223,7 @@ func repairOne(path string, slot int, rootCAPEM []byte, ops mountOps, logger *sl // Confirm through the mount, the same way the box's TLS clients will. res.RootsAfter = publicRootCountAt(path, rootCAPEM) - if res.RootsAfter == 0 { + if res.RootsAfter < minPlausiblePublicRoots { res.Outcome = TrustRepairFailed res.Err = "the rebuilt overlay still shows no public roots" logger.Error("trust store repair: rebuilt overlay reads back empty", "path", path, "overlay", overlay) @@ -270,6 +270,19 @@ func appendRootBlock(bundle, rootCAPEM []byte) []byte { return b.Bytes() } +// minPlausiblePublicRoots is the smallest number of public roots a real +// firmware bundle can be believed to hold. +// +// "More than zero" is not the right test, and a field bundle proved it: an +// ST20 on the fixed build reported ca-bundle.crt with TWO certificates, STR's +// root plus a single survivor. One public root passed the old check as +// healthy, the repair skipped the file, and the speaker went on failing every +// handshake. Both stores on a working box of the same firmware carry 158 and +// 165. Anything in single digits is the same corruption caught one step later, +// not a legitimately small trust store, and treating it as healthy is how a +// broken box gets told it is fine. +const minPlausiblePublicRoots = 10 + // publicRootCount counts the certificates in bundle that are not STR's own // root. That is the figure that decides whether the box can reach the // internet: a store holding only our root passes a naive "is it empty" check diff --git a/internal/tlsgen/trustrepair_test.go b/internal/tlsgen/trustrepair_test.go index a5af7148..2b4fb98e 100644 --- a/internal/tlsgen/trustrepair_test.go +++ b/internal/tlsgen/trustrepair_test.go @@ -2,6 +2,7 @@ package tlsgen import ( "errors" + "fmt" "io" "log/slog" "os" @@ -14,11 +15,21 @@ func quietLogger() *slog.Logger { return slog.New(slog.NewTextHandler(io.Discard, nil)) } -const ( - testSTRRoot = "-----BEGIN CERTIFICATE-----\nSTRROOTCA\n-----END CERTIFICATE-----\n" - testPublic = "-----BEGIN CERTIFICATE-----\nDIGICERTG2\n-----END CERTIFICATE-----\n" + - "-----BEGIN CERTIFICATE-----\nISRGROOTX1\n-----END CERTIFICATE-----\n" -) +const testSTRRoot = "-----BEGIN CERTIFICATE-----\nSTRROOTCA\n-----END CERTIFICATE-----\n" + +// wantPublic is how many public roots testPublic carries. It has to clear +// minPlausiblePublicRoots, because the repair judges a store by whether it +// holds a believable NUMBER of public roots rather than merely one. +const wantPublic = minPlausiblePublicRoots + 2 + +// testPublic stands in for a real firmware bundle. +var testPublic = func() string { + out := "" + for i := 0; i < wantPublic; i++ { + out += fmt.Sprintf("-----BEGIN CERTIFICATE-----\nPUBLICROOT%02d\n-----END CERTIFICATE-----\n", i) + } + return out +}() // fakeMounts models a bind mount over a single file: the "mounted" content // shadows the pristine file, and unmounting reveals it again. That is the @@ -109,13 +120,13 @@ func TestRepairRebuildsAStoreThatHoldsOnlyOurOwnRoot(t *testing.T) { if res[0].RootsBefore != 0 { t.Errorf("RootsBefore = %d, want 0 public roots before the repair", res[0].RootsBefore) } - if res[0].RootsAfter != 2 { - t.Errorf("RootsAfter = %d, want the 2 public roots back", res[0].RootsAfter) + if res[0].RootsAfter != wantPublic { + t.Errorf("RootsAfter = %d, want the %d public roots back", res[0].RootsAfter, wantPublic) } // The box has to trust the internet AND us: dropping our root would // break the Bose-domain server cert instead. live := readFile(t, f.path) - if !strings.Contains(live, "DIGICERTG2") || !strings.Contains(live, "ISRGROOTX1") { + if !strings.Contains(live, "PUBLICROOT00") || !strings.Contains(live, "PUBLICROOT05") { t.Error("repaired store lost the firmware's public roots") } if !strings.Contains(live, "STRROOTCA") { @@ -170,8 +181,8 @@ func TestRepairLeavesTheFirmwareBundleLiveWhenRemountFails(t *testing.T) { if res[0].Outcome != TrustRepairFailed { t.Fatalf("outcome = %q, want %q", res[0].Outcome, TrustRepairFailed) } - if res[0].RootsAfter != 2 { - t.Errorf("RootsAfter = %d, want the firmware's 2 public roots live", res[0].RootsAfter) + if res[0].RootsAfter != wantPublic { + t.Errorf("RootsAfter = %d, want the firmware's %d public roots live", res[0].RootsAfter, wantPublic) } if strings.Contains(readFile(t, f.path), "STRROOTCA") { t.Error("expected the pristine firmware bundle, not the broken overlay") @@ -246,8 +257,8 @@ func TestRepairWithoutOurRootStillRestoresThePublicRoots(t *testing.T) { if res[0].Outcome != TrustRepairRepaired { t.Fatalf("outcome = %q (err %q), want %q", res[0].Outcome, res[0].Err, TrustRepairRepaired) } - if res[0].RootsAfter != 2 { - t.Errorf("RootsAfter = %d, want 2", res[0].RootsAfter) + if res[0].RootsAfter != wantPublic { + t.Errorf("RootsAfter = %d, want %d", res[0].RootsAfter, wantPublic) } } @@ -277,3 +288,41 @@ func TestAppendRootBlockSeparatesTheMarkerFromABundleWithoutATrailingNewline(t * t.Errorf("missing the markers the boot script writes:\n%s", out) } } + +// The field case the first version of this repair walked straight past: an +// ST20 on the fixed build reported ca-bundle.crt holding TWO certificates, +// STR's root plus one survivor. "More than zero public roots" called that +// healthy, the file was left alone, and the speaker went on failing every +// handshake while the diagnostic said it was fine. +func TestRepairRebuildsAStoreLeftWithASingleSurvivingRoot(t *testing.T) { + const oneSurvivor = "-----BEGIN CERTIFICATE-----\nLONESURVIVOR\n-----END CERTIFICATE-----\n" + f := newFakeMounts(t, testPublic, oneSurvivor+testSTRRoot) + + res := repairTrustStorePaths([]string{f.path}, []byte(testSTRRoot), f.ops(), quietLogger()) + + if res[0].Outcome != TrustRepairRepaired { + t.Fatalf("outcome = %q (err %q), want %q: one public root is the same corruption, not a healthy store", + res[0].Outcome, res[0].Err, TrustRepairRepaired) + } + if res[0].RootsBefore != 1 { + t.Errorf("RootsBefore = %d, want the single survivor counted", res[0].RootsBefore) + } + if res[0].RootsAfter != wantPublic { + t.Errorf("RootsAfter = %d, want the firmware's %d roots back", res[0].RootsAfter, wantPublic) + } +} + +// A store that is merely SMALL but believable must still be left alone, so the +// threshold cannot be read as "rebuild anything that is not the biggest". +func TestRepairLeavesAPlausibleStoreAlone(t *testing.T) { + f := newFakeMounts(t, testPublic, testPublic+testSTRRoot) + + res := repairTrustStorePaths([]string{f.path}, []byte(testSTRRoot), f.ops(), quietLogger()) + + if res[0].Outcome != TrustRepairHealthy { + t.Fatalf("outcome = %q, want %q", res[0].Outcome, TrustRepairHealthy) + } + if f.unmounts != 0 || f.binds != 0 { + t.Error("a store with a believable number of roots must not be touched") + } +}