From 6fb0df2d6061f0b9786c82170075a4d03ee144c2 Mon Sep 17 00:00:00 2001 From: JRpersonal Date: Fri, 14 Aug 2026 09:31:23 +0200 Subject: [PATCH 1/3] chore(agent): a diagnostic says what the speaker complained about and what it was doing A SoundTouch 10 owner reports that his speaker reboots itself every night and that the first hardware preset press next morning lights the orange LED and plays nothing (#600). His two bundles show the press reaching the speaker correctly: it selects slot 5, STR logs that the box activates the native radio preset itself, and 700 ms later the speaker reports 4502 BMX_JSON_PARSE_ERROR and drops to INVALID_SOURCE. Before the nightly reboot the same speaker resolved a station through STR normally. What the bundle cannot say is what the speaker fetched, or from where. A native radio preset carries a location RELATIVE to the baseUrl in the BMX service list, so a speaker that never fetches that list cannot resolve a press at all, and the failure then surfaces as a parse error that reads like a broken station. That the request trail was empty is suggestive, but it is inference, and inference is what this has been answered with twice. Two facts, both cheap, both absent until now: Every error the speaker reports is kept alongside the preset location it was acting on and how long after the selection it arrived. The log already carried the errors, but finding them by eye among thousands of lines and pairing them with a press by timestamp is exactly the work a bundle should have done already. And the BMX registry response is counted. Zero fetches since the agent started is a statement, not a hint: the speaker cannot have resolved anything relative to a baseUrl it never asked for. Neither changes behaviour. The next bundle from this reporter should say outright which of the two mechanisms is at work. Refs #600 Co-Authored-By: Claude Opus 5 (1M context) --- cmd/agent/main.go | 19 +++++++++ internal/boxws/client.go | 72 +++++++++++++++++++++++++++++++++++ internal/boxws/client_test.go | 59 ++++++++++++++++++++++++++++ internal/boxws/dispatch.go | 6 +++ internal/marge/marge.go | 5 +++ internal/marge/responses.go | 6 +++ internal/marge/spy.go | 25 ++++++++++++ 7 files changed, 192 insertions(+) create mode 100644 internal/boxws/client_test.go diff --git a/cmd/agent/main.go b/cmd/agent/main.go index 20f50563..5efc26c2 100644 --- a/cmd/agent/main.go +++ b/cmd/agent/main.go @@ -848,6 +848,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. 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 +} From 0009998f9314b94e8a41e68fb09e250fbe03c7f9 Mon Sep 17 00:00:00 2001 From: JRpersonal Date: Fri, 14 Aug 2026 13:08:15 +0200 Subject: [PATCH 2/3] fix(speaker): the certificate repair now catches the case that was left broken, and takes effect The repair shipped in v0.9.43 did not help the speaker it was written for. Its owner updated, pressed the key, and got the same silence, and his diagnostic says why in two lines: store /etc/pki/tls/certs/ca-bundle.crt roots=2 publicRootsMissing=false repair /etc/pki/tls/certs/ca-bundle.crt healthy 1 -> 1 Two mistakes, both here. The test was "more than zero public roots". His bundle held exactly two certificates, STR's root plus a single survivor, so one public root counted as healthy and the file was left alone. A working speaker of the same firmware carries 158 and 165. A store down to single digits is the same corruption caught one step later, and calling it healthy is how a broken speaker gets told it is fine. The threshold is now a believable NUMBER of roots. The second is worse, because it applied even where the repair did fire. Go reads the system trust store once per process and caches it. Both the agent and the Spotify engine are started by a boot script that has already mounted the broken overlay, so both cached the poisoned copy long before the repair touched the file, and nothing re-reads it. Repairing the file changed what was on disk and nothing about what the speaker could reach. So a repair that actually rebuilt a store now exits, and the boot script's watchdog brings the agent and the engine back on the fixed store. Guarded to once per boot: a restart that keeps repeating is worse than a speaker that trusts nothing, and this path only runs on a speaker that already trusts nothing, so there is no playback to interrupt. Reproduced on an ST10 in the reporter's exact shape, one surviving root beside ours: 13:05:16 trust store lost its public roots, repairing certificates=2 13:05:16 trust store repaired publicRoots=166 firmwareRoots=166 13:05:16 restarting so this process and the Spotify engine read the fixed store 13:05:31 streborn starting Afterwards the store holds 167 and a handshake through it succeeds, where before the repair called the same file healthy and left it at two. Release-Note: fix(speaker): a speaker that trusts no internet station is now really repaired, including the case the previous version reported as healthy Co-Authored-By: Claude Opus 5 (1M context) --- cmd/agent/bootstrap.go | 52 ++++++++++++++++++++ internal/tlsgen/trustrepair.go | 19 ++++++-- internal/tlsgen/trustrepair_test.go | 73 ++++++++++++++++++++++++----- 3 files changed, 129 insertions(+), 15 deletions(-) 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/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") + } +} From 3a13376390663909151600a8d270c8866cf29da2 Mon Sep 17 00:00:00 2001 From: JRpersonal Date: Fri, 14 Aug 2026 13:08:15 +0200 Subject: [PATCH 3/3] chore(agent): the next time the agent is killed, the log says what it looked like first A live Portable lost its agent mid-Spotify on 2026-08-14: a healthy 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 nothing in the log could say whether the process had panicked, been killed for memory, or been stopped on purpose. 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 reasoning from an absence, which is what this replaces. Two measurements. A heartbeat every 30 s on tmpfs, so the next start knows what the previous run looked like just before it died: free memory, the agent's own footprint, thread count and whether Spotify was streaming. It costs no NAND, and it disappears on a box reboot while surviving an agent respawn, which is the same distinction bootReason already draws. And the kernel's own verdict: the OOM killer names its victim, and that line settles "killed for memory" outright instead of leaving it to be inferred from a memory graph. Both are reported as `last_exit` in /api/debug/state, and the start logs them only when there is something to say, so a normal boot stays silent. Co-Authored-By: Claude Opus 5 (1M context) --- cmd/agent/crashforensics.go | 217 ++++++++++++++++++++++++++++++++++++ cmd/agent/main.go | 16 +++ 2 files changed, 233 insertions(+) create mode 100644 cmd/agent/crashforensics.go 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 5efc26c2..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) @@ -989,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()