From 29837dfaa74dd22f897bea9b7ed31d5546a6457c Mon Sep 17 00:00:00 2001 From: glenn schrooyen Date: Sun, 27 Sep 2026 13:34:30 +0200 Subject: [PATCH 1/3] UX-11: safety log lines give one plain sentence and the code, the figures go to DEBUG - Every WARNING/ERROR line that reported a safety reason (direction, delivery, stuck meter, stale reading, peak guard, circulation, over-rating) now ends in the reason's code (messages.reason_code()). The reason itself, figures and limits included, is on a DEBUG line right after it and in the action log. - The reasons and state.json are unchanged, so an old state file loads and shows the same way: every saved reason opens with its code. - test_messages part 6 checks every WARNING+ line at 25 words as logged; nine non-safety families are listed with a reason and capped. The byte pin in test_watchdog now pins the meaning, in order. - The meter logs one WARNING per quiet episode, and INFO when back, so the red row's "the add-on log shows why" holds. The Why line past the hold names the missing reading. Action log: "25 engagements", "Shadow mode off: ...". No trigger, latch, threshold, log level, notification id, cadence, row colour or banner order changed. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01LyR88rXETvwhTgx6yHE39p --- STYLE.md | 2 +- .../DECISIONS/UX-08-short-notifications.md | 11 + goodwe_controller/DOCS.md | 18 +- goodwe_controller/app/main.py | 130 ++++++--- goodwe_controller/app/messages.py | 21 ++ goodwe_controller/app/watchdog.py | 9 +- goodwe_controller/test_clamp.py | 13 +- goodwe_controller/test_freshness.py | 7 +- goodwe_controller/test_messages.py | 274 ++++++++++++++++-- goodwe_controller/test_watchdog.py | 24 +- 10 files changed, 425 insertions(+), 84 deletions(-) diff --git a/STYLE.md b/STYLE.md index 09b06be..e3b3c8f 100644 --- a/STYLE.md +++ b/STYLE.md @@ -7,7 +7,7 @@ This applies to everything a home owner or installer reads: notifications, phone - **Body**: **one sentence** of at most 25 words, saying what happened and what to do. A **red alarm** may use up to **3 sentences** (70 words, each sentence at most 30 words), so that no action a person must take is lost. - **Details**: the last line links to the add-on documentation and names the section with the rest: `Details: add-on documentation, section "" under Notifications.` Background, figures, reason codes and history go there or into the log, never into the body. - **Status row**: one sentence of at most 15 words. A **red** row may use up to 3 sentences (30 words), like a red alarm. It shows the live numbers the reader acts on and never an HA entity id. **Banner**: at most 12 words. **Refusal**: at most 30 words, naming the setting by its label and then its key, as `messages.setting()` writes it: “Inverter rating” (max_w), or “Inverter rating” for inverter-b (inverters.max_w) for one inverter in the list. **Option name**: at most 6 words, not counting the group prefix. **Option description**: at most 30 words. Where a value comes from belongs in DOCS.md. -- **Log line** (WARNING/ERROR): one line, at most 25 words, with the numbers that matter. The reasoning goes on a DEBUG line. Log lines stay in English and are not translated. A reason text a line quotes (`%s`) keeps its reason code (`OUTPUT_CLAMP`, `STALE_READING`), because that is the evidence an installer searches for. The reason itself has the shape of a red alarm: at most 3 sentences of at most 30 words. The line as logged has no semicolon, banned word, capitals, "1 times" or "(s)". `test_messages.py` part 6 builds every such reason with the real code and checks it. A line that repeats every cycle is DEBUG. INFO lines carry no section numbers, ISO timestamps or capitals. +- **Log line** (WARNING/ERROR): one line of at most 25 words **as logged**, with any built text filled in. Log lines stay in English and are not translated. A line that reports a safety reason gives one plain sentence and the reason's code (`STALE_READING`, `OUTPUT_CLAMP`), the evidence an installer searches for. The reason itself, with its figures and limits, goes on a DEBUG line right after it and into the action log, never onto the WARNING/ERROR line. It keeps the shape of a red alarm: at most 3 sentences of at most 30 words. The line as logged has no semicolon, banned word, capitals, "1 times" or "(s)". `test_messages.py` part 6 builds every such text with the real code and checks it, and lists the few non-safety families still over 25 words. A line that repeats every cycle is DEBUG. INFO lines carry no section numbers, ISO timestamps or capitals. - **Refusal length is counted as shown**: a setting placeholder counts as its label and key, and the long cases are driven through the validator (`test_messages.py` part 3). - **Event line** under the buttons: the plain words of `messages.hint()`, like a green row. The add-on's own action log stays technical and is not shown on the page. Installers read it as `events` in the `status` JSON. - **Sentences**: one idea each, active voice, present tense, with nothing nested in brackets and no semicolons (a semicolon is a second sentence in disguise). These translate well into Dutch and French. diff --git a/goodwe_controller/DECISIONS/UX-08-short-notifications.md b/goodwe_controller/DECISIONS/UX-08-short-notifications.md index ee2cc44..e4b2832 100644 --- a/goodwe_controller/DECISIONS/UX-08-short-notifications.md +++ b/goodwe_controller/DECISIONS/UX-08-short-notifications.md @@ -78,3 +78,14 @@ The allowlist is empty and its cap is 0 (43 → 0). Every WARNING and ERROR line 7. **Review: the line as logged gets the shape too.** Part 6 first checked the quoted reason alone, so a title, a 2-sentence reason and two tails still logged as 4 sentences ("Power request too high …: OUTPUT_CLAMP: … +5000 W. The command this cycle was +1000 W. Control is still running. Cut back 1 time so far."). Part 6 now also checks the whole line: at most 3 sentences, none over 30 words. The wrappers became one sentence each, the circulation and peak guard reasons two, and `STALE_READING`'s fixed limits moved from the reason to a DEBUG line beside the ERROR (its release clause stays, pinned by test_freshness). The clamp lines for one inverter are pinned at 30 words at most: `OUTPUT_CLAMP: computed +9000 W, cut to the +5000 W rating, command now +2000 W`. Several clamped inverters read as one sentence of asked/sent pairs; which limit bound each is on its own action-log row and in the notification. Totals above 30 words remain on the direction, delivery, frozen-meter and stale lines (up to 74 words). Shortening them is a follow-up: the direction and delivery reasons are also persisted in state.json, and the direction one is pinned byte-for-byte in test_watchdog. 8. **Home Assistant 400 while it loads** now reads "Home Assistant refused number.set_value for number.x (error 400, no details). The entity may still be loading, or the value is out of range." A body with more than "400: Bad Request" is still quoted. Still WARNING, still once a minute, still a failed write. 9. **Witness** (admin/goodwe): the resolved push says "after no answers from … to …", as the resolved card does. The YAML with every title and message stripped is identical. + +# UX-11: safety log lines give the code, the figures go to DEBUG + +**Unchanged:** every trigger, latch, threshold and alarm log level (the WARNING and ERROR lines stay), every notification id and cadence, every row colour and the banner cascade. No notification is added. + +1. **One plain sentence and the code.** A WARNING/ERROR line that reports a safety reason (direction, delivery, stuck meter, stale reading, peak guard, circulation, over-rating) now ends in the reason's code, taken by `messages.reason_code()`. The reason itself, figures and limits included, is on a DEBUG line logged right after it ("Evidence for inverter-a: …"), and the action log entry carries it as before. Part 6 checks that pairing in the code. Circulation and the clamp lines were not among the five named, but they break the same 25-word rule, so they follow the same pattern. The clamp numbers stay in the notification (phase 2a item 3). +2. **The reasons and `state.json` are unchanged.** `reason` stays the evidence text, so what is saved has the same format as before. An old state file therefore loads and displays like a new one: every saved reason has opened with its code since it was first written (checked in the git history), and that code is all the ERROR line reads. The saved text goes on the DEBUG line. A stop saved without a reason shows `REASON_NOT_SAVED`. `test_messages.py` part 7 restarts from a state file holding the old long texts. The byte pin in `test_watchdog.py` now pins the meaning: the code first, then command, reading, time and both limits, in that order. +3. **The 25-word rule is checked as logged.** Part 6 fails any WARNING+ line over 25 words with its built text filled in. Nine non-safety families still run long (tariff plan words, price feed reasons, the state migration report, write refusals and claim scope errors that only a software fault raises, maintenance, trading gate and price history reasons). They are listed with a reason in `LONG_LINE_OK`, capped at 9, and a listed family that gets shorter fails until it is removed. Shortening them is a follow-up. +4. **The meter row's "the add-on log shows why" is now true.** When the meter goes quiet past its limit, the add-on logs one WARNING per episode, not one per cycle, and an INFO line when readings return. This is a new log line, not a new alarm: it has no notification and changes no decision. +5. **The Why line past the 15 s hold** names the missing reading ("No usable meter reading for over 15 seconds: 0 W", or the battery power or level of an inverter), instead of "A reading is missing: 0 W". +6. **Action log:** "25 engagement(s)" is "25 engagements", and "SHADOW MODE OFF - …" is "Shadow mode off: …". "SHADOW MODE ON" was not named in the card and is left as it is. diff --git a/goodwe_controller/DOCS.md b/goodwe_controller/DOCS.md index 1c4018b..a51a92c 100644 --- a/goodwe_controller/DOCS.md +++ b/goodwe_controller/DOCS.md @@ -3095,8 +3095,9 @@ stop control on the add-on page. This part is for installers. The texts live in `app/messages.py` and follow `STYLE.md`. Every notification keeps a fixed `notification_id`, so a repeat -replaces the card. The full figures and reason codes are on the ERROR or -WARNING line of the add-on log. +replaces the card. The ERROR or WARNING line of the add-on log names the +reason code. The full figures are on the DEBUG line logged right after it +(log level `debug`) and in `events` in the `status` JSON. | Title | Severity | id | Card | |---|---|---|---| @@ -3223,8 +3224,9 @@ ends. That row says how to clear it. ### For installers: status page -The texts are in `app/messages.py`. The full figures of any alarm are on its -ERROR or WARNING line in the add-on log. +The texts are in `app/messages.py`. An alarm's ERROR or WARNING line names its +reason code, and its full figures are on the DEBUG line right after it and in +`events` in the `status` JSON. - **Stuck-meter check: off** needs `meter_source: homewizard_local` (label “Where the meter reading comes from”), a `max_w` (“Inverter rating”) and a @@ -3246,9 +3248,13 @@ ERROR or WARNING line in the add-on log. check** SAFETY-42. - **Month peak** and **15-minute periods measured** are TARIFF-01 and TARIFF-13. The store's state at start is the INFO line `Month peak store: - …`, and the peak guard's full reason is on its log line. + …`, and the peak guard's full reason is on the DEBUG line after its ERROR. - ***name*: battery power reading stopped changing** is SAFETY-37/56/57. The - ERROR line carries the full `STALE_READING` reason and when it clears. + ERROR line says when it clears and names `STALE_READING`. The full reason, + with both possible causes, is on the DEBUG line after it. +- **Meter: no reading for …** (red): the add-on logs one WARNING when the + meter goes quiet, "No meter reading for …", and an INFO line when readings + return. Past `stale_input_s` the **Why** line names the missing reading. - The table at the top: **Why** is `messages.why()`, the arbiter's answer in words (`Resolution.explain()` stays on the log). **Tariff**, **Price history**, **Arbitrage** and **Shadow mode** keep every figure they had diff --git a/goodwe_controller/app/main.py b/goodwe_controller/app/main.py index 54598a1..a5df597 100644 --- a/goodwe_controller/app/main.py +++ b/goodwe_controller/app/main.py @@ -611,9 +611,13 @@ class Controller: self._grade_store_migration(store) for inv in self.inverters: if inv.sign_wd.tripped: + # UX-11: the plain sentence and the code. The saved reason, + # with its figures, is on the DEBUG line beside it. _LOG.error("%s stays at 0 W after the restart because its " "power went the wrong way, so find out why before " - "you start control. %s.", inv.name, + "you start control: %s.", inv.name, + messages.reason_code(inv.sign_wd.reason)) + _LOG.debug("Evidence for %s: %s.", inv.name, inv.sign_wd.reason or "(reason not recorded)") # --- SAFETY-42 + SAFETY-34 ------------------------------------------- @@ -637,8 +641,10 @@ class Controller: _LOG.error( "%s is still marked as not delivering after the restart " "while control keeps running, and only stopping and " - "starting control clears this. %s.", - inv.name, inv.delivery_wd.reason or "(reason not recorded)") + "starting control clears this: %s.", + inv.name, messages.reason_code(inv.delivery_wd.reason)) + _LOG.debug("Evidence for %s: %s.", inv.name, + inv.delivery_wd.reason or "(reason not recorded)") # --- SAFETY-30: THE SITE HALF OF THE SIGN CHECK ---------------------- # ⚠️ ONE PER SITE, BESIDE THE ONE PER INVERTER, AND ARMED ONLY AT N>=2. @@ -669,8 +675,9 @@ class Controller: _LOG.error( "After the restart every inverter stays at 0 W, as the total " "power went the wrong way, so find out why before starting " - "control. %s.", - self.site_sign_wd.reason or "(reason not recorded)") + "control: %s.", messages.reason_code(self.site_sign_wd.reason)) + _LOG.debug("Evidence for the site: %s.", + self.site_sign_wd.reason or "(reason not recorded)") # And the per-unit detectors are told which question they are asking, # here as well as in `cycle()`. `checks()` and the status page read # `inv.sign_wd.cfg` and can be called before the first cycle has run, so @@ -722,8 +729,10 @@ class Controller: _LOG.error( "After the restart every inverter stays at 0 W, as the " "inverters worked against each other, so find out why before " - "starting control. %s.", - self.circ_wd.reason or "(reason not recorded)") + "starting control: %s.", + messages.reason_code(self.circ_wd.reason)) + _LOG.debug("Evidence for the site: %s.", + self.circ_wd.reason or "(reason not recorded)") # SAFETY-03. The output clamp's alarm - see clamp.py for why the clamp # itself is the cheap half. @@ -929,6 +938,8 @@ class Controller: self.following = False self.reason = "starting" self.why_words = "Starting" + # UX-11: has this meter episode's WARNING been logged? See read_inputs. + self._meter_quiet_logged = False # ALLOC-01. The allocation record from the last resolution, or None # before the first cycle. ⚠️ IT IS KEPT SO THAT SOMETHING CAN GATE ON # IT: SAFETY-28 puts the write path behind this record, and DEV-02 reads @@ -1229,8 +1240,9 @@ class Controller: first.store_set("sign_tripped", True) _LOG.error( "%s is set to 0 W again because an older saved safety stop was " - "found, so find out why before you start control. %s.", - first.name, first.sign_wd.reason) + "found, so find out why before you start control: %s.", + first.name, messages.reason_code(first.sign_wd.reason)) + _LOG.debug("Evidence for %s: %s.", first.name, first.sign_wd.reason) _LOG.debug( "SAFETY-02 latch guard: the pre-DEV-02 flat key says the " "sign-disagreement failsafe is latched and no inverter came up " @@ -1726,6 +1738,18 @@ class Controller: return all(inv.soc is not None and inv.batt is not None for inv in self.inverters) + def missing_reading(self) -> str: + """UX-11: the first reading `inputs_ok` finds missing, in words.""" + if self.grid is None or not self.inverters: + return "meter" + for inv in self.inverters: + of = "" if len(self.inverters) == 1 else f" from {inv.name}" + if inv.batt is None: + return f"battery power{of}" + if inv.soc is None: + return f"battery level{of}" + return "input" + # -- io ------------------------------------------------------------------ @property def pv_roster(self) -> tuple: @@ -1885,6 +1909,21 @@ class Controller: horizon_h=float(price_option(o, "price_horizon_h")), provider=provider_configured(o), max_age_s=TARIFF_MAX_AGE_S) + # UX-11: the red meter row says "the add-on log shows why", so a meter + # that goes quiet gets one WARNING per episode, not one per cycle. It + # is a log line only: no notification, and nothing it decides. + if self.p1_enabled: + if (self.p1.stale and not self._meter_quiet_logged + and self.p1.published_age_s > self.p1.max_age_s): + self._meter_quiet_logged = True + _LOG.warning("No meter reading for %s, over the limit of %s, " + "so control waits and then sets the battery to " + "0 W.", messages.seconds(self.p1.published_age_s), + messages.seconds(self.p1.max_age_s)) + elif not self.p1.stale and self._meter_quiet_logged: + self._meter_quiet_logged = False + _LOG.info("Meter readings are back.") + if self.inputs_ok: if self.inputs_bad_since is not None: self.log_event("inputs recovered", @@ -1953,13 +1992,16 @@ class Controller: # learns to skim it. # UX-08 2d: plain, with SAFETY-57's escape clause kept as an # ordered pair (time, then power), and the reason still in `%s`. - # UX-10: one sentence, then the reason's two. Its limits are on - # the DEBUG line below, to keep the line within 3 sentences. + # UX-11: one sentence and the code. The reason, with SAFETY-56's + # two explanations and its figures, and the limits are on the + # DEBUG lines below and in the action log. _LOG.error("%s: battery power reading stopped changing, set to " "0 W until it changes, or %.0f s after the command " - "drops below %.0f W. %s.", + "drops below %.0f W: %s.", inv.name, inv.batt_fresh.bound.release_s, - inv.batt_fresh.bound.move_w, inv.batt_fresh.reason) + inv.batt_fresh.bound.move_w, + messages.reason_code(inv.batt_fresh.reason)) + _LOG.debug("Evidence for %s: %s.", inv.name, inv.batt_fresh.reason) _LOG.debug("%s: the limits are unchanged over %.0f s, a command " "over %.0f W and a move by over %.0f W.", inv.name, inv.batt_fresh.bound.unchanged_s, @@ -2491,8 +2533,10 @@ class Controller: self.log_event(f"FAILSAFE {inv.name}: " + inv.sign_wd.reason, hint=messages.hint("direction", unit=inv.name)) _LOG.error("%s is set to 0 W until control is started, " - "because its power went the wrong way. %s.", - inv.name, inv.sign_wd.reason) + "because its power went the wrong way: %s.", + inv.name, messages.reason_code(inv.sign_wd.reason)) + _LOG.debug("Evidence for %s: %s.", inv.name, + inv.sign_wd.reason) # ⚠️ THE SITE'S OWN STANDING COMMAND, WHICH IS THE SUM OF THE UNITS'. # SAFETY-07 and SAFETY-18 both grade a SITE quantity - the quarter-hour # average at the grid connection, and a meter that has stopped moving @@ -2540,7 +2584,10 @@ class Controller: hint=messages.hint("site_direction")) _LOG.error("Every inverter is set to 0 W until control is " "started, because the total power went the wrong " - "way. %s.", self.site_sign_wd.reason) + "way: %s.", + messages.reason_code(self.site_sign_wd.reason)) + _LOG.debug("Evidence for the site: %s.", + self.site_sign_wd.reason) # --- SAFETY-31, AND IT RUNS BESIDE SAFETY-02 FOR THE SAME REASON ----- # Evaluated EVERY cycle, unconditionally, above the "inputs missing but @@ -2572,8 +2619,9 @@ class Controller: hint=messages.hint("circulating")) _LOG.error( "Every inverter is set to 0 W until control is started, " - "because the inverters worked against each other. %s.", - self.circ_wd.reason) + "because the inverters worked against each other: %s.", + messages.reason_code(self.circ_wd.reason)) + _LOG.debug("Evidence for the site: %s.", self.circ_wd.reason) # --- SAFETY-42, AND IT RUNS HERE FOR SAFETY-02's AND SAFETY-31's REASON # Evaluated EVERY cycle, unconditionally, ABOVE the "inputs missing but @@ -2680,8 +2728,10 @@ class Controller: unit=inv.name)) _LOG.error( "%s is not delivering while control keeps running, and " - "only stopping and starting control clears this. %s.", - inv.name, inv.delivery_wd.reason) + "only stopping and starting control clears this: %s.", + inv.name, messages.reason_code(inv.delivery_wd.reason)) + _LOG.debug("Evidence for %s: %s.", inv.name, + inv.delivery_wd.reason) _LOG.debug( "SAFETY-42 reports and does not act: commanding a unit " "that is not listening achieves nothing (HW-01), and the " @@ -3554,9 +3604,14 @@ class Controller: # UX-10: `why_key()` maps a safety winner to its claim's reason, and # every key it can return has words in messages.WHY_WINNER. _why = why_key(resolution.winner, claims) - self.why_words = messages.why(_why, resolution.target_w, - resolution.bound_by, - contradiction=resolution.contradiction) + if _why == "inputs missing" and not resolution.contradiction: + # UX-11: past the hold, say which reading is missing. + self.why_words = messages.why_missing(self.missing_reading(), + stale_after) + else: + self.why_words = messages.why( + _why, resolution.target_w, resolution.bound_by, + contradiction=resolution.contradiction) # --- DEV-02: EACH INVERTER IS TOLD ITS OWN SHARE --------------------- # ⚠️ ITS OWN SHARE, NEVER THE SITE TARGET. `resolution.shares` is the # allocator's answer and `sum(shares) + unmet_w == round(target_w)` is @@ -3743,8 +3798,8 @@ class Controller: shadow.why(self.o, control_started=self.auto)) elif not first: self.log_event( - "SHADOW MODE OFF - the battery is being controlled again, " - f"resuming from {shadow.WIRE_W:.0f} W", + "Shadow mode off: the add-on controls the battery again, " + f"starting from {shadow.WIRE_W:.0f} W", hint=messages.hint("shadow_off")) _LOG.info( "Shadow mode is off, so the add-on controls the battery " @@ -3856,8 +3911,9 @@ class Controller: # write-path engagements and 2 loop-side ones. if engaged and not engaged_write: tag = f"{CLAMP_REASON} episode {self.clamp_wd.episodes}" - row = (f"{tag}: {self.clamp_wd.engagements} engagement(s) - " - f"{reason}") + row = (f"{tag}: " + f"{messages.count(self.clamp_wd.engagements, 'engagement')}" + f" - {reason}") if self.events and tag in self.events[0]: stamp = self.events[0].split(" ", 1)[0] self.events[0] = f"{stamp} {row}" @@ -3871,8 +3927,9 @@ class Controller: # WARNING and a plainly titled notice, same cadence. Its OWN id, so # it can never replace a BUG SIGNAL notice still on screen. _LOG.warning("The battery gives less than asked: %s. Held back %s " - "so far.", self.clamp_wd.reason, + "so far.", messages.reason_code(self.clamp_wd.reason), messages.times(self.clamp_wd.engagements)) + _LOG.debug("Evidence: %s.", self.clamp_wd.reason) _LOG.debug("A short hold after a large load or solar step is " "normal. If it lasts, check that the battery follows " "its commands.") @@ -3881,8 +3938,9 @@ class Controller: return _LOG.error( "Power request too high, a software fault: %s. Cut back %s so " - "far, control runs on.", - self.clamp_wd.reason, messages.times(self.clamp_wd.engagements)) + "far, control runs on.", messages.reason_code(self.clamp_wd.reason), + messages.times(self.clamp_wd.engagements)) + _LOG.debug("Evidence: %s.", self.clamp_wd.reason) _LOG.debug( "SAFETY-03: silently clipping this is how a winding integrator " "reached 14 768 W on this project before. The clamp makes every " @@ -3931,7 +3989,9 @@ class Controller: hint=messages.hint("peak_saturated")) _LOG.error( "Switch off large loads, the battery alone cannot keep this " - "15-minute period under the peak limit. %s.", g.reason) + "15-minute period under the peak limit: %s.", + messages.reason_code(g.reason)) + _LOG.debug("Evidence: %s.", g.reason) # A fixed notification_id, and a DIFFERENT one from every other alarm # here - check_meter_frozen() gives the reasoning. A saturated peak guard # is not a frozen meter and is not an out-of-range setpoint. @@ -3988,7 +4048,8 @@ class Controller: self.log_event(g.reason, hint=messages.hint("peak_reserve")) _LOG.error( "Switch off large loads, the peak guard may not draw the battery " - "lower. %s.", g.reason) + "lower: %s.", messages.reason_code(g.reason)) + _LOG.debug("Evidence: %s.", g.reason) # A fixed notification_id, and a DIFFERENT one from every other alarm # here - check_meter_frozen() gives the reasoning. A battery at its # energy floor is not a saturated inverter and is not a frozen meter, @@ -4148,8 +4209,9 @@ class Controller: hint=messages.hint("meter_frozen")) _LOG.error( "The meter shows the same value while the battery is asked for " - "full power, and control still follows it, so check the meter. " - "%s.", self.freeze_wd.reason) + "full power, and control still follows it, so check the meter: " + "%s.", messages.reason_code(self.freeze_wd.reason)) + _LOG.debug("Evidence: %s.", self.freeze_wd.reason) _LOG.debug( "SAFETY-18: nothing else stops this. The meter still answers, so " "its age is fresh, the firmware watchdog is fed and the arbiter " diff --git a/goodwe_controller/app/messages.py b/goodwe_controller/app/messages.py index e2e4297..0e072de 100644 --- a/goodwe_controller/app/messages.py +++ b/goodwe_controller/app/messages.py @@ -311,6 +311,22 @@ def seconds(value) -> str: return f"{n} second" if n == "1" else f"{n} seconds" +# One token each, like a code, so the line keeps its length and stays greppable. +NO_REASON_SAVED, NO_REASON_CODE = "REASON_NOT_SAVED", "REASON_WITHOUT_CODE" +_REASON_CODE = re.compile(r"\b[A-Z][A-Z0-9]*(?:_[A-Z0-9]+)+\b") + + +def reason_code(reason) -> str: + """UX-11: the code in a safety reason (`STALE_READING`), for the one plain + WARNING or ERROR line that reports it. The reason with its figures goes on + a DEBUG line beside it and into the action log. Saved reasons have always + opened with their code, so an old state file reads the same way.""" + if not reason: + return NO_REASON_SAVED + m = _REASON_CODE.search(str(reason)) + return m.group(0) if m else NO_REASON_CODE + + def times(n) -> str: return "1 time" if int(n) == 1 else f"{int(n)} times" @@ -813,6 +829,11 @@ def why(winner, target_w, bound_by=None, *, contradiction=False) -> str: return out +def why_missing(what, limit_s) -> str: + """UX-11: past the hold, which reading is missing and what it does.""" + return f"No usable {what} reading for over {seconds(limit_s)}: 0 W" + + def why_waiting(missing_s) -> str: """A reading went missing a moment ago: control holds and waits.""" return f"A reading is missing for {seconds(missing_s)}, control waits" diff --git a/goodwe_controller/app/watchdog.py b/goodwe_controller/app/watchdog.py index bbe857b..8bb97b6 100644 --- a/goodwe_controller/app/watchdog.py +++ b/goodwe_controller/app/watchdog.py @@ -670,11 +670,10 @@ class SignWatchdog: # ⚠️ `self.against` IS THE ONLY THING SAFETY-30 CHANGED IN THIS STRING, # and it defaults to the wording that shipped - "a meter reading" - so a # one-inverter install's `reason` is byte-identical to what an operator - # (and test_watchdog.py) has always read. A per-unit instance names what - # it actually compared instead, because "commanded +1500 W against a - # meter reading -1500 W" would be a false statement about which - # instrument produced the evidence, on the one line somebody woken by - # this alarm reads first. + # has always read (test_watchdog.py pins its meaning). A per-unit + # instance names what it actually compared instead, because "commanded + # +1500 W against a meter reading -1500 W" would be a false statement + # about which instrument produced the evidence. self.reason = ( f"SIGN_DISAGREEMENT: commanded {commanded_w:+.0f} W against " f"{self.against} {against_w:+.0f} W for {held:.0f} s continuously " diff --git a/goodwe_controller/test_clamp.py b/goodwe_controller/test_clamp.py index 3c900f0..9d5ca16 100644 --- a/goodwe_controller/test_clamp.py +++ b/goodwe_controller/test_clamp.py @@ -521,7 +521,8 @@ check(f"the action log records every engagement, coalesced into one row per " f"episode ({len(rows_r)} row(s), {ctl_r.clamp_wd.engagements} " f"engagement(s))", len(rows_r) == ctl_r.clamp_wd.episodes - and f"{ctl_r.clamp_wd.engagements} engagement(s)" in rows_r[0]) + and messages.count(ctl_r.clamp_wd.engagements, "engagement") + in rows_r[0]) # ⚠️ REGRESSION, AND IT WAS A REAL BUG BEFORE IT WAS A CHECK. `log_event()` keeps # 40 rows. A row per engagement flushes that ring inside 40 cycles of a winding @@ -538,7 +539,8 @@ check(f"a long winding episode does NOT flood the 40-row event log " f"({len(rows_l)} rows for {ctl_l.clamp_wd.engagements} engagements)", ctl_l.clamp_wd.engagements > 40 and len(rows_l) <= ctl_l.clamp_wd.episodes) check("...and the count in the row is the counter's, so nothing is lost", - f"{ctl_l.clamp_wd.engagements} engagement(s)" in nth(rows_l, -1)) + messages.count(ctl_l.clamp_wd.engagements, "engagement") + in nth(rows_l, -1)) # The RED row exists only while engaged, and the episode above is short, so it # is captured mid-run rather than asserted after the hysteresis has cleared it. check("the status page flags it WHILE it is engaged - amber, since it is the " @@ -2051,9 +2053,12 @@ check("it still NOTIFIES (not suppressed), under a title that claims no bug", check("...under its OWN notification_id, so it cannot replace a BUG SIGNAL " "notice still on screen", notes_i and all(n["notification_id"] == BOUND_ID for n in notes_i)) +# UX-11: the WARNING quotes the code. The reason is on the DEBUG line beside +# it (test_messages.py part 6). check("...logged as a WARNING, not an ERROR", - any(x.levelno == logging.WARNING and "reached its" in x.getMessage() - for x in log_i) + any(x.levelno == logging.WARNING + and x.getMessage().startswith("The battery gives less than asked: " + "OUTPUT_CLAMP.") for x in log_i) and not any(x.levelno >= logging.ERROR and "OUTPUT_CLAMP" in x.getMessage() for x in log_i)) check("...and the status row is amber, not red", diff --git a/goodwe_controller/test_freshness.py b/goodwe_controller/test_freshness.py index f09515c..80a8e3c 100644 --- a/goodwe_controller/test_freshness.py +++ b/goodwe_controller/test_freshness.py @@ -1813,6 +1813,11 @@ _S56_ACCUSATIONS = [ ] _log56 = [r.getMessage() for r in _LOGREC[_S56_LOG0:] if "battery power reading stopped changing" in r.getMessage()] +# UX-11: the ERROR line quotes the code, and the reason itself is on the DEBUG +# line logged beside it. +_dbg56 = [r.getMessage() for r in _LOGREC[_S56_LOG0:] + if r.levelno == logging.DEBUG + and r.getMessage().startswith("Evidence for ")] or [""] def _s56_row(c): @@ -1855,7 +1860,7 @@ check("PRECONDITION: all four operator-facing surfaces were really produced by " "two are the same string, which is 11b again on the log surface", len(_log56) == 2 and _log56[0] == _log56[1] and all(len(s) > 30 for s in _S56_SURFACES.values()) - and _r56_ref in _log56[-1]) + and _log56[-1].endswith(": STALE_READING.") and _r56_ref in _dbg56[-1]) _idx56 = [_r56_ref.find(t) for _w, t in _S56_EXPLANATIONS] check(f"11c. BOTH EXPLANATIONS ARE NAMED, AND IN THAT ORDER: " f"{_S56_EXPLANATIONS[0][1]!r} at {_idx56[0]} then " diff --git a/goodwe_controller/test_messages.py b/goodwe_controller/test_messages.py index 9943508..6bb209e 100644 --- a/goodwe_controller/test_messages.py +++ b/goodwe_controller/test_messages.py @@ -877,6 +877,8 @@ DATA = { "main.py:messages.when(brussels(self.tariff_at))", "main.py:messages.duration(TARIFF_MAX_AGE_S)", "main.py:messages.count(len(targets), 'inverter')", + "main.py:messages.seconds(self.p1.published_age_s)", + "main.py:messages.seconds(self.p1.max_age_s)", # maintenance.py, mqtt.py, p1.py "maintenance.py:phase", "mqtt.py:err", "p1.py:err", "p1.py:self.host", "p1.py:self.topic", "p1.py:poll_s", "p1.py:ingest.max_age_s", @@ -1047,20 +1049,35 @@ def _static(spec): return [t for t in out if len(words(t)) > 1] +# UX-11: a WARNING+ line quotes a safety reason by its code only. The reason, +# with its figures, is on a DEBUG line beside it and in the action log. +SAFETY_REASONS = { + "sign": _sign_texts, "circulation": _circ_texts, + "delivery": _delivery_texts, "clamp": _clamp_texts, "peak": _peak_texts, + "freeze": _freeze_texts, "stale": _stale_texts, +} + + +def _coded(maker): + """The codes a WARNING+ line shows for the reasons `maker` builds, plus + the fallback for a restored stop with no reason saved.""" + return lambda: ([messages.reason_code(t) for t in maker()] + + [messages.reason_code("")]) + + TEXT = { - "main.py:first.sign_wd.reason": _sign_texts, - "main.py:inv.sign_wd.reason": _sign_texts, - "main.py:inv.sign_wd.reason or '(reason not recorded)'": _sign_texts, - "main.py:self.site_sign_wd.reason": _sign_texts, - "main.py:self.site_sign_wd.reason or '(reason not recorded)'": _sign_texts, - "main.py:self.circ_wd.reason": _circ_texts, - "main.py:self.circ_wd.reason or '(reason not recorded)'": _circ_texts, - "main.py:inv.delivery_wd.reason": _delivery_texts, - "main.py:inv.delivery_wd.reason or '(reason not recorded)'": _delivery_texts, - "main.py:self.clamp_wd.reason": _clamp_texts, - "main.py:g.reason": _peak_texts, - "main.py:self.freeze_wd.reason": _freeze_texts, - "main.py:inv.batt_fresh.reason": _stale_texts, + "main.py:messages.reason_code(first.sign_wd.reason)": _coded(_sign_texts), + "main.py:messages.reason_code(inv.sign_wd.reason)": _coded(_sign_texts), + "main.py:messages.reason_code(self.site_sign_wd.reason)": + _coded(_sign_texts), + "main.py:messages.reason_code(self.circ_wd.reason)": _coded(_circ_texts), + "main.py:messages.reason_code(inv.delivery_wd.reason)": + _coded(_delivery_texts), + "main.py:messages.reason_code(self.clamp_wd.reason)": _coded(_clamp_texts), + "main.py:messages.reason_code(g.reason)": _coded(_peak_texts), + "main.py:messages.reason_code(self.freeze_wd.reason)": + _coded(_freeze_texts), + "main.py:messages.reason_code(inv.batt_fresh.reason)": _coded(_stale_texts), "main.py:rep.explain()": _migration_texts, "store.py:rep.explain()": _migration_texts, "main.py:plan.words": _tariff_texts, @@ -1086,6 +1103,26 @@ TEXT = { } +# UX-11: a WARNING+ line, as logged with its built text filled in, is at most +# 25 words (STYLE.md). These families are not safety reasons and were not +# rewritten by UX-11. Each is listed with why, the list may only shrink +# (LONG_LINE_CAP), and a listed key that no longer runs long fails. +LONG_LINE_OK = { + "main.py:plan.words": "tariff plan words, TARIFF-11 pins them, follow-up", + "static_tariff.py:read.reason": "price feed reasons, follow-up", + "main.py:rep.explain()": "state migration report, names saved keys", + "store.py:rep.explain()": "state migration report, names saved keys", + "main.py:refusal": "write refusals, a software fault only", + "main.py:' / '.join(resolution.scope_errors)": + "claim scope errors, a software fault only", + "maintenance.py:msg": "maintenance gate reasons, follow-up", + "price_forecast.py:gate.reason": "trading gate reasons, follow-up", + "price_history.py:self.last_error": "price history errors, follow-up", +} +LONG_LINE_CAP = 9 +LINE_WORDS = 25 + + def reason_problems(text): """STYLE.md's red-alarm shape, for a text a log line quotes.""" out = [] @@ -1133,10 +1170,12 @@ def _fill(template, fmt_node, key_part, sample): return template # %-style: filled by the caller -def scan_log_lines(files, text=None, data=None): +def scan_log_lines(files, text=None, data=None, long_ok=None, long_seen=None): """-> (unclassified keys, stale keys, [(key, sample, problems)]).""" text = TEXT if text is None else text data = DATA if data is None else data + long_ok = LONG_LINE_OK if long_ok is None else long_ok + long_seen = set() if long_seen is None else long_seen seen, bad = set(), [] for fname, tree in files: for key, call in dynamic_parts(tree, fname): @@ -1162,6 +1201,11 @@ def scan_log_lines(files, text=None, data=None): line = PLACEHOLDER.sub("X", line).replace("\0", sample) p += [f"as logged: {x}" for x in line_problems(line) + logged_shape(line) if x not in p] + if len(words(line)) > LINE_WORDS: + long_seen.add(key) + if key not in long_ok: + p.append(f"as logged: over {LINE_WORDS} words " + f"({len(words(line))})") if p: bad.append((key, sample, p)) unknown = sorted(seen - set(data) - set(text)) @@ -1171,14 +1215,79 @@ def scan_log_lines(files, text=None, data=None): _FILES = [(f.name, ast.parse(f.read_text(encoding="utf-8"))) for f in sorted(APP.glob("*.py"))] -_unknown, _stale, _bad = scan_log_lines(_FILES) +_long_seen = set() +_unknown, _stale, _bad = scan_log_lines(_FILES, long_seen=_long_seen) for k, sample, p in _bad: - print(f" BAD {k}: {'; '.join(p)} :: {sample[:110]!r}") + print(f" BAD {k}: {'; '.join(p)} :: {sample!r}") check(f"every dynamic part of a WARNING+ line is classified as data or as a " f"built text (unclassified: {_unknown})", not _unknown) check(f"...and no classification is left over from a line that is gone " f"(stale: {_stale})", not _stale) _n_texts = sum(len(m()) for m in TEXT.values() if m is not None) +check(f"UX-11: no WARNING+ line runs over {LINE_WORDS} words as logged, except " + f"the {len(LONG_LINE_OK)} listed families, and none of them is a safety " + f"reason (cap {LONG_LINE_CAP})", + len(LONG_LINE_OK) <= LONG_LINE_CAP + and not any("reason_code" in k for k in LONG_LINE_OK)) +check(f"...and every listed family still runs long, so the list only shrinks " + f"(no longer long: {sorted(set(LONG_LINE_OK) - _long_seen)})", + set(LONG_LINE_OK) <= _long_seen) + + +def _code_lines_without_evidence(files): + """WARNING+ calls quoting `messages.reason_code(X)` whose next statement + is not a DEBUG call that logs X itself (UX-11: nothing is lost).""" + out, n = [], 0 + for fname, tree in files: + for node in ast.walk(tree): + for body in (getattr(node, f, None) for f in ("body", "orelse")): + if not isinstance(body, list): + continue + for i, st in enumerate(body): + call = st.value if isinstance(st, ast.Expr) else None + if not (isinstance(call, ast.Call) + and LOG_CALL.search(ast.unparse(call.func))): + continue + coded = [a.args[0] for a in call.args + if isinstance(a, ast.Call) and a.args + and ast.unparse(a.func) == "messages.reason_code"] + if not coded: + continue + n += 1 + nxt = body[i + 1] if i + 1 < len(body) else None + dbg = (nxt.value if isinstance(nxt, ast.Expr) + and isinstance(nxt.value, ast.Call) + and ast.unparse(nxt.value.func).endswith(".debug") + else None) + want = ast.unparse(coded[0]) + if dbg is None or not any( + ast.unparse(a) == want + or ast.unparse(a).startswith(want + " or ") + for a in dbg.args): + out.append(f"{fname}:{call.lineno}") + return n, out + + +_n_coded, _no_evidence = _code_lines_without_evidence(_FILES) +check(f"every WARNING+ line that quotes a reason code ({_n_coded}) has the " + f"reason itself on a DEBUG line right after it (missing: {_no_evidence})", + _n_coded >= 14 and not _no_evidence) +_n_m, _m_bad = _code_lines_without_evidence([("x.py", ast.parse( + "_LOG.error('Stop: %s.', messages.reason_code(wd.reason))\n" + "_LOG.debug('Something else.')\n"))]) +check("...and a line whose DEBUG evidence was dropped is caught", + _n_m == 1 and _m_bad == ["x.py:1"]) +_evidence_bad = [(n, t, reason_problems(t)) for n, m in SAFETY_REASONS.items() + for t in m() if reason_problems(t)] +check(f"the safety reasons behind those lines, on the DEBUG line and in the " + f"action log, keep the red-alarm shape ({_evidence_bad})", + not _evidence_bad) +_codes = {n: [messages.reason_code(t) for t in m()] + for n, m in SAFETY_REASONS.items()} +check(f"...and every one carries a code the line can quote ({_codes})", + all(re.fullmatch(r"[A-Z]+(?:_[A-Z]+)+", c) + and c not in (messages.NO_REASON_SAVED, messages.NO_REASON_CODE) + for cs in _codes.values() for c in cs)) check(f"every built text, run for real, obeys the rule, and so does the line " f"that quotes it ({_n_texts} texts, {len(_bad)} bad)", not _bad) _counts = [f"{f}:{n.lineno}" for f, t in _FILES for n in ast.walk(t) @@ -1208,29 +1317,43 @@ _clamp_lines = { "error, write": (_clamp_line("Power request too high"), _w1), "warning, loop": (_clamp_line("The battery gives less than asked"), _at), } -_clamp_shown = {k: (f % (r, messages.times(1)) if f else None) +_clamp_shown = {k: (f % (messages.reason_code(r), messages.times(1)) + if f else None) for k, (f, r) in _clamp_lines.items()} for k, v in _clamp_shown.items(): print(f" {k}: {v!r} ({len(words(v or ''))} words)") -check("the clamp lines for one inverter are at most 3 sentences and 30 words, " - "and keep OUTPUT_CLAMP and the numbers", - all(v and sentences(v) <= 3 and len(words(v)) <= 30 +check("UX-11: the clamp lines are at most 25 words and keep OUTPUT_CLAMP and " + "the count, and the numbers are in the reason the DEBUG line beside " + "them logs", + all(v and len(words(v)) <= LINE_WORDS and "OUTPUT_CLAMP" in v and "1 time so far" in v - for v in _clamp_shown.values()) - and all(x in _clamp_shown["error, loop"] - for x in ("+9000 W", "+5000 W", "+2000 W", "software fault"))) + and "+9000" not in v for v in _clamp_shown.values()) + and "software fault" in _clamp_shown["error, loop"] + and all(x in _over for x in ("+9000 W", "+5000 W", "+2000 W"))) # Mutations: the scan catches what the 2d scan missed. _OLD_CLAMP = ("OUTPUT_CLAMP: the loop computed +2148 W, over the 2000 W rating, " "and it was clamped to +2000 W; the loop's command this cycle was " "+440 W. This is a BUG SIGNAL, not a limit being used: something " "upstream computed a setpoint the actuator cannot deliver.") -_mut_text = dict(TEXT, **{"main.py:self.clamp_wd.reason": lambda: [_OLD_CLAMP]}) +_mut_text = dict(TEXT, **{"main.py:messages.reason_code(self.clamp_wd.reason)": + lambda: [_OLD_CLAMP]}) _u, _s, _b = scan_log_lines([f for f in _FILES if f[0] == "main.py"], text=_mut_text) check("an injected bad reason (the 2d clamp text) is caught, on both clamp " f"lines ({sorted({k for k, _t, _p in _b if 'clamp' in k})})", - [k for k, _t, _p in _b].count("main.py:self.clamp_wd.reason") == 2) + [k for k, _t, _p in _b].count( + "main.py:messages.reason_code(self.clamp_wd.reason)") == 2) +# UX-11: the line that quoted the whole STALE_READING reason (60 words on +# TEST-23) is caught by the length rule alone. +_old_stale = dict(TEXT, **{"main.py:messages.reason_code(inv.batt_fresh.reason)": + _stale_texts}) +_u, _s, _b = scan_log_lines([f for f in _FILES if f[0] == "main.py"], + text=_old_stale) +check("...and the UX-10 stale line, which quoted the whole reason, is caught " + f"for its length ({[p for k, _t, p in _b if 'batt_fresh' in k][:1]})", + any("batt_fresh" in k and any(f"over {LINE_WORDS} words" in x for x in p) + for k, _t, p in _b)) _new_site = ast.parse("_LOG.warning('Something broke: %s', self.new_wd.reason)") _u, _s, _b = scan_log_lines([("main.py", _new_site)]) check(f"...and a new line quoting a text nobody classified is caught ({_u})", @@ -1487,6 +1610,9 @@ class _H: async def call(self, *a, **k): return True + async def set_number(self, *a, **k): + return True + class _S: data = {} @@ -1549,6 +1675,104 @@ _c.why_words = "Keeping the grid near zero: 0 W" check("...and once a cycle decides again, the line is that decision", _c.why_words == "Keeping the grid near zero: 0 W") +# UX-11 item 3: past the hold, the Why line says which reading is missing, +# not "A reading is missing: 0 W". Driven through cycle() for real. +_c.inputs_bad_since = _dt.now(_tz.utc) - _td(seconds=20) +asyncio.run(_c.cycle()) +check(f"past the hold, the Why line names the missing reading " + f"({_c.why_words!r})", + _c.why_words == "No usable meter reading for over 15 seconds: 0 W") + +# UX-11 item 2: the red meter row says the log shows why. A meter that goes +# quiet logs one WARNING per episode, not one per cycle, and INFO when back. +_c.p1_enabled = True +_c.p1 = _p1.P1Ingest(max_age_s=30.0) + + +def _meter_at(age_s): + import time as _time + _c.p1.submit(_p1.make_sample(_p1.SOURCE_HA, 500.0, 0.0, phases=1, + ingest_mono=_time.monotonic() - age_s)) + + +def _quiet_episodes(): + for age in (1, 40, 45, 50, 1, 2, 60, 65): + _meter_at(age) + asyncio.run(_c.read_inputs()) + + +_mq = [r for r in _captured("goodwe", _quiet_episodes) + if "meter" in r.getMessage().lower()] +_mq_warn = [r.getMessage() for r in _mq if r.levelno == logging.WARNING] +_mq_info = [r.getMessage() for r in _mq if r.levelno == logging.INFO] +check(f"a meter that goes quiet logs one WARNING per episode, not per cycle, " + f"and one INFO when readings return ({_mq_warn}, {_mq_info})", + len(_mq_warn) == 2 and _mq_info == ["Meter readings are back."] + and _mq_warn[0].startswith("No meter reading for 40 seconds, over the " + "limit of 30 seconds") + and len(words(_mq_warn[0])) <= LINE_WORDS) + +# UX-11 item 1: a state file saved before UX-11 holds the long reasons, and +# they load unchanged. The ERROR line at start shows the code, and the saved +# text goes on the DEBUG line beside it. Old and new files look the same, +# because the saved reason's format did not change and it opens with its code. +_OLD = { + "sign": "SIGN_DISAGREEMENT: commanded -1000 W against a meter reading " + "+1500 W for 180 s continuously (limits: both over 300 W, held " + "over 180 s)", + "delivery": "UNIT_NOT_DELIVERING: inverter-a is standing at +2000 W and " + "delivering +0 W - 2000 W of its share (100 % of it) is not " + "arriving - while inverter-b is not in that state. Nothing " + "this add-on reads explains it - held for 121 s continuously " + "(limit: over 120 s)", + "circ": "CIRCULATING_POWER: 5800 W measured going round between the " + "inverters for 61 s, peaking at 6000 W, over the limits of 250 W " + "and 60 s. The meter cannot see it, because it nets to zero there", +} + + +class _OldStore(_S): + data = {"unit/inverter-a/sign_tripped": True, + "unit/inverter-a/sign_reason": _OLD["sign"], + "unit/inverter-a/delivery_tripped": True, + "unit/inverter-a/delivery_reason": _OLD["delivery"], + "circ_tripped": True, "circ_reason": _OLD["circ"], + "site_sign_tripped": True, "site_sign_reason": ""} + + +_restart = [] +_rs = _captured("goodwe", lambda: _restart.append(Controller( + {"setpoint_entity": "number.sp", "meter_source": "off", "max_w": 2000}, + _H(), _OldStore(), _P(), stop=asyncio.Event()))) +_rs_err = [r.getMessage() for r in _rs if r.levelno == logging.ERROR] +_rs_dbg = [r.getMessage() for r in _rs if r.levelno == logging.DEBUG] +for _m in _rs_err: + print(f" {_m!r} ({len(words(_m))} words)") +check("an old state file's long reasons load unchanged, so the stops stay on", + _restart and _restart[0].inverters[0].sign_wd.tripped + and _restart[0].inverters[0].sign_wd.reason == _OLD["sign"] + and _restart[0].inverters[0].delivery_wd.reason == _OLD["delivery"] + and _restart[0].circ_wd.reason == _OLD["circ"]) +check("...each ERROR line at start is one plain sentence with the code, at " + f"most {LINE_WORDS} words, and a stop saved without a reason says so", + len(_rs_err) == 4 + and all(len(words(m)) <= LINE_WORDS and "(limits" not in m + for m in _rs_err) + and any(m.endswith(": SIGN_DISAGREEMENT.") for m in _rs_err) + and any(m.endswith(": UNIT_NOT_DELIVERING.") for m in _rs_err) + and any(m.endswith(": CIRCULATING_POWER.") for m in _rs_err) + and any(m.endswith(f": {messages.NO_REASON_SAVED}.") for m in _rs_err)) +check("...and the saved text, figures and all, is on a DEBUG line beside it", + all(any(t in m for m in _rs_dbg) for t in _OLD.values())) + +# UX-11 item 4: the action log's clamp count and the shadow-off entry. +_main_src = (APP / "main.py").read_text(encoding="utf-8") +check("the action log counts 'engagements' with a real plural and the " + "shadow-off entry is plain, not 'engagement(s)' or 'SHADOW MODE OFF -'", + "engagement(s)" not in _main_src and "SHADOW MODE OFF" not in _main_src + and messages.count(25, "engagement") == "25 engagements" + and messages.count(1, "engagement") == "1 engagement") + print() if fails: print(f"{len(fails)} FAILED") diff --git a/goodwe_controller/test_watchdog.py b/goodwe_controller/test_watchdog.py index 39940ea..cb8d5db 100644 --- a/goodwe_controller/test_watchdog.py +++ b/goodwe_controller/test_watchdog.py @@ -1422,14 +1422,22 @@ for _t in range(0, 400, 5): _wd_unit.evaluate(-1000.0, 1500.0, True, T0 + timedelta(seconds=_t)) print(f" site: {_wd_site.reason!r}") print(f" unit: {_wd_unit.reason!r}") -check("⚠️ THE SITE INSTANCE'S SENTENCE IS BYTE-IDENTICAL TO THE ONE THAT " - "SHIPPED. It is what an operator reads on the status page, what goes in " - "the action log and what is persisted to /data/state.json, so it is " - "asserted against the literal rather than against a format string", - _wd_site.reason == ( - "SIGN_DISAGREEMENT: commanded -1000 W against a meter reading " - "+1500 W for 180 s continuously (limits: both over 300 W, held over " - "180 s)")) +# UX-11: this was a byte pin. The reason is now the evidence: the action +# log, the DEBUG line and /data/state.json carry it, and the ERROR line quotes +# only its code (`messages.reason_code()`). So what is pinned is what it says: +# the code in front, where every saved reason has had it and where the ERROR +# line finds it, then the command and the reading in that order (habit 14), +# the time held and both limits. +_sr = _wd_site.reason +_order = [_sr.find(t) for t in ("commanded -1000 W", "meter reading +1500 W", + "for 180 s", "both over 300 W", + "held over 180 s")] +check("⚠️ THE SITE INSTANCE'S REASON SAYS WHAT SHIPPED, IN THE SAME ORDER: " + "the code first, then what was commanded, what the meter read, how " + f"long, and the two limits ({_order})", + _sr.startswith("SIGN_DISAGREEMENT: ") + and messages.reason_code(_sr) == "SIGN_DISAGREEMENT" + and all(i > 0 for i in _order) and _order == sorted(_order)) check("...and the per-unit instance names what it ACTUALLY compared instead. " "'against a meter reading' there would be a false statement about which " "instrument produced the evidence, on the one line somebody woken by " -- 2.54.0 From c628099e692fe052ff0614bec71fb4f549f009f1 Mon Sep 17 00:00:00 2001 From: glenn schrooyen <glenn@dsgpartners.be> Date: Sun, 27 Sep 2026 13:49:17 +0200 Subject: [PATCH 2/3] UX-11: the meter WARNING names the limit only, as 'over 30 seconds' TEST-23 showed 'No meter reading for 30 seconds, over the limit of 30 seconds': the age is 30.4 s, which rounds to the limit. The limit alone is always true at the moment the line is logged. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01LyR88rXETvwhTgx6yHE39p --- goodwe_controller/app/main.py | 5 ++--- goodwe_controller/test_messages.py | 5 ++--- 2 files changed, 4 insertions(+), 6 deletions(-) diff --git a/goodwe_controller/app/main.py b/goodwe_controller/app/main.py index a5df597..ff4abd0 100644 --- a/goodwe_controller/app/main.py +++ b/goodwe_controller/app/main.py @@ -1916,9 +1916,8 @@ class Controller: if (self.p1.stale and not self._meter_quiet_logged and self.p1.published_age_s > self.p1.max_age_s): self._meter_quiet_logged = True - _LOG.warning("No meter reading for %s, over the limit of %s, " - "so control waits and then sets the battery to " - "0 W.", messages.seconds(self.p1.published_age_s), + _LOG.warning("No meter reading for over %s, so control " + "waits and then sets the battery to 0 W.", messages.seconds(self.p1.max_age_s)) elif not self.p1.stale and self._meter_quiet_logged: self._meter_quiet_logged = False diff --git a/goodwe_controller/test_messages.py b/goodwe_controller/test_messages.py index 6bb209e..7513364 100644 --- a/goodwe_controller/test_messages.py +++ b/goodwe_controller/test_messages.py @@ -877,7 +877,6 @@ DATA = { "main.py:messages.when(brussels(self.tariff_at))", "main.py:messages.duration(TARIFF_MAX_AGE_S)", "main.py:messages.count(len(targets), 'inverter')", - "main.py:messages.seconds(self.p1.published_age_s)", "main.py:messages.seconds(self.p1.max_age_s)", # maintenance.py, mqtt.py, p1.py "maintenance.py:phase", "mqtt.py:err", "p1.py:err", "p1.py:self.host", @@ -1708,8 +1707,8 @@ _mq_info = [r.getMessage() for r in _mq if r.levelno == logging.INFO] check(f"a meter that goes quiet logs one WARNING per episode, not per cycle, " f"and one INFO when readings return ({_mq_warn}, {_mq_info})", len(_mq_warn) == 2 and _mq_info == ["Meter readings are back."] - and _mq_warn[0].startswith("No meter reading for 40 seconds, over the " - "limit of 30 seconds") + and _mq_warn[0] == "No meter reading for over 30 seconds, so control " + "waits and then sets the battery to 0 W." and len(words(_mq_warn[0])) <= LINE_WORDS) # UX-11 item 1: a state file saved before UX-11 holds the long reasons, and -- 2.54.0 From 3c298af3d89c252e46d4ccc11e7bd85c228a07b2 Mon Sep 17 00:00:00 2001 From: goodwe-reviewer <gschrooyen@gmail.com> Date: Sun, 27 Sep 2026 14:21:05 +0200 Subject: [PATCH 3/3] UX-11 review: restored stops log their figures to events, the quiet-meter WARNING is rate-limited - After a restart, each restored stop (direction per inverter and site, delivery, circulation) also writes its saved reason to the action log. log_level defaults to info and events starts empty, so the DEBUG evidence alone left the figures only in state.json. - A flapping meter (ha_signed under a flat load, 42-97 s between changes) logs at most one WARNING/INFO pair per 10 minutes, with the episodes in between at DEBUG. - LONG_LINE_OK refuses any key whose text is a safety reason. - test_watchdog keeps the byte pin beside the meaning pin, since the text did not change. - DOCS says the DEBUG line needs log_level debug. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> --- .../DECISIONS/UX-08-short-notifications.md | 5 +- goodwe_controller/DOCS.md | 9 ++-- goodwe_controller/app/main.py | 48 +++++++++++++++++-- goodwe_controller/test_messages.py | 27 +++++++++-- goodwe_controller/test_watchdog.py | 6 +++ 5 files changed, 82 insertions(+), 13 deletions(-) diff --git a/goodwe_controller/DECISIONS/UX-08-short-notifications.md b/goodwe_controller/DECISIONS/UX-08-short-notifications.md index e4b2832..3d88ff4 100644 --- a/goodwe_controller/DECISIONS/UX-08-short-notifications.md +++ b/goodwe_controller/DECISIONS/UX-08-short-notifications.md @@ -84,8 +84,9 @@ The allowlist is empty and its cap is 0 (43 → 0). Every WARNING and ERROR line **Unchanged:** every trigger, latch, threshold and alarm log level (the WARNING and ERROR lines stay), every notification id and cadence, every row colour and the banner cascade. No notification is added. 1. **One plain sentence and the code.** A WARNING/ERROR line that reports a safety reason (direction, delivery, stuck meter, stale reading, peak guard, circulation, over-rating) now ends in the reason's code, taken by `messages.reason_code()`. The reason itself, figures and limits included, is on a DEBUG line logged right after it ("Evidence for inverter-a: …"), and the action log entry carries it as before. Part 6 checks that pairing in the code. Circulation and the clamp lines were not among the five named, but they break the same 25-word rule, so they follow the same pattern. The clamp numbers stay in the notification (phase 2a item 3). -2. **The reasons and `state.json` are unchanged.** `reason` stays the evidence text, so what is saved has the same format as before. An old state file therefore loads and displays like a new one: every saved reason has opened with its code since it was first written (checked in the git history), and that code is all the ERROR line reads. The saved text goes on the DEBUG line. A stop saved without a reason shows `REASON_NOT_SAVED`. `test_messages.py` part 7 restarts from a state file holding the old long texts. The byte pin in `test_watchdog.py` now pins the meaning: the code first, then command, reading, time and both limits, in that order. +2. **The reasons and `state.json` are unchanged.** `reason` stays the evidence text, so what is saved has the same format as before. An old state file therefore loads and displays like a new one: every saved reason has opened with its code since it was first written (checked in the git history), and that code is all the ERROR line reads. The saved text goes on the DEBUG line. A stop saved without a reason shows `REASON_NOT_SAVED`. `test_messages.py` part 7 restarts from a state file holding the old long texts. `test_watchdog.py` pins the meaning (the code first, then command, reading, time and both limits, in that order) and, since the text did not change, still the bytes. 3. **The 25-word rule is checked as logged.** Part 6 fails any WARNING+ line over 25 words with its built text filled in. Nine non-safety families still run long (tariff plan words, price feed reasons, the state migration report, write refusals and claim scope errors that only a software fault raises, maintenance, trading gate and price history reasons). They are listed with a reason in `LONG_LINE_OK`, capped at 9, and a listed family that gets shorter fails until it is removed. Shortening them is a follow-up. -4. **The meter row's "the add-on log shows why" is now true.** When the meter goes quiet past its limit, the add-on logs one WARNING per episode, not one per cycle, and an INFO line when readings return. This is a new log line, not a new alarm: it has no notification and changes no decision. +4. **The meter row's "the add-on log shows why" is now true.** When the meter goes quiet past its limit, the add-on logs one WARNING per episode, not one per cycle, and an INFO line when readings return. A meter that flaps (on `ha_signed` a healthy meter under a flat load can go 42–97 s between changes) logs at most one such pair per 10 minutes, and the episodes in between go to DEBUG. This is a new log line, not a new alarm: it has no notification and changes no decision. 5. **The Why line past the 15 s hold** names the missing reading ("No usable meter reading for over 15 seconds: 0 W", or the battery power or level of an inverter), instead of "A reading is missing: 0 W". 6. **Action log:** "25 engagement(s)" is "25 engagements", and "SHADOW MODE OFF - …" is "Shadow mode off: …". "SHADOW MODE ON" was not named in the card and is left as it is. +7. **Review: after a restart the figures go on the action log too.** `log_level` defaults to `info`, so the DEBUG evidence line is not seen by default, and `events` starts empty. Each restored stop (direction per inverter and site, delivery, circulation) now also writes its saved reason to the action log ("FAILSAFE inverter-a, saved before the restart: …"), and the page's event line gets the same plain words the live stop gives. `LONG_LINE_OK` also refuses a key whose text is a safety reason, not only a `reason_code` key. diff --git a/goodwe_controller/DOCS.md b/goodwe_controller/DOCS.md index a51a92c..938c3c0 100644 --- a/goodwe_controller/DOCS.md +++ b/goodwe_controller/DOCS.md @@ -3096,8 +3096,10 @@ stop control on the add-on page. This part is for installers. The texts live in `app/messages.py` and follow `STYLE.md`. Every notification keeps a fixed `notification_id`, so a repeat replaces the card. The ERROR or WARNING line of the add-on log names the -reason code. The full figures are on the DEBUG line logged right after it -(log level `debug`) and in `events` in the `status` JSON. +reason code. The full figures are in `events` in the `status` JSON, also for a +stop restored after a restart, and on the DEBUG line logged right after it. +That DEBUG line only shows with “Log level” (log_level) set to `debug`; the +default `info` hides it. | Title | Severity | id | Card | |---|---|---|---| @@ -3254,7 +3256,8 @@ reason code, and its full figures are on the DEBUG line right after it and in with both possible causes, is on the DEBUG line after it. - **Meter: no reading for …** (red): the add-on logs one WARNING when the meter goes quiet, "No meter reading for …", and an INFO line when readings - return. Past `stale_input_s` the **Why** line names the missing reading. + return, at most once every 10 minutes. Past `stale_input_s` the **Why** + line names the missing reading. - The table at the top: **Why** is `messages.why()`, the arbiter's answer in words (`Resolution.explain()` stays on the log). **Tariff**, **Price history**, **Arbitrage** and **Shadow mode** keep every figure they had diff --git a/goodwe_controller/app/main.py b/goodwe_controller/app/main.py index ff4abd0..97dd201 100644 --- a/goodwe_controller/app/main.py +++ b/goodwe_controller/app/main.py @@ -119,6 +119,9 @@ WRITE_BUDGET_S = 4.0 # restart this add-on (measured on TEST-23), so a latched alarm is re-asserted # this often. Why: goodwe docs/DECISIONS.md, SAFETY-34. REANNOUNCE_S = 300.0 +# UX-11 review: a quiet meter logs at most one WARNING this often, because on +# `ha_signed` a healthy meter under a flat load can go 42-97 s between changes. +METER_QUIET_REPEAT_S = 600.0 _mono = time.monotonic # patched by the checks; asyncio keeps the real one # --------------------------------------------------------------------------- # @@ -619,6 +622,13 @@ class Controller: messages.reason_code(inv.sign_wd.reason)) _LOG.debug("Evidence for %s: %s.", inv.name, inv.sign_wd.reason or "(reason not recorded)") + # UX-11 review: `events` starts empty and DEBUG is off by + # default, so the saved figures go on the action log too. + saved = inv.sign_wd.reason or messages.NO_REASON_SAVED + self.log_event(f"FAILSAFE {inv.name}, saved before the " + f"restart: {saved}", + hint=messages.hint("stop_restored", + unit=inv.name)) # --- SAFETY-42 + SAFETY-34 ------------------------------------------- # ⚠️ A LATCH THAT DOES NOT ACT, WHICH IS THE ONE ASYMMETRY WITH EVERY @@ -645,6 +655,11 @@ class Controller: inv.name, messages.reason_code(inv.delivery_wd.reason)) _LOG.debug("Evidence for %s: %s.", inv.name, inv.delivery_wd.reason or "(reason not recorded)") + saved = inv.delivery_wd.reason or messages.NO_REASON_SAVED + self.log_event(f"NOT DELIVERING {inv.name}, saved before the " + f"restart: {saved}", + hint=messages.hint("not_delivering", + unit=inv.name)) # --- SAFETY-30: THE SITE HALF OF THE SIGN CHECK ---------------------- # ⚠️ ONE PER SITE, BESIDE THE ONE PER INVERTER, AND ARMED ONLY AT N>=2. @@ -678,6 +693,10 @@ class Controller: "control: %s.", messages.reason_code(self.site_sign_wd.reason)) _LOG.debug("Evidence for the site: %s.", self.site_sign_wd.reason or "(reason not recorded)") + self.log_event("FAILSAFE site, saved before the restart: " + + (self.site_sign_wd.reason + or messages.NO_REASON_SAVED), + hint=messages.hint("site_direction")) # And the per-unit detectors are told which question they are asking, # here as well as in `cycle()`. `checks()` and the status page read # `inv.sign_wd.cfg` and can be called before the first cycle has run, so @@ -733,6 +752,10 @@ class Controller: messages.reason_code(self.circ_wd.reason)) _LOG.debug("Evidence for the site: %s.", self.circ_wd.reason or "(reason not recorded)") + self.log_event("CIRCULATING POWER, saved before the restart: " + + (self.circ_wd.reason + or messages.NO_REASON_SAVED), + hint=messages.hint("circulating")) # SAFETY-03. The output clamp's alarm - see clamp.py for why the clamp # itself is the cheap half. @@ -940,6 +963,9 @@ class Controller: self.why_words = "Starting" # UX-11: has this meter episode's WARNING been logged? See read_inputs. self._meter_quiet_logged = False + # ...when the last WARNING was, and whether this episode logged one. + self._meter_quiet_warned = None + self._meter_quiet_loud = False # ALLOC-01. The allocation record from the last resolution, or None # before the first cycle. ⚠️ IT IS KEPT SO THAT SOMETHING CAN GATE ON # IT: SAFETY-28 puts the write path behind this record, and DEV-02 reads @@ -1912,16 +1938,30 @@ class Controller: # UX-11: the red meter row says "the add-on log shows why", so a meter # that goes quiet gets one WARNING per episode, not one per cycle. It # is a log line only: no notification, and nothing it decides. + # A flapping meter logs at most one WARNING per METER_QUIET_REPEAT_S, + # and the episodes in between go to DEBUG. if self.p1_enabled: if (self.p1.stale and not self._meter_quiet_logged and self.p1.published_age_s > self.p1.max_age_s): self._meter_quiet_logged = True - _LOG.warning("No meter reading for over %s, so control " - "waits and then sets the battery to 0 W.", - messages.seconds(self.p1.max_age_s)) + now = _mono() + self._meter_quiet_loud = ( + self._meter_quiet_warned is None + or now - self._meter_quiet_warned >= METER_QUIET_REPEAT_S) + if self._meter_quiet_loud: + self._meter_quiet_warned = now + _LOG.warning("No meter reading for over %s, so control " + "waits and then sets the battery to 0 W.", + messages.seconds(self.p1.max_age_s)) + else: + _LOG.debug("No meter reading for over %s again.", + messages.seconds(self.p1.max_age_s)) elif not self.p1.stale and self._meter_quiet_logged: self._meter_quiet_logged = False - _LOG.info("Meter readings are back.") + if self._meter_quiet_loud: + _LOG.info("Meter readings are back.") + else: + _LOG.debug("Meter readings are back.") if self.inputs_ok: if self.inputs_bad_since is not None: diff --git a/goodwe_controller/test_messages.py b/goodwe_controller/test_messages.py index 7513364..6a45287 100644 --- a/goodwe_controller/test_messages.py +++ b/goodwe_controller/test_messages.py @@ -1227,7 +1227,9 @@ check(f"UX-11: no WARNING+ line runs over {LINE_WORDS} words as logged, except " f"the {len(LONG_LINE_OK)} listed families, and none of them is a safety " f"reason (cap {LONG_LINE_CAP})", len(LONG_LINE_OK) <= LONG_LINE_CAP - and not any("reason_code" in k for k in LONG_LINE_OK)) + and not any("reason_code" in k + or TEXT.get(k) in SAFETY_REASONS.values() + for k in LONG_LINE_OK)) check(f"...and every listed family still runs long, so the list only shrinks " f"(no longer long: {sorted(set(LONG_LINE_OK) - _long_seen)})", set(LONG_LINE_OK) <= _long_seen) @@ -1397,6 +1399,7 @@ import logging # noqa: E402 from app import hass as _hass, p1 as _p1, validate as _validate, web as _web # noqa: E402 from app.arbiter import Claim # noqa: E402 from app.main import Controller, why_key # noqa: E402 +from app import main as _main # noqa: E402 class _Rec(logging.Handler): @@ -1695,7 +1698,12 @@ def _meter_at(age_s): def _quiet_episodes(): - for age in (1, 40, 45, 50, 1, 2, 60, 65): + # Two quiet episodes close together, then a third 10 minutes on. + for age in (1, 40, 45, 50, 1, 2, 60, 65, 1): + _meter_at(age) + asyncio.run(_c.read_inputs()) + _c._meter_quiet_warned -= _main.METER_QUIET_REPEAT_S + for age in (40, 45, 1): _meter_at(age) asyncio.run(_c.read_inputs()) @@ -1704,9 +1712,13 @@ _mq = [r for r in _captured("goodwe", _quiet_episodes) if "meter" in r.getMessage().lower()] _mq_warn = [r.getMessage() for r in _mq if r.levelno == logging.WARNING] _mq_info = [r.getMessage() for r in _mq if r.levelno == logging.INFO] +_mq_dbg = [r.getMessage() for r in _mq if r.levelno == logging.DEBUG] check(f"a meter that goes quiet logs one WARNING per episode, not per cycle, " - f"and one INFO when readings return ({_mq_warn}, {_mq_info})", - len(_mq_warn) == 2 and _mq_info == ["Meter readings are back."] + f"and one INFO when readings return, and a flapping meter at most one " + f"pair per {_main.METER_QUIET_REPEAT_S:.0f} s ({_mq_warn}, {_mq_info}, " + f"{_mq_dbg})", + len(_mq_warn) == 2 and _mq_info == ["Meter readings are back."] * 2 + and len(_mq_dbg) == 2 and _mq_warn[0] == "No meter reading for over 30 seconds, so control " "waits and then sets the battery to 0 W." and len(words(_mq_warn[0])) <= LINE_WORDS) @@ -1763,6 +1775,13 @@ check("...each ERROR line at start is one plain sentence with the code, at " and any(m.endswith(f": {messages.NO_REASON_SAVED}.") for m in _rs_err)) check("...and the saved text, figures and all, is on a DEBUG line beside it", all(any(t in m for m in _rs_dbg) for t in _OLD.values())) +# UX-11 review: `log_level` defaults to info and `events` starts empty, so the +# saved figures also go on the action log, where `status` shows them. +_rs_ev = _restart[0].events if _restart else [] +check(f"...and in the action log, which an installer reads at the default " + f"log level ({len(_rs_ev)} events)", + all(any(t in e for e in _rs_ev) for t in _OLD.values()) + and any(e.endswith(messages.NO_REASON_SAVED) for e in _rs_ev)) # UX-11 item 4: the action log's clamp count and the shadow-off entry. _main_src = (APP / "main.py").read_text(encoding="utf-8") diff --git a/goodwe_controller/test_watchdog.py b/goodwe_controller/test_watchdog.py index cb8d5db..7188da8 100644 --- a/goodwe_controller/test_watchdog.py +++ b/goodwe_controller/test_watchdog.py @@ -1438,6 +1438,12 @@ check("⚠️ THE SITE INSTANCE'S REASON SAYS WHAT SHIPPED, IN THE SAME ORDER: " _sr.startswith("SIGN_DISAGREEMENT: ") and messages.reason_code(_sr) == "SIGN_DISAGREEMENT" and all(i > 0 for i in _order) and _order == sorted(_order)) +# UX-11 review: the text itself did not change, and it is what state.json +# holds, so the byte pin stays beside the meaning pin. +check("...and it is still byte-identical to the one that shipped", + _sr == ("SIGN_DISAGREEMENT: commanded -1000 W against a meter reading " + "+1500 W for 180 s continuously (limits: both over 300 W, held " + "over 180 s)")) check("...and the per-unit instance names what it ACTUALLY compared instead. " "'against a meter reading' there would be a false statement about which " "instrument produced the evidence, on the one line somebody woken by " -- 2.54.0