SAFETY-112: say plainly that control waits for Home Assistant to start #188
@@ -0,0 +1,98 @@
|
||||
# SAFETY-112 - control waits for Home Assistant to finish starting
|
||||
|
||||
**Status: for review.** Tests: `test_safety112.py`, `test_messages.py`.
|
||||
Control is unchanged. The add-on now says plainly that it is waiting.
|
||||
|
||||
## Cause
|
||||
|
||||
The Supervisor's proxy refuses every add-on request with 502 until Core's
|
||||
state is `RUNNING`. The add-on reads every battery reading and writes every
|
||||
power request through that proxy, so it cannot control until then. Readings
|
||||
that are already live inside Home Assistant do not help.
|
||||
|
||||
Source, Supervisor 2026.08.0 (the image the live site ran at CFG-04):
|
||||
|
||||
- `supervisor/api/proxy.py`, `APIProxy.api()` (REST, used for reads and
|
||||
`number.set_value`) and `APIProxy.websocket()` both start with
|
||||
`if not await self.sys_homeassistant.api.check_api_state(): raise HTTPBadGateway`.
|
||||
- `supervisor/homeassistant/api.py`, `check_api_state()` returns
|
||||
`state.core_state == "RUNNING" or state.offline_db_migration`. The state
|
||||
comes from Core's `/api/core/state`.
|
||||
- Upstream `main` has the same gate in both handlers (read 2026-10-13).
|
||||
- A Core restart restarts only the Core container
|
||||
(`homeassistant/core.py`, `restart()`). The add-on keeps running.
|
||||
|
||||
The add-on itself has no wait. Nothing in `app/` reads Core's state or waits
|
||||
for an event. The loop reads its inputs every second, a 502 gives `None`,
|
||||
and missing inputs give 0 W. P1 backoff is not involved: the live site reads
|
||||
the meter straight from the HomeWizard (`homewizard_local`), not through Home
|
||||
Assistant.
|
||||
|
||||
## Measured
|
||||
|
||||
Repro stack `safety112-*`, all removed afterwards:
|
||||
|
||||
- Home Assistant 2026.9.4, as live.
|
||||
- A test integration whose `async_setup` sleeps, so Core stays `NOT_RUNNING`.
|
||||
- A fake meter and two fake inverters that update every 2 s from load.
|
||||
- The Supervisor's own `APIProxy` and `HomeAssistantAPI` from the 2026.08.0
|
||||
image. Only the add-on token lookup, Core's access token and the container
|
||||
check are stubbed.
|
||||
- The add-on on `meter_source: homewizard_local` against a fake HomeWizard.
|
||||
|
||||
Times are seconds after `docker restart` of Home Assistant:
|
||||
|
||||
| run | Core `NOT_RUNNING` | entities live in HA | Core `RUNNING` | proxy 502 | first write | wait from live readings |
|
||||
|---|---|---|---|---|---|---|
|
||||
| base 3050fa5, N=2 | 13.1 | 17.1 | 253.1 | 0.9-252.7 (1 132 requests) | 254.7 | 237.6 |
|
||||
| base 3050fa5, N=1 | 13.1 | 18.1 | 256.1 | 1.5-255.1 (573 requests) | 257.2 | 239.1 |
|
||||
| this change, N=2 | 12.2 | 17.2 | 313.2 | 1.4-312.5 (1 406 requests) | 317.6 | 300.4 |
|
||||
| this change, N=1 | 12.2 | 17.2 | 255.2 | 1.2-254.1 (571 requests) | 257.1 | 240.0 |
|
||||
|
||||
The first write comes 1.0-4.4 s after `RUNNING`, so the whole wait is the
|
||||
proxy's. With a 400 s sleep Core moved on at 300.88 s on its own (bootstrap's
|
||||
stage timeout), so one slow integration holds a start stage for about 5
|
||||
minutes. The whole start can take longer: the live one took 414 s.
|
||||
|
||||
Before this change the page said "Not ready — Battery level: no usable
|
||||
reading", which sends the reader to Developer Tools for an entity that is
|
||||
fine.
|
||||
|
||||
## Rule
|
||||
|
||||
1. No way around the Supervisor. The add-on still talks to Home Assistant
|
||||
only through the proxy.
|
||||
2. While the proxy does not answer on the API (`hass.OUTAGE.waiting()`), the
|
||||
first status row is red: "Home Assistant is not answering, perhaps it is
|
||||
still starting. Control resumes by itself when it answers." The banner
|
||||
reads "Not ready — Waiting for Home Assistant to finish starting". The Home
|
||||
pill reads "Waiting for Home Assistant", in English and Dutch.
|
||||
3. A safety stop, a stalled control loop or shadow mode keeps its own banner
|
||||
and state over the wait, because none of them clears by itself.
|
||||
4. The log has one WARNING when Home Assistant stops answering, an INFO line
|
||||
every 5 minutes while it is down, and an INFO line with the length of the
|
||||
wait when it answers again.
|
||||
5. Only the API counts. The meter websocket alone does not, because the meter
|
||||
has its own row.
|
||||
|
||||
## Why it is safe
|
||||
|
||||
The change is text only. `cycle()`, the writes, the heartbeat, the stand-down
|
||||
on shutdown and every watchdog are untouched. `test_safety112.py` part 3 shows
|
||||
the same targets and writes with the flag on and off, for N=1 and N=2.
|
||||
|
||||
## Open, for the owner
|
||||
|
||||
The add-on cannot control while Home Assistant starts. These ways around it
|
||||
were not taken:
|
||||
|
||||
- **Talk to Core directly with a long-lived token** (`http://homeassistant:8123`).
|
||||
Core's own API answers while `NOT_RUNNING`. In the repro `/api/core/state`
|
||||
answered from 12-13 s, and a direct `number.set_value` 10 s into
|
||||
`NOT_RUNNING` returned 200 and set the value. The cost is a secret stored
|
||||
at every client site, which `hass.py` exists to avoid.
|
||||
- **Talk to the control board directly** (ESPHome native API), so control
|
||||
does not need Home Assistant at all. This is a large change.
|
||||
- **Remove the slow start at the site.** On 2026-10-12 the Solis
|
||||
integration's discovery held the start. Fixing or disabling it shortens the
|
||||
wait there, but not on a client site with another slow integration.
|
||||
@@ -3478,6 +3478,7 @@ for a new install*.
|
||||
|
||||
| Row starts with | What it tells you |
|
||||
|---|---|
|
||||
| Home Assistant is not answering | Home Assistant is not passing readings or power requests on, usually because it is still starting. The add-on cannot control until then. It resumes by itself. Nothing to do unless it lasts. |
|
||||
| Control | When control last ran. Red when it has stopped running: the control board then sets the inverter to 0 W. |
|
||||
| Meter | The grid reading, its age, how many readings were refused, and how long its value has not changed. Just after a start it is amber and *waiting for the first reading*. Red means no reading for longer than the limit. |
|
||||
| Stuck-meter check | Whether the add-on can warn you about a stuck meter. |
|
||||
@@ -3536,6 +3537,13 @@ reason code, and its full figures are on the DEBUG line right after it and in
|
||||
(TARIFF-11), in words.
|
||||
- **Solar production** reads `pv_entity` or `pv_entities` (TEL-11/12). The
|
||||
*Reversed-sign solar entities* setting is `pv_invert_entities` (TEL-14).
|
||||
- **Home Assistant is not answering** (SAFETY-112): the Supervisor answers
|
||||
502 to every add-on read, write and websocket until Home Assistant is
|
||||
RUNNING, even when its entities are already live. A slow integration at
|
||||
start-up therefore holds control for as long as it holds Home Assistant's
|
||||
start. The log has one WARNING, a "Still waiting" INFO line every 5
|
||||
minutes and "answers again after …" at the end. See
|
||||
`DECISIONS/SAFETY-112-waiting-for-home-assistant.md`.
|
||||
- **Shadow mode** (SAFETY-10): the banner turns red when a latch is up
|
||||
(circulating power, or a site or per-inverter sign trip), and that latch keeps
|
||||
its own red row.
|
||||
|
||||
@@ -11,6 +11,8 @@ import time
|
||||
|
||||
import aiohttp
|
||||
|
||||
from . import messages
|
||||
|
||||
_LOG = logging.getLogger("goodwe.hass")
|
||||
|
||||
CORE_API = "http://supervisor/core/api"
|
||||
@@ -19,6 +21,7 @@ BAD_STATES = ("unknown", "unavailable", "none", "")
|
||||
# What the Supervisor's proxy answers while Home Assistant restarts.
|
||||
UNAVAILABLE = (502, 503, 504)
|
||||
STATES_TIMEOUT_S = 10 # UX-13's entity list, like every other read here
|
||||
STILL_WAITING_S = 300 # SAFETY-112: one reminder line per 5 minutes down
|
||||
|
||||
|
||||
class Outage:
|
||||
@@ -29,15 +32,30 @@ class Outage:
|
||||
("502, message='Bad Gateway', url=URL(...)", "Received message 8:1000 is
|
||||
not str"). Now the first channel to fail says it once at WARNING, the raw
|
||||
text goes to DEBUG, and the last channel to recover says so at INFO.
|
||||
|
||||
SAFETY-112: the Supervisor answers 502 for every read, write and
|
||||
websocket until Home Assistant has finished starting, however live its
|
||||
entities already are (DECISIONS/SAFETY-112-waiting-for-home-assistant.md).
|
||||
So an outage also says, every STILL_WAITING_S, that it is still on, and
|
||||
`waiting()` puts it on the status page.
|
||||
"""
|
||||
|
||||
def __init__(self):
|
||||
self.down_on = set()
|
||||
self.since = None # monotonic start of this outage
|
||||
self._told = None # when the last "still waiting" line went
|
||||
|
||||
def down(self, channel: str, what: str, detail) -> None:
|
||||
now = time.monotonic()
|
||||
if not self.down_on:
|
||||
_LOG.warning("Home Assistant is not answering (%s), perhaps it is "
|
||||
"restarting. The add-on keeps trying.", what)
|
||||
"still starting. Control waits and resumes by itself.",
|
||||
what)
|
||||
self.since = self._told = now
|
||||
elif now - self._told >= STILL_WAITING_S:
|
||||
self._told = now
|
||||
_LOG.info("Still waiting for Home Assistant to finish starting, "
|
||||
"%s so far.", messages.duration(now - self.since))
|
||||
self.down_on.add(channel)
|
||||
_LOG.debug("Home Assistant not answering on %s: %s", channel, detail)
|
||||
|
||||
@@ -45,7 +63,13 @@ class Outage:
|
||||
if channel in self.down_on:
|
||||
self.down_on.discard(channel)
|
||||
if not self.down_on:
|
||||
_LOG.info("Home Assistant answers again.")
|
||||
_LOG.info("Home Assistant answers again after %s.",
|
||||
messages.duration(time.monotonic() - self.since))
|
||||
|
||||
def waiting(self) -> bool:
|
||||
"""True while Home Assistant's API does not answer. The API, not the
|
||||
meter websocket: every battery reading and every write rides on it."""
|
||||
return "api" in self.down_on
|
||||
|
||||
|
||||
OUTAGE = Outage()
|
||||
|
||||
@@ -909,13 +909,14 @@ def month_peak(c, now):
|
||||
return out
|
||||
|
||||
|
||||
def state_of(c, level, shadow):
|
||||
def state_of(c, level, shadow, waiting=False):
|
||||
"""One word for the pill and the banner's colour: running, shadow,
|
||||
stopped, alarm or warning."""
|
||||
stopped, alarm, waiting or warning. `waiting`: the red headline is
|
||||
Home Assistant still starting (SAFETY-112), which needs nobody."""
|
||||
if shadow:
|
||||
return "shadow"
|
||||
if level == "bad":
|
||||
return "alarm"
|
||||
return "waiting" if waiting else "alarm"
|
||||
if not c.auto:
|
||||
return "stopped"
|
||||
if level == "warn":
|
||||
@@ -924,20 +925,22 @@ def state_of(c, level, shadow):
|
||||
|
||||
|
||||
def build(c, *, level: str, checks: list, now: datetime | None = None,
|
||||
lang: str = "en", held: bool | None = None) -> dict:
|
||||
lang: str = "en", held: bool | None = None,
|
||||
waiting: bool = False) -> dict:
|
||||
"""The structured half of `/status`, in `lang` (UX-13 P5). Pure reads of
|
||||
the controller."""
|
||||
_LANG[0] = uitext.lang_of(lang)
|
||||
try:
|
||||
return _build(c, level=level, checks=checks, now=now, held=held)
|
||||
return _build(c, level=level, checks=checks, now=now, held=held,
|
||||
waiting=waiting)
|
||||
finally:
|
||||
_LANG[0] = "en"
|
||||
|
||||
|
||||
def _build(c, *, level, checks, now, held=None):
|
||||
def _build(c, *, level, checks, now, held=None, waiting=False):
|
||||
now = now or datetime.now(timezone.utc)
|
||||
shadow = bool(c.shadow)
|
||||
kind = state_of(c, level, shadow)
|
||||
kind = state_of(c, level, shadow, waiting)
|
||||
# A red banner means every inverter is at 0 W (the status cascade), so
|
||||
# nothing is planned until it clears. Shadow mode still plans: it is
|
||||
# what the add-on would do. `held` False: an alarm while control runs
|
||||
@@ -1332,7 +1335,7 @@ def _samples() -> list:
|
||||
out += [("title", mode_word(k)) for k in words["modes"]]
|
||||
out += [("title", mode_house()), ("title", attn_shadow()),
|
||||
("line", attn_shadow_body())]
|
||||
for k in ("running", "shadow", "stopped", "alarm", "warning"):
|
||||
for k in ("running", "shadow", "stopped", "alarm", "waiting", "warning"):
|
||||
out += [("title", pill(k)), ("line", banner_sub(k))]
|
||||
for sh in (False, True):
|
||||
out += [("title", tile_solar(v, s)) for v, s in
|
||||
|
||||
@@ -69,7 +69,7 @@ from . import messages
|
||||
from .freeze import (
|
||||
FreezeWatchdog, FreezeWatchdogConfig, looks_frozen, rail_unreachable, rail_w,
|
||||
)
|
||||
from .hass import CORE_API, HomeAssistant
|
||||
from .hass import CORE_API, OUTAGE, HomeAssistant
|
||||
# ⚠️ `LINK_STALE_S` IS RE-EXPORTED DELIBERATELY. `live_units()` reasons about it
|
||||
# and two checks read `app.main.LINK_STALE_S` to build a stale link, so the
|
||||
# window an operator would look up here is the one the roster actually uses.
|
||||
@@ -6590,6 +6590,14 @@ class Controller:
|
||||
else:
|
||||
out.append({"ok": True, "warn": False, "id": "controller",
|
||||
"text": messages.row_controller_ran(_pass_age)})
|
||||
# SAFETY-112. The headline unless control has stalled: while the
|
||||
# Supervisor gives 502 (Home Assistant not yet RUNNING) no reading or
|
||||
# write gets through, and the rows below that need it follow from it.
|
||||
if OUTAGE.waiting():
|
||||
out.insert(1 if out[0]["ok"] is False else 0,
|
||||
{"ok": False, "warn": False, "id": "home_assistant",
|
||||
"banner": messages.banner_ha_waiting(),
|
||||
"text": messages.row_ha_waiting()})
|
||||
if self.p1_enabled:
|
||||
age = self.p1.published_age_s
|
||||
if (self.p1.stale and self.p1.age_s() is None
|
||||
@@ -7099,7 +7107,7 @@ class Controller:
|
||||
# control goes on, so it neither reads "Not ready" nor holds the page.
|
||||
runs = [c for c in bad if c.get("runs")]
|
||||
bad = [c for c in bad if not c.get("runs")]
|
||||
running_alarm = False
|
||||
running_alarm = waiting = False
|
||||
# --- SAFETY-10, AND IT IS FIRST IN THE CASCADE -----------------------
|
||||
# "The battery is NOT being controlled" is the one sentence on this
|
||||
# page that may never be displaced by another condition. A banner that
|
||||
@@ -7150,6 +7158,10 @@ class Controller:
|
||||
# headline nobody reads. UX-08: without the key, the banner takes
|
||||
# the row's first sentence, so it stays a headline.
|
||||
level, banner = "bad", messages.banner_not_ready(bad[0])
|
||||
# SAFETY-112: nothing to do but wait, so Home says that instead
|
||||
# of "Needs you now". Only when it IS the headline: a safety stop
|
||||
# above outranks it and still needs a person.
|
||||
waiting = bad[0].get("id") == "home_assistant"
|
||||
elif not self.auto:
|
||||
level, banner = "warn", messages.banner_stopped()
|
||||
elif runs:
|
||||
@@ -7296,7 +7308,7 @@ class Controller:
|
||||
# fields are served alone (the page then shows the installer details).
|
||||
try:
|
||||
out.update(homeview.build(self, level=level, checks=checks,
|
||||
lang=lang, held=held))
|
||||
lang=lang, held=held, waiting=waiting))
|
||||
except Exception: # noqa: BLE001
|
||||
# Once per process at ERROR: the page polls every 3 s.
|
||||
if not getattr(self, "_home_failed", False):
|
||||
|
||||
@@ -436,6 +436,17 @@ def banner_shadow(latched: bool) -> str:
|
||||
return "Shadow mode: the battery is not controlled. Inverters stay at 0 W."
|
||||
|
||||
|
||||
def banner_ha_waiting() -> str:
|
||||
"""SAFETY-112: the Supervisor passes nothing on until Home Assistant has
|
||||
finished starting, so the add-on can neither read nor write."""
|
||||
return "Waiting for Home Assistant to finish starting"
|
||||
|
||||
|
||||
def row_ha_waiting() -> str:
|
||||
return ("Home Assistant is not answering, perhaps it is still starting. "
|
||||
"Control resumes by itself when it answers.")
|
||||
|
||||
|
||||
# Rows: control and the meter. "Control" is what the add-on does, as in
|
||||
# "start control" (STYLE.md section 4).
|
||||
def row_controller_starting() -> str:
|
||||
@@ -1055,6 +1066,10 @@ def status_samples() -> list:
|
||||
("banner_setup_only", None, banner_setup_only()),
|
||||
("row_setup_only", AMBER, row_setup_only()),
|
||||
("banner_shadow", None, banner_shadow(True)),
|
||||
("banner_not_ready", None, banner_not_ready(
|
||||
{"text": row_ha_waiting(), "banner": banner_ha_waiting()})),
|
||||
("banner_ha_waiting", None, banner_ha_waiting()),
|
||||
("row_ha_waiting", RED, row_ha_waiting()),
|
||||
("row_controller_starting", GREEN, row_controller_starting()),
|
||||
("row_controller_ran", GREEN, row_controller_ran(2)),
|
||||
("row_controller_stalled", RED, row_controller_stalled(45, 30)),
|
||||
|
||||
@@ -100,7 +100,7 @@
|
||||
}
|
||||
function renderPill() {
|
||||
const st = S.state || null;
|
||||
const dot = st ? ({ running: "", shadow: " warn", stopped: " warn", warning: " warn", alarm: " bad" }[st.kind] ?? " warn")
|
||||
const dot = st ? ({ running: "", shadow: " warn", stopped: " warn", warning: " warn", alarm: " bad", waiting: " warn" }[st.kind] ?? " warn")
|
||||
: (S.level === "ok" ? "" : S.level === "bad" ? " bad" : " warn");
|
||||
const words = st ? [st.pill, st.ran].filter(Boolean).join(". ") : S.setup_only === true ? t("setup_only.name") : S.banner;
|
||||
$("#pill").replaceChildren(h("span", { class: "dot" + dot, "aria-hidden": "true" }), h("span", {}, words));
|
||||
@@ -399,7 +399,7 @@
|
||||
$("#batt-how").hidden = !modes;
|
||||
const docs = $("#batt-docs");
|
||||
if (S.control && S.control.docs_url) { docs.href = S.control.docs_url; docs.hidden = false; } else docs.hidden = true;
|
||||
if (S.state && ["shadow", "stopped", "alarm"].includes(S.state.kind)) banner($("#batt-banner"), S.level, S.state.pill, S.state.sub, S.level === "bad" ? "alert" : null);
|
||||
if (S.state && ["shadow", "stopped", "alarm", "waiting"].includes(S.state.kind)) banner($("#batt-banner"), S.level, S.state.pill, S.state.sub, S.level === "bad" ? "alert" : null);
|
||||
else $("#batt-banner").replaceChildren();
|
||||
keepFocus(() => {
|
||||
$("#bcards").replaceChildren(...S.batteries.map(batteryCard));
|
||||
|
||||
@@ -267,6 +267,7 @@
|
||||
"shadow": "Shadow mode",
|
||||
"stopped": "Stopped",
|
||||
"alarm": "Needs you now",
|
||||
"waiting": "Waiting for Home Assistant",
|
||||
"warning": "Running, with a warning"
|
||||
},
|
||||
"banner_sub": {
|
||||
@@ -274,6 +275,7 @@
|
||||
"shadow": "The plans below say what the add-on would do.",
|
||||
"stopped": "Start control below when you are ready.",
|
||||
"alarm": "See Needs attention below for what to do.",
|
||||
"waiting": "Control resumes by itself when Home Assistant answers.",
|
||||
"warning": "See Needs attention below."
|
||||
},
|
||||
"tile": {
|
||||
@@ -431,6 +433,7 @@
|
||||
"stopped": "Control is stopped. Every inverter is at 0 W."
|
||||
},
|
||||
"attn": {
|
||||
"home_assistant": "Home Assistant is not answering",
|
||||
"controller": "Control is not running",
|
||||
"meter": "Meter reading",
|
||||
"meter_frozen": "Meter reading may be stuck",
|
||||
|
||||
@@ -230,8 +230,8 @@
|
||||
"zero_held": "Op 0 W gehouden",
|
||||
"zero_going": "Gaat naar 0 W",
|
||||
"verdict": {"held": "Op 0 W gehouden", "stopped": "Gestopt", "cycle": "Vandaag maandelijkse cyclus", "trade": "Handelt op prijs", "house": "Volgt het huis"},
|
||||
"pill": {"running": "Actief", "shadow": "Schaduwmodus", "stopped": "Gestopt", "alarm": "Heeft u nu nodig", "warning": "Actief, met een waarschuwing"},
|
||||
"banner_sub": {"running": "De batterijen volgen het plan hieronder.", "shadow": "De plannen hieronder tonen wat de add-on zou doen.", "stopped": "Start de regeling hieronder als u klaar bent.", "alarm": "Zie Vraagt aandacht hieronder voor wat u moet doen.", "warning": "Zie Vraagt aandacht hieronder."},
|
||||
"pill": {"running": "Actief", "shadow": "Schaduwmodus", "stopped": "Gestopt", "alarm": "Heeft u nu nodig", "waiting": "Wacht op Home Assistant", "warning": "Actief, met een waarschuwing"},
|
||||
"banner_sub": {"running": "De batterijen volgen het plan hieronder.", "shadow": "De plannen hieronder tonen wat de add-on zou doen.", "stopped": "Start de regeling hieronder als u klaar bent.", "alarm": "Zie Vraagt aandacht hieronder voor wat u moet doen.", "waiting": "De regeling gaat vanzelf verder zodra Home Assistant antwoordt.", "warning": "Zie Vraagt aandacht hieronder."},
|
||||
"tile": {"not_set_up": "Niet ingesteld", "no_reading": "Geen meting", "producing": "Produceert", "not_producing": "Produceert niet", "needs_solar": "Zonnemeting nodig", "not_adding_up": "Metingen kloppen niet", "using": "Verbruikt", "taking": "Neemt af van het net", "feeding": "Injecteert", "balanced": "In evenwicht", "giving": "Levert stroom", "charging": "Laadt", "resting": "Rust"},
|
||||
"now": {
|
||||
"no_reading": "Geen meting van deze batterij.",
|
||||
@@ -354,6 +354,7 @@
|
||||
"peak_not_covered": "Geen piekgrens: deze meter meet geen kwartieren.",
|
||||
"control": {"shadow": "Schaduwmodus: elke omvormer blijft op 0 W.", "running": "De regeling is actief.", "stopped": "De regeling is gestopt. Elke omvormer staat op 0 W."},
|
||||
"attn": {
|
||||
"home_assistant": "Home Assistant antwoordt niet",
|
||||
"controller": "Regeling is niet actief",
|
||||
"meter": "Meting van de meter",
|
||||
"meter_frozen": "Meter staat mogelijk vast",
|
||||
|
||||
@@ -1469,8 +1469,11 @@ _info = [r.getMessage() for r in _out if r.levelno == logging.INFO]
|
||||
check(f"a Home Assistant restart is one plain WARNING line, and one INFO line "
|
||||
f"when both connections are back ({_warn}, {_info})",
|
||||
_warn[:1] == ["Home Assistant is not answering (error 502), perhaps it "
|
||||
"is restarting. The add-on keeps trying."]
|
||||
and _info == ["Home Assistant answers again."] and len(_warn) == 2)
|
||||
"is still starting. Control waits and resumes by itself."]
|
||||
and len(_info) == 1
|
||||
and re.fullmatch(r"Home Assistant answers again after \d+ seconds\.",
|
||||
_info[0]) is not None and len(_warn) == 2)
|
||||
# SAFETY-112's reminder and its timing are graded in test_safety112.py.
|
||||
check("...and the library's own text is kept, at DEBUG",
|
||||
any("Received message 8:1000" in r.getMessage() for r in _out
|
||||
if r.levelno == logging.DEBUG)
|
||||
|
||||
@@ -0,0 +1,440 @@
|
||||
"""SAFETY-112: waiting for Home Assistant to finish starting. `python3 -B test_safety112.py`
|
||||
|
||||
The Supervisor answers 502 to every add-on read, write and websocket until
|
||||
Home Assistant is RUNNING (DECISIONS/SAFETY-112-waiting-for-home-assistant.md),
|
||||
so the add-on cannot control then. This file grades what it says meanwhile:
|
||||
|
||||
1. The log: one WARNING when Home Assistant stops answering, one INFO line
|
||||
every 5 minutes while it stays down, one INFO line with the wait when it
|
||||
answers again. Only the API channel counts as "waiting": a 502 or a
|
||||
refused connection turns it on, the next good read off, a timeout never.
|
||||
2. The status page, N=1 and N=2: the waiting row is first and red, and is the
|
||||
banner. Home says "Waiting for Home Assistant" in English and Dutch, not
|
||||
"Needs you now", unless a safety stop outranks it. The page script has it.
|
||||
3. Control is unchanged: the same readings give the same writes with the
|
||||
waiting flag on or off, with 502 readings and with live ones.
|
||||
|
||||
Mutating a module this file grades? Read MUTATION.md first (purge __pycache__).
|
||||
"""
|
||||
|
||||
import asyncio
|
||||
import logging
|
||||
import os
|
||||
import re
|
||||
from types import SimpleNamespace
|
||||
|
||||
from app import hass as _hass
|
||||
from app import messages
|
||||
from app.main import Controller
|
||||
|
||||
fails = []
|
||||
|
||||
|
||||
def check(name, cond):
|
||||
print(f" {'ok ' if cond else 'FAIL'} {name}")
|
||||
if not cond:
|
||||
fails.append(name)
|
||||
|
||||
|
||||
class _Rec(logging.Handler):
|
||||
def __init__(self):
|
||||
super().__init__(logging.DEBUG)
|
||||
self.records = []
|
||||
|
||||
def emit(self, record):
|
||||
self.records.append(record)
|
||||
|
||||
|
||||
def captured(fn):
|
||||
rec, lg = _Rec(), logging.getLogger("goodwe.hass")
|
||||
old = lg.level
|
||||
lg.addHandler(rec)
|
||||
lg.setLevel(logging.DEBUG)
|
||||
try:
|
||||
fn()
|
||||
finally:
|
||||
lg.removeHandler(rec)
|
||||
lg.setLevel(old)
|
||||
return [(r.levelno, r.getMessage()) for r in rec.records
|
||||
if r.levelno >= logging.INFO]
|
||||
|
||||
|
||||
class Clock:
|
||||
"""`hass.time` stand-in: only `monotonic` is read by Outage."""
|
||||
|
||||
def __init__(self):
|
||||
self.t = 1000.0
|
||||
|
||||
def monotonic(self):
|
||||
return self.t
|
||||
|
||||
|
||||
def with_clock(fn):
|
||||
clock, real = Clock(), _hass.time
|
||||
_hass.time = SimpleNamespace(monotonic=clock.monotonic)
|
||||
try:
|
||||
return fn(clock)
|
||||
finally:
|
||||
_hass.time = real
|
||||
|
||||
|
||||
# --------------------------------------------------------------------------- #
|
||||
print("1. the log while Home Assistant does not answer")
|
||||
W, I = logging.WARNING, logging.INFO
|
||||
|
||||
|
||||
def outage(clock):
|
||||
o = _hass.Outage()
|
||||
o.down("api", "error 502", "read sensor.x: 502")
|
||||
for t in (1, 60, 299):
|
||||
clock.t = 1000 + t
|
||||
o.down("api", "error 502", "read sensor.x: 502")
|
||||
clock.t = 1300
|
||||
o.down("api", "error 502", "") # 5 minutes: the first reminder
|
||||
clock.t = 1301
|
||||
o.down("websocket", "the meter connection closed", "")
|
||||
clock.t = 1599
|
||||
o.down("api", "error 502", "") # 299 s after the reminder: none
|
||||
clock.t = 1600
|
||||
o.down("api", "error 502", "") # 10 minutes: the second
|
||||
clock.t = 1640
|
||||
o.up("api")
|
||||
o.up("websocket") # 640 s in all
|
||||
clock.t = 2000
|
||||
o.down("api", "no connection", "") # a new outage starts afresh
|
||||
clock.t = 2030
|
||||
o.up("api")
|
||||
|
||||
|
||||
lines = with_clock(lambda c: captured(lambda: outage(c)))
|
||||
check(f"one WARNING per outage, in plain words ({lines})",
|
||||
[m for lv, m in lines if lv == W] == [
|
||||
"Home Assistant is not answering (error 502), perhaps it is still "
|
||||
"starting. Control waits and resumes by itself.",
|
||||
"Home Assistant is not answering (no connection), perhaps it is "
|
||||
"still starting. Control waits and resumes by itself."])
|
||||
check("one 'still waiting' line per 5 minutes down, with the time so far",
|
||||
[m for lv, m in lines if lv == I and m.startswith("Still")] == [
|
||||
"Still waiting for Home Assistant to finish starting, 5 minutes "
|
||||
"so far.",
|
||||
"Still waiting for Home Assistant to finish starting, 10 minutes "
|
||||
"so far."])
|
||||
check("one INFO line when the last channel is back, with the wait, and a new "
|
||||
"outage counts from its own start",
|
||||
[m for lv, m in lines if lv == I and m.startswith("Home")] == [
|
||||
"Home Assistant answers again after 11 minutes.",
|
||||
"Home Assistant answers again after 30 seconds."])
|
||||
|
||||
|
||||
def channels(_clock):
|
||||
o = _hass.Outage()
|
||||
seen = [o.waiting()]
|
||||
o.down("websocket", "the meter connection closed", "")
|
||||
seen.append(o.waiting())
|
||||
o.down("api", "error 502", "")
|
||||
seen.append(o.waiting())
|
||||
o.up("websocket")
|
||||
seen.append(o.waiting())
|
||||
o.up("api")
|
||||
seen.append(o.waiting())
|
||||
return seen
|
||||
|
||||
|
||||
check("waiting() follows the API channel only, not the meter websocket",
|
||||
with_clock(channels) == [False, False, True, True, False])
|
||||
|
||||
|
||||
# The flag as `HomeAssistant.state()` sets it: a 502 or a refused connection
|
||||
# turns it on, the next good read turns it off, and a timeout (a slow Home
|
||||
# Assistant, not a starting one) leaves it alone.
|
||||
class _Answer:
|
||||
def __init__(self, what):
|
||||
self.what = what
|
||||
|
||||
async def __aenter__(self):
|
||||
if isinstance(self.what, BaseException):
|
||||
raise self.what
|
||||
return self
|
||||
|
||||
async def __aexit__(self, *_a):
|
||||
return False
|
||||
|
||||
@property
|
||||
def status(self):
|
||||
return self.what
|
||||
|
||||
def raise_for_status(self):
|
||||
pass
|
||||
|
||||
async def json(self):
|
||||
return {"state": "1"}
|
||||
|
||||
|
||||
class _Session:
|
||||
def __init__(self, answers):
|
||||
self.answers = list(answers)
|
||||
|
||||
def get(self, *_a, **_k):
|
||||
return _Answer(self.answers.pop(0))
|
||||
|
||||
|
||||
def reads(answers):
|
||||
async def go():
|
||||
real, _hass.OUTAGE = _hass.OUTAGE, _hass.Outage()
|
||||
lg = logging.getLogger("goodwe.hass")
|
||||
lg.disabled = True
|
||||
try:
|
||||
h = _hass.HomeAssistant(_Session(answers), token="t")
|
||||
seen = []
|
||||
for _ in answers:
|
||||
await h.state("sensor.x")
|
||||
seen.append(_hass.OUTAGE.waiting())
|
||||
return seen
|
||||
finally:
|
||||
_hass.OUTAGE = real
|
||||
lg.disabled = False
|
||||
return asyncio.run(go())
|
||||
|
||||
|
||||
check("a 502 read turns waiting on and the next good read turns it off",
|
||||
reads([502, 200, 503, 404]) == [True, False, True, False])
|
||||
check("a refused connection is waiting too",
|
||||
reads([_hass.aiohttp.ClientConnectionError(), 200]) == [True, False])
|
||||
check("a read timeout is not waiting",
|
||||
reads([TimeoutError(), TimeoutError()]) == [False, False])
|
||||
|
||||
|
||||
# --------------------------------------------------------------------------- #
|
||||
print("2. the status page, N=1 and N=2")
|
||||
|
||||
|
||||
class _Hass:
|
||||
session = None
|
||||
token = ""
|
||||
|
||||
def __init__(self):
|
||||
self.writes = []
|
||||
|
||||
async def limits(self, _e):
|
||||
return (-5000.0, 5000.0, 1.0)
|
||||
|
||||
async def number(self, _e, invert=False):
|
||||
return None # what a 502 read gives
|
||||
|
||||
async def state(self, _e):
|
||||
return None
|
||||
|
||||
async def set_number(self, e, v):
|
||||
self.writes.append((e, float(v)))
|
||||
return False # what a 502 write gives
|
||||
|
||||
async def call(self, *_a):
|
||||
return False
|
||||
|
||||
async def states(self):
|
||||
return None
|
||||
|
||||
|
||||
class _Store:
|
||||
def __init__(self):
|
||||
self.data = {}
|
||||
|
||||
def set(self, k, v):
|
||||
self.data[k] = v
|
||||
|
||||
def get(self, k, d=None):
|
||||
return self.data.get(k, d)
|
||||
|
||||
def set_time(self, k, v):
|
||||
self.data[k] = v.isoformat()
|
||||
|
||||
def get_time(self, k):
|
||||
return None
|
||||
|
||||
|
||||
class _Pub:
|
||||
enabled = False
|
||||
|
||||
def publish(self, *_a, **_k):
|
||||
pass
|
||||
|
||||
def close(self):
|
||||
pass
|
||||
|
||||
|
||||
ONE = {"setpoint_entity": "number.sp", "meter_entity": "sensor.grid",
|
||||
"soc_entity": "sensor.soc", "batt_entity": "sensor.batt",
|
||||
"meter_source": "off", "max_w": 5000, "shadow_mode": "off",
|
||||
"maintenance_enabled": False, "stale_input_s": 15}
|
||||
TWO = dict(ONE, setpoint_entity="", soc_entity="", batt_entity="", inverters=[
|
||||
{"name": "inverter-a", "setpoint_entity": "number.a", "soc_entity":
|
||||
"sensor.soc_a", "batt_entity": "sensor.batt_a", "max_w": 2500,
|
||||
"bms_soc_floor": 10},
|
||||
{"name": "inverter-b", "setpoint_entity": "number.b", "soc_entity":
|
||||
"sensor.soc_b", "batt_entity": "sensor.batt_b", "max_w": 2500,
|
||||
"bms_soc_floor": 10}])
|
||||
|
||||
|
||||
def make(opts, hass=None):
|
||||
c = Controller(dict(opts), hass or _Hass(), _Store(), _Pub(),
|
||||
stop=asyncio.Event())
|
||||
c.auto = True
|
||||
for inv in c.inverters:
|
||||
inv.dev_min, inv.dev_max = -5000.0, 5000.0
|
||||
return c
|
||||
|
||||
|
||||
def waiting_on():
|
||||
_hass.OUTAGE.down_on = {"api"}
|
||||
_hass.OUTAGE.since = _hass.OUTAGE._told = _hass.time.monotonic()
|
||||
|
||||
|
||||
def waiting_off():
|
||||
_hass.OUTAGE.down_on = set()
|
||||
|
||||
|
||||
BANNER = "Not ready — Waiting for Home Assistant to finish starting"
|
||||
for label, opts in (("N=1", ONE), ("N=2", TWO)):
|
||||
c = make(opts)
|
||||
waiting_off()
|
||||
plain = c.checks()
|
||||
pay_off = c.status_payload()
|
||||
waiting_on()
|
||||
rows = c.checks()
|
||||
pay = c.status_payload()
|
||||
pay_nl = c.status_payload(lang="nl")
|
||||
waiting_off()
|
||||
check(f"{label}: no waiting row while Home Assistant answers",
|
||||
not [r for r in plain if r.get("id") == "home_assistant"]
|
||||
and pay_off["state"]["kind"] != "waiting")
|
||||
check(f"{label}: while it does not, the waiting row is first and red",
|
||||
rows[0] == {"ok": False, "warn": False, "id": "home_assistant",
|
||||
"banner": messages.banner_ha_waiting(),
|
||||
"text": messages.row_ha_waiting()}
|
||||
and rows[1:] == plain)
|
||||
check(f"{label}: ...and it is the banner ({pay['banner']!r})",
|
||||
pay["banner"] == BANNER and pay["level"] == "bad")
|
||||
check(f"{label}: Home says waiting, not 'Needs you now' "
|
||||
f"({pay['state']['pill']!r}, {pay['state']['sub']!r})",
|
||||
pay["state"]["kind"] == "waiting"
|
||||
and pay["state"]["pill"] == "Waiting for Home Assistant"
|
||||
and pay["state"]["sub"] == "Control resumes by itself when Home "
|
||||
"Assistant answers.")
|
||||
check(f"{label}: ...and in Dutch ({pay_nl['state']['pill']!r})",
|
||||
pay_nl["state"]["pill"] == "Wacht op Home Assistant"
|
||||
and pay_nl["state"]["sub"] == "De regeling gaat vanzelf verder "
|
||||
"zodra Home Assistant antwoordt.")
|
||||
check(f"{label}: Needs attention lists it first, with its own title",
|
||||
pay["attention"][0]["id"] == "home_assistant"
|
||||
and pay["attention"][0]["title"] == "Home Assistant is not answering"
|
||||
and pay_nl["attention"][0]["title"] == "Home Assistant antwoordt "
|
||||
"niet")
|
||||
|
||||
# A safety stop outranks the wait: it still needs a person.
|
||||
c = make(TWO)
|
||||
c.inverters[1].sign_wd.tripped = True
|
||||
waiting_on()
|
||||
pay = c.status_payload()
|
||||
waiting_off()
|
||||
check(f"a safety stop keeps its banner and 'Needs you now' over the wait "
|
||||
f"({pay['banner']!r}, {pay['state']['kind']!r})",
|
||||
pay["banner"] == messages.banner_direction(True)
|
||||
and pay["state"]["kind"] == "alarm")
|
||||
# A stalled control loop does not resume by itself, so it stays the headline.
|
||||
c = make(ONE)
|
||||
c.loop_pass_mono = 0.0
|
||||
waiting_on()
|
||||
rows, pay = c.checks(), c.status_payload()
|
||||
waiting_off()
|
||||
check(f"a stalled control loop stays first and keeps 'Needs you now' "
|
||||
f"({pay['banner']!r})",
|
||||
[r["id"] for r in rows[:2]] == ["controller", "home_assistant"]
|
||||
and pay["state"]["kind"] == "alarm")
|
||||
c = make(dict(ONE, shadow_mode="on"))
|
||||
waiting_on()
|
||||
pay = c.status_payload()
|
||||
waiting_off()
|
||||
check("shadow mode keeps its own state over the wait",
|
||||
pay["state"]["kind"] == "shadow")
|
||||
|
||||
|
||||
# The page script, read as text (the image has no JS engine): an amber dot,
|
||||
# and the batteries tab carries the banner like the other held states.
|
||||
JS = open(os.path.join(os.path.dirname(os.path.abspath(__file__)), "app",
|
||||
"static", "app.js"), encoding="utf-8").read()
|
||||
check("the page script gives 'waiting' an amber dot",
|
||||
re.search(r'alarm: " bad", waiting: " warn" \}\[st\.kind\]', JS)
|
||||
is not None)
|
||||
check("...and shows it as the batteries-tab banner",
|
||||
'["shadow", "stopped", "alarm", "waiting"].includes(S.state.kind)'
|
||||
in JS)
|
||||
|
||||
|
||||
# --------------------------------------------------------------------------- #
|
||||
print("3. control is unchanged by the waiting flag")
|
||||
|
||||
|
||||
def run(opts, flag):
|
||||
async def go():
|
||||
h = _Hass()
|
||||
c = make(opts, h)
|
||||
(waiting_on if flag else waiting_off)()
|
||||
targets = []
|
||||
for _ in range(4):
|
||||
await c.read_inputs()
|
||||
await c.cycle()
|
||||
await c.send_heartbeats(asyncio.get_running_loop().time(), 10.0)
|
||||
targets.append(c.target)
|
||||
waiting_off()
|
||||
return targets, h.writes
|
||||
return asyncio.run(go())
|
||||
|
||||
|
||||
for label, opts in (("N=1", ONE), ("N=2", TWO)):
|
||||
off, on = run(opts, False), run(opts, True)
|
||||
check(f"{label}: same targets and writes with the flag on or off "
|
||||
f"({on[0]}, {len(on[1])} writes)", off == on)
|
||||
check(f"{label}: ...and every write while Home Assistant does not answer "
|
||||
f"asks 0 W", on[1] and all(v == 0.0 for _e, v in on[1]))
|
||||
|
||||
|
||||
# With 502 readings every write is 0 W whatever the flag says, so the check
|
||||
# above cannot see a flag that forces 0 W. Live readings can: the flag alone
|
||||
# must not change a non-zero write.
|
||||
class _LiveHass(_Hass):
|
||||
async def number(self, e, invert=False):
|
||||
v = {"sensor.grid": 900.0}.get(e, 50.0 if "soc" in e else 0.0)
|
||||
return -v if invert else v
|
||||
|
||||
async def set_number(self, e, v):
|
||||
self.writes.append((e, float(v)))
|
||||
return True
|
||||
|
||||
|
||||
def run_live(opts, flag):
|
||||
async def go():
|
||||
h = _LiveHass()
|
||||
c = make(opts, h)
|
||||
(waiting_on if flag else waiting_off)()
|
||||
for _ in range(4):
|
||||
await c.read_inputs()
|
||||
await c.cycle()
|
||||
await c.send_heartbeats(asyncio.get_running_loop().time(), 10.0)
|
||||
waiting_off()
|
||||
return h.writes
|
||||
return asyncio.run(go())
|
||||
|
||||
|
||||
for label, opts in (("N=1", ONE), ("N=2", TWO)):
|
||||
off, on = run_live(opts, False), run_live(opts, True)
|
||||
check(f"{label}: with live readings the flag changes no write "
|
||||
f"({on[-2:]})", off == on and any(v != 0.0 for _e, v in on))
|
||||
|
||||
|
||||
print()
|
||||
if fails:
|
||||
print(f"{len(fails)} FAILED")
|
||||
for f in fails:
|
||||
print(" -", f)
|
||||
raise SystemExit(1)
|
||||
print("all passed")
|
||||
Reference in New Issue
Block a user