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>

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.

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

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:

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")

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 "