Skip to content

Commit 8b67d5e

Browse files
feat(octopus): log a diagnostic IOG dispatch timeline (#4516 Stage 1) (#4948)
* 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. * 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 <noreply@anthropic.com> * 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 <noreply@anthropic.com> * 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 <noreply@anthropic.com> --------- Co-authored-by: Claude Opus 5 <noreply@anthropic.com>
1 parent 64a58d6 commit 8b67d5e

5 files changed

Lines changed: 369 additions & 1 deletion

File tree

‎apps/predbat/fetch.py‎

Lines changed: 13 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1402,6 +1402,7 @@ def fetch_sensor_data_cars(self):
14021402

14031403
completed = []
14041404
planned = []
1405+
started = []
14051406

14061407
if entity_id and "octopus_intelligent_slot_action_config" in self.args:
14071408
config_entry = self.get_arg("octopus_intelligent_slot_action_config", None, indirect=False)
@@ -1415,10 +1416,22 @@ def fetch_sensor_data_cars(self):
14151416
try:
14161417
completed = self.get_state_wrapper(entity_id=entity_id, attribute="completed_dispatches") or self.get_state_wrapper(entity_id=entity_id, attribute="completedDispatches")
14171418
planned = self.get_state_wrapper(entity_id=entity_id, attribute="planned_dispatches") or self.get_state_wrapper(entity_id=entity_id, attribute="plannedDispatches")
1419+
# Not merged into octopus_slots or used for any rate/plan decision yet - read
1420+
# only for the #4516 Stage 1 diagnostic timeline log below, to observe whether
1421+
# this is a trustworthy earlier-than-completed confirmation signal before
1422+
# building any gating logic on it (Stage 2, deferred).
1423+
started = self.get_state_wrapper(entity_id=entity_id, attribute="started_dispatches") or self.get_state_wrapper(entity_id=entity_id, attribute="startedDispatches")
14181424
except (ValueError, TypeError):
14191425
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))
14201426
self.record_status(message="Error: octopus_intelligent_slot not set correctly in apps.yaml for car {}".format(car_n), had_errors=True)
14211427

1428+
# #4516 Stage 1: diagnostic dispatch-timeline log. Purely observational - see
1429+
# build_dispatch_timeline()'s and dispatch_timeline_should_log()'s docstrings.
1430+
timeline = self.build_dispatch_timeline(car_n, completed, started, planned)
1431+
should_log, marker = self.dispatch_timeline_should_log(car_n, timeline)
1432+
if should_log:
1433+
self.log("Octopus: Dispatch timeline car {} @ {} [-4h..+24h]: {}{}".format(car_n, self.time_abs_str(self.minutes_now), timeline, marker))
1434+
14221435
# Completed and planned slots - merge from all cars
14231436
if completed:
14241437
self.octopus_slots[car_n] += completed

‎apps/predbat/octopus.py‎

Lines changed: 101 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -2910,9 +2910,14 @@ def load_saving_slot(self, octopus_saving_slots, rate_dict, export=False, rate_r
29102910
if not export:
29112911
self.load_scaling_dynamic[minute] = self.load_scaling_saving
29122912

2913-
def decode_octopus_slot(self, car_n, slot, raw=False):
2913+
def decode_octopus_slot(self, car_n, slot, raw=False, boundaries_only=False):
29142914
"""
29152915
Decode IOG slot
2916+
2917+
boundaries_only skips the kWh/source/location handling below - including the "remove
2918+
empty slots" check, which real HA-integration started_dispatches entries (start/end only,
2919+
no kWh, source or location) would otherwise trip, decoding them as empty (#4516 Stage 1's
2920+
build_dispatch_timeline() review). Only start/end are meaningful there.
29162921
"""
29172922
if "start" in slot:
29182923
start = datetime.strptime(slot["start"], TIME_FORMAT)
@@ -2936,6 +2941,9 @@ def decode_octopus_slot(self, car_n, slot, raw=False):
29362941
if start_minutes == end_minutes:
29372942
return 0, 0, 0, source, location
29382943

2944+
if boundaries_only:
2945+
return start_minutes, end_minutes, 0, source, location
2946+
29392947
cap_minutes = end_minutes - start_minutes
29402948

29412949
# The load expected is stored in chargeKwh for the period in use
@@ -3021,6 +3029,98 @@ def get_octopus_slot_max(self):
30213029
return OCTOPUS_SLOT_MAX_CAPPED
30223030
return OCTOPUS_SLOT_MAX_DEFAULT
30233031

3032+
def build_dispatch_timeline(self, car_n, completed, started, planned, window_before_hours=4, window_after_hours=24, step=30):
3033+
"""
3034+
Build a fixed-width, one-character-per-block dispatch status string for the diagnostic
3035+
timeline log (#4516 Stage 1 - not yet used for any rate/plan decision, purely observational).
3036+
3037+
Each character covers `step` minutes, offset from now, spanning
3038+
[-window_before_hours, +window_after_hours). '.' = nothing known, 'P' = planned
3039+
(provisional), 'S' = started, 'C' = completed. Where lists disagree on the same block, the
3040+
most-confirmed status wins (completed > started > planned) - reflects Octopus's own view
3041+
having moved on, not a genuine simultaneous claim.
3042+
3043+
The letter is lowercased where Predbat's own plan charges in that block, so 'p' is a
3044+
provisional slot Predbat is relying on and 'P' one it is not. That distinction is the
3045+
point: a slot that disappears having never been planned against costs nothing, while one
3046+
Predbat committed an import to is a plan that will not happen.
3047+
3048+
Stacking consecutive lines (a heartbeat one per 30-minute boundary, plus one on any
3049+
earlier change - see the caller in fetch.py) in a monospace log viewer reveals dispatch
3050+
lifecycle as diagonal stripes: a specific dispatch drifts one column per line as `now`
3051+
advances, so a rescinded slot shows as a stripe that stops before reaching the `now`
3052+
column, while a genuinely-delivered one runs through into 'C'.
3053+
"""
3054+
total_before = window_before_hours * 60
3055+
total_after = window_after_hours * 60
3056+
num_blocks = (total_before + total_after) // step
3057+
status = ["."] * num_blocks
3058+
3059+
def mark(slots, char):
3060+
for slot in slots or []:
3061+
start_minutes, end_minutes, _, _, _ = self.decode_octopus_slot(car_n, slot, raw=True, boundaries_only=True)
3062+
if start_minutes == end_minutes:
3063+
continue
3064+
start_offset = start_minutes - self.minutes_now
3065+
end_offset = end_minutes - self.minutes_now
3066+
block_start = max(0, (start_offset + total_before) // step)
3067+
block_end = min(num_blocks, -(-(end_offset + total_before) // step)) # ceil division
3068+
for block in range(int(block_start), int(block_end)):
3069+
status[block] = char
3070+
3071+
mark(planned, "P")
3072+
mark(started, "S")
3073+
mark(completed, "C")
3074+
3075+
# Lowercase where Predbat's own plan plans to import - so a stripe shows not just the
3076+
# dispatch's lifecycle but whether Predbat had committed a charge window to it. A slot
3077+
# that reads 'p' and then vanishes before reaching the now column is one Predbat planned
3078+
# around and lost, which is the case a plain P/S/C timeline cannot distinguish from a
3079+
# slot nothing depended on.
3080+
#
3081+
# This runs in fetch, before the planner, so the windows are the *previous* cycle's plan -
3082+
# one 5-minute cycle stale against 30-minute blocks. That is deliberate: what Predbat
3083+
# believed while the slot was still live is the more useful thing to record.
3084+
for window_n, window in enumerate(self.charge_window_best or []):
3085+
if window_n < len(self.charge_limit_best or []) and self.charge_limit_best[window_n] <= 0:
3086+
continue
3087+
start_offset = window.get("start", 0) - self.minutes_now
3088+
end_offset = window.get("end", 0) - self.minutes_now
3089+
block_start = max(0, (start_offset + total_before) // step)
3090+
block_end = min(num_blocks, -(-(end_offset + total_before) // step))
3091+
for block in range(int(block_start), int(block_end)):
3092+
if status[block] in ("P", "S", "C"):
3093+
status[block] = status[block].lower()
3094+
3095+
return "".join(status)
3096+
3097+
def dispatch_timeline_should_log(self, car_n, timeline):
3098+
"""
3099+
Decide whether fetch.py should log a dispatch-timeline diagnostic line this cycle, and
3100+
what marker to append if so.
3101+
3102+
A 30-minute heartbeat always logs - dispatch decisions are 30-min-granular anyway, so log
3103+
volume stays sane at that cadence - but a change from the last logged timeline for this
3104+
car also logs immediately outside that boundary, marked with a trailing ' *' (#4948
3105+
review). Without this, a provisional slot that appears and disappears entirely within one
3106+
half-hour window would never appear in this log at all, however briefly Predbat's own
3107+
plan relied on it - exactly the pattern this diagnostic exists to catch.
3108+
3109+
The marker is a suffix, appended by the caller after build_dispatch_timeline()'s
3110+
fixed-width string, rather than a prefix - so heartbeat and change-triggered lines still
3111+
stack column-for-column in a monospace viewer. That alignment is the whole point of the
3112+
render: consecutive lines are meant to line up into diagonal stripes.
3113+
3114+
Records the new timeline as "last logged" as a side effect whenever this returns True, so
3115+
a caller must log with the returned marker exactly when told to, and no other times.
3116+
"""
3117+
is_heartbeat = self.minutes_now % 30 == 0
3118+
changed = timeline != self.dispatch_timeline_last.get(car_n)
3119+
if not (is_heartbeat or changed):
3120+
return False, ""
3121+
self.dispatch_timeline_last[car_n] = timeline
3122+
return True, "" if is_heartbeat else " *"
3123+
30243124
def load_octopus_slots(self, car_n, octopus_slots, octopus_intelligent_consider_full):
30253125
"""
30263126
Turn octopus slots into charging plan

‎apps/predbat/predbat.py‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -497,6 +497,7 @@ def reset(self):
497497
self.octopus_intelligent_consider_full = False
498498
self.notify_devices = ["notify"]
499499
self.octopus_url_cache = {}
500+
self.dispatch_timeline_last = {}
500501
self.ge_url_cache = {}
501502
self.github_url_cache = {}
502503
self.load_minutes = {}

0 commit comments

Comments
 (0)