diff --git a/goodwe_controller/CHANGELOG.md b/goodwe_controller/CHANGELOG.md index 5d02a9f..67ecef3 100644 --- a/goodwe_controller/CHANGELOG.md +++ b/goodwe_controller/CHANGELOG.md @@ -2,6 +2,7 @@ ### Not in a release yet +- When the add-on stops, a command that was already on its way can no longer reach an inverter after the 0 W. The 0 W is now the last thing every inverter gets, also when Stop is pressed ([[SAFETY-137]]). - When the add-on stops, an inverter that can steer itself is handed back instead of held at 0 W. Safety stops still hold 0 W, and a GoodWe site is not affected ([[SMA-10]]). - Each inverter is now reached through a driver, so another make can be added later. Nothing changes for a GoodWe site ([[SMA-2]]). - Home now draws today's charge from the grid for every hour the add-on will really charge, not only the run under way ([[UX-77]]). diff --git a/goodwe_controller/DECISIONS/SAFETY-137-last-write-is-zero.md b/goodwe_controller/DECISIONS/SAFETY-137-last-write-is-zero.md new file mode 100644 index 0000000..c558f07 --- /dev/null +++ b/goodwe_controller/DECISIONS/SAFETY-137-last-write-is-zero.md @@ -0,0 +1,21 @@ +# SAFETY-137 - the shutdown 0 W is the last write every unit hears + +SMA-10 made a hand-back release wait for a write already on its way +(`_release_last`, `Inverter.inflight`). A GoodWe unit skipped that, and rig 5b +saw a cycle write (-2 823 W) land after the shutdown 0 W and stay until relaunch. + +Now the 0 W of shutdown and of the Stop button is a *last* write +(`_write_unit(last=True)`), for every driver: + +- It first waits, at most `SETTLE_BUDGET_S` (2 s), for the writes already on + its way to that unit (`_await_inflight`, shared with `_release_last`). A hung + write is not waited out and not cancelled; the 0 W goes anyway. +- Once shutdown has begun (`stopping`), every other write (cycle, heartbeat, + safety stop) is dropped at the same place, right before the write is created. + That is the gate that keeps the control cycle quiet; the cycle itself needs + no cancelling. +- Worst case for a GoodWe unit is 2 s + `WRITE_BUDGET_S` (4 s) = 6 s, the same + as `HAND_BACK_WORST_S`; the units are handled together. + +Not touched: the heartbeat's own timing, safety-stop paths, the maintenance +abort (still a plain 0 W). diff --git a/goodwe_controller/app/main.py b/goodwe_controller/app/main.py index 6b2e6fe..25def79 100644 --- a/goodwe_controller/app/main.py +++ b/goodwe_controller/app/main.py @@ -153,6 +153,13 @@ RELEASE_BUDGET_S = WRITE_BUDGET_S FALLBACK_BUDGET_S = 2.0 HAND_BACK_WORST_S = RELEASE_BUDGET_S + FALLBACK_BUDGET_S +# SAFETY-137. How long a LAST write (the Stop 0 W, the shutdown 0 W, a release) +# waits for a write already on its way to the same unit. Half the release +# budget, as `_release_last` always waited. For a GoodWe unit that is +# SETTLE_BUDGET_S + WRITE_BUDGET_S = 6 s at worst, which is HAND_BACK_WORST_S: +# the wind-down is no slower than SMA-10's worst case. +SETTLE_BUDGET_S = RELEASE_BUDGET_S / 2 + # SAFETY-34: a Core-only restart wipes persistent_notification and does NOT # restart this add-on (measured on TEST-23), so a latched alarm is re-asserted # this often. Why: goodwe docs/DECISIONS.md, SAFETY-34. @@ -4020,7 +4027,7 @@ class Controller: return rec.authorises(inv.name, value, self.alloc_tick) async def write_setpoint(self, value: float, *, force: bool = False, - unit=None) -> None: + unit=None, last: bool = False) -> None: """Put `value` on ONE inverter, or - with `unit=None` - on all of them. ⚠️ `unit=None` IS FOR A NUMBER THAT IS NOT A SHARE. The stop button, @@ -4059,16 +4066,23 @@ class Controller: targets = [unit] if not targets: return - await asyncio.gather(*(self._write_unit(inv, value, force=force) + await asyncio.gather(*(self._write_unit(inv, value, force=force, + last=last) for inv in targets)) + async def _await_inflight(self, inv, budget_s: float) -> None: + """Wait, at most `budget_s`, for the writes already on their way to + `inv` (SAFETY-137: every driver, GoodWe too). A write still running at + the bound is left alone, not cancelled: its own WRITE_BUDGET_S ends it.""" + pending = [t for t in inv.inflight if not t.done()] + if pending: + await asyncio.wait(pending, timeout=budget_s) + async def _release_last(self, inv) -> bool: """`release()`, after a write already on its way to `inv` has finished (at most half the budget is spent waiting for it), so the release is the LAST thing the unit hears and a late write cannot undo it.""" - pending = [t for t in inv.inflight if not t.done()] - if pending: - await asyncio.wait(pending, timeout=RELEASE_BUDGET_S / 2) + await self._await_inflight(inv, SETTLE_BUDGET_S) return await self._driver(inv).release() async def _hand_back(self, inv, *, force: bool = False) -> bool: @@ -4141,7 +4155,8 @@ class Controller: _LOG.debug("The fallback write to %s failed: %r", inv.name, err) return False - async def _write_unit(self, inv, value: float, *, force: bool = False) -> None: + async def _write_unit(self, inv, value: float, *, force: bool = False, + last: bool = False) -> None: if not inv.driver.configured(): return # --- SMA-10: A UNIT THAT HANDS BACK IS NOT WRITTEN WHILE THE ADD-ON IS @@ -4284,6 +4299,21 @@ class Controller: value, inv.name, shadow.WIRE_W) value = shadow.WIRE_W + # --- SAFETY-137: THE 0 W THAT ENDS THINGS IS THE LAST WRITE THE UNIT + # HEARS. `last` is the Stop 0 W and the shutdown 0 W (and nothing else). + # It first waits, bounded, for a write already on its way to this unit, + # so that write cannot land after it. And once shutdown has begun every + # other write (cycle, heartbeat, a safety stop) is dropped here: the + # check sits right before the write is created with no await between, + # so a write that starts after it cannot exist, and one that started + # before is in `inflight` for the wait above. The idle gate for a + # hand-back unit is higher up and does the same for those. + if last: + await self._await_inflight(inv, SETTLE_BUDGET_S) + elif self.stopping: + _LOG.debug("Shutting down, so %+.0f W to %s is not sent.", + value, inv.name) + return changed = (inv.last_write is None or value != inv.last_write) if not (changed or force): return @@ -4295,11 +4325,11 @@ class Controller: # `changed` is still true. try: _w = self._driver(inv).write(value) - if inv.driver.hands_back: - # SMA-10: kept, so a release can wait for it (`_release_last`) - _w = asyncio.ensure_future(_w) - inv.inflight.add(_w) - _w.add_done_callback(inv.inflight.discard) + # SMA-10 / SAFETY-137: kept for every driver, so a release or a last + # 0 W can wait for it (`_await_inflight`). + _w = asyncio.ensure_future(_w) + inv.inflight.add(_w) + _w.add_done_callback(inv.inflight.discard) ok = await asyncio.wait_for(_w, timeout=WRITE_BUDGET_S) except (asyncio.TimeoutError, TimeoutError): ok = False @@ -7209,17 +7239,17 @@ class Controller: call takes no longer than its slowest bound. """ if not any(inv.driver.hands_back for inv in self.inverters): - await self.command_site_zero() + await self.command_site_zero(last=True) return self.target = 0.0 for inv in self.inverters: inv.target = 0.0 await asyncio.gather(*( self._hand_back(inv, force=True) if inv.driver.hands_back - else self._write_unit(inv, 0.0, force=True) + else self._write_unit(inv, 0.0, force=True, last=True) for inv in self.inverters)) - async def command_site_zero(self) -> None: + async def command_site_zero(self, *, last: bool = False) -> None: """Every inverter to 0 W, and every inverter's TARGET to 0 W with it. ⚠️ THE SECOND HALF IS NOT BOOKKEEPING, AND IT IS A HAZARD DEV-02 @@ -7241,7 +7271,7 @@ class Controller: self.target = 0.0 for inv in self.inverters: inv.target = 0.0 - await self.write_setpoint(0.0, force=True) + await self.write_setpoint(0.0, force=True, last=last) # -- UI ------------------------------------------------------------------ def checks(self, when: datetime | None = None) -> list: diff --git a/goodwe_controller/test_safety137_last_write.py b/goodwe_controller/test_safety137_last_write.py new file mode 100644 index 0000000..483109f --- /dev/null +++ b/goodwe_controller/test_safety137_last_write.py @@ -0,0 +1,332 @@ +"""SAFETY-137: the 0 W of shutdown and of the Stop button is the last write every +unit hears. `python3 test_safety137_last_write.py` + +A cycle write already on its way (0.3-0.6 s, or hung) must not land after the +0 W, for a GoodWe unit and for a fake unit that does not hand back, at N=1 and +N=2, at shutdown and at Stop. The control cycle (and the heartbeat) issue no +new write once shutdown has begun. The whole wind-down stays inside +HAND_BACK_WORST_S (6 s) when a write hangs. + +Mutating a module this file grades? Read MUTATION.md first (purge __pycache__). +The mutants this file was run against are listed at the end. +""" + +import asyncio +import sys +import time +from pathlib import Path + +HERE = Path(__file__).resolve().parent +sys.path.insert(0, str(HERE)) + +from app import main as M # noqa: E402 +from app.drivers import Driver, Probe, REGISTRY # noqa: E402 +from app.main import Controller # noqa: E402 +from app.store import DEFAULTS # noqa: E402 + +fails = [] + + +def check(name, cond): + print(f" {'ok ' if cond else 'FAIL'} {name}") + if not cond: + fails.append(name) + + +class PlainFake(Driver): + """A unit that does not hand back (so, like GoodWe, no release()). A write + of anything but 0 W takes `delay` s to land; every write is logged when it + LANDS (`landed`) and when it STARTS (`started`).""" + name = "plainfake" + writer_key = "host" + brand = "Fake" + hands_back = False + delay = 0.0 + + def __init__(self, host="", port=502, unit_id=1, rating=2000.0): + self.host, self.port, self.unit_id = host, port, unit_id + self.rating, self.power = rating, 0.0 + self.landed, self.started = [], [] + + @classmethod + def from_entry(cls, entry): + return cls(entry.get("host", ""), entry.get("port", 502), + entry.get("unit_id", 1)) + + @classmethod + def actuator_id_of(cls, entry): + host = str(entry.get("host") or "").strip() + return f"{host}:{entry.get('port', 502)}:{entry.get('unit_id', 1)}" \ + if host else "" + + def configured(self): + return bool(self.host) + + def actuator_id(self): + return f"{self.host}:{self.port}:{self.unit_id}" + + def soc_source(self): + return "fake-soc" + + def batt_source(self): + return "fake-power" + + async def limits(self): + return -self.rating, self.rating + + async def read(self): + return 60.0, self.power, {} + + async def write(self, w): + self.started.append((time.monotonic(), float(w))) + if w != 0 and self.delay: + await asyncio.sleep(self.delay) + self.landed.append((time.monotonic(), float(w))) + self.power = w + return True + + async def probe(self): + return Probe(-self.rating, self.rating, 60.0, self.power, {}) + + +REGISTRY["plainfake"] = PlainFake + + +class MemStore: + def __init__(self): + self.data = dict(DEFAULTS) + + def set(self, k, v): + self.data[k] = v + + def get_time(self, *a): + return None + + def set_time(self, *a): + pass + + +class Pub: + enabled = False + + def publish(self, values): + pass + + def close(self): + pass + + +class SlowHass: + """Home Assistant for the GoodWe units. A set_number of anything but 0 W + takes `delay` s to land; the log gets the write when it lands.""" + + def __init__(self): + self.delay = 0.0 + self.landed, self.started = [], [] # (t, entity, value) + self.numbers = {"sensor.grid": 3000.0, "sensor.soc_a": 50.0, + "sensor.batt_a": 0.0, "sensor.soc_b": 50.0, + "sensor.batt_b": 0.0} + + async def number(self, entity, invert=False): + return self.numbers.get(entity) + + async def limits(self, entity): + return (-3000.0, 3000.0, 1.0) + + async def set_number(self, entity, value): + self.started.append((time.monotonic(), entity, value)) + if value != 0 and self.delay: + await asyncio.sleep(self.delay) + self.landed.append((time.monotonic(), entity, value)) + return True + + async def state(self, entity): + return None + + async def call(self, *a): + return True + + +def gw(name, suffix): + return dict(name=name, setpoint_entity=f"number.sp_{suffix}", + soc_entity=f"sensor.soc_{suffix}", + batt_entity=f"sensor.batt_{suffix}", max_w=3000, + bms_soc_floor=10) + + +def fk(name): + return dict(name=name, driver="plainfake", host="10.9.9.9", port=502, + unit_id=3, max_w=2000, bms_soc_floor=10) + + +ROSTERS = { + "N=1 GoodWe": [gw("inverter-a", "a")], + "N=1 fake": [fk("inverter-a")], + "N=2 GoodWe+GoodWe": [gw("inverter-a", "a"), gw("inverter-b", "b")], + "N=2 GoodWe+fake": [gw("inverter-a", "a"), fk("inverter-b")], +} + + +def site(inverters, delay): + opts = dict(meter_source="off", meter_entity="sensor.grid", max_w=5000, + gain=0.6, slew_w=0, deadband_w=15, target_grid_w=0, step_w=10, + heartbeat_s=10, stale_input_s=15, shadow_mode="off", + inverters=inverters) + hass = SlowHass() + hass.delay = delay + c = Controller(opts, hass, MemStore(), Pub(), stop=asyncio.Event()) + for inv in c.inverters: + inv.dev_min, inv.dev_max = -3000.0, 3000.0 + if isinstance(inv.driver, PlainFake): + inv.driver.delay = delay + c.auto = True + return c, hass + + +def per_unit(c, hass, kind="landed"): + """name -> [(t, value)] in the order the writes LANDED (or started).""" + out = {} + for inv in c.inverters: + d = inv.driver + if isinstance(d, PlainFake): + out[inv.name] = list(getattr(d, kind)) + else: + ent = d.setpoint_entity + out[inv.name] = [(t, v) for t, e, v in getattr(hass, kind) + if e == ent] + return out + + +async def cycles(c, n=2): + for _ in range(n): + await c.read_inputs() + await c.cycle() + + +async def in_flight(c): + """A cycle write on its way to every unit (what rig 5b had): the real + cycle, whose writes are authorised and take `delay` s to land.""" + tasks = [asyncio.ensure_future(cycles(c, 1))] + await asyncio.sleep(0.1) + assert all(not t.done() for t in tasks) + return tasks + + +async def finish(tasks): + for t in tasks: + t.cancel() + for t in tasks: + try: + await t + except BaseException: # noqa: BLE001 - cancelled or timed out + pass + + +def last_is_zero(c, hass): + got = per_unit(c, hass) + return all(w and w[-1][1] == 0.0 for w in got.values()), got + + +def scenario(label, inverters, how, delay): + """how: 'shutdown' or 'stop'. Returns (seconds, ok, detail).""" + c, hass = site(inverters, delay) + + async def go(): + tasks = await in_flight(c) + t0 = time.monotonic() + if how == "shutdown": + await c.shutdown() + else: + await c.handle_action("auto_toggle") # Stop + dt = time.monotonic() - t0 + # let a write that is still on its way land, to see if it overtakes + await asyncio.sleep(0.8 if delay < 5 else 0.0) + await finish(tasks) + return dt + + dt = asyncio.run(go()) + ok, got = last_is_zero(c, hass) + n_sent = {n: len(w) for n, w in got.items()} + check(f"{label}: the cycle write was on its way at {how} (test sees it)", + all(len(w) >= 2 for w in per_unit(c, hass, "started").values())) + print(f" {label}: {how}, delay {delay} s: {dt:.2f} s, " + f"landed per unit {n_sent}, last " + f"{ {n: (w[-1][1] if w else None) for n, w in got.items()} }") + return dt, ok, got + + +print("SAFETY-137 - the 0 W is the last write") + +print("1. a slow write on its way (0.3 s, 0.6 s) when shutdown / Stop starts") +for label, roster in ROSTERS.items(): + for how in ("shutdown", "stop"): + for delay in (0.3, 0.6): + dt, ok, got = scenario(label, roster, how, delay) + check(f"{label}, {how}, {delay} s in flight: the last write per " + f"unit is 0 W", ok) + check(f"{label}, {how}, {delay} s in flight: the slow write " + f"landed first, then the 0 W (not dropped, not overtaken)", + all(len(w) >= 2 and w[-2][1] != 0.0 + for w in got.values())) + check(f"{label}, {how}: took about the write, not the budget " + f"({dt:.2f} s)", dt < delay + 1.0) + +print("2. a hung write on its way: the 0 W still reaches every unit, in time") +for label, roster in ROSTERS.items(): + for how in ("shutdown", "stop"): + dt, ok, got = scenario(label, roster, how, 3600.0) + check(f"{label}, {how}, hung write: 0 W landed on every unit and is " + f"its last write", ok) + check(f"{label}, {how}, hung write: inside HAND_BACK_WORST_S " + f"({dt:.2f} s <= {M.HAND_BACK_WORST_S:.0f} s)", + dt <= M.HAND_BACK_WORST_S) + check(f"{label}, {how}, hung write: the 0 W goes after the settle " + f"wait ({M.SETTLE_BUDGET_S:.0f} s), not after the write's own " + f"budget ({dt:.2f} s)", dt <= M.SETTLE_BUDGET_S + 0.5) + +print("3. no new write once shutdown has begun (cycle, heartbeat)") +for label, roster in ROSTERS.items(): + c, hass = site(roster, 0.4) + + async def go3(): + tasks = await in_flight(c) + s = asyncio.ensure_future(c.shutdown()) + await asyncio.sleep(0) # shutdown has begun + begun = time.monotonic() + await cycles(c, 3) # would write: grid 3000 W + await c.send_heartbeats(10 ** 9, 10) # every unit is due + await asyncio.wait_for(s, 10) + await asyncio.sleep(0.8) + await finish(tasks) + return begun + + begun = asyncio.run(go3()) + starts = per_unit(c, hass, "started") + late = {n: [v for t, v in w if t >= begun and v != 0.0] + for n, w in starts.items()} + check(f"{label}: no non-zero write started after shutdown began " + f"({late})", all(not v for v in late.values())) + ok, got = last_is_zero(c, hass) + check(f"{label}: and the last write per unit is 0 W", ok) + # sanity: the same cycles DO write before shutdown + c2, hass2 = site(roster, 0.0) + asyncio.run(cycles(c2, 3)) + before = per_unit(c2, hass2, "started") + check(f"{label}: control, same cycles before shutdown, write non-zero " + f"(the test can see a write)", + all(any(v != 0.0 for _t, v in w) for w in before.values())) + +print() +if fails: + print(f"FAILED {len(fails)}:") + for f in fails: + print(" -", f) + sys.exit(1) +print("all ok") + +# MUTANTS this file was run against (each must turn it red): +# (a) _await_inflight does nothing (no wait for in-flight writes), GoodWe too +# (b) the `elif self.stopping: return` gate removed (cycle not stopped) +# (c) `last=True` not passed by command_site_release (Stop/shutdown 0 W is a +# plain write) +# (d) the wait unbounded (no timeout): red on the settle-bound check diff --git a/goodwe_controller/test_sma10_two_idle_states.py b/goodwe_controller/test_sma10_two_idle_states.py index d88d2f1..b395333 100644 --- a/goodwe_controller/test_sma10_two_idle_states.py +++ b/goodwe_controller/test_sma10_two_idle_states.py @@ -1103,8 +1103,9 @@ ss = src.splitlines() def calls_in(name): - """Line numbers of every `await self.()` in main.py.""" - return [i + 1 for i, ln in enumerate(ss) if f"await self.{name}()" in ln] + """Line numbers of every `await self.(...)` in main.py (SAFETY-137: + the all-GoodWe branch passes `last=True`).""" + return [i + 1 for i, ln in enumerate(ss) if f"await self.{name}(" in ln] rel, zer = calls_in("command_site_release"), calls_in("command_site_zero")