SMA-10 round 2: a failed release sends 0 W once, retries at heartbeat pace

When release() fails (False, raises or hangs past RELEASE_BUDGET_S) the unit
gets one bounded write(0) through the new Driver.release_fallback() hook
(default write(0)), then nothing more, so the inverter's own fallback timer is
not reset. The release is retried once per heartbeat, not on every idle
write. One error line and one action-log event per failure streak, one line on
recovery. Dutch default "terug naar de eigen sturing". DECISIONS says what a
unit is left at.

test_messages.py: the RELEASE_BUDGET_S data entry is gone again (the line
that needed it is gone).

Co-Authored-By: Claude <noreply@anthropic.com>

goodwe_controller/DECISIONS/SMA-10-two-idle-states.md

@@ -49,3 +49,12 @@ after `release()`, per-driver timing, DOCS.md's safety model and the
 "control stalled" sentence, the site-level "Held at 0 W" tiles in shadow mode on
 a mixed roster, and the MQTT per-unit setpoint of a handed-back unit (it still
 publishes 0).
+
+**After a failed release** (returns False, raises or hangs past the bound) the
+unit gets one `write(0)` through `Driver.release_fallback()` (default
+`write(0)`; a driver where 0 W is not always safe overrides it), then nothing:
+a repeated 0 W would keep resetting the inverter's own fallback timer, so after
+that the unit is left to its own fallback. The release is retried once per
+heartbeat; one error line and one action-log event per failure streak, one line
+on recovery. Worst case at shutdown is `RELEASE_BUDGET_S` + `FALLBACK_BUDGET_S`
+(6 s).

goodwe_controller/app/drivers.py

@@ -160,6 +160,14 @@ class Driver:
         never a release: that is `write(0)`."""
         return await self.write(0.0)
 
+    async def release_fallback(self) -> bool:
+        """SMA-10 round 2. What to send, ONCE, when `release()` has failed
+        (False, raised, or hung past the bound), so the unit does not carry its
+        last command while nothing else steers it. Default: `write(0)`. It is
+        not repeated: a repeat would keep resetting the inverter's own fallback
+        timer. A driver for which 0 W is not always a safe hold overrides this."""
+        return await self.write(0.0)
+
     async def probe(self) -> Probe:
         """A read-only look, usable without a Controller (panel, wizard)."""
         raise NotImplementedError

goodwe_controller/app/handback.py

@@ -27,7 +27,7 @@ import re
 from dataclasses import dataclass
 
 _BACK_EN = "its own control"
-_BACK_NL = "eigen sturing"
+_BACK_NL = "de eigen sturing"
 
 
 @dataclass(frozen=True)

goodwe_controller/app/inverter.py

@@ -284,6 +284,12 @@ class Inverter:
         # SMA-10. Writes to a hand-back driver that are on their way (see
         # Controller._write_unit), so the release can wait for them and be LAST.
         self.inflight: set = set()
+        # SMA-10 round 2. A failed hand-back: how many tries in a row failed
+        # (the log is written at the first and on recovery only), when the next
+        # try is due (monotonic s), and whether the one fallback 0 W was sent.
+        self.release_fails = 0
+        self.release_retry_at = 0.0
+        self.release_zero_sent = False
         self.last_write_ok = None
         # ⚠️ TWO TIMESTAMPS, NOT ONE FLAG. `last_write_ok` is the last write's
         # verdict and it flips on a single transient 400; liveness needs a RUN

goodwe_controller/app/main.py

@@ -147,6 +147,12 @@ WRITE_BUDGET_S = 4.0
 # to it. A release still running at the bound is abandoned, not awaited.
 RELEASE_BUDGET_S = WRITE_BUDGET_S
 
+# SMA-10 round 2. The one fallback write after a failed release (default 0 W,
+# `Driver.release_fallback()`). Worst case for a unit whose release hangs:
+# RELEASE_BUDGET_S + FALLBACK_BUDGET_S = 6 s, against the Supervisor's 10 s.
+FALLBACK_BUDGET_S = 2.0
+HAND_BACK_WORST_S = RELEASE_BUDGET_S + FALLBACK_BUDGET_S
+
 # 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.
@@ -4065,7 +4071,7 @@ class Controller:
             await asyncio.wait(pending, timeout=RELEASE_BUDGET_S / 2)
         return await self._driver(inv).release()
 
-    async def _hand_back(self, inv) -> bool:
+    async def _hand_back(self, inv, *, force: bool = False) -> bool:
         """SMA-10. Give ONE unit back: exactly one `release()`, then nothing.
 
         True when the unit is handed back (now, or already). Never raises: a
@@ -4086,27 +4092,54 @@ class Controller:
             return True
         if not inv.driver.configured():
             return False
+        # After a failure the next try waits one heartbeat, so a hung release
+        # costs a cycle its 4 s once per heartbeat, not on every cycle. The
+        # Stop button and shutdown (`force`) always try.
+        now_m = time.monotonic()
+        if not force and now_m < inv.release_retry_at:
+            return False
         inv.released = True
+        why = ""
         try:
             ok = bool(await _bounded(self._release_last(inv),
                                      RELEASE_BUDGET_S))
         except (asyncio.TimeoutError, TimeoutError):
-            ok = False
-            _LOG.error("Handing back %s took over %.0f s and was dropped. It "
-                       "is tried again.", inv.name, RELEASE_BUDGET_S)
+            ok, why = False, f"took over {RELEASE_BUDGET_S:.0f} s"
         except Exception as err:  # noqa: BLE001 - one unit never stops the rest
-            ok = False
-            _LOG.error("Handing back %s failed: %s. It is tried again.",
-                       inv.name, err)
+            ok, why = False, f"{type(err).__name__}: {err}"
         if ok:
             inv.last_write = None
+            if inv.release_fails:
+                _LOG.info("Handing back %s worked again after %d failed "
+                          "tries.", inv.name, inv.release_fails)
+            inv.release_fails = 0
+            inv.release_retry_at = 0.0
+            inv.release_zero_sent = False
             self.log_event(f"{inv.name}: handed back",
                            hint=messages.hint("handed_back", unit=inv.name))
-        else:
-            inv.released = False
+            return True
+        inv.released = False
+        inv.release_fails += 1
+        inv.release_retry_at = now_m + float(self.o.get("heartbeat_s", 10))
+        _LOG.debug("Handing back %s failed (try %d): %s", inv.name,
+                   inv.release_fails, why)
+        if inv.release_fails == 1:          # one line per failure streak
+            _LOG.error("Handing back %s failed, so it is sent 0 W once and "
+                       "handing back is tried again.", inv.name)
             self.log_event(f"{inv.name}: hand-back failed",
                            hint=messages.hint("hand_back_failed", unit=inv.name))
-        return ok
+        if not inv.release_zero_sent:
+            # ⚠️ ONCE. The unit must not keep carrying its last command, but a
+            # 0 W re-sent on every try would reset the inverter's own fallback
+            # timer for ever. The driver says what the one write is.
+            inv.release_zero_sent = True
+            try:
+                if await _bounded(self._driver(inv).release_fallback(),
+                                  FALLBACK_BUDGET_S):
+                    inv.last_write = 0.0
+            except Exception as err:  # noqa: BLE001
+                _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:
         if not inv.driver.configured():
@@ -7176,7 +7209,7 @@ class Controller:
         for inv in self.inverters:
             inv.target = 0.0
         await asyncio.gather(*(
-            self._hand_back(inv) if inv.driver.hands_back
+            self._hand_back(inv, force=True) if inv.driver.hands_back
             else self._write_unit(inv, 0.0, force=True)
             for inv in self.inverters))
 

goodwe_controller/app/messages.py

@@ -1389,7 +1389,7 @@ HINTS = {
     "roster": "Inverter list read: {n} inverters",
     "maint_history": "Maintenance history did not move over cleanly",
     "handed_back": "{unit}: handed back, the add-on writes nothing to it",
-    "hand_back_failed": "{unit}: could not be handed back, trying again",
+    "hand_back_failed": "{unit}: could not be handed back, set to 0 W once, trying again",
     "stop_restored": "{unit}: an earlier safety stop is back, it stays at 0 W",
     "readings_late": "Home Assistant readings arrive late, control holds",
     "readings_back": "Home Assistant readings are on time again",

goodwe_controller/test_messages.py

@@ -851,7 +851,7 @@ DATA = {
     "main.py:inv.batt_fresh.bound.release_s", "main.py:inv.batt_fresh.bound.move_w",
     "main.py:inv.batt_fresh.bound.unchanged_s", "main.py:inv.batt_fresh.held",
     "main.py:value", "main.py:float(value)",
-    "main.py:entity", "main.py:WRITE_BUDGET_S", "main.py:RELEASE_BUDGET_S",
+    "main.py:entity", "main.py:WRITE_BUDGET_S",
     "main.py:_e",
     "main.py:messages.times(self.clamp_wd.engagements)",
     "main.py:messages.when(brussels(self.tariff_at))",

goodwe_controller/test_sma10_two_idle_states.py

@@ -336,6 +336,23 @@ def run(coro):
     return asyncio.run(coro)
 
 
+_real_time = M.time
+
+
+class _FakeTime:
+    """A clock the test moves; everything else is the real `time`."""
+    t = 1000.0
+
+    def monotonic(self):
+        return self.t
+
+    def __getattr__(self, name):
+        return getattr(_real_time, name)
+
+
+FT = _FakeTime()
+
+
 def gw(name="inverter-a", suffix="a"):
     return dict(name=name, setpoint_entity=f"number.sp_{suffix}",
                 soc_entity=f"sensor.soc_{suffix}",
@@ -853,10 +870,11 @@ run(c.command_site_release())
 took = time.monotonic() - t0
 print(f"    command_site_release() with one raising, one hanging and one "
       f"failing unit: {took:.2f} s "
-      f"(bound {M.RELEASE_BUDGET_S:.1f} s)")
-check("the bound: it returns within RELEASE_BUDGET_S plus a margin, however "
-      "many units hang (they run together)",
-      took < M.RELEASE_BUDGET_S + 1.5)
+      f"(release {M.RELEASE_BUDGET_S:.1f} s + fallback {M.FALLBACK_BUDGET_S:.1f}"
+      f" s = {M.HAND_BACK_WORST_S:.1f} s at most)")
+check("the bound: it returns within RELEASE_BUDGET_S + FALLBACK_BUDGET_S plus "
+      "a margin, however many units hang (they run together)",
+      took < M.HAND_BACK_WORST_S + 1.5)
 check("the healthy unit was released (once) and the GoodWe unit zeroed, "
       "though three others raised, failed or hung",
       n_calls(fd_ok, "release") == 1 and c.inverters[3].released
@@ -865,9 +883,13 @@ check("the units that raised, failed or hung are NOT marked handed back, so "
       "they are tried again", not any(c.inverters[i].released
                                       for i in (1, 2, 4)))
 fb_raise.mode = "ok"
+FT.t = _real_time.monotonic() + 11.0                   # one heartbeat later
+M.time = FT
 run(c.send_heartbeats(60_000.0, 10.0))
-check("...and the next idle write retries the one that raised (now answers): "
-      "released, and the healthy unit is not released a second time",
+M.time = _real_time
+check("...and the next idle write (a heartbeat later) retries the one that "
+      "raised (now answers): released, and the healthy unit is not released a "
+      "second time",
       n_calls(fb_raise, "release") == 2 and c.inverters[1].released
       and n_calls(fd_ok, "release") == 1)
 c, h, p = site([gw("inverter-a", "a"), fk("inverter-b"),
@@ -879,9 +901,111 @@ run(c.shutdown())
 took = time.monotonic() - t0
 check("shutdown() with one unit hanging finishes inside the bound, the other "
       "unit is released and the GoodWe unit at 0 W",
-      took < M.RELEASE_BUDGET_S + 1.5 and n_calls(fc_ok, "release") == 1
+      took < M.HAND_BACK_WORST_S + 1.5 and n_calls(fc_ok, "release") == 1
       and h.writes()[-1] == 0.0)
 
+# --- 3h2. a failed release: one 0 W, retries at heartbeat pace, logged once ---
+print("    (a failed release: the unit carries 1120 W)")
+_cap = []
+
+
+class _Cap2(logging.Handler):
+    def emit(self, rec):
+        _cap.append((rec.levelno, rec.getMessage()))
+
+
+_h2 = _Cap2()
+logging.getLogger("goodwe").addHandler(_h2)
+
+
+def failing_site(mode):
+    c, h, p = site([gw("inverter-a", "a"), fk("inverter-b")])
+    f = fakes(c)[0]
+    run(cycles(c, 5))
+    f.power = 1120.0                             # the unit carries 1120 W
+    f.mode = mode
+    return c, h, f
+
+
+for mode in ("false", "raise", "hang"):
+    c, h, f = failing_site(mode)
+    n_w = len(writes_of(f))
+    t0 = time.monotonic()
+    run(c.handle_action("auto_toggle"))          # Stop
+    took = time.monotonic() - t0
+    print(f"    Stop, release {mode}: {took:.2f} s; calls after: "
+          f"{[x for x in f.calls[-4:]]}")
+    check(f"FAILED RELEASE ({mode}): the unit that carried 1120 W gets exactly "
+          f"one 0 W write after the release, inside the bound",
+          writes_of(f)[n_w:] == [0.0] and n_calls(f, "release") == 1
+          and took < M.HAND_BACK_WORST_S + 1.5
+          and not c.inverters[1].released)
+    run(c.send_heartbeats(10_000.0, 10.0))
+    run(cycles(c, 3))
+    check(f"FAILED RELEASE ({mode}): heartbeats and cycles in the same moment "
+          f"add no write and no retry",
+          writes_of(f)[n_w:] == [0.0] and n_calls(f, "release") == 1)
+
+# the cadence and the log, over N failed retries on a clock we move
+c, h, f = failing_site("false")
+M.time = FT
+FT.t = 5000.0
+_cap.clear()
+run(c.handle_action("auto_toggle"))              # Stop: try 1 (forced)
+n_w = len(writes_of(f))
+N = 6
+for k in range(N):
+    for step in range(5):                        # idle writes inside a heartbeat
+        FT.t += 1.9
+        run(c.send_heartbeats(20_000.0 + FT.t, 10.0))
+        run(cycles(c, 1))
+    FT.t += 1.0                                  # the heartbeat is due
+    run(c.send_heartbeats(40_000.0 + FT.t, 10.0))
+print(f"    {N} heartbeats: release() called {n_calls(f, 'release')} times, "
+      f"0 W writes after the first: {writes_of(f)[n_w:]}")
+check("CADENCE: one try at Stop plus one per heartbeat, not one per idle "
+      "write", n_calls(f, "release") == 1 + N)
+check("ONE 0 W only, however many retries fail: the inverter's fallback timer "
+      "is not reset", writes_of(f)[n_w - 1:] == [0.0])
+errs = [m for lv, m in _cap if lv >= logging.ERROR and "inverter-b" in m]
+evs = [e for e in c.events if "hand-back failed" in str(e)]
+check(f"LOG: {N + 1} failed tries make ONE error line and ONE action-log event",
+      len(errs) == 1 and len(evs) == 1)
+f.mode = "ok"
+FT.t += 11.0
+run(c.send_heartbeats(90_000.0, 10.0))
+for _ in range(3):
+    FT.t += 11.0
+    run(c.send_heartbeats(95_000.0 + FT.t, 10.0))
+inf = [m for lv, m in _cap if "worked again" in m]
+check("RECOVERY: logged once ('worked again after 7 failed tries'), released, "
+      "and no further release() calls",
+      len(inf) == 1 and "7 failed" in inf[0] and c.inverters[1].released
+      and n_calls(f, "release") == 2 + N
+      and len([e for e in c.events if "inverter-b: handed back" in str(e)]) == 1)
+run(c.handle_action("auto_toggle"))               # Start
+run(cycles(c, 3))
+f.mode = "false"
+_cap.clear()
+run(c.handle_action("auto_toggle"))               # Stop, fails again
+check("a NEW failure streak is logged again, once",
+      len([1 for lv, m in _cap if lv >= logging.ERROR]) == 1)
+M.time = _real_time
+
+# shutdown with a failed release: the one 0 W still goes out inside the bound
+c, h, f = failing_site("hang")
+n_w = len(writes_of(f))
+t0 = time.monotonic()
+run(c.shutdown())
+took = time.monotonic() - t0
+print(f"    shutdown, release hangs: {took:.2f} s (worst {M.HAND_BACK_WORST_S:.1f} s)")
+check("SHUTDOWN with a failed release: the one 0 W is sent, inside the bound",
+      writes_of(f)[n_w:] == [0.0] and took < M.HAND_BACK_WORST_S + 1.5)
+check("a driver's own fallback replaces the 0 W (the hook), not the add-on",
+      "release_fallback" in dir(HB) and HB.release_fallback is
+      drivers.Driver.release_fallback)
+logging.getLogger("goodwe").removeHandler(_h2)
+
 # --- 3i. per-unit state and the other counts ---------------------------------
 c, h, p = site([gw("inverter-a", "a"), fk("inverter-b")])
 run(cycles(c, 4))
@@ -1021,3 +1145,7 @@ print("all passed")
 #   k. the release does not wait for a write on its way (it is not the last).
 #   l. the hand-back words are hard-coded "SMA control", not the driver's.
 #   m. a GoodWe-only roster gets a changed banner.
+#   n. (round 2) the fallback 0 W is sent on every failed try.
+#   o. (round 2) a failed release is retried on every idle write.
+#   p. (round 2) every failed try is logged.
+#   q. (round 2) no fallback 0 W after a failed release.