From 45121be459dbe51a84cf423a2569f1bc5010f528 Mon Sep 17 00:00:00 2001 From: Rik Allen Date: Fri, 14 Aug 2026 21:13:20 +0100 Subject: [PATCH 1/4] feat(octopus): log a per-car IOG dispatch timeline diagnostic (#4516 Stage 1) Issue #4516: a future daytime IOG dispatch slot is still Octopus's own provisional/revisable plan, but Predbat currently treats it the same as a confirmed one. Before building any gating/replan logic on a specific confirmation signal, first observe real dispatch lifecycles - two signals investigated for this (intelligent_charge_cap_hours, then the intelligent_dispatching binary_sensor's default mode) both looked promising and both turned out unreliable on inspection. Adds build_dispatch_timeline() (octopus.py): a small render helper producing a fixed-width, one-character-per-30-min-block status string ('.' nothing, 'P' planned, 'S' started, 'C' completed) across a -4h..+24h window around now. Logged once per car per 30-minute boundary from fetch_sensor_data_cars() - purely observational, not merged into octopus_slots or used for any rate/plan decision. Stacking consecutive lines in a monospace log viewer reveals dispatch lifecycle as diagonal stripes: a specific dispatch drifts one column per line as now advances, so a rescinded slot shows as a stripe that stops before reaching the 'now' column. Also reads started_dispatches/startedDispatches from the octopus_intelligent_slot entity for the first time - present on the entity (confirmed against the actual Octopus Energy HA integration source) but not previously read anywhere in Predbat. 8 new unit tests for the render helper (empty/planned/started/completed rendering, confirmed-status priority ordering, out-of-window slots, multi-block spans). Sanity-checked against a real captured debug.yaml's octopus_slots data - handles real-world irregularities (negative charge_in_kwh, non-standard location values) without crashing. Stage 2 (the actual confirmed-slot gating + immediate-replan trigger) is deferred until dispatch timelines have been observed for a while. --- apps/predbat/fetch.py | 13 ++ apps/predbat/octopus.py | 38 +++++ apps/predbat/tests/test_dispatch_timeline.py | 143 +++++++++++++++++++ apps/predbat/unit_test.py | 2 + 4 files changed, 196 insertions(+) create mode 100644 apps/predbat/tests/test_dispatch_timeline.py diff --git a/apps/predbat/fetch.py b/apps/predbat/fetch.py index bbc33e2af..c3e406c60 100644 --- a/apps/predbat/fetch.py +++ b/apps/predbat/fetch.py @@ -1402,6 +1402,7 @@ def fetch_sensor_data_cars(self): completed = [] planned = [] + started = [] if entity_id and "octopus_intelligent_slot_action_config" in self.args: config_entry = self.get_arg("octopus_intelligent_slot_action_config", None, indirect=False) @@ -1415,10 +1416,22 @@ def fetch_sensor_data_cars(self): try: completed = self.get_state_wrapper(entity_id=entity_id, attribute="completed_dispatches") or self.get_state_wrapper(entity_id=entity_id, attribute="completedDispatches") planned = self.get_state_wrapper(entity_id=entity_id, attribute="planned_dispatches") or self.get_state_wrapper(entity_id=entity_id, attribute="plannedDispatches") + # Not merged into octopus_slots or used for any rate/plan decision yet - read + # only for the #4516 Stage 1 diagnostic timeline log below, to observe whether + # this is a trustworthy earlier-than-completed confirmation signal before + # building any gating logic on it (Stage 2, deferred). + started = self.get_state_wrapper(entity_id=entity_id, attribute="started_dispatches") or self.get_state_wrapper(entity_id=entity_id, attribute="startedDispatches") except (ValueError, TypeError): self.log("Warn: Unable to get data from {} for car {} - octopus_intelligent_slot may not be set correctly in apps.yaml".format(entity_id, car_n)) self.record_status(message="Error: octopus_intelligent_slot not set correctly in apps.yaml for car {}".format(car_n), had_errors=True) + # #4516 Stage 1: diagnostic dispatch-timeline log, once per 30-minute boundary so + # log volume stays sane (dispatch decisions are 30-min-granular anyway). Purely + # observational - see build_dispatch_timeline()'s docstring. + if self.minutes_now % 30 == 0: + timeline = self.build_dispatch_timeline(car_n, completed, started, planned) + self.log("Octopus: Dispatch timeline car {} @ {} [-4h..+24h]: {}".format(car_n, self.time_abs_str(self.minutes_now), timeline)) + # Completed and planned slots - merge from all cars if completed: self.octopus_slots[car_n] += completed diff --git a/apps/predbat/octopus.py b/apps/predbat/octopus.py index acd6bb575..6e09cccf2 100644 --- a/apps/predbat/octopus.py +++ b/apps/predbat/octopus.py @@ -2983,6 +2983,44 @@ def get_octopus_slot_max(self): if OctopusAPI.has_six_hour_cap(tariff_code): return OCTOPUS_SLOT_MAX_CAPPED return OCTOPUS_SLOT_MAX_DEFAULT + def build_dispatch_timeline(self, car_n, completed, started, planned, window_before_hours=4, window_after_hours=24, step=30): + """ + Build a fixed-width, one-character-per-block dispatch status string for the diagnostic + timeline log (#4516 Stage 1 - not yet used for any rate/plan decision, purely observational). + + Each character covers `step` minutes, offset from now, spanning + [-window_before_hours, +window_after_hours). '.' = nothing known, 'P' = planned + (provisional), 'S' = started, 'C' = completed. Where lists disagree on the same block, the + most-confirmed status wins (completed > started > planned) - reflects Octopus's own view + having moved on, not a genuine simultaneous claim. + + Stacking consecutive lines (one per 30-minute boundary) in a monospace log viewer reveals + dispatch lifecycle as diagonal stripes: a specific dispatch drifts one column per line as + `now` advances, so a rescinded slot shows as a stripe that stops before reaching the `now` + column, while a genuinely-delivered one runs through into 'C'. + """ + total_before = window_before_hours * 60 + total_after = window_after_hours * 60 + num_blocks = (total_before + total_after) // step + status = ["."] * num_blocks + + def mark(slots, char): + for slot in slots or []: + start_minutes, end_minutes, _, _, _ = self.decode_octopus_slot(car_n, slot, raw=True) + if start_minutes == end_minutes: + continue + start_offset = start_minutes - self.minutes_now + end_offset = end_minutes - self.minutes_now + block_start = max(0, (start_offset + total_before) // step) + block_end = min(num_blocks, -(-(end_offset + total_before) // step)) # ceil division + for block in range(int(block_start), int(block_end)): + status[block] = char + + mark(planned, "P") + mark(started, "S") + mark(completed, "C") + + return "".join(status) def load_octopus_slots(self, car_n, octopus_slots, octopus_intelligent_consider_full): """ diff --git a/apps/predbat/tests/test_dispatch_timeline.py b/apps/predbat/tests/test_dispatch_timeline.py new file mode 100644 index 000000000..b278abc79 --- /dev/null +++ b/apps/predbat/tests/test_dispatch_timeline.py @@ -0,0 +1,143 @@ +# ----------------------------------------------------------------------------- +# Predbat Home Battery System +# Copyright Trefor Southwell 2026 - All Rights Reserved +# This application maybe used for personal use only and not for commercial use +# ----------------------------------------------------------------------------- +# fmt off +# pylint: disable=consider-using-f-string +# pylint: disable=line-too-long +# pylint: disable=attribute-defined-outside-init + +""" +Unit tests for Octopus.build_dispatch_timeline() - the #4516 Stage 1 diagnostic dispatch-timeline +render helper. Purely observational (not used for any rate/plan decision yet), so these tests only +check the rendered status string, not any side effect on rates or the plan. +""" + +from datetime import datetime, timedelta + +import pytz + +UTC = pytz.UTC +TIME_FORMAT = "%Y-%m-%dT%H:%M:%S%z" + + +def _slot(start, end): + return {"start": start.strftime(TIME_FORMAT), "end": end.strftime(TIME_FORMAT), "source": "smart-charge", "location": "AT_HOME"} + + +def run_dispatch_timeline_tests(my_predbat): + """ + Test for build_dispatch_timeline() - the #4516 Stage 1 diagnostic dispatch-timeline render. + """ + failed = False + print("**** Running dispatch_timeline tests ****") + + # Save state that will be mutated + saved_now_utc = my_predbat.now_utc + saved_midnight_utc = my_predbat.midnight_utc + saved_minutes_now = my_predbat.minutes_now + + try: + # Fixed, mutually-consistent midnight/now so this test doesn't depend on (or leak into) + # whatever the ambient fixture state happens to be elsewhere in a full suite run. + midnight_utc = datetime(2026, 1, 1, 0, 0, 0, tzinfo=UTC) + my_predbat.midnight_utc = midnight_utc + my_predbat.now_utc = midnight_utc + timedelta(hours=10) + my_predbat.minutes_now = 10 * 60 + + # Default window: -4h..+24h at 30-min step = 56 blocks. "now" (offset 0) sits at block 8 (4h * 2). + NUM_BLOCKS = 56 + NOW_BLOCK = 8 + + print("Test 1: nothing scheduled - all dots") + timeline = my_predbat.build_dispatch_timeline(0, [], [], []) + if timeline != "." * NUM_BLOCKS: + print(" ERROR: expected all dots, got {!r}".format(timeline)) + failed = True + + print("Test 2: a single future planned slot renders as P at the right offset") + slot_start = midnight_utc + timedelta(hours=12) # 2h from now (now=10:00) -> offset block NOW_BLOCK+4 + slot_end = slot_start + timedelta(minutes=30) + timeline = my_predbat.build_dispatch_timeline(0, [], [], [_slot(slot_start, slot_end)]) + expected = list("." * NUM_BLOCKS) + expected[NOW_BLOCK + 4] = "P" + expected = "".join(expected) + if timeline != expected: + print(" ERROR: expected {!r}, got {!r}".format(expected, timeline)) + failed = True + + print("Test 3: a currently-active started slot renders as S") + slot_start = midnight_utc + timedelta(hours=10) # now + slot_end = slot_start + timedelta(minutes=30) + timeline = my_predbat.build_dispatch_timeline(0, [], [_slot(slot_start, slot_end)], []) + expected = list("." * NUM_BLOCKS) + expected[NOW_BLOCK] = "S" + expected = "".join(expected) + if timeline != expected: + print(" ERROR: expected {!r}, got {!r}".format(expected, timeline)) + failed = True + + print("Test 4: a past completed slot renders as C, placed before the 'now' column") + slot_start = midnight_utc + timedelta(hours=9) # 1h before now -> offset block NOW_BLOCK-2 + slot_end = slot_start + timedelta(minutes=30) + timeline = my_predbat.build_dispatch_timeline(0, [_slot(slot_start, slot_end)], [], []) + expected = list("." * NUM_BLOCKS) + expected[NOW_BLOCK - 2] = "C" + expected = "".join(expected) + if timeline != expected: + print(" ERROR: expected {!r}, got {!r}".format(expected, timeline)) + failed = True + + print("Test 5: when completed, started and planned all cover the same block, completed wins") + slot_start = midnight_utc + timedelta(hours=12) + slot_end = slot_start + timedelta(minutes=30) + slot = _slot(slot_start, slot_end) + timeline = my_predbat.build_dispatch_timeline(0, [slot], [slot], [slot]) + expected = list("." * NUM_BLOCKS) + expected[NOW_BLOCK + 4] = "C" + expected = "".join(expected) + if timeline != expected: + print(" ERROR: expected completed to win over started/planned, got {!r}".format(timeline)) + failed = True + + print("Test 6: started wins over planned when completed is absent") + timeline = my_predbat.build_dispatch_timeline(0, [], [slot], [slot]) + expected = list("." * NUM_BLOCKS) + expected[NOW_BLOCK + 4] = "S" + expected = "".join(expected) + if timeline != expected: + print(" ERROR: expected started to win over planned, got {!r}".format(timeline)) + failed = True + + print("Test 7: a slot entirely outside the window has no effect and does not crash") + slot_start = midnight_utc + timedelta(days=3) # far beyond +24h + slot_end = slot_start + timedelta(minutes=30) + timeline = my_predbat.build_dispatch_timeline(0, [], [], [_slot(slot_start, slot_end)]) + if timeline != "." * NUM_BLOCKS: + print(" ERROR: expected all dots for an out-of-window slot, got {!r}".format(timeline)) + failed = True + + print("Test 8: a slot spanning multiple 30-min blocks marks every block it touches") + slot_start = midnight_utc + timedelta(hours=12) + slot_end = slot_start + timedelta(hours=1, minutes=30) # 3 blocks + timeline = my_predbat.build_dispatch_timeline(0, [], [], [_slot(slot_start, slot_end)]) + expected = list("." * NUM_BLOCKS) + expected[NOW_BLOCK + 4] = "P" + expected[NOW_BLOCK + 5] = "P" + expected[NOW_BLOCK + 6] = "P" + expected = "".join(expected) + if timeline != expected: + print(" ERROR: expected 3 consecutive P blocks, got {!r}".format(timeline)) + failed = True + finally: + my_predbat.now_utc = saved_now_utc + my_predbat.midnight_utc = saved_midnight_utc + my_predbat.minutes_now = saved_minutes_now + + if failed: + print("\n**** dispatch_timeline tests: FAILED ****") + else: + print("\n**** dispatch_timeline tests: PASSED ****") + + return failed diff --git a/apps/predbat/unit_test.py b/apps/predbat/unit_test.py index 57485ef24..0e2b4ffbd 100644 --- a/apps/predbat/unit_test.py +++ b/apps/predbat/unit_test.py @@ -225,6 +225,7 @@ from tests.test_annual_tariff import test_annual_tariff from tests.test_rate_add_io_slots import run_rate_add_io_slots_tests from tests.test_iog_charge_skew import run_iog_charge_skew_tests +from tests.test_dispatch_timeline import run_dispatch_timeline_tests from tests.test_battery_curve_keys import run_battery_curve_keys_tests from tests.test_balance_inverters import run_balance_inverters_tests from tests.test_octopus_download_rates import test_octopus_download_rates_wrapper @@ -524,6 +525,7 @@ def main(): ("multi_car_iog", run_multi_car_iog_tests, "Multi-car IOG tests", False), ("rate_add_io_slots", run_rate_add_io_slots_tests, "Rate add IO slots tests", False), ("iog_charge_skew", run_iog_charge_skew_tests, "IOG earlier-charge skew characterisation tests", False), + ("dispatch_timeline", run_dispatch_timeline_tests, "Dispatch timeline diagnostic tests (#4516 Stage 1)", False), ("rate_replicate", test_rate_replicate, "Rate replicate comprehensive tests (missing slots, IO, offsets, gas)", False), ("find_charge_window", test_find_charge_window, "Find charge window gap handling tests", False), ("find_charge_rate", test_find_charge_rate, "Find charge rate tests", False), From 719e8a7e4fb9381e1725361ba66de826ed7bb688 Mon Sep 17 00:00:00 2001 From: Rik Allen Date: Sat, 5 Sep 2026 20:12:25 +0100 Subject: [PATCH 2/4] feat(octopus): mark in the dispatch timeline where Predbat plans to charge The Stage 1 timeline shows a dispatch's lifecycle (planned -> started -> completed) but not whether Predbat depended on it. A slot that disappears having never been planned against costs nothing; one Predbat committed an import to is a plan that will not happen. Those look identical in a P/S/C render. Lowercase the letter where Predbat's plan charges in that block, so 'p' is a provisional slot being relied on and 'P' one that is not. Read as stripes, a run of 'p' that stops before reaching the now column is exactly the case worth finding: Predbat planned around a slot and lost it. This runs in fetch, before the planner, so the windows are the previous cycle's plan - one 5-minute cycle stale against 30-minute blocks. Deliberate: what Predbat believed while the slot was still live is the more useful record, and the error is well inside a block. Windows with a zero charge limit are not treated as charging. Still purely observational - no rate or plan decision reads this. Co-Authored-By: Claude Opus 5 --- apps/predbat/octopus.py | 26 ++++++++++++ apps/predbat/tests/test_dispatch_timeline.py | 43 ++++++++++++++++++++ 2 files changed, 69 insertions(+) diff --git a/apps/predbat/octopus.py b/apps/predbat/octopus.py index 6e09cccf2..df0d71128 100644 --- a/apps/predbat/octopus.py +++ b/apps/predbat/octopus.py @@ -2983,6 +2983,7 @@ def get_octopus_slot_max(self): if OctopusAPI.has_six_hour_cap(tariff_code): return OCTOPUS_SLOT_MAX_CAPPED return OCTOPUS_SLOT_MAX_DEFAULT + def build_dispatch_timeline(self, car_n, completed, started, planned, window_before_hours=4, window_after_hours=24, step=30): """ Build a fixed-width, one-character-per-block dispatch status string for the diagnostic @@ -2994,6 +2995,11 @@ def build_dispatch_timeline(self, car_n, completed, started, planned, window_bef most-confirmed status wins (completed > started > planned) - reflects Octopus's own view having moved on, not a genuine simultaneous claim. + The letter is lowercased where Predbat's own plan charges in that block, so 'p' is a + provisional slot Predbat is relying on and 'P' one it is not. That distinction is the + point: a slot that disappears having never been planned against costs nothing, while one + Predbat committed an import to is a plan that will not happen. + Stacking consecutive lines (one per 30-minute boundary) in a monospace log viewer reveals dispatch lifecycle as diagonal stripes: a specific dispatch drifts one column per line as `now` advances, so a rescinded slot shows as a stripe that stops before reaching the `now` @@ -3020,6 +3026,26 @@ def mark(slots, char): mark(started, "S") mark(completed, "C") + # Lowercase where Predbat's own plan plans to import - so a stripe shows not just the + # dispatch's lifecycle but whether Predbat had committed a charge window to it. A slot + # that reads 'p' and then vanishes before reaching the now column is one Predbat planned + # around and lost, which is the case a plain P/S/C timeline cannot distinguish from a + # slot nothing depended on. + # + # This runs in fetch, before the planner, so the windows are the *previous* cycle's plan - + # one 5-minute cycle stale against 30-minute blocks. That is deliberate: what Predbat + # believed while the slot was still live is the more useful thing to record. + for window_n, window in enumerate(self.charge_window_best or []): + if window_n < len(self.charge_limit_best or []) and self.charge_limit_best[window_n] <= 0: + continue + start_offset = window.get("start", 0) - self.minutes_now + end_offset = window.get("end", 0) - self.minutes_now + block_start = max(0, (start_offset + total_before) // step) + block_end = min(num_blocks, -(-(end_offset + total_before) // step)) + for block in range(int(block_start), int(block_end)): + if status[block] in ("P", "S", "C"): + status[block] = status[block].lower() + return "".join(status) def load_octopus_slots(self, car_n, octopus_slots, octopus_intelligent_consider_full): diff --git a/apps/predbat/tests/test_dispatch_timeline.py b/apps/predbat/tests/test_dispatch_timeline.py index b278abc79..082040ea3 100644 --- a/apps/predbat/tests/test_dispatch_timeline.py +++ b/apps/predbat/tests/test_dispatch_timeline.py @@ -37,6 +37,8 @@ def run_dispatch_timeline_tests(my_predbat): saved_now_utc = my_predbat.now_utc saved_midnight_utc = my_predbat.midnight_utc saved_minutes_now = my_predbat.minutes_now + saved_charge_window_best = my_predbat.charge_window_best + saved_charge_limit_best = my_predbat.charge_limit_best try: # Fixed, mutually-consistent midnight/now so this test doesn't depend on (or leak into) @@ -50,6 +52,11 @@ def run_dispatch_timeline_tests(my_predbat): NUM_BLOCKS = 56 NOW_BLOCK = 8 + # No plan by default: the existing cases below assert uppercase letters, which only hold + # when Predbat is not charging in those blocks + my_predbat.charge_window_best = [] + my_predbat.charge_limit_best = [] + print("Test 1: nothing scheduled - all dots") timeline = my_predbat.build_dispatch_timeline(0, [], [], []) if timeline != "." * NUM_BLOCKS: @@ -130,10 +137,46 @@ def run_dispatch_timeline_tests(my_predbat): if timeline != expected: print(" ERROR: expected 3 consecutive P blocks, got {!r}".format(timeline)) failed = True + print("Test 9: a planned slot Predbat charges in renders lowercase") + slot_start = midnight_utc + timedelta(hours=12) # 2h from now -> block NOW_BLOCK+4 + slot_end = slot_start + timedelta(minutes=30) + my_predbat.charge_window_best = [{"start": 12 * 60, "end": 12 * 60 + 30}] + my_predbat.charge_limit_best = [5.0] + timeline = my_predbat.build_dispatch_timeline(0, [], [], [_slot(slot_start, slot_end)]) + expected = list("." * NUM_BLOCKS) + expected[NOW_BLOCK + 4] = "p" + expected = "".join(expected) + if timeline != expected: + print(" ERROR: a slot Predbat plans to charge in should be 'p', expected {!r}, got {!r}".format(expected, timeline)) + failed = True + + print("Test 10: a charge window with a zero limit does not lowercase the slot") + my_predbat.charge_limit_best = [0.0] + timeline = my_predbat.build_dispatch_timeline(0, [], [], [_slot(slot_start, slot_end)]) + expected = list("." * NUM_BLOCKS) + expected[NOW_BLOCK + 4] = "P" + expected = "".join(expected) + if timeline != expected: + print(" ERROR: a zero-limit window is not a charge, expected {!r}, got {!r}".format(expected, timeline)) + failed = True + + print("Test 11: a charge window where there is no slot leaves dots untouched") + my_predbat.charge_window_best = [{"start": 14 * 60, "end": 14 * 60 + 30}] + my_predbat.charge_limit_best = [5.0] + timeline = my_predbat.build_dispatch_timeline(0, [], [], []) + if timeline != "." * NUM_BLOCKS: + print(" ERROR: charging where no dispatch exists must not mark the timeline, got {!r}".format(timeline)) + failed = True + + my_predbat.charge_window_best = [] + my_predbat.charge_limit_best = [] + finally: my_predbat.now_utc = saved_now_utc my_predbat.midnight_utc = saved_midnight_utc my_predbat.minutes_now = saved_minutes_now + my_predbat.charge_window_best = saved_charge_window_best + my_predbat.charge_limit_best = saved_charge_limit_best if failed: print("\n**** dispatch_timeline tests: FAILED ****") From 68d735cf16692c8b442e0a255085dbe472a2904a Mon Sep 17 00:00:00 2001 From: Rik Allen Date: Sun, 6 Sep 2026 12:04:44 +0100 Subject: [PATCH 3/4] fix(octopus): decode dispatch-timeline slot boundaries without the metadata reject Copilot review on #4948: decode_octopus_slot()'s "remove empty slots" check rejects a slot with no kWh, source or location as empty. A real started_dispatches entry from the HA Octopus Energy integration carries only start/end - no metadata at all - so build_dispatch_timeline()'s mark() call decoded every real started dispatch as empty and 'S' could never render for real data. The existing tests all use a _slot() helper that adds source/location, which masked this. The timeline only needs start/end; it never reads the kWh/source/location this rejection is guarding. Added decode_octopus_slot(boundaries_only=True), returning right after the start/end decode and before the metadata handling, and pointed build_dispatch_timeline() at it. Every other caller is unaffected - the parameter defaults False. Co-Authored-By: Claude Opus 5 --- apps/predbat/octopus.py | 12 ++++++++-- apps/predbat/tests/test_dispatch_timeline.py | 24 +++++++++++++++++++- 2 files changed, 33 insertions(+), 3 deletions(-) diff --git a/apps/predbat/octopus.py b/apps/predbat/octopus.py index df0d71128..3553ff0e4 100644 --- a/apps/predbat/octopus.py +++ b/apps/predbat/octopus.py @@ -2910,9 +2910,14 @@ def load_saving_slot(self, octopus_saving_slots, rate_dict, export=False, rate_r if not export: self.load_scaling_dynamic[minute] = self.load_scaling_saving - def decode_octopus_slot(self, car_n, slot, raw=False): + def decode_octopus_slot(self, car_n, slot, raw=False, boundaries_only=False): """ Decode IOG slot + + boundaries_only skips the kWh/source/location handling below - including the "remove + empty slots" check, which real HA-integration started_dispatches entries (start/end only, + no kWh, source or location) would otherwise trip, decoding them as empty (#4516 Stage 1's + build_dispatch_timeline() review). Only start/end are meaningful there. """ if "start" in slot: start = datetime.strptime(slot["start"], TIME_FORMAT) @@ -2936,6 +2941,9 @@ def decode_octopus_slot(self, car_n, slot, raw=False): if start_minutes == end_minutes: return 0, 0, 0, source, location + if boundaries_only: + return start_minutes, end_minutes, 0, source, location + cap_minutes = end_minutes - start_minutes # The load expected is stored in chargeKwh for the period in use @@ -3012,7 +3020,7 @@ def build_dispatch_timeline(self, car_n, completed, started, planned, window_bef def mark(slots, char): for slot in slots or []: - start_minutes, end_minutes, _, _, _ = self.decode_octopus_slot(car_n, slot, raw=True) + start_minutes, end_minutes, _, _, _ = self.decode_octopus_slot(car_n, slot, raw=True, boundaries_only=True) if start_minutes == end_minutes: continue start_offset = start_minutes - self.minutes_now diff --git a/apps/predbat/tests/test_dispatch_timeline.py b/apps/predbat/tests/test_dispatch_timeline.py index 082040ea3..2c96f60ee 100644 --- a/apps/predbat/tests/test_dispatch_timeline.py +++ b/apps/predbat/tests/test_dispatch_timeline.py @@ -26,6 +26,12 @@ def _slot(start, end): return {"start": start.strftime(TIME_FORMAT), "end": end.strftime(TIME_FORMAT), "source": "smart-charge", "location": "AT_HOME"} +def _bare_slot(start, end): + """A slot with only start/end - the real shape of a started_dispatches entry from the HA + Octopus Energy integration (no kWh, source or location).""" + return {"start": start.strftime(TIME_FORMAT), "end": end.strftime(TIME_FORMAT)} + + def run_dispatch_timeline_tests(my_predbat): """ Test for build_dispatch_timeline() - the #4516 Stage 1 diagnostic dispatch-timeline render. @@ -160,7 +166,23 @@ def run_dispatch_timeline_tests(my_predbat): print(" ERROR: a zero-limit window is not a charge, expected {!r}, got {!r}".format(expected, timeline)) failed = True - print("Test 11: a charge window where there is no slot leaves dots untouched") + print("Test 11: a bare started slot (start/end only, no kWh/source/location) still renders as S") + # Copilot review on #4948: real started_dispatches entries from the HA Octopus Energy + # integration carry only start/end. decode_octopus_slot()'s "remove empty slots" check + # (no kWh, source or location) would otherwise decode a real one as empty, so 'S' could + # never render for real data - every other test here uses _slot(), which adds source and + # location and masked this. + slot_start = midnight_utc + timedelta(hours=10) # now + slot_end = slot_start + timedelta(minutes=30) + timeline = my_predbat.build_dispatch_timeline(0, [], [_bare_slot(slot_start, slot_end)], []) + expected = list("." * NUM_BLOCKS) + expected[NOW_BLOCK] = "S" + expected = "".join(expected) + if timeline != expected: + print(" ERROR: a bare start/end-only started slot should still render as S, expected {!r}, got {!r}".format(expected, timeline)) + failed = True + + print("Test 12: a charge window where there is no slot leaves dots untouched") my_predbat.charge_window_best = [{"start": 14 * 60, "end": 14 * 60 + 30}] my_predbat.charge_limit_best = [5.0] timeline = my_predbat.build_dispatch_timeline(0, [], [], []) From 45dd25765d947dfd51654de96819624da1a0ff93 Mon Sep 17 00:00:00 2001 From: Rik Allen Date: Sun, 6 Sep 2026 13:37:00 +0100 Subject: [PATCH 4/4] feat(octopus): log the dispatch timeline on change, not just the 30-min heartbeat PR #4948 review: a heartbeat every 30 minutes alone can miss a provisional slot that appears, influences Predbat's plan, and disappears again entirely within one half-hour window - exactly the "stripe that never reaches now" pattern this diagnostic exists to catch, invisible regardless of how little time it had to affect SoC. The underlying dispatch lists were already being re-read every 5-minute cycle; only the log line itself was gated to the 30-minute boundary. Added dispatch_timeline_should_log(), called every cycle: the 30-minute heartbeat still always logs unmarked, and a change from the last logged timeline for that car now also logs immediately, marked with a trailing ' *' so the two kinds of line can be told apart (or grepped separately). The marker is a suffix, appended after build_dispatch_timeline()'s fixed-width string rather than before it, so heartbeat and change-triggered lines keep stacking column-for-column in a monospace viewer - the whole point of the render is that consecutive lines line up into diagonal stripes, and a prefix of differing length between the two line kinds would break that. 5 new tests for the logging decision itself (heartbeat, no-change, change, no-repeat, independent per-car state), confirmed to fail with an AttributeError against the pre-change code. Co-Authored-By: Claude Opus 5 --- apps/predbat/fetch.py | 12 ++--- apps/predbat/octopus.py | 34 +++++++++++-- apps/predbat/predbat.py | 1 + apps/predbat/tests/test_dispatch_timeline.py | 50 ++++++++++++++++++-- 4 files changed, 85 insertions(+), 12 deletions(-) diff --git a/apps/predbat/fetch.py b/apps/predbat/fetch.py index c3e406c60..c8fc928fa 100644 --- a/apps/predbat/fetch.py +++ b/apps/predbat/fetch.py @@ -1425,12 +1425,12 @@ def fetch_sensor_data_cars(self): self.log("Warn: Unable to get data from {} for car {} - octopus_intelligent_slot may not be set correctly in apps.yaml".format(entity_id, car_n)) self.record_status(message="Error: octopus_intelligent_slot not set correctly in apps.yaml for car {}".format(car_n), had_errors=True) - # #4516 Stage 1: diagnostic dispatch-timeline log, once per 30-minute boundary so - # log volume stays sane (dispatch decisions are 30-min-granular anyway). Purely - # observational - see build_dispatch_timeline()'s docstring. - if self.minutes_now % 30 == 0: - timeline = self.build_dispatch_timeline(car_n, completed, started, planned) - self.log("Octopus: Dispatch timeline car {} @ {} [-4h..+24h]: {}".format(car_n, self.time_abs_str(self.minutes_now), timeline)) + # #4516 Stage 1: diagnostic dispatch-timeline log. Purely observational - see + # build_dispatch_timeline()'s and dispatch_timeline_should_log()'s docstrings. + timeline = self.build_dispatch_timeline(car_n, completed, started, planned) + should_log, marker = self.dispatch_timeline_should_log(car_n, timeline) + if should_log: + self.log("Octopus: Dispatch timeline car {} @ {} [-4h..+24h]: {}{}".format(car_n, self.time_abs_str(self.minutes_now), timeline, marker)) # Completed and planned slots - merge from all cars if completed: diff --git a/apps/predbat/octopus.py b/apps/predbat/octopus.py index 3553ff0e4..d805ddf60 100644 --- a/apps/predbat/octopus.py +++ b/apps/predbat/octopus.py @@ -3008,9 +3008,10 @@ def build_dispatch_timeline(self, car_n, completed, started, planned, window_bef point: a slot that disappears having never been planned against costs nothing, while one Predbat committed an import to is a plan that will not happen. - Stacking consecutive lines (one per 30-minute boundary) in a monospace log viewer reveals - dispatch lifecycle as diagonal stripes: a specific dispatch drifts one column per line as - `now` advances, so a rescinded slot shows as a stripe that stops before reaching the `now` + Stacking consecutive lines (a heartbeat one per 30-minute boundary, plus one on any + earlier change - see the caller in fetch.py) in a monospace log viewer reveals dispatch + lifecycle as diagonal stripes: a specific dispatch drifts one column per line as `now` + advances, so a rescinded slot shows as a stripe that stops before reaching the `now` column, while a genuinely-delivered one runs through into 'C'. """ total_before = window_before_hours * 60 @@ -3056,6 +3057,33 @@ def mark(slots, char): return "".join(status) + def dispatch_timeline_should_log(self, car_n, timeline): + """ + Decide whether fetch.py should log a dispatch-timeline diagnostic line this cycle, and + what marker to append if so. + + A 30-minute heartbeat always logs - dispatch decisions are 30-min-granular anyway, so log + volume stays sane at that cadence - but a change from the last logged timeline for this + car also logs immediately outside that boundary, marked with a trailing ' *' (#4948 + review). Without this, a provisional slot that appears and disappears entirely within one + half-hour window would never appear in this log at all, however briefly Predbat's own + plan relied on it - exactly the pattern this diagnostic exists to catch. + + The marker is a suffix, appended by the caller after build_dispatch_timeline()'s + fixed-width string, rather than a prefix - so heartbeat and change-triggered lines still + stack column-for-column in a monospace viewer. That alignment is the whole point of the + render: consecutive lines are meant to line up into diagonal stripes. + + Records the new timeline as "last logged" as a side effect whenever this returns True, so + a caller must log with the returned marker exactly when told to, and no other times. + """ + is_heartbeat = self.minutes_now % 30 == 0 + changed = timeline != self.dispatch_timeline_last.get(car_n) + if not (is_heartbeat or changed): + return False, "" + self.dispatch_timeline_last[car_n] = timeline + return True, "" if is_heartbeat else " *" + def load_octopus_slots(self, car_n, octopus_slots, octopus_intelligent_consider_full): """ Turn octopus slots into charging plan diff --git a/apps/predbat/predbat.py b/apps/predbat/predbat.py index 9de299952..16c2ad4d8 100644 --- a/apps/predbat/predbat.py +++ b/apps/predbat/predbat.py @@ -497,6 +497,7 @@ def reset(self): self.octopus_intelligent_consider_full = False self.notify_devices = ["notify"] self.octopus_url_cache = {} + self.dispatch_timeline_last = {} self.ge_url_cache = {} self.github_url_cache = {} self.load_minutes = {} diff --git a/apps/predbat/tests/test_dispatch_timeline.py b/apps/predbat/tests/test_dispatch_timeline.py index 2c96f60ee..2984fb256 100644 --- a/apps/predbat/tests/test_dispatch_timeline.py +++ b/apps/predbat/tests/test_dispatch_timeline.py @@ -9,9 +9,10 @@ # pylint: disable=attribute-defined-outside-init """ -Unit tests for Octopus.build_dispatch_timeline() - the #4516 Stage 1 diagnostic dispatch-timeline -render helper. Purely observational (not used for any rate/plan decision yet), so these tests only -check the rendered status string, not any side effect on rates or the plan. +Unit tests for Octopus.build_dispatch_timeline() and dispatch_timeline_should_log() - the #4516 +Stage 1 diagnostic dispatch-timeline render and its heartbeat/change-triggered logging decision. +Purely observational (not used for any rate/plan decision yet), so these tests only check the +rendered status string and the logging decision, not any side effect on rates or the plan. """ from datetime import datetime, timedelta @@ -43,6 +44,7 @@ def run_dispatch_timeline_tests(my_predbat): saved_now_utc = my_predbat.now_utc saved_midnight_utc = my_predbat.midnight_utc saved_minutes_now = my_predbat.minutes_now + saved_dispatch_timeline_last = my_predbat.dispatch_timeline_last saved_charge_window_best = my_predbat.charge_window_best saved_charge_limit_best = my_predbat.charge_limit_best @@ -193,10 +195,52 @@ def run_dispatch_timeline_tests(my_predbat): my_predbat.charge_window_best = [] my_predbat.charge_limit_best = [] + # ------------------------------------------------------------------ + # dispatch_timeline_should_log() - #4948 review: a heartbeat every 30 minutes alone would + # miss a provisional slot that appears and disappears entirely within one half-hour window. + my_predbat.dispatch_timeline_last = {} + + print("Test 13: minute 0 (a 30-min boundary) always logs, unmarked, as a heartbeat") + my_predbat.minutes_now = 10 * 60 # 10:00, a boundary + should_log, marker = my_predbat.dispatch_timeline_should_log(0, "....") + if not (should_log and marker == ""): + print(" ERROR: expected a heartbeat to log with no marker, got should_log={!r} marker={!r}".format(should_log, marker)) + failed = True + + print("Test 14: off-boundary with no change since the last log does not log") + my_predbat.minutes_now = 10 * 60 + 5 # not a boundary + should_log, marker = my_predbat.dispatch_timeline_should_log(0, "....") + if should_log: + print(" ERROR: an unchanged timeline off-boundary should not log, got should_log={!r} marker={!r}".format(should_log, marker)) + failed = True + + print("Test 15: off-boundary with a change logs immediately, marked") + should_log, marker = my_predbat.dispatch_timeline_should_log(0, "...P") + if not (should_log and marker == " *"): + print(" ERROR: a changed timeline off-boundary should log marked ' *', got should_log={!r} marker={!r}".format(should_log, marker)) + failed = True + + print("Test 16: the same changed timeline does not log again next cycle") + my_predbat.minutes_now += 5 + should_log, marker = my_predbat.dispatch_timeline_should_log(0, "...P") + if should_log: + print(" ERROR: a timeline unchanged since the change-triggered log should not log again, got should_log={!r} marker={!r}".format(should_log, marker)) + failed = True + + print("Test 17: cars are tracked independently") + my_predbat.minutes_now = 11 * 60 + 5 # off-boundary, car 0 already logged "...P" + should_log, marker = my_predbat.dispatch_timeline_should_log(1, "...P") + if not (should_log and marker == " *"): + print(" ERROR: a second car's first-seen timeline should log independently of car 0's, got should_log={!r} marker={!r}".format(should_log, marker)) + failed = True + + my_predbat.dispatch_timeline_last = {} + finally: my_predbat.now_utc = saved_now_utc my_predbat.midnight_utc = saved_midnight_utc my_predbat.minutes_now = saved_minutes_now + my_predbat.dispatch_timeline_last = saved_dispatch_timeline_last my_predbat.charge_window_best = saved_charge_window_best my_predbat.charge_limit_best = saved_charge_limit_best