diff --git a/HANDOVER.md b/HANDOVER.md index 7a314e8..dd4846b 100644 --- a/HANDOVER.md +++ b/HANDOVER.md @@ -56,9 +56,13 @@ python3 test_control.py && python3 test_maintenance.py && python3 test_arbiter.p && python3 test_validate.py && python3 test_p1.py && python3 test_loop.py ``` -⚠️ `test_loop.py` takes about **35 seconds** and that is not a bug. It drives the real -control loop, which sleeps 1 s a tick, to prove a wall-clock property about it -(SAFETY-12); mocking the clock there would leave the assertion testing the mock. +⚠️ `test_loop.py` takes about **95 seconds** (measured 93 s) and that is not a bug. It +drives the real control loop, which sleeps 1 s a tick, eight times over, to prove a +wall-clock property about it (SAFETY-12); mocking the clock there would leave the +assertion testing the mock. The other five suites together are ~395 checks and finish in +seconds. If you shorten `test_loop.py`'s windows, re-measure and correct this figure — +an understated runtime is what makes a slow test look like a hung one, and a slow test +that looks hung gets deleted. --- diff --git a/goodwe_controller/CHANGELOG.md b/goodwe_controller/CHANGELOG.md index a0f38b0..1f8b237 100644 --- a/goodwe_controller/CHANGELOG.md +++ b/goodwe_controller/CHANGELOG.md @@ -76,6 +76,26 @@ indicator read healthy, and a command computed from an old reading kept being executed through whatever the load did next. Measured on the rig during TEL-05: 70 s at a literally constant 350.0 W with 14 arrivals and zero cycles. +**It was worse than a latency limit: it was a safety claim that could not +fire.** `stale_input_s` and the `inputs missing -> 0 W` claim both live *inside* +`cycle()`. Pre-fix, if the meter value happened to be constant, `cycle()` was +never called again - so that claim had no way to run. Constant meter, SoC entity +dying at t=4 s, same binary: + +``` +pre-fix writes: [(0.0, 220.0), (0.0, 220.0), (10.1, 220.0)] + final target: 220.0 W reason: 'loop -> 220 W' +post-fix writes: [(0.0, 220.0), (0.0, 220.0), (3.0, 430.0), (9.1, 0.0), (10.1, 0.0)] + final target: 0.0 W reason: 'safety -> 0 W' +``` + +The pre-fix controller held 220 W through the entire input outage with its +status line still reading `loop -> 220 W`, and layer 1 does not cover that case +on a `meter_source: off` install: no P1 age sensor is published, so the firmware +has nothing to veto on, while the heartbeat keeps its watchdog fed. So the old +behaviour was not "holds a stale command safely" - it was a failsafe that a +repeating meter switched off. `test_loop.py` asserts both halves. + `cycle_floor_s` (default **15 s**) is a deadline on the gap between cycles, not a second scheduler: every cycle resets it, whichever trigger fired. On a healthy meter it never elapses, so the cycle rate, the write sequence and therefore the @@ -84,6 +104,16 @@ per-cycle gain the tuning was measured against are unchanged - asserted in `cycle_floor_s` reproduces the old behaviour exactly) and comparing the commanded values. +The reset is not the only thing holding that up, and the other argument is the +sturdier one: the combined cycle rate is `max(arrival rate, 1/floor)`, never the +sum. At 1/15 s the floor is strictly slower than the ~1/5 s arrival rate, so +even a hypothetical floor racing the arrivals could not exceed the nominal +healthy rate. The re-tune is unreachable by construction. ⚠️ That holds only +while `cycle_floor_s` stays above the meter's update interval, and the schema +minimum is 5 s - which is exactly the reference meter's interval. Nothing +enforces the relationship; `validate.py` is the obvious home for it and does not +have it yet. + Observed over six real minutes on the same rig, one binary, meter held at a literally constant 350.0 W: **before, 1 cycle** (at startup) and then nothing, the command stuck at 220 W against a 350 W import for the rest of the window. @@ -96,21 +126,38 @@ both sides, the same values in the same order.** The heartbeat write count never moves; the only writes the fix adds are the ten the loop was supposed to be making all along. -15 s is bracketed, not round. Below it: arrivals are ~5 s (NOTES.md measures -4.97 s), detected up to 1 s late by the 1 s poll, and one dropped poll is -retried on the next tick - about 11 s worst case on a meter that is merely -unlucky, which the floor must not fire on. Above it: `meter_max_age_s` is 30 s, -past which there is no reading to evaluate, and the firmware's ingest veto is -also 30 s - so the loop is guaranteed to have re-decided at least twice inside -any window in which layer 1 might otherwise be the only thing deciding. It is -also exactly `stale_input_s`, this system's existing answer to "how long may we -hold without re-deciding". +15 s is bracketed, not round. -A floor cycle runs the **full** law on the same inputs, integrator included. The -freshness question is already answered upstream and answered harder - past -`meter_max_age_s` the reading is None, which is "inputs missing", which is a -`P_SAFETY` 0 W claim - so a floor cycle can only ever run on a reading this -system already calls fresh. The integrator advances per *cycle*, not per second, +**Below it, ~11 s, and it arises more routinely than a dropped poll.** +`HomeWizardLocalSource` polls at 5.0 s against a meter that updates every 4.97 s +(NOTES.md:640). Two near-equal periods beat, so roughly once every ~14 minutes +the poller steps over an update entirely - a ~10 s gap between changed values on +a perfectly healthy meter, plus up to 1 s for the 1 s tick to notice. A failed +HTTP poll (retried on the next tick, no backoff) adds another 5 s. The floor +sits above the beat-skip so it does not fire on that alone; what it takes to +reach 15 s is a beat-skip *and* a failed poll coinciding. + +**Above it, 30 s.** `meter_max_age_s` is 30 s, past which there is no reading to +evaluate, and the firmware's ingest veto is also 30 s - so the loop is +guaranteed to have re-decided at least twice inside any window in which layer 1 +might otherwise be the only thing deciding. ⚠️ The default is therefore not +independently justified at 15: if the firmware's veto ever moves, this moves +with it. Noted beside the constant in `main.py`. + +It is also exactly `stale_input_s`, this system's existing answer to "how long +may we hold without re-deciding". + +A floor cycle runs the **full** law on the same inputs, integrator included. In +P1 mode the freshness question is already answered upstream and answered harder +- past `meter_max_age_s` the reading is None, which is "inputs missing", which +is a `P_SAFETY` 0 W claim - so a floor cycle there can only ever run on a reading +this system already calls fresh. ⚠️ That is transport-conditional: with +`meter_source: off`, `read_inputs()` takes the grid figure straight from +`hass.number()` with **no age gate at all**, so a Home Assistant entity that has +gone quiet reads as current on that path, with or without this change. Running +the full law is still right there - the alternative is a degraded second law +reasoning about an age nobody measured - but the floor does not make that path +fresh. The integrator advances per *cycle*, not per second, so bounding the gap bounds the accumulation; `integrator_max_w` bounds it after that. A gentler second law for floor cycles would be a second set of dynamics nobody can test on this hardware. diff --git a/goodwe_controller/app/main.py b/goodwe_controller/app/main.py index 4c34014..5865baa 100644 --- a/goodwe_controller/app/main.py +++ b/goodwe_controller/app/main.py @@ -345,17 +345,33 @@ class Controller: # ⚠️ SAFETY-12. The floor is a DEADLINE ON THE GAP BETWEEN CYCLES, not a # second scheduler running alongside the arrival trigger. Every cycle # resets it, whichever trigger fired, so on a healthy changing meter it - # never elapses and not one existing cycle moves - no beat frequency - # between the two triggers, no doubled cycle rate, and therefore no + # never elapses and not one existing cycle moves - and therefore no # change to the per-cycle gain the tuning was measured against. # - # Why it has to exist: `self.grid != last_grid` alone means a meter that - # repeats a value runs NO control cycles at all, while the heartbeat - # below keeps re-emitting the last command and the firmware keeps - # putting it on the wire - so every indicator reads healthy while the - # loop has not evaluated and the load may have moved underneath it. - # Measured on the rig during TEL-05: 70 s at a literally constant - # 350.0 W, 14 arrivals, zero cycles. + # That is true twice over, and the second reason is the sturdier one: + # the combined cycle rate is max(arrival rate, 1/floor), never the sum. + # At the defaults 1/15 s is strictly slower than the ~1/5 s arrival + # rate, so even a floor that raced the arrivals could not push the loop + # past its nominal healthy rate. The re-tune is unreachable by + # construction, not merely by the reset. ⚠️ That argument holds only + # while floor > the meter's update interval - which is why the schema + # minimum of 5 s deserves the second look validate.py has not given it + # yet: 5 s IS the reference meter's interval, i.e. the one configurable + # value that would double the cycle rate. + # + # Why it has to exist, and it is not only about latency: `self.grid != + # last_grid` alone means a meter that repeats a value runs NO control + # cycles at all. The heartbeat below keeps re-emitting the last command + # and the firmware keeps putting it on the wire, so every indicator + # reads healthy - and, worse, the `inputs missing -> 0 W` claim lives + # INSIDE cycle(), so on a repeating meter THAT SAFETY CLAIM CANNOT FIRE. + # Demonstrated in test_loop.py: constant meter, SoC entity dies at t=4 s, + # and the pre-fix controller holds 220 W through the whole outage with + # the status line still reading "loop -> 220 W". Layer 1 does not cover + # it on a `meter_source: off` install either - no P1 age sensor is + # published, so the firmware has nothing to veto on. Measured on the rig + # during TEL-05: 70 s at a literally constant 350.0 W, 14 arrivals, zero + # cycles. # # This is NOT a freeze detector, and deliberately so - see # HomeWizardLocalSource.unchanged_s for why one cannot be built here (at @@ -363,6 +379,13 @@ class Controller: # so any freeze threshold false-trips at the exact operating point we # run at). Nothing here decides whether a repeated reading is true. It # only stops "the number is the same" from meaning "do not think". + # + # ⚠️ THE 15 s DEFAULT HAS A CEILING IT DOES NOT OWN. It is under + # validate.FIRMWARE_INGEST_VETO_S (30 s) and under meter_max_age_s on + # purpose, so the loop re-decides at least twice inside any window in + # which layer 1 might otherwise be the only thing deciding. If the + # firmware's veto ever moves, this default moves with it - it is not + # independently justified at 15. floor = float(self.o.get("cycle_floor_s", 15)) last_cycle = None while not self.stopping: @@ -375,13 +398,23 @@ class Controller: last_grid = self.grid last_cycle = now_mono # ⚠️ The FULL cycle, not a degraded one. A floor cycle runs the - # same law on the same inputs as an arrival cycle, because the - # freshness question is already answered upstream and answered - # harder: past `meter_max_age_s` (30 s) p1.net_w is None, which - # is "inputs missing", which becomes a P_SAFETY 0 W claim. So a - # floor cycle can only ever run on a reading this system already - # calls fresh - it cannot run the PI on a 60 s old figure, - # because at 60 s there is no figure. And the integrator + # same law on the same inputs as an arrival cycle, because in P1 + # mode the freshness question is already answered upstream and + # answered harder: past `meter_max_age_s` (30 s) p1.net_w is + # None, which is "inputs missing", which becomes a P_SAFETY 0 W + # claim. So a floor cycle cannot run the PI on a 60 s old + # figure, because at 60 s there is no figure. + # + # ⚠️ THAT GUARANTEE IS TRANSPORT-CONDITIONAL, and saying so + # matters more than the guarantee: with `meter_source: off`, + # read_inputs() takes self.grid straight from hass.number() with + # NO age gate at all, so a Home Assistant entity that has gone + # quiet reads as a current value on that path with or without + # this change. Running the full law is still the right choice + # there - the alternative is a degraded second law reasoning + # about an age nobody measured - but the floor does not make + # that path fresh, and nothing here should be read as claiming + # it does. And the integrator # advances per CYCLE, not per second (control.py), so bounding # the gap bounds the accumulation: at most one extra # gain x error per floor interval, under the same diff --git a/goodwe_controller/test_loop.py b/goodwe_controller/test_loop.py index 01b1da6..61292b6 100644 --- a/goodwe_controller/test_loop.py +++ b/goodwe_controller/test_loop.py @@ -6,10 +6,15 @@ previous poll, so a meter that repeats a value ran NO control cycles while the heartbeat kept re-emitting the last command - measured on the rig during TEL-05 as 70 s at a literally constant 350.0 W with 14 arrivals and zero cycles. -⚠️ THIS TEST TAKES ~35 SECONDS OF WALL CLOCK, on purpose. The thing under test -is a wall-clock floor inside a loop that sleeps 1 s; mocking the clock would -leave the assertion testing the mock. It drives the real `run_control()` and -counts what actually happened. +⚠️ THIS TEST TAKES ~95 SECONDS OF WALL CLOCK (measured 93 s), on purpose, and +that figure is the only thing standing between it and a future developer who +decides a slow test is a broken one. The thing under test is a wall-clock floor +inside a loop that sleeps 1 s; mocking the clock would leave the assertion +testing the mock. It drives the real `run_control()` and counts what actually +happened. Eight runs of the real loop is what the eight scenarios cost. + +⚠️ If you shorten the windows, re-measure and update this number and the one in +HANDOVER.md. An understated runtime reads as a hang. `cycle_floor_s` is read from options with no lower bound in code, so a huge value reproduces the pre-fix behaviour exactly. Every claim below is therefore @@ -35,8 +40,9 @@ def check(name, cond): class FakeHass: """A scripted meter and a plant that tracks the command instantly.""" - def __init__(self, meter): + def __init__(self, meter, soc_dies_at=None): self.meter = meter + self.soc_dies_at = soc_dies_at self.batt = 0.0 self.writes = [] self.t0 = time.monotonic() @@ -45,11 +51,14 @@ class FakeHass: return (-5000.0, 5000.0, 1.0) async def number(self, entity, invert=False): + now = time.monotonic() - self.t0 if entity == "sensor.grid": - return self.meter(time.monotonic() - self.t0) + return self.meter(now) if entity == "sensor.batt": return self.batt if entity == "sensor.soc": + if self.soc_dies_at is not None and now >= self.soc_dies_at: + return None return 50.0 return None @@ -83,12 +92,12 @@ BASE = {"setpoint_entity": "number.sp", "meter_entity": "sensor.grid", "heartbeat_s": 10, "stale_input_s": 15} -def drive(meter, floor, seconds): +def drive(meter, floor, seconds, soc_dies_at=None, **over): """Run the real control loop for `seconds`; return (cycle times, writes).""" async def go(): - hass = FakeHass(meter) - c = Controller(dict(BASE, cycle_floor_s=floor), hass, _Store(), _Pub(), - stop=asyncio.Event()) + hass = FakeHass(meter, soc_dies_at) + c = Controller(dict(BASE, cycle_floor_s=floor, **over), hass, _Store(), + _Pub(), stop=asyncio.Event()) c.auto = True stamps = [] real = c.cycle @@ -102,7 +111,7 @@ def drive(meter, floor, seconds): await asyncio.sleep(seconds) c.stopping = True await asyncio.wait_for(task, timeout=10) - return stamps, hass.writes + return stamps, hass.writes, c.target, c.reason return asyncio.run(go()) @@ -117,7 +126,7 @@ print("a meter that repeats the same value") FLAT = lambda t: 350.0 # noqa: E731 FLOOR, SECONDS = 3.0, 12.0 -pre_stamps, pre_writes = drive(FLAT, NEVER, SECONDS) +pre_stamps, pre_writes, _, _ = drive(FLAT, NEVER, SECONDS) # The defect itself, demonstrated rather than described: one cycle at startup # and then nothing for the rest of the window, while writes keep happening. check("pre-fix: a constant meter runs exactly one cycle, at startup", @@ -125,7 +134,7 @@ check("pre-fix: a constant meter runs exactly one cycle, at startup", check("...while the heartbeat keeps writing anyway, so nothing looks wrong", len(pre_writes) >= 2) -post_stamps, post_writes = drive(FLAT, FLOOR, SECONDS) +post_stamps, post_writes, _, _ = drive(FLAT, FLOOR, SECONDS) check("post-fix: the same constant meter runs cycles throughout", len(post_stamps) >= int(SECONDS / FLOOR) - 1) # The actual acceptance criterion: a BOUND on the gap, not a count. @@ -147,8 +156,8 @@ print("a meter that changes normally - nothing may move") STEPS = [0.0, 300.0, 850.0, -400.0, 120.0, -900.0, 60.0] LIVE = lambda t: STEPS[int(t // 2) % len(STEPS)] # noqa: E731 -a_stamps, a_writes = drive(LIVE, NEVER, 12.0) -b_stamps, b_writes = drive(LIVE, FLOOR, 12.0) +a_stamps, a_writes, _, _ = drive(LIVE, NEVER, 12.0) +b_stamps, b_writes, _, _ = drive(LIVE, FLOOR, 12.0) check("a changing meter runs the same number of cycles as before the fix", len(a_stamps) == len(b_stamps)) check("...commanding exactly the same sequence of values", a_writes == b_writes) @@ -160,12 +169,42 @@ print("a meter parked at the target - the converged operating point") # write nothing but the heartbeat, because the deadband - not the arrival # trigger - is what holds the command still. AT_TARGET = lambda t: -10.0 # noqa: E731 -c_stamps, c_writes = drive(AT_TARGET, NEVER, 12.0) -d_stamps, d_writes = drive(AT_TARGET, FLOOR, 12.0) +c_stamps, c_writes, _, _ = drive(AT_TARGET, NEVER, 12.0) +d_stamps, d_writes, _, _ = drive(AT_TARGET, FLOOR, 12.0) check("the loop evaluates at the converged point too", len(d_stamps) > len(c_stamps)) check("...and the deadband still holds the command, so writes are unchanged", d_writes == c_writes) +# --------------------------------------------------------------------------- # +print("an input dies while the meter repeats - the safety claim must still fire") +# ⚠️ THE STRONGEST PROPERTY IN SAFETY-12, and the one that makes it a safety fix +# rather than a latency fix. The `inputs missing -> 0 W` claim lives INSIDE +# cycle() (main.py, the stale_input_s branch and the P_SAFETY claim below it). +# Pre-fix, on a meter whose value happened to repeat, cycle() was never called +# again - so that claim could not fire AT ALL. The controller held its last +# command through an input outage of unbounded length with the status line still +# reading "loop -> N W". +# +# Layer 1 does not cover this either on a `meter_source: off` install: no P1 age +# sensor is published (see Controller.publish), so the firmware has nothing to +# veto on, and the heartbeat keeps its watchdog fed the whole time. +# +# stale_input_s is shortened to 3 s here so the outage resolves inside a test +# rather than inside a quarter of a minute. The mechanism is the default one. +c2_stamps, c2_writes, pre_target, pre_reason = drive( + FLAT, NEVER, 10.0, soc_dies_at=4.0, stale_input_s=3) +check("pre-fix: a dead input during a constant meter never reaches the safety claim", + pre_target != 0.0 and "safety" not in pre_reason) +check(f"...so it holds its last command instead ({pre_target:g} W, {pre_reason!r})", + pre_target == 220.0) + +d2_stamps, d2_writes, post_target, post_reason = drive( + FLAT, FLOOR, 10.0, soc_dies_at=4.0, stale_input_s=3) +check("post-fix: the same outage commands 0 W", post_target == 0.0) +check(f"...through the safety claim, not by accident ({post_reason!r})", + "safety" in post_reason) +check("...and the 0 W actually reached the device", 0.0 in d2_writes) + # --------------------------------------------------------------------------- # print() if fails: