From 5c97fe03f65598470ac5b5d74cd25cb50163a2be Mon Sep 17 00:00:00 2001 From: Fredrik Ahlgren Date: Fri, 31 Jul 2026 11:03:27 +0200 Subject: [PATCH 1/2] feat(api): one-file help report for "why is it doing that?" MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit GET /api/support/report returns a single Markdown file describing what FTW is doing and why, reachable from a "Something looks wrong?" button under the plan chart and from any driver's Diagnose modal. It exists because answering a user's "why is it discharging when the plan says charge?" currently costs a screenshot round-trip per question. One thread needed nine of them to establish that the load forecast said 383 W while the house was drawing 7.9 kW — a fact the first file should have stated outright. The report opens with Findings: checks in the order a person would run them — stale plan, fallback solver, offline or faulted devices, active safety limits, an untrained load model, and forecast against reality for both load and solar. Then the live state, the plan slot covering *this moment* stated before anything about the next one, the surrounding slots with the solver's reasoning, forecast accuracy, driver health, versions, and the recent warning and error log. One file, not a bundle: people paste it into a chat and ask for help there. The plan window is trimmed to a few hours either side of now and logs to warnings and errors, which keeps a live report near 3 kB. /api/support/dump is unchanged and stays the deep bundle. Co-Authored-By: Claude Opus 5 --- .changeset/support-help-report.md | 28 + go/internal/api/api.go | 1 + go/internal/api/api_support_report.go | 711 +++++++++++++++++++++ go/internal/api/api_support_report_test.go | 262 ++++++++ web/app.css | 24 + web/diagnostics-modal.js | 12 + web/help-report.test.mjs | 31 + web/index.html | 10 + web/plan.js | 39 ++ 9 files changed, 1118 insertions(+) create mode 100644 .changeset/support-help-report.md create mode 100644 go/internal/api/api_support_report.go create mode 100644 go/internal/api/api_support_report_test.go create mode 100644 web/help-report.test.mjs diff --git a/.changeset/support-help-report.md b/.changeset/support-help-report.md new file mode 100644 index 00000000..9ee3e457 --- /dev/null +++ b/.changeset/support-help-report.md @@ -0,0 +1,28 @@ +--- +"ftw": minor +--- + +Help report: `GET /api/support/report` returns a single Markdown file +describing what FTW is doing and why, reachable from a "Something looks +wrong?" button under the plan chart and from any driver's Diagnose modal. +It exists because answering "why is it discharging when the plan says +charge?" currently takes a screenshot round-trip per question — one thread +needed nine of them to establish that a load forecast said 383 W while the +house was drawing 7.9 kW. + +The file opens with `Findings`: automated checks written in the order a +person would run them — stale plan, fallback solver, offline or faulted +devices, active safety limits, and a forecast-versus-reality comparison for +both load and solar. Under that come the live site state, the plan slot +covering *this moment* (stated before anything about the next one, since +confusing the two is what sends these threads sideways), the surrounding +slots with the solver's reasoning, forecast accuracy, driver health, +component versions, and the recent warning and error log. + +It is one file rather than a bundle because people paste it into a chat and +ask for help there; a tarball of JSON does not survive that. The plan window +is trimmed to a few hours either side of now and logs to warnings and errors, +which keeps it small enough to upload and to read in full. + +`/api/support/dump` is unchanged and remains the deep bundle for cases the +report cannot close. diff --git a/go/internal/api/api.go b/go/internal/api/api.go index fa5ed888..4baa48a9 100644 --- a/go/internal/api/api.go +++ b/go/internal/api/api.go @@ -268,6 +268,7 @@ func (s *Server) routes() { s.handle("GET /api/drivers/{name}/logs", s.handleDriverLogs) s.handle("GET /api/logs", s.handleGlobalLogs) s.handle("GET /api/support/dump", s.handleSupportDump) + s.handle("GET /api/support/report", s.handleSupportReport) s.handle("POST /api/drivers/{name}/restart", s.handleDriverRestart) s.handle("POST /api/drivers/{name}/disable", s.handleDriverDisable) s.handle("POST /api/drivers/{name}/enable", s.handleDriverEnable) diff --git a/go/internal/api/api_support_report.go b/go/internal/api/api_support_report.go new file mode 100644 index 00000000..8dcbdef4 --- /dev/null +++ b/go/internal/api/api_support_report.go @@ -0,0 +1,711 @@ +package api + +// The "I need help" report. +// +// GET /api/support/report returns ONE self-explanatory Markdown file that +// answers the questions people actually ask in support channels: why is the +// battery discharging, why did it export, why is nothing happening, why is my +// device offline, why did it not update. +// +// Design constraints, learned from a support thread that took six hours and +// nine screenshots to establish that a load forecast said 383 W while the +// house drew 7.9 kW: +// +// - ONE file. People paste it into a chat and tag the bot. A tarball of +// twelve JSON files does not survive that journey. +// - Small enough for a chat upload and a model's context: the plan is +// trimmed to a few hours either side of now, logs to warnings and errors. +// - Self-diagnosing. Findings runs the checks a human would run first, so +// the file is useful before anyone reads the tables under it. +// - NOW is answered before NEXT. The dashboard's plan card leads with the +// next action; that ambiguity is what sent the thread down the wrong path. +// - No secrets. Config is not dumped — only the planner settings that +// change decisions. +// +// /api/support/dump remains the deep bundle (logs, telemetry, config) for +// cases this report cannot close. + +import ( + "context" + "fmt" + "math" + "net/http" + "sort" + "strings" + "time" + + "github.com/srcfl/ftw/go/internal/control" + "github.com/srcfl/ftw/go/internal/mpc" + "github.com/srcfl/ftw/go/internal/telemetry" +) + +// reportPlanWindow is how far either side of now the plan table reaches. +// Three hours covers "what just happened" and "what happens next" without +// pushing a 48 h horizon into the file. +const reportPlanWindow = 3 * time.Hour + +// reportLogLines caps the warning/error tail. Enough for one incident. +const reportLogLines = 120 + +// loadmodelWarmBucketsForTrust is the point past which the weekly load +// pattern is filled in enough that its predictions carry the plan. Below +// it the planner is guessing, which is worth saying out loud before +// anyone debugs a decision built on that guess. Roughly two-thirds of the +// 168 hourly buckets. +const loadmodelWarmBucketsForTrust = 112 + +// Severity labels. Plain words, not symbols — a model reading this file +// should not have to infer meaning from an emoji. +const ( + sevProblem = "PROBLEM" + sevWarning = "WARNING" + sevNote = "NOTE" +) + +type finding struct { + Severity string + Title string + Detail string +} + +func (s *Server) handleSupportReport(w http.ResponseWriter, r *http.Request) { + now := time.Now() + body := s.buildSupportReport(r.Context(), now) + stamp := now.UTC().Format("20060102-150405") + w.Header().Set("Content-Type", "text/markdown; charset=utf-8") + w.Header().Set("Content-Disposition", `attachment; filename="ftw-help-`+stamp+`.md"`) + w.Header().Set("Cache-Control", "no-store") + _, _ = w.Write([]byte(body)) +} + +// liveSnapshot is the aggregated site state the report needs. It mirrors +// handleStatus's aggregation but deliberately skips Tel.UpdateLoad — that +// call mutates the shared smoothing filter, and generating a report must +// not perturb control inputs. The unsmoothed value is what we want anyway: +// a report should show the instant, not a filtered version of it. +type liveSnapshot struct { + GridW float64 + HaveGrid bool + PVW float64 + BatW float64 + EVW float64 + V2XW float64 + LoadW float64 + SoCPct float64 + HaveSoC bool + PredictedPV float64 + PredictedLd float64 +} + +func (s *Server) liveNow(ctrl control.State, now time.Time) liveSnapshot { + var snap liveSnapshot + if statusDriverTelemetryUsable(s.deps.Tel, ctrl.SiteMeterDriver) { + if r := s.deps.Tel.Get(ctrl.SiteMeterDriver, telemetry.DerMeter); r != nil { + snap.GridW = r.SmoothedW + snap.HaveGrid = true + } + } + for _, r := range s.deps.Tel.ReadingsByType(telemetry.DerPV) { + if h := s.deps.Tel.DriverHealth(r.Driver); h == nil || !h.IsOnline() { + continue + } + snap.PVW += r.SmoothedW + } + var socSum, socWeight float64 + for _, r := range s.deps.Tel.ReadingsByType(telemetry.DerBattery) { + if h := s.deps.Tel.DriverHealth(r.Driver); h == nil || !h.IsOnline() { + continue + } + snap.BatW += r.SmoothedW + if r.SoC != nil { + socSum += *r.SoC + socWeight++ + } + } + if socWeight > 0 { + snap.SoCPct = socSum / socWeight * 100 + snap.HaveSoC = true + } + snap.EVW = s.deps.Tel.SumOnlineEVW() + snap.V2XW = s.deps.Tel.SumOnlineV2XW() + if snap.HaveGrid { + snap.LoadW = snap.GridW - snap.BatW - snap.PVW - snap.EVW - snap.V2XW + if snap.LoadW < 0 { + snap.LoadW = 0 + } + } + if s.deps.PVModel != nil { + snap.PredictedPV = -s.deps.PVModel.PredictNow() + } + if s.deps.LoadModel != nil { + snap.PredictedLd = s.deps.LoadModel.Predict(now) + } + return snap +} + +func (s *Server) buildSupportReport(ctx context.Context, now time.Time) string { + s.deps.CtrlMu.Lock() + ctrl := *s.deps.Ctrl + targets := append([]control.DispatchTarget{}, s.deps.Ctrl.LastTargets...) + s.deps.CtrlMu.Unlock() + + snap := s.liveNow(ctrl, now) + + var plan *mpc.Plan + var activeSlot *mpc.Action + var lastReplanAt time.Time + var lastReplanReason string + if s.deps.MPC != nil { + plan = s.deps.MPC.Latest() + lastReplanAt, lastReplanReason = s.deps.MPC.LastReplanInfo() + activeSlot = activeAction(plan, now) + } + + health := s.deps.Tel.AllHealth() + findings := s.collectFindings(ctrl, snap, plan, activeSlot, targets, health, now) + + var b strings.Builder + writeReportHeader(&b, s.deps.Version, now) + writeFindings(&b, findings) + writeRightNow(&b, ctrl, snap, activeSlot, targets, now) + writePlanSection(&b, plan, lastReplanAt, lastReplanReason, now) + writeForecastSection(&b, s, snap, activeSlot, now) + writeDeviceSection(&b, health, now) + s.writeComponentSection(&b, ctx, plan) + s.writeLogSection(&b) + writeReportFooter(&b) + return b.String() +} + +func writeReportHeader(b *strings.Builder, version string, now time.Time) { + fmt.Fprintf(b, "# FTW help report\n\n") + fmt.Fprintf(b, "Generated %s · FTW %s\n\n", now.Format("2006-01-02 15:04:05 MST"), version) + b.WriteString("Sign convention: **positive W = power into the site** " + + "(importing, charging the battery); **negative W = power out** " + + "(exporting, discharging). This holds in every table below.\n\n") + b.WriteString("Read `Findings` first — it lists what looks wrong without " + + "needing the tables. `Right now` is what the system is doing at this " + + "instant; `Plan` is what it intends to do next. Those two answer " + + "different questions and often disagree, which is usually the point " + + "of the question.\n\n") +} + +func writeFindings(b *strings.Builder, findings []finding) { + b.WriteString("## Findings\n\n") + if len(findings) == 0 { + b.WriteString("No automated check fired. The system looks healthy from " + + "the inside, so the question is probably about intent rather than " + + "a fault — see `Plan` for the reasoning behind the current slot.\n\n") + return + } + // Problems first: a reader (human or model) should hit the worst thing + // before the merely notable. + order := map[string]int{sevProblem: 0, sevWarning: 1, sevNote: 2} + sort.SliceStable(findings, func(i, j int) bool { + return order[findings[i].Severity] < order[findings[j].Severity] + }) + for _, f := range findings { + fmt.Fprintf(b, "- **%s — %s.** %s\n", f.Severity, f.Title, f.Detail) + } + b.WriteString("\n") +} + +func writeRightNow( + b *strings.Builder, + ctrl control.State, + snap liveSnapshot, + activeSlot *mpc.Action, + targets []control.DispatchTarget, + now time.Time, +) { + b.WriteString("## Right now\n\n") + fmt.Fprintf(b, "Mode **%s**", ctrl.Mode) + if ctrl.PlanStale { + b.WriteString(" · plan is **stale**, running safe live balancing") + } + b.WriteString("\n\n") + + b.WriteString("| Measure | Value |\n|---|---|\n") + if snap.HaveGrid { + fmt.Fprintf(b, "| Grid | %s |\n", fmtReportW(snap.GridW)) + } else { + b.WriteString("| Grid | **no site meter reading** |\n") + } + fmt.Fprintf(b, "| Solar | %s |\n", fmtReportW(snap.PVW)) + fmt.Fprintf(b, "| House load | %s |\n", fmtReportW(snap.LoadW)) + fmt.Fprintf(b, "| Battery | %s |\n", fmtReportW(snap.BatW)) + if snap.EVW != 0 { + fmt.Fprintf(b, "| EV | %s |\n", fmtReportW(snap.EVW)) + } + if snap.V2XW != 0 { + fmt.Fprintf(b, "| V2X | %s |\n", fmtReportW(snap.V2XW)) + } + if snap.HaveSoC { + fmt.Fprintf(b, "| Battery charge | %.1f%% |\n", snap.SoCPct) + } + fmt.Fprintf(b, "| Grid setpoint | %s |\n", fmtReportW(ctrl.GridTargetW)) + b.WriteString("\n") + + // The plan's intent for THIS slot, stated before anything about the + // next one. The dashboard leads with "next"; a report that repeats + // that mistake cannot settle a "why is it doing this right now" + // argument. + if activeSlot != nil { + end := time.UnixMilli(activeSlot.SlotStartMs). + Add(time.Duration(activeSlot.SlotLenMin) * time.Minute) + fmt.Fprintf(b, "The plan slot covering this moment (%s–%s) intends "+ + "**battery %s** — %q.\n\n", + time.UnixMilli(activeSlot.SlotStartMs).Format("15:04"), + end.Format("15:04"), + fmtReportW(activeSlot.BatteryW), + activeSlot.Reason) + if delta := math.Abs(activeSlot.BatteryW - snap.BatW); delta > 500 { + fmt.Fprintf(b, "The battery is **%s away from that intent** "+ + "(planned %s, actual %s). A gap this size is either a "+ + "safety clamp, a device that cannot follow the command, or "+ + "a plan replaced since the slot began — check the replan "+ + "reason in `Plan`.\n\n", + fmtReportW(delta), fmtReportW(activeSlot.BatteryW), fmtReportW(snap.BatW)) + } + } else { + b.WriteString("No plan slot covers this moment.\n\n") + } + + if len(targets) > 0 { + b.WriteString("Commands sent to each device on the last control tick:\n\n") + b.WriteString("| Device | Target | Limited by safety |\n|---|---|---|\n") + for _, t := range targets { + clamped := "no" + if t.Clamped { + clamped = "**yes**" + } + fmt.Fprintf(b, "| %s | %s | %s |\n", t.Driver, fmtReportW(t.TargetW), clamped) + } + b.WriteString("\n") + } + + st := ctrl.SlotDeliveryStats + if st.OverDeliveryCount+st.UnderDeliveryCount+st.SignMismatchCount > 0 { + fmt.Fprintf(b, "Slot delivery misses since start: %d over, %d under, "+ + "%d in the wrong direction.\n\n", + st.OverDeliveryCount, st.UnderDeliveryCount, st.SignMismatchCount) + } +} + +func writePlanSection( + b *strings.Builder, + plan *mpc.Plan, + replanAt time.Time, + replanReason string, + now time.Time, +) { + b.WriteString("## Plan\n\n") + if plan == nil { + b.WriteString("No plan exists. The planner is off, or it has not " + + "produced one yet.\n\n") + return + } + fmt.Fprintf(b, "Strategy **%s** · %d slots · built %s", + plan.Mode, len(plan.Actions), + time.UnixMilli(plan.GeneratedAtMs).Format("15:04:05")) + if !replanAt.IsZero() { + fmt.Fprintf(b, " · last replan %s ago", fmtReportAge(now.Sub(replanAt))) + if replanReason != "" { + fmt.Fprintf(b, " (%s)", replanReason) + } + } + b.WriteString("\n\n") + + if sv := plan.Solver; sv != nil { + engine := sv.Engine + if sv.Backend != "" { + engine += " / " + sv.Backend + } + fmt.Fprintf(b, "Solver **%s** · %s", engine, sv.Status) + if sv.SolveMs > 0 { + fmt.Fprintf(b, " · %.0f ms", sv.SolveMs) + } + b.WriteString("\n\n") + if sv.Fallback { + fmt.Fprintf(b, "This plan came from the **built-in Go fallback**, "+ + "not the mathematical optimizer: %s\n\n", sv.FallbackReason) + } + } else { + b.WriteString("No solver information on this plan.\n\n") + } + + fmt.Fprintf(b, "Slots within %s of now. `→` marks the slot covering this "+ + "moment. Solar is negative because generation flows out of the site.\n\n", + fmtReportAge(reportPlanWindow)) + b.WriteString("| | Time | Price | Spot | Solar | Load | Battery | Grid | Charge end | Reason |\n") + b.WriteString("|---|---|---|---|---|---|---|---|---|---|\n") + from := now.Add(-reportPlanWindow).UnixMilli() + to := now.Add(reportPlanWindow).UnixMilli() + shown := 0 + for i := range plan.Actions { + a := &plan.Actions[i] + if a.SlotStartMs < from || a.SlotStartMs > to { + continue + } + marker := "" + if isActiveAction(a, now) { + marker = "→" + } + fmt.Fprintf(b, "| %s | %s | %.1f | %.1f | %s | %s | %s | %s | %.1f%% | %s |\n", + marker, + time.UnixMilli(a.SlotStartMs).Format("15:04"), + a.PriceOre, a.SpotOre, + fmtReportW(a.PVW), fmtReportW(a.LoadW), + fmtReportW(a.BatteryW), fmtReportW(a.GridW), + a.SoCPct, a.Reason) + shown++ + } + if shown == 0 { + b.WriteString("| | _no slots in this window_ | | | | | | | | |\n") + } + b.WriteString("\n") +} + +func writeForecastSection(b *strings.Builder, s *Server, snap liveSnapshot, activeSlot *mpc.Action, now time.Time) { + b.WriteString("## Forecast quality\n\n") + b.WriteString("The planner decides against forecasts, not live readings. " + + "When a forecast is wrong the plan is wrong, however well the " + + "optimizer solves it.\n\n") + + b.WriteString("| Quantity | Forecast | Actual now |\n|---|---|---|\n") + fmt.Fprintf(b, "| House load | %s | %s |\n", + fmtReportW(snap.PredictedLd), fmtReportW(snap.LoadW)) + fmt.Fprintf(b, "| Solar | %s | %s |\n", + fmtReportW(snap.PredictedPV), fmtReportW(snap.PVW)) + if activeSlot != nil { + fmt.Fprintf(b, "| Load the active slot assumed | %s | %s |\n", + fmtReportW(activeSlot.LoadW), fmtReportW(snap.LoadW)) + fmt.Fprintf(b, "| Solar the active slot assumed | %s | %s |\n", + fmtReportW(activeSlot.PVW), fmtReportW(snap.PVW)) + } + b.WriteString("\n") + + if s.deps.LoadModel != nil { + m := s.deps.LoadModel.Model() + stats := loadModelStatsFrom(m) + fmt.Fprintf(b, "Load model: %d samples · average error %s · quality %.2f · "+ + "%d of %d weekly buckets trained · heating %.0f W/°C · profile %s\n\n", + stats.Samples, fmtReportW(stats.MAEW), stats.Quality, + stats.BucketsWarm, stats.BucketsTotal, stats.HeatingWPerDegC, + s.deps.LoadModel.Profile()) + b.WriteString("The load model learns from `grid − solar − battery − EV`. " + + "It discards any sample where that arithmetic comes out negative, " + + "so on a site with large solar the surviving daytime samples skew " + + "low. A model that reports a small average error while the table " + + "above shows a large gap has learned the wrong house.\n\n") + } else { + b.WriteString("Load model is not running: the planner is using a flat " + + "base load for every slot.\n\n") + } +} + +func writeDeviceSection(b *strings.Builder, health map[string]telemetry.DriverHealth, now time.Time) { + b.WriteString("## Devices\n\n") + if len(health) == 0 { + b.WriteString("No drivers are registered.\n\n") + return + } + names := make([]string, 0, len(health)) + for n := range health { + names = append(names, n) + } + sort.Strings(names) + + b.WriteString("| Device | State | Last reading | Errors in a row | Last error |\n") + b.WriteString("|---|---|---|---|---|\n") + for _, n := range names { + h := health[n] + state := "ok" + if !h.IsOnline() { + state = "**offline**" + } + if h.DeviceFault { + state = "**device fault**" + if h.DeviceFaultReason != "" { + state += " (" + h.DeviceFaultReason + ")" + } + } + last := "never" + if h.LastSuccess != nil { + last = fmtReportAge(now.Sub(*h.LastSuccess)) + " ago" + } + lastErr := h.LastError + if lastErr == "" { + lastErr = "—" + } + fmt.Fprintf(b, "| %s | %s | %s | %d | %s |\n", + n, state, last, h.ConsecutiveErrors, truncateReport(lastErr, 90)) + } + b.WriteString("\n") +} + +func (s *Server) writeComponentSection(b *strings.Builder, ctx context.Context, plan *mpc.Plan) { + b.WriteString("## Versions\n\n") + fmt.Fprintf(b, "- Core **%s**\n", s.deps.Version) + if s.deps.MPC == nil || s.deps.MPC.Optimizer == nil { + b.WriteString("- Optimizer **not configured** — every plan comes from " + + "the built-in Go fallback\n") + } else if h, ok := s.deps.MPC.Optimizer.(optimizerHealth); ok { + hctx, cancel := context.WithTimeout(ctx, 2*time.Second) + info, err := h.Health(hctx) + cancel() + if err != nil { + fmt.Fprintf(b, "- Optimizer **unreachable**: %s\n", err.Error()) + } else { + fmt.Fprintf(b, "- Optimizer **%s** (protocol %d)\n", + info.Version, info.ProtocolVersion) + } + } + if plan != nil && plan.Solver != nil && plan.Solver.Fallback { + b.WriteString("- The active plan is running on the fallback, whatever " + + "the optimizer reports above\n") + } + b.WriteString("\n") +} + +func (s *Server) writeLogSection(b *strings.Builder) { + b.WriteString("## Recent warnings and errors\n\n") + if s.deps.LogRing == nil { + b.WriteString("Log buffer is not configured.\n\n") + return + } + entries := s.deps.LogRing.RecentGlobal(0) + kept := make([]telemetry.LogEntry, 0, reportLogLines) + for i := len(entries) - 1; i >= 0 && len(kept) < reportLogLines; i-- { + lvl := strings.ToUpper(entries[i].Level) + if lvl == "WARN" || lvl == "WARNING" || lvl == "ERROR" { + kept = append(kept, entries[i]) + } + } + if len(kept) == 0 { + b.WriteString("None in the buffer.\n\n") + return + } + b.WriteString("```\n") + // kept is newest-first from the scan above; print oldest-first so the + // tail reads like a log. + for i := len(kept) - 1; i >= 0; i-- { + e := kept[i] + fmt.Fprintf(b, "%s %s ", e.TS.Format("15:04:05"), e.Level) + if e.Driver != "" { + fmt.Fprintf(b, "[%s] ", e.Driver) + } + b.WriteString(e.Msg) + if e.Attrs != "" { + b.WriteByte(' ') + b.WriteString(truncateReport(e.Attrs, 200)) + } + b.WriteByte('\n') + } + b.WriteString("```\n\n") +} + +func writeReportFooter(b *strings.Builder) { + b.WriteString("---\n\n") + b.WriteString("Deeper data lives in `/api/support/dump` (logs, telemetry, " + + "redacted config) and `/api/mpc/diagnose` (every slot the optimizer " + + "saw). This report deliberately omits both to stay readable.\n") +} + +// ---- findings ---- + +func (s *Server) collectFindings( + ctrl control.State, + snap liveSnapshot, + plan *mpc.Plan, + activeSlot *mpc.Action, + targets []control.DispatchTarget, + health map[string]telemetry.DriverHealth, + now time.Time, +) []finding { + var out []finding + + if !snap.HaveGrid { + out = append(out, finding{sevProblem, "No site meter reading", + "Dispatch stops without a live site meter. Everything below is " + + "guesswork until the meter reports again."}) + } + + if ctrl.PlanStale { + out = append(out, finding{sevProblem, "The plan is stale", + "The planner has not produced a usable plan, so control fell back " + + "to safe live balancing. The plan shown in the app may no " + + "longer be the one being followed."}) + } + + if plan == nil && strings.HasPrefix(string(ctrl.Mode), "planner_") { + out = append(out, finding{sevProblem, "Planner mode with no plan", + "A planner strategy is selected but no plan exists."}) + } + + if plan != nil && plan.Solver != nil && plan.Solver.Fallback { + out = append(out, finding{sevProblem, "Running on the built-in fallback", + "The mathematical optimizer did not produce this plan: " + + plan.Solver.FallbackReason}) + } + + // The load-forecast check. This is the one that would have closed the + // 383 W thread in a single message. + if forecastMiss(snap.PredictedLd, snap.LoadW) { + out = append(out, finding{sevProblem, "The load forecast is far from reality", + fmt.Sprintf("The model predicts %s for right now; the house is "+ + "drawing %s. The planner sized this slot against the forecast, "+ + "so its charge and discharge decisions are built on the wrong "+ + "house. Resetting the load model (Settings, or POST "+ + "/api/loadmodel/reset) makes it relearn.", + fmtReportW(snap.PredictedLd), fmtReportW(snap.LoadW))}) + } else if activeSlot != nil && forecastMiss(activeSlot.LoadW, snap.LoadW) { + out = append(out, finding{sevProblem, "The active slot assumed a different house", + fmt.Sprintf("This slot was planned for a load of %s; actual load is "+ + "%s. Expect the live setpoint to diverge from the plan, and "+ + "expect frequent replans.", + fmtReportW(activeSlot.LoadW), fmtReportW(snap.LoadW))}) + } + + if activeSlot != nil && forecastMiss(math.Abs(activeSlot.PVW), math.Abs(snap.PVW)) { + out = append(out, finding{sevWarning, "The solar forecast is far from reality", + fmt.Sprintf("This slot was planned for %s of solar; actual is %s.", + fmtReportW(activeSlot.PVW), fmtReportW(snap.PVW))}) + } + + if activeSlot != nil { + if delta := math.Abs(activeSlot.BatteryW - snap.BatW); delta > 1000 { + out = append(out, finding{sevWarning, "The battery is not following the plan", + fmt.Sprintf("The slot intends %s, the battery is doing %s. "+ + "Either safety clamped it, the device cannot deliver, or "+ + "a replan changed the plan after this slot started.", + fmtReportW(activeSlot.BatteryW), fmtReportW(snap.BatW))}) + } + } + + var clamped []string + for _, t := range targets { + if t.Clamped { + clamped = append(clamped, t.Driver) + } + } + if len(clamped) > 0 { + out = append(out, finding{sevWarning, "Safety limits are active", + fmt.Sprintf("These devices are being held below the requested "+ + "power: %s. Safety limits always win over the plan.", + strings.Join(clamped, ", "))}) + } + + var offline, faulted []string + for name, h := range health { + if h.DeviceFault { + faulted = append(faulted, name) + continue + } + if !h.IsOnline() { + offline = append(offline, name) + } + } + sort.Strings(offline) + sort.Strings(faulted) + if len(faulted) > 0 { + out = append(out, finding{sevProblem, "A device reports a fault", + fmt.Sprintf("%s can be reached but cannot act. The planner excludes "+ + "it, and any power it was expected to move becomes grid flow "+ + "instead.", strings.Join(faulted, ", "))}) + } + if len(offline) > 0 { + out = append(out, finding{sevProblem, "Devices are offline", + fmt.Sprintf("%s. An offline device gets its safe default mode and "+ + "is left out of the plan.", strings.Join(offline, ", "))}) + } + + // A fresh install makes odd-looking decisions for a legitimate reason, + // and "quality 0.00" in the table below does not say so out loud. + if s.deps.LoadModel != nil { + stats := loadModelStatsFrom(s.deps.LoadModel.Model()) + if stats.BucketsWarm < loadmodelWarmBucketsForTrust { + out = append(out, finding{sevNote, "The load model is still learning", + fmt.Sprintf("Only %d of %d hourly patterns have enough samples "+ + "to trust. Until the week fills in, the planner is working "+ + "from a rough guess at this household's demand.", + stats.BucketsWarm, stats.BucketsTotal)}) + } + } + + if snap.HaveSoC { + if snap.SoCPct <= 12 { + out = append(out, finding{sevNote, "The battery is near empty", + fmt.Sprintf("Charge is %.0f%%. Near the floor the battery stops "+ + "discharging whatever the plan says.", snap.SoCPct)}) + } + if snap.SoCPct >= 97 { + out = append(out, finding{sevNote, "The battery is full", + fmt.Sprintf("Charge is %.0f%%. Surplus solar exports because "+ + "there is nowhere to put it.", snap.SoCPct)}) + } + } + + if !strings.HasPrefix(string(ctrl.Mode), "planner_") { + out = append(out, finding{sevNote, "No planning strategy is running", + fmt.Sprintf("Mode is %s. Price-aware scheduling only happens in a "+ + "planner strategy; in this mode the battery follows a simple "+ + "live rule.", ctrl.Mode)}) + } + + return out +} + +// forecastMiss reports whether a forecast is wrong enough to change decisions. +// The 500 W floor keeps small absolute errors on a quiet house from firing; +// the 60 % band is wide enough that ordinary forecast noise stays quiet. +func forecastMiss(predicted, actual float64) bool { + base := math.Max(math.Abs(actual), 500) + return math.Abs(predicted-actual)/base > 0.6 +} + +// ---- helpers ---- + +func activeAction(plan *mpc.Plan, now time.Time) *mpc.Action { + if plan == nil { + return nil + } + for i := range plan.Actions { + if isActiveAction(&plan.Actions[i], now) { + return &plan.Actions[i] + } + } + return nil +} + +func isActiveAction(a *mpc.Action, now time.Time) bool { + start := a.SlotStartMs + end := start + int64(a.SlotLenMin)*60_000 + ms := now.UnixMilli() + return ms >= start && ms < end +} + +func fmtReportW(v float64) string { + if math.Abs(v) >= 1000 { + return fmt.Sprintf("%.2f kW", v/1000) + } + return fmt.Sprintf("%.0f W", v) +} + +func fmtReportAge(d time.Duration) string { + switch { + case d < time.Minute: + return fmt.Sprintf("%.0f s", d.Seconds()) + case d < time.Hour: + return fmt.Sprintf("%.0f min", d.Minutes()) + default: + return fmt.Sprintf("%.1f h", d.Hours()) + } +} + +func truncateReport(s string, max int) string { + if len(s) <= max { + return s + } + return s[:max] + "…" +} diff --git a/go/internal/api/api_support_report_test.go b/go/internal/api/api_support_report_test.go new file mode 100644 index 00000000..a715e16e --- /dev/null +++ b/go/internal/api/api_support_report_test.go @@ -0,0 +1,262 @@ +package api + +import ( + "net/http" + "net/http/httptest" + "strings" + "sync" + "testing" + "time" + + "github.com/srcfl/ftw/go/internal/control" + "github.com/srcfl/ftw/go/internal/mpc" + "github.com/srcfl/ftw/go/internal/telemetry" +) + +func reportTestServer(t *testing.T) (*Server, *control.State, *telemetry.Store) { + t.Helper() + st := control.NewState(0, 50, "meter") + tel := telemetry.NewStore() + tel.DriverHealthMut("meter").RecordSuccess() + tel.Update("meter", telemetry.DerMeter, 500, nil, nil) + srv := New(&Deps{ + Ctrl: st, + CtrlMu: &sync.Mutex{}, + Tel: tel, + Version: "test-version", + }) + return srv, st, tel +} + +func TestSupportReportServesMarkdownAttachment(t *testing.T) { + srv, _, _ := reportTestServer(t) + req := httptest.NewRequest(http.MethodGet, "/api/support/report", nil) + rec := httptest.NewRecorder() + srv.Handler().ServeHTTP(rec, req) + + if rec.Code != http.StatusOK { + t.Fatalf("GET /api/support/report = %d, want 200", rec.Code) + } + if ct := rec.Header().Get("Content-Type"); !strings.HasPrefix(ct, "text/markdown") { + t.Errorf("Content-Type = %q, want text/markdown", ct) + } + cd := rec.Header().Get("Content-Disposition") + if !strings.Contains(cd, "attachment") || !strings.Contains(cd, "ftw-help-") { + t.Errorf("Content-Disposition = %q, want an ftw-help attachment", cd) + } + body := rec.Body.String() + for _, want := range []string{ + "# FTW help report", + "## Findings", + "## Right now", + "## Plan", + "## Forecast quality", + "## Devices", + "## Versions", + "test-version", + } { + if !strings.Contains(body, want) { + t.Errorf("report is missing %q", want) + } + } +} + +// The report must survive a host where every optional service is nil — +// that is exactly the state a confused user is most likely to be in. +func TestSupportReportWithNoDependencies(t *testing.T) { + srv := New(&Deps{Ctrl: control.NewState(0, 50, ""), CtrlMu: &sync.Mutex{}, Tel: telemetry.NewStore()}) + req := httptest.NewRequest(http.MethodGet, "/api/support/report", nil) + rec := httptest.NewRecorder() + srv.Handler().ServeHTTP(rec, req) + + if rec.Code != http.StatusOK { + t.Fatalf("GET /api/support/report = %d, want 200", rec.Code) + } + body := rec.Body.String() + if !strings.Contains(body, "No plan exists") { + t.Error("expected the report to say no plan exists") + } + if !strings.Contains(body, "No site meter reading") { + t.Error("expected a finding about the missing site meter") + } +} + +// The load-forecast check is the reason this report exists: a plan built +// against 383 W while the house draws 7.9 kW must be called out in +// Findings, not left for someone to spot in a table. +func TestSupportReportFlagsLoadForecastMiss(t *testing.T) { + srv, ctrl, _ := reportTestServer(t) + now := time.Now() + snap := liveSnapshot{ + HaveGrid: true, + LoadW: 7900, + PredictedLd: 383, + } + findings := srv.collectFindings(*ctrl, snap, nil, nil, nil, nil, now) + + var got *finding + for i := range findings { + if strings.Contains(findings[i].Title, "load forecast") { + got = &findings[i] + break + } + } + if got == nil { + t.Fatalf("no load-forecast finding; got %+v", findings) + } + if got.Severity != sevProblem { + t.Errorf("severity = %q, want %q", got.Severity, sevProblem) + } + if !strings.Contains(got.Detail, "383 W") || !strings.Contains(got.Detail, "7.90 kW") { + t.Errorf("detail should quote both numbers, got %q", got.Detail) + } +} + +func TestForecastMiss(t *testing.T) { + cases := []struct { + name string + predicted, actual float64 + want bool + }{ + {"the 383 W case", 383, 7900, true}, + {"close enough", 2000, 2200, false}, + {"exact", 1000, 1000, false}, + // A quiet house: 200 W of absolute error must not fire just + // because the ratio looks bad against a small denominator. + {"small absolute error on a quiet house", 100, 300, false}, + {"forecast far too high", 8000, 400, true}, + } + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + if got := forecastMiss(tc.predicted, tc.actual); got != tc.want { + t.Errorf("forecastMiss(%v, %v) = %v, want %v", + tc.predicted, tc.actual, got, tc.want) + } + }) + } +} + +// "Now" must be answered before "next". The dashboard's plan card leads +// with the next action, and that ambiguity is what made a support thread +// run for six hours. +func TestSupportReportMarksTheActiveSlot(t *testing.T) { + _, ctrl, _ := reportTestServer(t) + now := time.Now() + slotStart := now.Add(-5 * time.Minute).UnixMilli() + plan := &mpc.Plan{ + GeneratedAtMs: now.Add(-time.Minute).UnixMilli(), + Mode: mpc.ModeArbitrage, + Actions: []mpc.Action{ + {SlotStartMs: slotStart, SlotLenMin: 15, BatteryW: -8400, Reason: "discharge — export at peak"}, + {SlotStartMs: slotStart + 15*60_000, SlotLenMin: 15, BatteryW: 2900, Reason: "absorb PV surplus"}, + }, + Solver: &mpc.SolverInfo{Engine: "highspy", Backend: "highs", Status: "optimal"}, + } + + var b strings.Builder + writePlanSection(&b, plan, now.Add(-time.Minute), "reactive-load", now) + out := b.String() + + lines := strings.Split(out, "\n") + var marked string + for _, ln := range lines { + if strings.HasPrefix(ln, "| → |") { + marked = ln + } + } + if marked == "" { + t.Fatalf("no slot marked as active:\n%s", out) + } + if !strings.Contains(marked, "export at peak") { + t.Errorf("the wrong slot is marked active: %q", marked) + } + if !strings.Contains(out, "highspy / highs") { + t.Error("solver identity should be in the plan section") + } + if !strings.Contains(out, "reactive-load") { + t.Error("the replan reason should be in the plan section") + } + + // And the live section should state the active slot's intent in prose. + var live strings.Builder + writeRightNow(&live, *ctrl, liveSnapshot{HaveGrid: true, BatW: -7500}, &plan.Actions[0], nil, now) + if !strings.Contains(live.String(), "-8.40 kW") { + t.Errorf("active-slot intent missing from Right now:\n%s", live.String()) + } +} + +func TestSupportReportFlagsFallbackSolver(t *testing.T) { + srv, ctrl, _ := reportTestServer(t) + plan := &mpc.Plan{ + Solver: &mpc.SolverInfo{ + Engine: "go-dp", + Backend: "bellman", + Fallback: true, + FallbackReason: "optimizer handshake failed", + }, + } + findings := srv.collectFindings(*ctrl, + liveSnapshot{HaveGrid: true, LoadW: 1000, PredictedLd: 1000}, + plan, nil, nil, nil, time.Now()) + + found := false + for _, f := range findings { + if strings.Contains(f.Title, "fallback") { + found = true + if !strings.Contains(f.Detail, "optimizer handshake failed") { + t.Errorf("detail should carry the reason, got %q", f.Detail) + } + } + } + if !found { + t.Errorf("no fallback finding; got %+v", findings) + } +} + +func TestSupportReportFlagsOfflineAndFaultedDevices(t *testing.T) { + srv, ctrl, _ := reportTestServer(t) + health := map[string]telemetry.DriverHealth{ + "healthy": {Name: "healthy", LastSuccess: ptrTime(time.Now())}, + "gone": {Name: "gone", Status: telemetry.StatusOffline}, + "faulting": {Name: "faulting", DeviceFault: true, DeviceFaultReason: "Fault mode"}, + } + findings := srv.collectFindings(*ctrl, + liveSnapshot{HaveGrid: true, LoadW: 1000, PredictedLd: 1000}, + nil, nil, nil, health, time.Now()) + + var sawOffline, sawFault bool + for _, f := range findings { + if strings.Contains(f.Detail, "gone") { + sawOffline = true + } + if strings.Contains(f.Detail, "faulting") { + sawFault = true + } + } + if !sawOffline { + t.Error("offline driver not reported") + } + if !sawFault { + t.Error("faulted driver not reported") + } +} + +// Findings are sorted worst-first so a reader hits the real problem before +// the notes. +func TestFindingsAreSortedBySeverity(t *testing.T) { + var b strings.Builder + writeFindings(&b, []finding{ + {sevNote, "a note", "detail"}, + {sevProblem, "a problem", "detail"}, + {sevWarning, "a warning", "detail"}, + }) + out := b.String() + pi := strings.Index(out, "a problem") + wi := strings.Index(out, "a warning") + ni := strings.Index(out, "a note") + if !(pi < wi && wi < ni) { + t.Errorf("findings out of order:\n%s", out) + } +} + +func ptrTime(t time.Time) *time.Time { return &t } diff --git a/web/app.css b/web/app.css index ae320807..b630bb9a 100644 --- a/web/app.css +++ b/web/app.css @@ -1442,6 +1442,30 @@ body.ftw-app .plan-help { } body.ftw-app .plan-actions { gap: 10px; display: flex; align-items: center; } +/* The "why is it doing that?" escape hatch, below the chart because + that's where the question forms. Understated: it should be findable + when something looks wrong, not compete with the plan itself. */ +body.ftw-app .plan-help-request { + margin: 10px 0 2px; + padding-top: 10px; + border-top: 1px solid var(--border); +} +body.ftw-app .plan-help-request button { padding-left: 0; } +body.ftw-app .plan-help-request button[disabled] { + opacity: 0.6; + cursor: default; + text-decoration: none; +} +body.ftw-app .plan-help-request small { + display: block; + font-family: var(--sans); + font-size: 11px; + line-height: 1.5; + color: var(--fg-muted); + margin-top: 2px; + max-width: 68ch; +} + body.ftw-app .more-actions { display: grid; grid-template-columns: repeat(3, minmax(0, 1fr)); diff --git a/web/diagnostics-modal.js b/web/diagnostics-modal.js index e14b16f1..ee106f7d 100644 --- a/web/diagnostics-modal.js +++ b/web/diagnostics-modal.js @@ -468,6 +468,7 @@ html += ''; html += '

Local exports

' + + '' + '' + '' + '
'; @@ -484,6 +485,17 @@ state.bodyEl.innerHTML = html; + // The report is the one to reach for first: it explains what the + // system is doing and why, in a single file someone else can read. + // The log bundle below it is for when that isn't enough. + state.bodyEl.querySelector('[data-role="report"]').addEventListener("click", function () { + downloadWithFeedback( + "/api/support/report", + "Building help report", + "Collecting live state, the active plan slot, forecast accuracy and driver health.", + "ftw-help.md" + ); + }); state.bodyEl.querySelector('[data-role="dump"]').addEventListener("click", function () { downloadWithFeedback( "/api/support/dump", diff --git a/web/help-report.test.mjs b/web/help-report.test.mjs new file mode 100644 index 00000000..7a2402bd --- /dev/null +++ b/web/help-report.test.mjs @@ -0,0 +1,31 @@ +import assert from "node:assert/strict"; +import { readFileSync } from "node:fs"; +import test from "node:test"; + +const plan = readFileSync(new URL("./plan.js", import.meta.url), "utf8"); +const index = readFileSync(new URL("./index.html", import.meta.url), "utf8"); +const diagnostics = readFileSync(new URL("./diagnostics-modal.js", import.meta.url), "utf8"); + +test("the plan card offers a help report", () => { + assert.match(index, /id="plan-help-report"/); + // The label has to name the problem the user has, not the artefact we + // produce — someone whose battery is misbehaving does not search for + // "diagnostics". + assert.match(index, /Something looks wrong\?/); +}); + +test("the help-report button downloads from the report endpoint", () => { + assert.match(plan, /getElementById\('plan-help-report'\)/); + assert.match(plan, /apiFetch\('\/api\/support\/report'\)/); + assert.match(plan, /a\.download = 'ftw-help-'/); +}); + +test("the help-report button reports failure instead of failing silently", () => { + assert.match(plan, /restore\('Failed: '/); + assert.match(plan, /btn\.disabled = true/); +}); + +test("the driver diagnose modal also links the report", () => { + assert.match(diagnostics, /data-role="report"/); + assert.match(diagnostics, /"\/api\/support\/report"/); +}); diff --git a/web/index.html b/web/index.html index fdc42703..b671183b 100644 --- a/web/index.html +++ b/web/index.html @@ -569,6 +569,16 @@

Plan

Discharge SoC + +
+ + One file describing what FTW is doing and why. Share it when asking for help. +
diff --git a/web/plan.js b/web/plan.js index 4f2e8807..53588b95 100644 --- a/web/plan.js +++ b/web/plan.js @@ -1015,6 +1015,45 @@ import { derivePlanBrief } from "./plan-brief.js"; else helpModal.setAttribute('open', ''); }); } + const reportBtn = document.getElementById('plan-help-report'); + if (reportBtn) reportBtn.addEventListener('click', downloadHelpReport); + } + + // Pulls GET /api/support/report and saves it. Kept here rather than in + // the driver Diagnose modal because the question it answers ("why is it + // doing that?") is asked while looking at the plan, not at a device. + function downloadHelpReport() { + const btn = document.getElementById('plan-help-report'); + if (!btn || btn.disabled) return; + const original = btn.textContent; + btn.disabled = true; + btn.textContent = 'Building report…'; + const restore = function (text) { + btn.textContent = text; + setTimeout(function () { + btn.disabled = false; + btn.textContent = original; + }, 4000); + }; + apiFetch('/api/support/report') + .then(function (resp) { + if (!resp.ok) throw new Error('HTTP ' + resp.status); + return resp.blob().then(function (blob) { + const stamp = new Date().toISOString().slice(0, 16).replace(/[-:T]/g, ''); + const url = URL.createObjectURL(blob); + const a = document.createElement('a'); + a.href = url; + a.download = 'ftw-help-' + stamp + '.md'; + document.body.appendChild(a); + a.click(); + a.remove(); + setTimeout(function () { URL.revokeObjectURL(url); }, 30000); + restore('Downloaded'); + }); + }) + .catch(function (err) { + restore('Failed: ' + (err && err.message ? err.message : String(err))); + }); } if (document.readyState === 'loading') { From aa50bff146bc9d62843997b04e527cc55bc414c7 Mon Sep 17 00:00:00 2001 From: Fredrik Ahlgren Date: Fri, 31 Jul 2026 13:40:57 +0200 Subject: [PATCH 2/2] fix(api): collapse repeats in the help report's log tail The first report generated against a live stack came back with 49 of its 120 log lines carrying one warning, repeated every control tick. A single unique ERROR would have been pushed clean out of the window by that noise, and Findings said nothing about the repetition at all. Three fixes, all from that one report: - Group warnings and errors on (level, driver, message), ignoring the per-tick attribute tail, and show a count. The cap is now 40 distinct messages rather than 120 lines, so a chatty loop cannot crowd out a one-off failure. - A message repeating 10+ times becomes a finding in its own right, reported generically by count so it does not rot when someone rewords a log line. ERROR-level repetition is a problem, WARN a warning. - Say what the dispatch table's clamp column covers. It reports per-device limits only; the site-meter clamp caps the fleet total upstream and cannot appear there, so "no" on every row was reading as "nothing was limited" while the log showed the total clamped from 9.0 to 6.4 kW. Verified against the dev stack: the log section went from 49 lines to 3 grouped entries, and the clamp now leads Findings instead of being something to scroll past. Co-Authored-By: Claude Opus 5 --- go/internal/api/api_support_report.go | 139 +++++++++++++++++---- go/internal/api/api_support_report_test.go | 119 ++++++++++++++++++ 2 files changed, 234 insertions(+), 24 deletions(-) diff --git a/go/internal/api/api_support_report.go b/go/internal/api/api_support_report.go index 8dcbdef4..733a306e 100644 --- a/go/internal/api/api_support_report.go +++ b/go/internal/api/api_support_report.go @@ -44,8 +44,14 @@ import ( // pushing a 48 h horizon into the file. const reportPlanWindow = 3 * time.Hour -// reportLogLines caps the warning/error tail. Enough for one incident. -const reportLogLines = 120 +// reportLogGroups caps the log tail, counted in DISTINCT messages rather +// than lines. Repeats collapse into one entry with a count, so a loop +// warning every tick can no longer crowd out a one-off error. +const reportLogGroups = 40 + +// logRepeatThreshold is the repeat count at which a warning stops being +// noise in the log and becomes a finding in its own right. +const logRepeatThreshold = 10 // loadmodelWarmBucketsForTrust is the point past which the weekly load // pattern is filled in enough that its predictions carry the plan. Below @@ -273,7 +279,7 @@ func writeRightNow( if len(targets) > 0 { b.WriteString("Commands sent to each device on the last control tick:\n\n") - b.WriteString("| Device | Target | Limited by safety |\n|---|---|---|\n") + b.WriteString("| Device | Target | Held below request |\n|---|---|---|\n") for _, t := range targets { clamped := "no" if t.Clamped { @@ -281,7 +287,15 @@ func writeRightNow( } fmt.Fprintf(b, "| %s | %s | %s |\n", t.Driver, fmtReportW(t.TargetW), clamped) } - b.WriteString("\n") + // This column covers per-device limits only — state of charge, + // rated power, the fuse guard. The site-meter clamp that caps the + // fleet total before this split happens upstream of these targets + // and cannot show up here, so "no" on every row is not the same as + // "nothing was limited". Say so rather than let the table imply it. + b.WriteString("\nThis column covers per-device limits: charge level, " + + "rated power, fuse guard. A limit applied to the site total " + + "before it was split across devices does not appear here — check " + + "the log for clamp messages.\n\n") } st := ctrl.SlotDeliveryStats @@ -468,37 +482,86 @@ func (s *Server) writeComponentSection(b *strings.Builder, ctx context.Context, b.WriteString("\n") } +// logGroup collapses repeats of the same message. A control loop that +// warns every tick produced 49 identical lines in the first real report, +// which would have pushed a single unique ERROR clean out of the window. +// Grouping on (level, driver, message) — not on the attribute tail, which +// carries per-tick numbers — keeps one line per distinct problem. +type logGroup struct { + Level string + Driver string + Msg string + Attrs string // from the most recent occurrence + Count int + First time.Time + Last time.Time +} + +// groupLogs returns distinct warnings and errors, most-recent last. +func groupLogs(entries []telemetry.LogEntry) []logGroup { + type key struct{ level, driver, msg string } + index := map[key]int{} + var groups []logGroup + for _, e := range entries { + lvl := strings.ToUpper(e.Level) + if lvl != "WARN" && lvl != "WARNING" && lvl != "ERROR" { + continue + } + k := key{lvl, e.Driver, e.Msg} + if i, ok := index[k]; ok { + groups[i].Count++ + groups[i].Attrs = e.Attrs + if e.TS.After(groups[i].Last) { + groups[i].Last = e.TS + } + continue + } + index[k] = len(groups) + groups = append(groups, logGroup{ + Level: lvl, Driver: e.Driver, Msg: e.Msg, Attrs: e.Attrs, + Count: 1, First: e.TS, Last: e.TS, + }) + } + sort.SliceStable(groups, func(i, j int) bool { + return groups[i].Last.Before(groups[j].Last) + }) + return groups +} + func (s *Server) writeLogSection(b *strings.Builder) { b.WriteString("## Recent warnings and errors\n\n") if s.deps.LogRing == nil { b.WriteString("Log buffer is not configured.\n\n") return } - entries := s.deps.LogRing.RecentGlobal(0) - kept := make([]telemetry.LogEntry, 0, reportLogLines) - for i := len(entries) - 1; i >= 0 && len(kept) < reportLogLines; i-- { - lvl := strings.ToUpper(entries[i].Level) - if lvl == "WARN" || lvl == "WARNING" || lvl == "ERROR" { - kept = append(kept, entries[i]) - } - } - if len(kept) == 0 { + groups := groupLogs(s.deps.LogRing.RecentGlobal(0)) + if len(groups) == 0 { b.WriteString("None in the buffer.\n\n") return } + b.WriteString("Repeats are collapsed; `×N` is how many times the same " + + "message appeared. The attribute tail comes from the most recent one.\n\n") + if len(groups) > reportLogGroups { + fmt.Fprintf(b, "Showing the %d most recent of %d distinct messages.\n\n", + reportLogGroups, len(groups)) + groups = groups[len(groups)-reportLogGroups:] + } b.WriteString("```\n") - // kept is newest-first from the scan above; print oldest-first so the - // tail reads like a log. - for i := len(kept) - 1; i >= 0; i-- { - e := kept[i] - fmt.Fprintf(b, "%s %s ", e.TS.Format("15:04:05"), e.Level) - if e.Driver != "" { - fmt.Fprintf(b, "[%s] ", e.Driver) - } - b.WriteString(e.Msg) - if e.Attrs != "" { + for _, g := range groups { + fmt.Fprintf(b, "%s %s ", g.Last.Format("15:04:05"), g.Level) + if g.Driver != "" { + fmt.Fprintf(b, "[%s] ", g.Driver) + } + b.WriteString(g.Msg) + if g.Count > 1 { + fmt.Fprintf(b, " ×%d", g.Count) + if span := g.Last.Sub(g.First); span > time.Second { + fmt.Fprintf(b, " over %s", fmtReportAge(span)) + } + } + if g.Attrs != "" { b.WriteByte(' ') - b.WriteString(truncateReport(e.Attrs, 200)) + b.WriteString(truncateReport(g.Attrs, 200)) } b.WriteByte('\n') } @@ -596,6 +659,34 @@ func (s *Server) collectFindings( strings.Join(clamped, ", "))}) } + // A message repeating every control tick is the loudest signal in the + // log and the easiest to scroll past. The first real report carried 49 + // copies of one clamp warning while Findings said nothing at all. + // Reported generically, by count, so this does not rot the moment + // someone rewords a log line. + if s.deps.LogRing != nil { + var worst logGroup + for _, g := range groupLogs(s.deps.LogRing.RecentGlobal(0)) { + if g.Count > worst.Count { + worst = g + } + } + if worst.Count >= logRepeatThreshold { + sev := sevWarning + if worst.Level == "ERROR" { + sev = sevProblem + } + detail := fmt.Sprintf("%q has been logged %d times", + worst.Msg, worst.Count) + if span := worst.Last.Sub(worst.First); span > time.Second { + detail += " in " + fmtReportAge(span) + } + detail += ". Something is retrying or being limited on every " + + "control cycle; the full line is in the log section below." + out = append(out, finding{sev, "A message is repeating", detail}) + } + } + var offline, faulted []string for name, h := range health { if h.DeviceFault { diff --git a/go/internal/api/api_support_report_test.go b/go/internal/api/api_support_report_test.go index a715e16e..04d5e626 100644 --- a/go/internal/api/api_support_report_test.go +++ b/go/internal/api/api_support_report_test.go @@ -1,6 +1,7 @@ package api import ( + "fmt" "net/http" "net/http/httptest" "strings" @@ -259,4 +260,122 @@ func TestFindingsAreSortedBySeverity(t *testing.T) { } } +// A control loop warning every tick produced 49 identical lines in the +// first real report. Grouping is what keeps a single unique error from +// being pushed out of the window by that noise. +func TestLogGroupsCollapseRepeats(t *testing.T) { + base := time.Now().Add(-2 * time.Minute) + var entries []telemetry.LogEntry + for i := 0; i < 49; i++ { + entries = append(entries, telemetry.LogEntry{ + TS: base.Add(time.Duration(i) * 2 * time.Second), + Level: "WARN", + Msg: "dispatch: meter clamp reduced battery target", + // The attribute tail differs every tick; grouping must ignore it. + Attrs: fmt.Sprintf("requested_total_w=%d", 9000+i), + }) + } + entries = append(entries, telemetry.LogEntry{ + TS: base.Add(100 * time.Second), Level: "ERROR", + Msg: "the one that matters", Driver: "ferroamp", + }) + + groups := groupLogs(entries) + if len(groups) != 2 { + t.Fatalf("got %d groups, want 2: %+v", len(groups), groups) + } + var clamp, unique *logGroup + for i := range groups { + if groups[i].Level == "ERROR" { + unique = &groups[i] + } else { + clamp = &groups[i] + } + } + if clamp == nil || clamp.Count != 49 { + t.Fatalf("clamp group = %+v, want count 49", clamp) + } + if clamp.Attrs != "requested_total_w=9048" { + t.Errorf("attrs should come from the newest occurrence, got %q", clamp.Attrs) + } + if unique == nil { + t.Fatal("the unique error was dropped") + } +} + +func TestLogSectionSurvivesNoisyNeighbour(t *testing.T) { + // Far more distinct messages than the cap, plus one loud repeater. + var entries []telemetry.LogEntry + base := time.Now().Add(-time.Hour) + for i := 0; i < reportLogGroups+20; i++ { + entries = append(entries, telemetry.LogEntry{ + TS: base.Add(time.Duration(i) * time.Minute), Level: "WARN", + Msg: fmt.Sprintf("distinct message %d", i), + }) + } + groups := groupLogs(entries) + if len(groups) != reportLogGroups+20 { + t.Fatalf("got %d groups, want %d", len(groups), reportLogGroups+20) + } + // Newest last, so trimming to the cap keeps the most recent. + if !groups[len(groups)-1].Last.After(groups[0].Last) { + t.Error("groups should be ordered oldest-first") + } +} + +// 49 clamp warnings with a Findings section reading only "no planning +// strategy is running" is the failure this guards. +func TestRepeatedWarningBecomesAFinding(t *testing.T) { + st := control.NewState(0, 50, "meter") + tel := telemetry.NewStore() + tel.DriverHealthMut("meter").RecordSuccess() + ring := telemetry.NewLogRing() + for i := 0; i < 20; i++ { + ring.Append(telemetry.LogEntry{ + TS: time.Now(), Level: "WARN", + Msg: "dispatch: meter clamp reduced battery target", + }) + } + srv := New(&Deps{Ctrl: st, CtrlMu: &sync.Mutex{}, Tel: tel, LogRing: ring}) + + findings := srv.collectFindings(*st, + liveSnapshot{HaveGrid: true, LoadW: 1000, PredictedLd: 1000}, + nil, nil, nil, nil, time.Now()) + + var got *finding + for i := range findings { + if strings.Contains(findings[i].Title, "repeating") { + got = &findings[i] + } + } + if got == nil { + t.Fatalf("a warning repeated 20 times produced no finding: %+v", findings) + } + if !strings.Contains(got.Detail, "20 times") { + t.Errorf("detail should carry the count, got %q", got.Detail) + } + if !strings.Contains(got.Detail, "meter clamp") { + t.Errorf("detail should name the message, got %q", got.Detail) + } +} + +// "Held below request: no" on every row must not read as "nothing limited +// anything" — the site-meter clamp caps the fleet total upstream of these +// per-device numbers and cannot appear in the column. +func TestDispatchTableDisclaimsSiteLevelClamps(t *testing.T) { + st := control.NewState(0, 50, "meter") + var b strings.Builder + writeRightNow(&b, *st, liveSnapshot{HaveGrid: true}, + nil, + []control.DispatchTarget{{Driver: "ferroamp", TargetW: 6400, Clamped: false}}, + time.Now()) + out := b.String() + if !strings.Contains(out, "per-device limits") { + t.Errorf("dispatch table lacks its scope caveat:\n%s", out) + } + if !strings.Contains(out, "site total") { + t.Errorf("dispatch table should point at site-level clamps:\n%s", out) + } +} + func ptrTime(t time.Time) *time.Time { return &t }