From e40e237f5decb323fd45d09a0bf191af0cb04b3a Mon Sep 17 00:00:00 2001 From: Fredrik Ahlgren Date: Wed, 29 Jul 2026 20:13:03 +0200 Subject: [PATCH] test: measure the refused-write flap across the catalog sungrow 1.5.7 fixed a driver that reissued a refused write on every watchdog tick, forever, after a customer's SG12RT logged "self-consumption reset write failed: modbus exception function=0x06" once per tick indefinitely. This measures whether that shape is one driver or many. It is eleven. driver_default_mode runs on a timer -- lease expiry, the telemetry watchdog, the stale-meter standdown, shutdown -- and nothing reaching it can say no, so a driver that writes whatever the device answers keeps writing for the life of the session: atmoce deye ferroamp_modbus huawei pixii sigenergy solaredge solaredge_legacy solaredge_pv solinteg solis All eleven write 1 or 2 registers per call and never settle. sungrow is the only one that stops, and only because the field report forced it. refused_write_probe.lua refuses every write, calls driver_default_mode eight times and reports the per-call counts. test_refused_write_settles.py ratchets against refused-write-baseline.json the way #36 did for reads: a count that rises fails, a driver not listed must be clean, and a count that falls fails until the file is updated. Verified by putting the sungrow flap back -- it fails. This is the write-side twin of test_absent_register_settles.py, and the two failures are not equally severe. A failed read fails the whole poll and takes the site offline; a refused write costs bus traffic and a log line per tick. So this measures the flap rather than treating every occurrence as an outage -- but that log line is the one an operator reads to find the real fault, and on the SG12RT it drowned it. Also fixes host_mock.lua, which had no host.sleep. It is in spec/host-api.md and the real host provides it; solis and deye call it to space out writes. Lua turns a missing field into "attempt to call a nil value", so any test reaching their write-retry path died there rather than measuring it, and both looked like they crashed inside driver_default_mode when they do nothing of the kind. The mock now advances its clock instead of sleeping. Second time the mock has been caught lying, after #42. No driver changes. Paying the debt down is follow-up work, in batches, the way #36 did it. make check -- 3195 passed, 1361 skipped. Signed-off-by: Fredrik Ahlgren Co-Authored-By: Claude Opus 5 --- CHANGELOG.md | 9 ++ Makefile | 8 ++ docs/WRITING-A-DRIVER.md | 49 +++++++ drivers/tests/lua_harness/host_mock.lua | 11 ++ .../tests/lua_harness/refused_write_probe.lua | 124 +++++++++++++++++ drivers/tests/refused-write-baseline.json | 34 +++++ drivers/tests/test_refused_write_settles.py | 127 ++++++++++++++++++ 7 files changed, 362 insertions(+) create mode 100644 drivers/tests/lua_harness/refused_write_probe.lua create mode 100644 drivers/tests/refused-write-baseline.json create mode 100644 drivers/tests/test_refused_write_settles.py diff --git a/CHANGELOG.md b/CHANGELOG.md index e7863bb..8469893 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,15 @@ Driver versions follow [Semantic Versioning](https://semver.org/spec/v2.0.0.html ## [Unreleased] +### Added +- **The flap sungrow 1.5.7 fixed is measured across the catalog, and it is not one driver — it is eleven.** `drivers/tests/refused_write_probe.lua` refuses every write a device is asked to take, then calls `driver_default_mode` eight times and counts what the driver does about it. That path runs on a timer — lease expiry, the telemetry watchdog, the stale-meter standdown, shutdown — and nothing reaching it can say no, so a driver that writes whatever the device answers keeps writing for the life of the session. **atmoce, deye, ferroamp_modbus, huawei, pixii, sigenergy, solaredge, solaredge_legacy, solaredge_pv, solinteg and solis** all reissue the same refused write on every call and never stop. sungrow is the only one that settles, and only because a customer's SG12RT forced it +- `drivers/tests/test_refused_write_settles.py` ratchets against `refused-write-baseline.json`, the way #36 did for reads: a count that rises fails, a driver not listed must be clean, and a count that falls fails until the file is updated, so the debt cannot be quietly re-borrowed. `make refused-write-report ID=` prints it for one driver +- This is the write-side twin of `test_absent_register_settles.py`, and the two failures are not equally severe. A failed read fails the whole poll and takes the site offline; a refused write costs bus traffic and a log line per tick. That is why this measures the flap rather than treating every occurrence as an outage — but the log line is the one an operator reads to find the real fault, and on the SG12RT it drowned it + +### Fixed +- **`host_mock.lua` was missing `host.sleep`, so two drivers could not be measured at all.** It is in `spec/host-api.md` and the real host provides it; solis and deye call it to space out writes. Lua turns a missing field into `attempt to call a nil value`, so any test reaching their write-retry path died there instead of measuring it — and both looked like they crashed in `driver_default_mode` when they do nothing of the kind. The mock now advances its clock instead of sleeping. Second time the mock has been caught lying, after #42 +- `docs/WRITING-A-DRIVER.md` carries the write rule beside the read one, with the helper and the command that checks a driver before the pull request. It also says why the guard counts refusals rather than reading a model label: the device can be holding a state the driver did not set, and a label tells you nothing about that + ### Fixed - **sungrow** 1.5.7 — **The driver kept writing a register block the inverter had already refused.** An SG12RT in the field logged `self-consumption reset write failed: modbus exception function=0x06` once per watchdog tick, indefinitely. `driver_init`'s startup reset, the watchdog, `driver_cleanup` and the `deinit` action all write 13049-13051, and nothing counted how often the device said no. The EMS block now follows the rule the register reads have followed since #36: absence has to be proved, three refusals prove it, and the paths that write unprompted stop. Measured on the reported device — writes per watchdog tick went `3,3,3,3,3,3,3,3` to `3,3,0,0,0,0,0,0`, and the warn lines over eight ticks from 9 to 3 - **Deliberately not gated on `model_family`, which is the obvious fix, the one the field thread proposed, and the wrong one.** The startup reset exists because the inverter can be holding a forced state this driver did not set: a container that died mid-force, an older driver version, iSolarCloud or another EMS on the same bus. None of those care what `classify_device_type` decided, and a hybrid shipped under a device-type code the driver has not been taught is classified `string`. Skipping the release on the label leaves exactly that inverter forced with nothing left to write mode 0 back. What separates the cases is not the label but whether the device took the write: one that refuses it cannot be holding a forced state, one that accepts it keeps its release diff --git a/Makefile b/Makefile index e196cd3..7f351fd 100644 --- a/Makefile +++ b/Makefile @@ -7,6 +7,7 @@ ARTIFACT_DIR ?= .artifacts/$(ID) LEVEL ?= patch .PHONY: bootstrap new-driver test-driver package-driver check boundary \ + refused-write-report absent-register-report \ sync-manifests bump-driver history ftw-baseline ftw-baseline-report \ host-api @@ -29,6 +30,13 @@ absent-register-report: test -n "$(ID)" ./lua55 drivers/tests/lua_harness/absent_register_probe.lua . "drivers/lua/$(ID).lua" +# Does this driver keep writing a register the device refuses? The watchdog +# reaches driver_default_mode on a timer, so anything but a settled count +# repeats for the life of the session. +refused-write-report: + test -n "$(ID)" + ./lua55 drivers/tests/lua_harness/refused_write_probe.lua . "drivers/lua/$(ID).lua" + bootstrap: uv sync --frozen --extra package --extra dev diff --git a/docs/WRITING-A-DRIVER.md b/docs/WRITING-A-DRIVER.md index 89f8c6d..2d6555e 100644 --- a/docs/WRITING-A-DRIVER.md +++ b/docs/WRITING-A-DRIVER.md @@ -106,6 +106,55 @@ A new driver must be clean. The drivers that already carried this debt when it was first measured are listed in `absent-register-baseline.json`, and that file may only shrink. +## The same rule for writes + +A device can refuse a write as easily as it can fail a read, and one path +writes without anyone asking: `driver_default_mode()`. The host calls it on +lease expiry, on the telemetry watchdog, on shutdown. Nothing there can say no, +so a driver that writes whatever the device answers goes on writing for the +life of the session, one log line per tick. + +Count refusals the way you count missed reads, and stop: + +```lua +local WRITE_ATTEMPTS = 3 +local write_failures = 0 + +local function block_worth_writing() + return write_failures < WRITE_ATTEMPTS +end + +local function note_write(err) + if err == nil or err == "" then + write_failures = 0 -- one success proves the register is there + else + write_failures = write_failures + 1 + end +end +``` + +Three rather than one, for the same reason as reads: a busy bus is not proof. +The count lives in the process, so a restart always tries once — which is what +the startup reset is for. A single success clears it, so firmware that gains +the register is picked up without waiting for a restart. + +Do not gate this on the model instead. The device can be holding a state your +driver did not set — a container that died mid-command, an older driver +version, another EMS on the same bus — and a model label tells you nothing +about that. Whether the device took the write does. + +Once it has given up, report the default as held rather than failed. A +permanent `false` has the watchdog escalate against a device that was never +under control. + +```bash +make refused-write-report ID=example +``` + +`drivers/tests/test_refused_write_settles.py` holds every driver to this, with +`refused-write-baseline.json` recording what already shipped. `sungrow` is the +worked example, and the only one clean when this was first measured. + ## Sign convention **Positive watts flow into the site.** Every driver, every device, no diff --git a/drivers/tests/lua_harness/host_mock.lua b/drivers/tests/lua_harness/host_mock.lua index 28bd821..3d6170c 100644 --- a/drivers/tests/lua_harness/host_mock.lua +++ b/drivers/tests/lua_harness/host_mock.lua @@ -110,6 +110,17 @@ function host.millis() return host._millis_counter end +-- host.sleep is in spec/host-api.md and the real host provides it, so a driver +-- that needs a gap between writes calls it. The mock did not have it, and Lua +-- turns a missing field into "attempt to call a nil value" -- so any test that +-- reached solis's or deye's write-retry path died there rather than measuring +-- it. Advance the clock instead of sleeping: tests must stay fast, and a +-- driver that reads the clock either side of a gap should see one. +function host.sleep(milliseconds) + record_call("sleep", milliseconds) + host._millis_counter = host._millis_counter + (tonumber(milliseconds) or 0) +end + function host.set_make(name) record_call("set_make", name) host._make = name diff --git a/drivers/tests/lua_harness/refused_write_probe.lua b/drivers/tests/lua_harness/refused_write_probe.lua new file mode 100644 index 0000000..4a7fb84 --- /dev/null +++ b/drivers/tests/lua_harness/refused_write_probe.lua @@ -0,0 +1,124 @@ +-- For one driver, refuse every write the device is asked to take, then call +-- the safe-default path over and over and watch what the driver does about it. +-- +-- The rule being measured: a driver whose device refuses a write must stop +-- making that write unprompted. +-- +-- driver_default_mode is the path that runs on a timer. FTW reaches it through +-- Registry.SendDefault on lease expiry, the telemetry watchdog, the +-- stale-site-meter standdown and shutdown -- never from a command, and never +-- with anything to say no to it. A driver that writes there whatever the +-- device answers keeps writing for the life of the session. +-- +-- A Sungrow SG12RT is the worked example. Its EMS registers do not exist, so +-- every write came back "modbus exception function=0x06", and the driver +-- reissued three of them on every watchdog tick and logged a warn line each +-- time. Fixed in sungrow 1.5.7 by counting refusals: three prove the block is +-- absent, and the unprompted paths stop. See the entry in CHANGELOG.md. +-- +-- driver_init and driver_cleanup write once per process, so they cannot flap +-- and are not measured. A command cannot flap either -- something asked for +-- it, and refusing to try is its own failure. +-- +-- What is NOT a violation: a driver that never writes here, and a driver that +-- stops. Returning false while it is still trying is honest and is left to the +-- caller to read; this measures the writes, not the verdict. +-- +-- Usage: lua55 refused_write_probe.lua +-- Prints one line: +-- DEFAULT_MODE SETTLED <0|1> WRITES a,b,c,... RETURNED x,y,z,... +-- or a single "SKIP " for a driver this cannot measure. + +local root = arg[1] +local driver_path = arg[2] +package.path = root .. "/drivers/tests/lua_harness/?.lua;" .. package.path +require("host_mock") + +-- Enough calls that a driver bounded at three attempts is clearly settled and +-- one that never settles is clearly not. +local CALLS = 8 + +-- What a device says when the register is not implemented. The exact string +-- does not matter to the driver -- any non-empty return from host.modbus_write +-- is an error -- but it matters to whoever reads a failure here and goes +-- looking for the same words in a gateway log. +local REFUSAL = "modbus exception function=0x06 code=0x02" + +local CONFIG = { + host = "127.0.0.1", port = 502, unit_id = 1, slave_id = 1, + nominal_w = 10000, rated_w = 10000, + url = "http://127.0.0.1", topic = "test", serial = "TEST123", +} + +local function fill_registers() + local regs = {} + for addr = 0, 65535 do regs[addr] = 100 end + -- SunSpec magic, so identity probes pass and the driver reaches its real + -- register map instead of bailing at the front door. + regs[40000] = 0x5375 + regs[40001] = 0x6e53 + host._modbus_registers.holding = regs + host._modbus_registers.input = regs +end + +local function clear_globals() + driver_init, driver_poll, driver_cleanup = nil, nil, nil + driver_command, driver_default_mode = nil, nil + driver_command_v2, driver_default_mode_v2 = nil, nil + DRIVER, PROTOCOL = nil, nil +end + +local function count_writes(from) + local n = 0 + for i = from + 1, #host._calls do + local func = host._calls[i].func + if func == "modbus_write" or func == "modbus_write_multiple" then + n = n + 1 + end + end + return n +end + +host.reset() +clear_globals() +fill_registers() + +if not pcall(dofile, driver_path) then print("SKIP load failed") return end +if PROTOCOL ~= "modbus" then print("SKIP not modbus") return end +if type(driver_default_mode) ~= "function" then + print("SKIP no driver_default_mode") + return +end + +-- Let the driver reach the state it would really be in: initialised, and +-- polled often enough to have classified the device and settled its reads. +-- Writes answer normally here, so a driver that checks a readback at startup +-- gets the answer it expects. +if type(driver_init) == "function" then pcall(driver_init, CONFIG) end +if type(driver_poll) == "function" then + for _ = 1, 3 do pcall(driver_poll) end +end + +-- From here the device refuses everything it is asked to write. +host._modbus_write_error = REFUSAL + +local writes, returned = {}, {} +for _ = 1, CALLS do + local before = #host._calls + local ok, result = pcall(driver_default_mode) + writes[#writes + 1] = count_writes(before) + if not ok then + returned[#returned + 1] = "error" + else + returned[#returned + 1] = tostring(result) + end +end + +-- Settled means it stopped writing. The last call is what the gateway is +-- still paying for an hour later, so that is the one that decides. +local settled = writes[#writes] == 0 and 1 or 0 + +print(string.format("DEFAULT_MODE SETTLED %d WRITES %s RETURNED %s", + settled, + table.concat(writes, ","), + table.concat(returned, ","))) diff --git a/drivers/tests/refused-write-baseline.json b/drivers/tests/refused-write-baseline.json new file mode 100644 index 0000000..a11ee9b --- /dev/null +++ b/drivers/tests/refused-write-baseline.json @@ -0,0 +1,34 @@ +{ + "_comment": [ + "Drivers whose driver_default_mode keeps writing a register the device", + "refuses. The watchdog, lease expiry and shutdown all reach that path, so", + "each of these reissues the same rejected write on every tick for the life", + "of the session, and logs a failure each time.", + "", + "A customer's Sungrow SG12RT is the worked example: 'self-consumption", + "reset write failed: modbus exception function=0x06' once per tick,", + "indefinitely, drowning the log while the site was offline for an", + "unrelated reason. Fixed in sungrow 1.5.7 by counting refusals.", + "", + "This file records debt that already shipped: 11 drivers when first", + "measured. The ratchet in test_refused_write_settles.py blocks new debt", + "immediately and asks for this file to shrink as each is paid off.", + "Shrink it, never grow it.", + "", + "Check one driver with:", + " make refused-write-report ID=" + ], + "drivers": { + "atmoce": 1, + "deye": 1, + "ferroamp_modbus": 1, + "huawei": 1, + "pixii": 1, + "sigenergy": 1, + "solaredge": 1, + "solaredge_legacy": 1, + "solaredge_pv": 1, + "solinteg": 1, + "solis": 1 + } +} diff --git a/drivers/tests/test_refused_write_settles.py b/drivers/tests/test_refused_write_settles.py new file mode 100644 index 0000000..5a97074 --- /dev/null +++ b/drivers/tests/test_refused_write_settles.py @@ -0,0 +1,127 @@ +"""A driver whose device refuses a write must stop making it unprompted. + +`driver_default_mode` is the one control path that runs on a timer. FTW reaches +it through `Registry.SendDefault` on lease expiry, the telemetry watchdog, the +stale-site-meter standdown and shutdown — never from a command, and never with +anything able to say no to it. A driver that writes there whatever the device +answers goes on writing for the life of the session. + +A customer's Sungrow SG12RT is the worked example. Its EMS registers are not +implemented on that model, so every write came back `modbus exception +function=0x06`, and the driver reissued three of them on every watchdog tick +and logged a warn line each time — drowning the log an operator was reading to +find why the site was offline, which it was for an unrelated reason. Fixed in +sungrow 1.5.7 by counting refusals: three prove the block is absent, and the +unprompted paths stop. + +This is the write-side twin of `test_absent_register_settles.py`, which holds +the same property for reads. The two failures are not equally severe — a failed +read fails the whole poll and takes the site offline, while a failed write +costs bus traffic and a log line — which is why this one measures the flap +rather than treating every occurrence as an outage. + +## What is not a violation + +* A driver that never writes in `driver_default_mode`. +* A driver that stops after a bounded number of attempts. +* Returning `false` while it is still attempting. That is honest, and it is + what a caller needs to know. What must not last forever is the writing. + +## Why a baseline rather than a plain assertion + +11 of the 12 Modbus drivers with a writing `driver_default_mode` violated the +rule when this was first measured; sungrow was the only one that settled, and +only because a field report forced it. Failing all 11 would gate every +unrelated change until the fleet is fixed, so the counts live in +`refused-write-baseline.json` and this test ratchets, the way #36 did for +reads: + +* a driver whose count goes **up** fails — new debt is blocked at the door; +* a driver **absent from the baseline** must be clean — new drivers get the + rule in full; +* a driver whose count goes **down** also fails, asking for the baseline to be + updated, so the debt cannot quietly be re-borrowed. + +Shrink the baseline. Never grow it. +""" + +import json +import subprocess +from pathlib import Path + +import pytest + +ROOT = Path(__file__).resolve().parents[2] +LUA = ROOT / "lua55" +PROBE = ROOT / "drivers" / "tests" / "lua_harness" / "refused_write_probe.lua" +DRIVERS = ROOT / "drivers" / "lua" +BASELINE = Path(__file__).parent / "refused-write-baseline.json" + +pytestmark = pytest.mark.skipif( + not LUA.exists(), reason="run make check to build ./lua55") + + +def load_baseline() -> dict: + return json.loads(BASELINE.read_text())["drivers"] + + +def probe(driver: str) -> tuple[list[int], str | None]: + """Return the per-call write counts if the driver never settles. + + An empty list means it settled, or never wrote. A skip reason means this + driver cannot be measured at all. + """ + result = subprocess.run( + [str(LUA), str(PROBE), str(ROOT), str(DRIVERS / f"{driver}.lua")], + capture_output=True, text=True, cwd=ROOT) + assert result.returncode == 0, result.stdout + result.stderr + + for line in result.stdout.splitlines(): + if line.startswith("SKIP "): + return [], line[5:].strip() + if not line.startswith("DEFAULT_MODE "): + continue + parts = line.split() + settled = int(parts[2]) + writes = [int(n) for n in parts[4].split(",")] + if settled or not any(writes): + return [], None + return writes, None + return [], "no probe output" + + +def driver_names() -> list[str]: + return sorted(p.stem for p in DRIVERS.glob("*.lua")) + + +@pytest.mark.holds_for_ftw_drivers +@pytest.mark.parametrize("driver", driver_names()) +def test_refused_write_debt_does_not_grow(driver: str) -> None: + baseline = load_baseline() + writes, skip = probe(driver) + if skip is not None: + # Not Modbus, or no driver_default_mode. Nothing to measure. + assert driver not in baseline, ( + f"{driver} is in the baseline but can no longer be measured " + f"({skip}). Remove it from {BASELINE.name}.") + return + + found = 1 if writes else 0 + expected = baseline.get(driver, 0) + + if driver not in baseline: + assert found == 0, ( + f"{driver} reissues a refused write on every driver_default_mode " + f"call and never stops: {writes} writes per call. The watchdog " + f"reaches this path on a timer, so on a model that does not " + f"implement the register it repeats for the life of the session. " + f"Count the refusals and stop — sungrow 1.5.7 is the pattern.") + return + + assert found <= expected, ( + f"{driver} went from settling to not settling: {writes} writes per " + f"call, forever.") + + assert found == expected, ( + f"{driver} settles now — good. Remove it from {BASELINE.name} so it " + f"is held to the rule in full.")