diff --git a/goodwe_controller/DECISIONS/SMA-10-two-idle-states.md b/goodwe_controller/DECISIONS/SMA-10-two-idle-states.md index 778b1b6..4f8d701 100644 --- a/goodwe_controller/DECISIONS/SMA-10-two-idle-states.md +++ b/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). diff --git a/goodwe_controller/app/drivers.py b/goodwe_controller/app/drivers.py index 915a891..8d607d8 100644 --- a/goodwe_controller/app/drivers.py +++ b/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 diff --git a/goodwe_controller/app/handback.py b/goodwe_controller/app/handback.py index b0c5a74..8f2c819 100644 --- a/goodwe_controller/app/handback.py +++ b/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) diff --git a/goodwe_controller/app/inverter.py b/goodwe_controller/app/inverter.py index 69161d0..7af5188 100644 --- a/goodwe_controller/app/inverter.py +++ b/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 diff --git a/goodwe_controller/app/main.py b/goodwe_controller/app/main.py index a34cc7f..afeb1a3 100644 --- a/goodwe_controller/app/main.py +++ b/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)) diff --git a/goodwe_controller/app/messages.py b/goodwe_controller/app/messages.py index 3e24bc1..0c234e1 100644 --- a/goodwe_controller/app/messages.py +++ b/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", diff --git a/goodwe_controller/test_messages.py b/goodwe_controller/test_messages.py index 3636a2a..c007134 100644 --- a/goodwe_controller/test_messages.py +++ b/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))", diff --git a/goodwe_controller/test_sma10_two_idle_states.py b/goodwe_controller/test_sma10_two_idle_states.py index 7bad08b..2d4d614 100644 --- a/goodwe_controller/test_sma10_two_idle_states.py +++ b/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.