Merge pull request 'SAFETY-137: the shutdown 0 W must be the last write every unit hears' (#240) from SAFETY-137 into release/1.0

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]]).

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).

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()]
+        await self._await_inflight(inv, SETTLE_BUDGET_S)
-        if pending:
-            await asyncio.wait(pending, timeout=RELEASE_BUDGET_S / 2)
         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 / SAFETY-137: kept for every driver, so a release or a last
-                # SMA-10: kept, so a release can wait for it (`_release_last`)
+            # 0 W can wait for it (`_await_inflight`).
-                _w = asyncio.ensure_future(_w)
+            _w = asyncio.ensure_future(_w)
-                inv.inflight.add(_w)
+            inv.inflight.add(_w)
-                _w.add_done_callback(inv.inflight.discard)
+            _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:

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

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.<name>()` in main.py."""
+    """Line numbers of every `await self.<name>(...)` in main.py (SAFETY-137:
-    return [i + 1 for i, ln in enumerate(ss) if f"await self.{name}()" in ln]
+    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")