feat(debug): rolling debug-history snapshot buffer with automation hooks - #4438
feat(debug): rolling debug-history snapshot buffer with automation hooks#4438chalfontchubby wants to merge 14 commits into
Conversation
…oks (#4417) Predbat's create_debug_yaml() (what bug reporters attach for a --redo replay) only ever wrote when switch.predbat_debug_enable was already on, on every ~5-minute cycle with no pruning at all - unbounded disk growth if left on, and no history to look back at for anyone who didn't already have it on before something went wrong. Adds a rolling buffer instead, mirroring the existing annual_store.py ring-buffer pattern and the Storage component's save/expiry/cleanup: - debug_history.py: capture/list/load/prune snapshots, keyed by timestamp, independent of debug_enable. - Three new config items: debug_history_count (default 15, 0 = off), debug_history_interval (default 3h; 15x3h matches the History tab's worst-case "yesterday + today so far" coverage), and debug_history_force_capture - a self-resetting switch so an automation that notices something worth investigating can trigger an immediate, precisely-timed capture rather than waiting on the routine interval, and fetch it via ?id=latest without a separate lookup round-trip. - predbat.py: _capture_debug_history(), throttled in-memory, wired alongside the existing debug_enable capture call. - web.py: /debug_history_list and /debug_history_download routes, reusing the existing html_file() attachment-serving helper, plus a dropdown on the dashboard Debug panel. - web_helper.py: a Debug column on the plan's History/Yesterday view (only there - its rows are the ones with a real past timestamp to match against), fetched and matched client-side by wall-clock time rather than threaded through publish_html_plan(), which is shared by three other call sites with no relationship to a captured snapshot's timing. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
Adds a "Debug history" subsection to customisation.md covering the three new config items, documents the dashboard's new History dropdown in web-interface.md, and adds the plan History view's new Debug column to predbat-plan-card.md's column reference alongside the other conditionally-shown columns. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
… loading Rebuilding the <select>'s options via appendChild doesn't reliably repaint the closed box's displayed label - confirmed live, it kept showing the "Click to load..." placeholder text until the dropdown was manually opened once, even though the options had already populated correctly underneath. Explicitly setting selectedIndex = 0 after populating forces a real value-change the browser has to redraw for. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
…ot symmetric A snapshot captures Predbat's full live state (including its current plan) at one moment - it can describe a row shortly at or after that moment, but tells you nothing reliable about a row well after it, since Predbat replans every cycle and the plan may have moved on by then. The previous +/-90 minute symmetric window treated a snapshot 25 minutes before a row the same as one 35 minutes after it, so two rows 30 minutes apart could both point at the same earlier snapshot as if it still described the later one - confirmed live, dogfooding this against a real instance. Replaces it with a small forward grace (30 min, covers a snapshot landing a little into a row's own slot) plus a much larger backward window (3.5h, comfortably covers the default 3-hourly interval), picking the closest snapshot that satisfies that asymmetric bound rather than the closest by absolute distance in either direction. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
…steps-back labels Two related UX problems in the plan History view's Debug column (#4417): 1. Snapshots were captured with a raw self.now_utc timestamp - whatever moment the ~5-minute cycle happened to trigger the capture, not aligned to the plan's own 30-minute (plan_interval_minutes) grid. The row-to- snapshot matching in web_helper.py therefore needed a fuzzy nearest-within-a-window search, which let several adjacent rows all claim the same snapshot - not the one row it most neatly corresponds to. 2. The dropdown and the plan column link both labelled a snapshot by how many captures back it was ("3 steps back") rather than its actual time. Fixed both together: _capture_debug_history() now floors the capture timestamp to self.midnight_utc + N * plan_interval_minutes - the exact same anchor and step output.py uses to build every plan row's own row.time. A snapshot's timestamp is then either an exact match for one row or it isn't a match at all, which also gives each snapshot at most one owning row for free (two rows plan_interval_minutes apart can never both equal the same floored capture instant). findNearestDebugSnapshot() simplified from an asymmetric forward-grace/backward-window search down to a direct timestamp comparison (1s tolerance, only for formatting noise). The throttle-tracking timestamp (debug_history_last_capture) deliberately still uses the real capture moment, not the floored one, so routine-interval spacing tracks actual elapsed time regardless of how the snapshot itself gets labelled. Both the dashboard dropdown and the plan column link now show the snapshot's absolute time instead of "N steps back" - the dropdown already had the absolute time alongside the steps-back suffix, so that part is just dropping the suffix; the plan column link switches from "N back" to a short local time. debug_history.py's annotate_steps_back()/steps_back field is untouched - still useful for API consumers, just no longer the primary UI label. Added a dedicated regression test for the slot-flooring behaviour (debug_history_capture_alignment) and fixed an existing test (test 6b in debug_history_capture) that advanced now_utc by only 1 minute between two forced captures - previously enough for a distinct snapshot id, now floors back to the same slot and would collide. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
…nload Chasing a user through the per-snapshot picker to find the right moment is exactly the back-and-forth this buffer was meant to avoid. One link now downloads every retained snapshot as a gzip tarball; the plan page's own History/Yesterday view (a separate consumer of the same snapshot index) is untouched. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
…position steps_back is the snapshot's current position in the retention ring, not a property of the snapshot itself - it shifts as newer captures push it back. Baking it into the filename meant the same real capture got a different name in every archive downloaded after it, making archives from different times impossible to merge/deduplicate by filename. snapshot_id (its capture timestamp) is already unique and stable; that's all the filename needs. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
30b85ff to
5625a57
Compare
…tention window Two captures landing in the same calendar minute (a routine capture and a close-by force-capture) used to both stay in the ring, reaching the UI as two identically-named chart series and breaking "Deselect all", which keys off series name. capture_snapshot() now discards the older of any same-minute pair, keeping the newer. Also add an optional max_age prune so a burst of close-together captures can't leave something far older than the buffer's intended window sitting there just because the count cap alone hasn't caught up to it - wired through from predbat.py as interval_hours * count. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
ReviewNice feature — went through the diff in detail. A few correctness issues worth fixing before merge, plus some lower-priority cleanup. Correctness bugs
Docs no longer match shipped behavior
Efficiency
Reuse / duplication
Simplification
Test coveragePer this repo's usual bar, a couple of gaps:
Minor
Most worth fixing before merge: #1–#4 and #6 (correctness/security), #8–#9 (docs actively mislead users right now), and #21–#22 (test coverage). The rest is good-to-have cleanup, happy to see it split into a follow-up if you'd rather keep this PR focused. |
Suggestion: split
|
…ded raw disk writes Per @springfall2008's review on #4438: "debug_enable still causes unbounded disk growth - the original problem isn't actually fixed yet." The rolling debug-history buffer (#4417) shipped alongside the original raw create_debug_yaml() disk write, not in place of it, so leaving the switch on still wrote an uncapped predbat_debug_HH_MM_SS.yaml every ~5-minute cycle. Rather than remove the raw write outright: debug_enable also gates verbose logging and the C++ kernel bypass (the more accurate but far slower prediction path, see #4453's investigation), both genuinely useful for watching a live issue develop cycle to cycle - finer-grained than the history buffer's coarsest 1-hour interval floor (debug_history_interval's min is 1, unit is hours). Removing the write entirely would be a real capability loss for exactly the kind of live debugging this session has been doing. Instead, track when debug_enable was turned on (debug_enable_started) and auto-disable it (expose_config, so it's visible in HA too) after DEBUG_ENABLE_MAX_HOURS (2h). Bounds both the disk growth and the standing performance cost of leaving the slow path on by accident, while preserving full-resolution capture for someone actively watching a problem. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
…imum raised to 1 Per @springfall2008's review on #4438: "give the rotating buffer its own on/off switch, rather than overloading debug_history_count == 0" - inconsistent with how the codebase normally does on/off (debug_enable and debug_history_force_capture are both real switch CONFIG_ITEMS already). Defaults on, preserving existing behaviour for anyone already relying on debug_history_count=15 as "on". debug_history_force_capture still fires regardless of this switch, matching the existing "explicit capture now request is a different intent to the rolling background history" design. Also raises debug_history_count's config-schema minimum from 0 to 1 - with a dedicated switch, count=0 no longer needs to double as an off-switch, so removing it as a valid value avoids "switch is on but count is 0" becoming a second, silently-conflicting way to end up disabled. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
…on genuine success Per @springfall2008's review on #4438 (items 1-3): 1. debug_history_last_capture was reset unconditionally after the try/except, so a failed capture (an exception, caught and logged as a Warning) was silently treated as if it had succeeded - deferring the next routine retry a full debug_history_interval instead of leaving it to retry at the normal cadence. 2. The storage-unavailable path returned before that reset, so it was never throttled at all - every ~5-minute cycle re-entered and re-logged the same warning indefinitely. Fixed with a separate debug_history_storage_warned timestamp, deliberately independent of the capture throttle, so a later genuine capture attempt is never skipped just because the warning was recently logged. 3. debug_history_force_capture reset on trigger, before storage was even checked or a capture attempted - contradicting docs/customisation.md's "Predbat resets the switch back off itself once the snapshot has been taken." A failed forced capture now leaves the switch on, so it retries every cycle until it genuinely succeeds (or the switch is turned off), rather than the request being silently swallowed by an early reset. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
…hot id Per @springfall2008's review on #4438: Item 4 (race condition): html_debug_history_download's id=latest case called load_snapshot(storage, "latest") - which resolves "latest" internally but discards the resolved id - then called list_snapshots() a second, independent time just to rebuild the filename. A capture landing between the two calls could serve one snapshot's bytes under a different snapshot's filename. Added resolve_and_load_snapshot(), returning (resolved_id, text) from a single resolution, and used it in the route so the id used for the filename is always the same one the data actually came from. load_snapshot() now delegates to it, unchanged for existing callers. Item 6 (reflected XSS): "Snapshot {} not found".format(snapshot_id) reflected the raw ?id= query param unescaped into a text/html response. Escaped via html.escape(), matching the existing pattern used elsewhere in web.py (e.g. the plan-log highlighting). Item 21 (test coverage): the three debug-history web routes had zero tests. Added test_web_debug_history_routes.py covering all three (list/download/download-all) against a real StorageLocalFiles backend, including the specific race (item 4) and XSS (item 6) fixes above. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
…havior Per @springfall2008's review on #4438 (items 8-9): docs described the dropdown snapshot picker and "nearest"/"how many snapshots ago" matching from an earlier design in this PR, replaced during development by a single "Download all (.tgz)" link and exact floored-slot matching (confirmed against the shipped JS - findNearestDebugSnapshot's tolerance is 1000ms, guarding only sub-second formatting noise, not a real nearest- within-a-window search; labels use absolute local time, not "N ago"). Updated docs/web-interface.md, docs/predbat-plan-card.md, and docs/customisation.md to describe what actually ships. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
Per @springfall2008's review on #4438 (item 22): findNearestDebugSnapshot, loadDebugHistoryData, and the plan table's Debug column were untested. Follows test_plan_why_reason.py's established precedent for this kind of embedded-JS test - assert on the JS source text's structure directly (there's no JS engine in this suite), rather than executing it. Covers: the exact/tight-tolerance (not nearest-of-several) snapshot match, the fetch being wired to the Yesterday view switch rather than the frequent plan poll, and the Debug column linking by the matched snapshot's own id with a real time label - locking in the same shipped behaviour docs were just corrected to describe. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
|
Thanks for the thorough review - went through it in priority order. Everything flagged as "most worth fixing before merge" is addressed, split into separate commits so each is reviewable on its own: Correctness (items 1-4, 6)
Docs (items 8-9)
Tests (items 21-22)
Design suggestions in your second comment
Full suite + pre-commit clean after every commit. The remaining items (#5, #7, #10-20, #23-24) are left as follow-up per your own note that they're good-to-have cleanup rather than blocking - happy to pick any of them up next if you'd like them in this PR instead. |

Summary
Fixes #4417.
create_debug_yaml()(what bug reporters attach so a maintainer can replay their exact plan computation viaunit_test.py --debug_file --redo) only ever wrote whenswitch.predbat_debug_enablewas already on, on every ~5-minute cycle with no pruning at all - unbounded disk growth if left on, and no history to look back at for anyone who didn't already have it on before something went wrong (originally raised in #1745, never actually built).Replaces that with a rolling buffer:
debug_history.py(new) - capture/list/load/prune snapshots, mirroring the existingannual_store.pyring-buffer pattern and going through the Storage component rather than the filesystem directly. Snapshots are saved withformat="text"(the payload is already-rendered YAML text fromcreate_debug_yaml(write_file=False), not a Python object -format="yaml"would double-serialise it into something--debug_filecouldn't parse).debug_history_count(default 15,0disables the routine capture),debug_history_interval(default 3h - 15x3h matches the History tab's worst-case "yesterday + today so far" coverage), anddebug_history_force_capture- a self-resetting switch so an automation that notices something worth investigating can trigger an immediate, precisely-timed capture rather than waiting on the routine interval, then fetch it via?id=latestwithout a separate lookup round-trip. Still honoured even whendebug_history_count=0(an explicit "give me one right now" is a different intent than "keep a rolling background history").predbat.py:_capture_debug_history(), throttled in-memory, wired alongside the existingdebug_enablecapture call. Independent of that switch entirely.web.py:/debug_history_listand/debug_history_downloadroutes (reusing the existinghtml_file()attachment-serving helper the manualpredbat_debug.yamldownload already uses), plus a dropdown on the dashboard's Debug panel.web_helper.py: a Debug column on the plan's History/Yesterday view only (its rows are the ones with a real past timestamp to match a snapshot against - the live Plan view is mostly future predictions with nothing to match). Fetched and matched client-side by wall-clock time rather than threaded throughpublish_html_plan(), which is shared by three other call sites (live plan, Annual results viewer, Compare) with no relationship to when a snapshot was actually captured.customisation.md(new "Debug history" subsection),web-interface.md(dashboard dropdown),predbat-plan-card.md(new Debug column in the plan column reference).Test plan
apps/predbat/tests/test_debug_history.py- capture/list/load round-trip, pruning to a configured count on both Storage eviction paths (delete-capable and expiry-fallback),annotate_steps_back, corrupt-index handling,latest/falsy-id resolution, and a real-StorageLocalFilesround-trip of genuine YAML-syntax text (guards theformat="text"vs"yaml"trap directly)apps/predbat/tests/test_debug_history_capture.py- interval throttling,count<=0disabling routine capture, force-capture bypassing both the count and interval, the switch resetting itself, and graceful handling with no storage component available./run_all --quickpasses with no regressions./run_pre_commitpasses (ruff, black, cspell, markdownlint, full test suite)🤖 Generated with Claude Code