UX-10: the last plain-language leftovers: log lines, two table rows, 'Why: Other', red at 0 s
- test_messages.py part 6: every dynamic part of a WARNING+ line is classified as data or as a built text, and every built text is produced by the real code and checked. This is the gap the 2d scan had: it counted `%s` as one word, so reasons built by loop_clamp_note() and friends were never seen. - Quoted reasons rewritten to STYLE.md (red-alarm shape, codes kept): OUTPUT_CLAMP, METER_FROZEN, CIRCULATING_POWER, STALE_READING, the peak guard (codes now PEAK_GUARD*), the migration report, price feed, price history and gate reasons. Plurals via messages.times()/count(). - Top table: Price history "96 prices over 24 hours for 26 Sep", Tariff "one every 15 minutes or every hour", "not final yet" dropped. - Levels and noise: per-cycle shadow line DEBUG, shadow on/off INFO, aiohttp access log only at log level debug, settings warnings once per start, one plain line per Home Assistant outage (hass.Outage). - INFO jargon and error texts: no "§8.3", ISO times, "banked", "keys ARE", "NOT_OBSERVED", "did NOT land", "AND". - Display bugs: WHY_WINNER covers every winner and safety reason (main.why_key(), part 7 finds them in the code); the meter row is amber "waiting for the first reading" inside its limit after a start; the missing-reading age is counted when the page asks. - STYLE.md and DECISIONS/UX-08-short-notifications.md (UX-10 section). No change to safety behaviour, alarm levels, notification ids, triggers, cadence or the banner cascade. One row colour changes (meter at start), justified in DECISIONS. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
This commit is contained in:
glenn schrooyen
co-authored by
Claude Opus 5.5
Claude Opus 5.5
parent
125b0702a2
commit
23a3a3f5b5
@@ -580,7 +580,7 @@ check(f"every event the add-on records gives the page its plain words, from "
|
||||
f"messages.hint() ({_calls} calls, without: {_bare})",
|
||||
_calls >= 40 and not _bare)
|
||||
_raw = ("OUTPUT_CLAMP", "BUG SIGNAL", "FAILSAFE", "SIGN_DISAGREEMENT",
|
||||
"ALLOCATOR", "UNMET", "ARBITER", "PEAK GUARD")
|
||||
"ALLOCATOR", "UNMET", "ARBITER", "PEAK GUARD", "PEAK_GUARD")
|
||||
check("no hint carries the raw event codes the page used to show",
|
||||
not [t for _k, t in messages.hint_samples()
|
||||
if any(r in t for r in _raw)])
|
||||
@@ -796,6 +796,656 @@ _bad = ast.parse("await self.hass.call('persistent_notification', 'create', "
|
||||
check("a hand-written notification payload is seen by part 2",
|
||||
any(not (isinstance(c.args[2], ast.Call)) for c in notification_calls(_bad)))
|
||||
|
||||
|
||||
# ============================================================================== #
|
||||
print("\n6. log lines as they are built at run time (UX-10)")
|
||||
# Part 3 reads a WARNING+ line's own literal and counts each placeholder as one
|
||||
# word. So a reason text built elsewhere and passed in as `%s` was never seen:
|
||||
# the 2d test found "…clamped to +2000 W; … This is a BUG SIGNAL … Cut back 1
|
||||
# times" in the log while part 3 was green, because `loop_clamp_note()` built
|
||||
# it. This part closes that gap in two steps.
|
||||
# a. Every dynamic part of every WARNING+ line in `app/` is classified here,
|
||||
# as data (a number, a name, a path, an exception's own text) or as a text
|
||||
# the add-on builds. A new dynamic part that is in neither list fails, so a
|
||||
# new builder cannot slip past.
|
||||
# b. Every built text is produced by the real code and checked. It is the
|
||||
# evidence behind an alarm, so it gets the red-alarm shape: at most 3
|
||||
# sentences of at most 30 words, 70 in all. It keeps its reason code. The
|
||||
# whole line, as logged, may carry no semicolon, banned term, capitals,
|
||||
# "1 times", "(s)" or a doubled full stop.
|
||||
from datetime import datetime as _dt, timedelta as _td, timezone as _tz # noqa: E402
|
||||
|
||||
from app import clamp as _clamp, freshness as _fresh, peakguard as _pg # noqa: E402
|
||||
from app import store as _store # noqa: E402
|
||||
from app.circulation import CirculationConfig, CirculationWatchdog # noqa: E402
|
||||
from app.control import Tuning, compute # noqa: E402
|
||||
from app.delivery import (DeliveryConfig, DeliveryWatchdog, UnitDelivery, # noqa: E402
|
||||
delinquent)
|
||||
from app.freeze import FreezeWatchdog, FreezeWatchdogConfig # noqa: E402
|
||||
from app.price import PricePoint, PriceProduct, PriceRead # noqa: E402
|
||||
from app.static_tariff import TariffPlan # noqa: E402
|
||||
from app.tariff import Projection # noqa: E402
|
||||
from app.watchdog import (AGAINST_METER, AGAINST_OWN_POWER, SignWatchdog, # noqa: E402
|
||||
SignWatchdogConfig)
|
||||
|
||||
_T0 = _dt(2026, 9, 27, 9, 0, tzinfo=_tz.utc)
|
||||
PLURAL = re.compile(r"\b1 [a-z]{2,}s\b(?<!\b1 [a-z]ss)|\w\(s\)")
|
||||
COUNT_PLURAL = re.compile(r"%d [a-z]{2,}s\b")
|
||||
|
||||
|
||||
def dynamic_parts(tree, fname):
|
||||
"""(key, call) for every dynamic part of a WARNING+ log call in `tree`."""
|
||||
for node in ast.walk(tree):
|
||||
if not isinstance(node, ast.Call):
|
||||
continue
|
||||
name = ast.unparse(node.func)
|
||||
moan = name.endswith("._moan")
|
||||
if not (LOG_CALL.search(name) or moan):
|
||||
continue
|
||||
i = 1 if moan else 0
|
||||
if len(node.args) <= i:
|
||||
continue
|
||||
fmt = node.args[i]
|
||||
parts = [ast.unparse(a) for a in node.args[i + 1:]]
|
||||
if isinstance(fmt, ast.JoinedStr):
|
||||
parts += [ast.unparse(v.value) for v in fmt.values
|
||||
if isinstance(v, ast.FormattedValue)]
|
||||
elif not (isinstance(fmt, ast.Constant) and isinstance(fmt.value, str)):
|
||||
parts.append(ast.unparse(fmt))
|
||||
for part in parts:
|
||||
yield f"{fname}:{part}", node
|
||||
|
||||
|
||||
# a. DATA: shown as it is, never worded by the add-on. An exception's text is
|
||||
# the library's (hass.py words the Home Assistant ones, UX-10 item 3).
|
||||
DATA = {
|
||||
# hass.py: the _moan() wrapper and what its callers pass
|
||||
"hass.py:msg", "hass.py:*args", "hass.py:entity_id", "hass.py:err",
|
||||
"hass.py:obj", "hass.py:raw", "hass.py:domain", "hass.py:service",
|
||||
"hass.py:resp.status", "hass.py:body[:200]", "hass.py:what",
|
||||
# main.py
|
||||
"main.py:'cancelled' if task.cancelled() else repr(exc) if exc else 'returned'",
|
||||
"main.py:EXIT_CONTROL_DIED", "main.py:first.name", "main.py:OPTIONS_PATH",
|
||||
"main.py:err", "main.py:', '.join(sorted(stranded))",
|
||||
"main.py:sorted(on_roster)", "main.py:inv.name",
|
||||
"main.py:inv.batt_fresh.bound.release_s", "main.py:inv.batt_fresh.bound.move_w",
|
||||
"main.py:inv.batt_fresh.bound.unchanged_s", "main.py:inv.batt_fresh.held",
|
||||
"main.py:value", "main.py:float(value)",
|
||||
"main.py:entity", "main.py:WRITE_BUDGET_S",
|
||||
"main.py:_e",
|
||||
"main.py:messages.times(self.clamp_wd.engagements)",
|
||||
"main.py:messages.when(brussels(self.tariff_at))",
|
||||
"main.py:messages.duration(TARIFF_MAX_AGE_S)",
|
||||
"main.py:messages.count(len(targets), 'inverter')",
|
||||
# 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",
|
||||
"p1.py:backoff", "p1.py:self.url", "p1.py:str(err) or type(err).__name__",
|
||||
"p1.py:self.poll_s",
|
||||
# price.py
|
||||
"price.py:doc.get('deprecated')", "price.py:len(dropped)",
|
||||
"price.py:messages.count(len(times), 'time')", "price.py:plugin_id",
|
||||
"price.py:override",
|
||||
"price.py:', '.join((str(i) for i in dropped[:5])) + (' and more' if len(dropped) > 5 else '')",
|
||||
"price.py:*(d.isoformat() for d in brussels_date_range(since, until))",
|
||||
"price.py:pid",
|
||||
"price.py:'/'.join(sorted((c.value for c in caps.sources - {Component.ENERGY})))",
|
||||
"price.py:' and '.join(ignored) + (' is' if len(ignored) == 1 else ' are')",
|
||||
"price.py:getattr(cls, 'id', cls)", "price.py:e", "price.py:type(e).__name__",
|
||||
# price_history.py, selfconfig.py, static_tariff.py, store.py, tariff.py
|
||||
"price_history.py:self.path", "price_history.py:day_words(want)",
|
||||
"price_history.py:messages.count(len(points), 'price')",
|
||||
"price_history.py:err",
|
||||
"selfconfig.py:messages.count(len(problems), 'problem')",
|
||||
"selfconfig.py:', '.join(changed) or 'none this page also edited'",
|
||||
"static_tariff.py:e", "store.py:err", "store.py:key", "store.py:raw",
|
||||
"tariff.py:self.path", "tariff.py:err", "tariff.py:start", "tariff.py:month",
|
||||
# validate.py: option values and keys (the refusals are part 3's)
|
||||
"validate.py:integ_w", "validate.py:max_w", "validate.py:disch_w",
|
||||
"validate.py:maint_where", "validate.py:maint_cap", "validate.py:pid",
|
||||
"validate.py:i", "validate.py:TAXES_PROFILE_OPTION", "validate.py:negative",
|
||||
"validate.py:EXPORT_FORMULA_OPTION", "validate.py:xspec.passthrough",
|
||||
"validate.py:xspec.offset_eur_kwh", "validate.py:'=' * 72",
|
||||
"validate.py:'-' * 72",
|
||||
"web.py:err",
|
||||
}
|
||||
|
||||
|
||||
# b. BUILT TEXT: each producer, run for real. A reason that is only ever
|
||||
# stored and restored (a saved safety stop) is produced by the same builder.
|
||||
def _sign(against, cmd=1500.0, got=-1400.0):
|
||||
wd = SignWatchdog(SignWatchdogConfig(min_w=250.0, hold_s=60.0),
|
||||
against=against)
|
||||
for s in (0, 61):
|
||||
wd.evaluate(cmd, got, True, _T0 + _td(seconds=s))
|
||||
return wd.reason
|
||||
|
||||
|
||||
def _sign_texts():
|
||||
return [_sign(AGAINST_METER), _sign(AGAINST_OWN_POWER, -1100.0, 2000.0)]
|
||||
|
||||
|
||||
def _circ_texts():
|
||||
wd = CirculationWatchdog(CirculationConfig(min_w=250.0, hold_s=60.0))
|
||||
for s, w in ((0, 5200.0), (30, 6000.0), (61, 5800.0)):
|
||||
wd.evaluate(w, _T0 + _td(seconds=s))
|
||||
return [wd.reason]
|
||||
|
||||
|
||||
def _delivery_texts():
|
||||
units = [UnitDelivery("inverter-a", 1000.0, 990.0),
|
||||
UnitDelivery("inverter-b", 2000.0, 0.0)]
|
||||
sentence = delinquent(units, 200.0)["inverter-b"]
|
||||
wd = DeliveryWatchdog(DeliveryConfig(hold_s=120.0))
|
||||
for s in (0, 121):
|
||||
wd.evaluate(sentence, _T0 + _td(seconds=s))
|
||||
return [wd.reason]
|
||||
|
||||
|
||||
def _freeze_texts():
|
||||
out = []
|
||||
for dev in (None, 4700.0):
|
||||
wd = FreezeWatchdog(FreezeWatchdogConfig(hold_s=600.0))
|
||||
wd.evaluate(3600.0, 4480.0 if dev else 5000.0, 5000.0, _T0,
|
||||
dev_min=-dev if dev else None, dev_max=dev)
|
||||
out.append(wd.reason)
|
||||
return out
|
||||
|
||||
|
||||
def _stale_texts():
|
||||
one = _fresh.Freshness(_fresh.BOUNDS["batt"])
|
||||
for t in range(0, 40):
|
||||
one.submit(-1200.0, -1200.0 if t < 1 else 1300.0, float(t))
|
||||
two = _fresh.Freshness(_fresh.BOUNDS["batt"])
|
||||
for t in range(0, 40):
|
||||
two.submit(-1200.0, -1200.0 if t < 1 else 1300.0, float(t))
|
||||
for t in range(40, 80):
|
||||
two.submit(-1200.0, 0.0, float(t))
|
||||
for t in range(80, 130):
|
||||
two.submit(-1200.0, 1300.0, float(t))
|
||||
return [one.reason, two.reason]
|
||||
|
||||
|
||||
def _clamp_texts():
|
||||
over = compute(prev_w=1000.0, grid_w=9000.0, actual_w=1000.0,
|
||||
tuning=Tuning(max_w=5000.0, slew_w=1000.0, gain=0.6,
|
||||
integrator_max_w=9000.0), i_w=8000.0)
|
||||
at = compute(prev_w=1000.0, grid_w=9000.0, actual_w=1000.0,
|
||||
tuning=Tuning(max_w=5000.0, slew_w=1000.0, gain=0.6),
|
||||
i_w=4500.0)
|
||||
write = [(n, _clamp.clamp_to_rating(w, 5000.0, -2500.0, 2500.0))
|
||||
for n, w in (("inverter-a", 3000.0), ("inverter-b", -7412.0))]
|
||||
return [_clamp.loop_clamp_note(over), _clamp.loop_clamp_note(at),
|
||||
_clamp.write_clamp_note(write[:1]), _clamp.write_clamp_note(write)]
|
||||
|
||||
|
||||
def _peak_texts():
|
||||
proj = Projection(projected_w=4338.0, elapsed_w=4338.0, elapsed_s=799.0,
|
||||
covered_frac=1.0, complete=False, block_start=_T0,
|
||||
held_w=0.0)
|
||||
kw = dict(cap_w=3500.0, reading=None, soc_floor=30.0, max_hold_s=30.0)
|
||||
sat = _pg.decide(proj, batt_w=1500.0, achievable_w=5000.0, soc=80.0, **kw)
|
||||
low = _pg.decide(proj, batt_w=1500.0, achievable_w=5000.0, soc=20.0, **kw)
|
||||
unread = _pg.decide(proj, batt_w=1500.0, achievable_w=5000.0, soc=None, **kw)
|
||||
return [sat.reason, low.reason, unread.reason]
|
||||
|
||||
|
||||
def _migration_texts():
|
||||
out = []
|
||||
for moved, kept, lost, wrong in (
|
||||
(2, 0, 0, 0), (2, 1, 1, 0), (2, 0, 0, 1), (0, 2, 0, 0),
|
||||
(0, 2, 1, 0)):
|
||||
rep = _store.MigrationReport()
|
||||
rep.ran = moved > 0 or lost > 0
|
||||
rep.from_version = 1
|
||||
rep.roster = ["inverter-a"]
|
||||
rep.moved = {f"unit/inverter-a/k{i}": True for i in range(moved)}
|
||||
rep.kept = [f"unit/inverter-a/old{i}" for i in range(kept)]
|
||||
for i in range(lost):
|
||||
note = f"unit/inverter-a/k{i} was written as True and reads back as None"
|
||||
rep.problems.append(note)
|
||||
rep.lost.append(note)
|
||||
for i in range(wrong):
|
||||
note = (f"unit/garage/k{i} was migrated into namespace 'garage', "
|
||||
f"which is not in the inverter list")
|
||||
rep.problems.append(note)
|
||||
rep.misdirected.append(note)
|
||||
out.append(rep.explain())
|
||||
return out
|
||||
|
||||
|
||||
def _tariff_texts():
|
||||
hours = [_T0 + _td(minutes=15 * i) for i in range(8)]
|
||||
pts = [PricePoint(h, 0.2, i >= 4) for i, h in enumerate(hours)]
|
||||
read = PriceRead.series(pts, PriceProduct.DAY_AHEAD, "x", _T0)
|
||||
return [TariffPlan(read, None, "provider").words,
|
||||
TariffPlan(PriceRead.no_data("the price feed timed out"), None,
|
||||
"none").words]
|
||||
|
||||
|
||||
def _static(spec):
|
||||
"""Templates for a family of builders that is not one function: the first
|
||||
argument of every call to `spec`, or every value assigned to `spec`, in
|
||||
the named file (placeholders count as one word, as in part 3)."""
|
||||
fname, kind, name = spec
|
||||
out = []
|
||||
for f in ([APP / fname] if fname != "*" else sorted(APP.glob("*.py"))):
|
||||
tree = ast.parse(f.read_text(encoding="utf-8"))
|
||||
for node in ast.walk(tree):
|
||||
if kind == "call" and isinstance(node, ast.Call) and node.args \
|
||||
and ast.unparse(node.func).split(".")[-1] == name:
|
||||
out += [t for _n, t in strings_in(node.args[0])]
|
||||
elif kind == "assign" and isinstance(node, ast.Assign) \
|
||||
and ast.unparse(node.targets[0]) == name:
|
||||
out += [t for _n, t in strings_in(node.value)]
|
||||
elif kind == "return" and isinstance(node, ast.FunctionDef) \
|
||||
and node.name == name:
|
||||
out += [t for r in ast.walk(node) if isinstance(r, ast.Return)
|
||||
and r.value is not None for _n, t in strings_in(r.value)]
|
||||
return [t for t in out if len(words(t)) > 1]
|
||||
|
||||
|
||||
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:rep.explain()": _migration_texts,
|
||||
"store.py:rep.explain()": _migration_texts,
|
||||
"main.py:plan.words": _tariff_texts,
|
||||
# Families: every builder of the text, as a template.
|
||||
"main.py:refusal": lambda: (_static(("main.py", "return", "write_refusal"))
|
||||
+ _static(("allocator.py", "return", "authorises"))),
|
||||
"main.py:' / '.join(resolution.scope_errors)":
|
||||
lambda: _static(("arbiter.py", "return", "scope_violations"))
|
||||
+ _static(("arbiter.py", "call", "append")),
|
||||
"price_forecast.py:gate.reason": lambda: _static(("*", "call", "block")),
|
||||
"static_tariff.py:read.reason": lambda: _static(("*", "call", "no_data")),
|
||||
"price_history.py:self.last_error":
|
||||
lambda: _static(("price_history.py", "assign", "self.last_error")),
|
||||
"price_history.py:bad": lambda: _static(("price_history.py", "return",
|
||||
"_parse_points")),
|
||||
"maintenance.py:msg": lambda: _static(("maintenance.py", "assign", "msg")),
|
||||
"validate.py:aged": lambda: _static(("*", "return", "stale_card")),
|
||||
"validate.py:xaged": lambda: _static(("*", "return", "stale_card")),
|
||||
# Refusals: part 3 holds them to the refusal rule already.
|
||||
"selfconfig.py:problems[0]": None,
|
||||
"validate.py:problem": None,
|
||||
"p1.py:problem": None,
|
||||
}
|
||||
|
||||
|
||||
def reason_problems(text):
|
||||
"""STYLE.md's red-alarm shape, for a text a log line quotes."""
|
||||
out = []
|
||||
n_s, n_w = sentences(text), len(words(text))
|
||||
if n_s > 3:
|
||||
out.append(f"over 3 sentences ({n_s})")
|
||||
if n_w > 70:
|
||||
out.append(f"over 70 words ({n_w})")
|
||||
long = [x for x in re.split(r"(?<=[.!?])\s+", text) if len(words(x)) > 30]
|
||||
if long:
|
||||
out.append(f"a sentence over 30 words ({len(words(long[0]))})")
|
||||
return out + line_problems(text)
|
||||
|
||||
|
||||
def line_problems(text):
|
||||
"""What no WARNING+ line may carry, whatever its length."""
|
||||
out = []
|
||||
if ";" in text:
|
||||
out.append("semicolon")
|
||||
if re.search(r"(?<!\.)\.\.(?!\.)|\.{4,}|\.:|:\s*\.", text):
|
||||
out.append("a doubled full stop")
|
||||
if PLURAL.search(text):
|
||||
out.append("plural: " + PLURAL.search(text).group(0))
|
||||
return out + text_problems(text, keys=True, entities=True)
|
||||
|
||||
|
||||
def _fill(template, fmt_node, key_part, sample):
|
||||
"""The line as logged: `sample` in the text slot, `X` in the others."""
|
||||
if isinstance(fmt_node, ast.JoinedStr):
|
||||
return template.replace("{" + key_part + "}", sample)
|
||||
return template # %-style: filled by the caller
|
||||
|
||||
|
||||
def scan_log_lines(files, text=None, data=None):
|
||||
"""-> (unclassified keys, stale keys, [(key, sample, problems)])."""
|
||||
text = TEXT if text is None else text
|
||||
data = DATA if data is None else data
|
||||
seen, bad = set(), []
|
||||
for fname, tree in files:
|
||||
for key, call in dynamic_parts(tree, fname):
|
||||
seen.add(key)
|
||||
if key in data or key not in text:
|
||||
continue
|
||||
maker = text[key]
|
||||
if maker is None:
|
||||
continue
|
||||
i = 1 if ast.unparse(call.func).endswith("._moan") else 0
|
||||
fmt = call.args[i]
|
||||
template = render(fmt) or ""
|
||||
args = [ast.unparse(a) for a in call.args[i + 1:]]
|
||||
part = key.split(":", 1)[1]
|
||||
for sample in maker():
|
||||
p = reason_problems(sample)
|
||||
if isinstance(fmt, ast.JoinedStr):
|
||||
line = template.replace("{" + part + "}", sample)
|
||||
else:
|
||||
slots = iter(["%s" if a != part else "\0" for a in args])
|
||||
line = re.sub(r"%[-+ #0-9.]*[sdrfgx]",
|
||||
lambda m: next(slots, m.group(0)), template)
|
||||
line = PLACEHOLDER.sub("X", line).replace("\0", sample)
|
||||
p += [f"as logged: {x}" for x in line_problems(line)
|
||||
if x not in p]
|
||||
if p:
|
||||
bad.append((key, sample, p))
|
||||
unknown = sorted(seen - set(data) - set(text))
|
||||
stale = sorted((set(data) | set(text)) - seen)
|
||||
return unknown, stale, bad
|
||||
|
||||
|
||||
_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)
|
||||
for k, sample, p in _bad:
|
||||
print(f" BAD {k}: {'; '.join(p)} :: {sample[:110]!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"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)
|
||||
if isinstance(n, ast.Call) and (LOG_CALL.search(ast.unparse(n.func))
|
||||
or ast.unparse(n.func).endswith("._moan"))
|
||||
for a in n.args[:2] if isinstance(a, ast.Constant)
|
||||
and isinstance(a.value, str) and COUNT_PLURAL.search(a.value)]
|
||||
check(f"no WARNING+ line puts a plural noun after a bare count, which reads "
|
||||
f"'1 times' (use messages.times() and friends; found: {_counts})",
|
||||
not _counts)
|
||||
|
||||
# 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]})
|
||||
_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)
|
||||
_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})",
|
||||
_u == ["main.py:self.new_wd.reason"])
|
||||
check("...and '1 times', '(s)', a semicolon and a doubled full stop in a "
|
||||
"logged line are caught",
|
||||
all(line_problems(t) for t in ("Cut back 1 times so far.",
|
||||
"2 malformed point row(s) dropped.",
|
||||
"It failed; retrying.",
|
||||
"Cut back to +2000 W.. Only this.",
|
||||
"index 0, 1, .... Those are left out.",
|
||||
"moved to one part: . Problems")))
|
||||
check("...while '1 s' and '1 time' are fine",
|
||||
not line_problems("Held for 1 s, cut back 1 time so far."))
|
||||
# INFO lines are not held to the length rule, but the 2d test found "§8.3",
|
||||
# ISO timestamps and "keys ARE" in them. Their literals may carry none.
|
||||
INFO_JARGON = re.compile(r"§\s?\d|isoformat|\b(?:ARE|NOT|AND)\b")
|
||||
_info_bad = [f"{f}:{n.lineno}" for f, t in _FILES for n in ast.walk(t)
|
||||
if isinstance(n, ast.Call) and n.args
|
||||
and re.search(r"(?:^|\.)(?:_LOG|log|logger|LOG)\.info$",
|
||||
ast.unparse(n.func))
|
||||
for _n, s in strings_in(n.args[0])
|
||||
if INFO_JARGON.search(ast.unparse(n.args[0])) or SHOUT.search(s)]
|
||||
check(f"no INFO line carries a section number, an ISO timestamp or capitals "
|
||||
f"(found: {_info_bad})", not _info_bad)
|
||||
check("...and one that did is caught",
|
||||
bool(INFO_JARGON.search('"§8.3 price history: %s"'))
|
||||
and bool(SHOUT.search("the flat keys ARE NOT that pack's history")))
|
||||
|
||||
|
||||
# ============================================================================== #
|
||||
print("\n7. log levels, log noise and the display bugs (UX-10)")
|
||||
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
|
||||
|
||||
|
||||
class _Rec(logging.Handler):
|
||||
def __init__(self):
|
||||
super().__init__(logging.DEBUG)
|
||||
self.records = []
|
||||
|
||||
def emit(self, record):
|
||||
self.records.append(record)
|
||||
|
||||
|
||||
def _captured(logger_name, fn):
|
||||
rec, lg = _Rec(), logging.getLogger(logger_name)
|
||||
old = lg.level
|
||||
lg.addHandler(rec)
|
||||
lg.setLevel(logging.DEBUG)
|
||||
try:
|
||||
fn()
|
||||
finally:
|
||||
lg.removeHandler(rec)
|
||||
lg.setLevel(old)
|
||||
return rec.records
|
||||
|
||||
|
||||
def _level_of(fname, words_in_line):
|
||||
"""The level of the log call in `fname` whose literal holds the words."""
|
||||
tree = ast.parse((APP / fname).read_text(encoding="utf-8"))
|
||||
for node in ast.walk(tree):
|
||||
if isinstance(node, ast.Call) and node.args \
|
||||
and re.search(r"_LOG\.\w+$", ast.unparse(node.func)):
|
||||
text = render(node.args[0]) or ""
|
||||
if words_in_line in text:
|
||||
return ast.unparse(node.func).rsplit(".", 1)[-1]
|
||||
return None
|
||||
|
||||
|
||||
check("the shadow line of every cycle is DEBUG, not INFO in capitals "
|
||||
f"({_level_of('main.py', 'Shadow mode: would send')})",
|
||||
_level_of("main.py", "Shadow mode: would send") == "debug"
|
||||
and _level_of("main.py", "SHADOW MODE: not commanding") is None)
|
||||
check("'Shadow mode is on' and 'is off', which follow a setting or a button, "
|
||||
f"are INFO ({_level_of('main.py', 'Shadow mode is on')}, "
|
||||
f"{_level_of('main.py', 'Shadow mode is off')})",
|
||||
_level_of("main.py", "Shadow mode is on") == "info"
|
||||
and _level_of("main.py", "Shadow mode is off") == "info")
|
||||
_access = {}
|
||||
for _lvl in (logging.INFO, logging.DEBUG):
|
||||
logging.getLogger("goodwe.web").setLevel(_lvl)
|
||||
_access[logging.getLevelName(_lvl)] = _web.access_log()
|
||||
logging.getLogger("goodwe.web").setLevel(logging.NOTSET)
|
||||
_start_src = " ".join(
|
||||
ast.unparse(n) for n in ast.walk(ast.parse(
|
||||
(APP / "web.py").read_text(encoding="utf-8")))
|
||||
if isinstance(n, ast.AsyncFunctionDef) and n.name == "start")
|
||||
check(f"the page's own polls are not logged at INFO: aiohttp's access log is "
|
||||
f"off unless the log level is debug ({_access})",
|
||||
_access["INFO"] is None
|
||||
and isinstance(_access["DEBUG"], logging.Logger)
|
||||
and "access_log=access_log()" in _start_src)
|
||||
_validate.WARN_ONCE.seen.clear() # part 3 ran the validator already
|
||||
_twice = _captured("goodwe.config", lambda: [
|
||||
_validate.validate_startup_config(
|
||||
dict(_BASE, price_provider="generic_dayahead", static_profile=""),
|
||||
-5000, 5000) for _ in range(2)])
|
||||
_sp = [r for r in _twice if "static_profile is empty" in r.getMessage()]
|
||||
check(f"a settings warning is logged once per start, though the check runs "
|
||||
f"twice ({len(_sp)} line(s))", len(_sp) == 1
|
||||
and _sp[0].levelno == logging.WARNING)
|
||||
|
||||
|
||||
def _outage():
|
||||
o = _hass.Outage()
|
||||
o.down("api", "error 502", "read sensor.x: 502, message='Bad Gateway'")
|
||||
o.down("api", "error 502", "read sensor.y: 502")
|
||||
o.down("websocket", "the meter connection closed",
|
||||
"Received message 8:1000 is not str")
|
||||
o.up("api")
|
||||
o.up("websocket")
|
||||
o.down("api", "no connection", "Cannot connect to host supervisor:80")
|
||||
|
||||
|
||||
_out = _captured("goodwe.hass", _outage)
|
||||
_warn = [r.getMessage() for r in _out if r.levelno == logging.WARNING]
|
||||
_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)
|
||||
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)
|
||||
and not any("8:1000" in m or "Bad Gateway" in m for m in _warn + _info))
|
||||
|
||||
|
||||
class _WS:
|
||||
def __init__(self, kind):
|
||||
self.kind = kind
|
||||
|
||||
async def receive(self):
|
||||
return type("M", (), {"type": self.kind, "data": "{}"})()
|
||||
|
||||
|
||||
def _closed_ws():
|
||||
try:
|
||||
asyncio.run(_p1._receive_json(_WS(_p1.aiohttp.WSMsgType.CLOSE)))
|
||||
except ConnectionResetError as e:
|
||||
return str(e)
|
||||
return None
|
||||
|
||||
|
||||
check(f"a socket Home Assistant closed is a plain ConnectionResetError, which "
|
||||
f"the reconnect loop reports through that one line ({_closed_ws()!r})",
|
||||
(_closed_ws() or "").startswith("Home Assistant closed the connection"))
|
||||
|
||||
# "Why: Other". Every winner and every safety reason the code can produce has
|
||||
# words. The keys are found in the code: each `Claim.set(source, ..., reason)`
|
||||
# through main.why_key(), plus main.py's own refusal to split ("unsplit").
|
||||
_SOURCES = {}
|
||||
for _f in sorted(APP.glob("*.py")):
|
||||
_tree = ast.parse(_f.read_text(encoding="utf-8"))
|
||||
_consts = _module_constants(_tree)
|
||||
for _n in ast.walk(_tree):
|
||||
if isinstance(_n, ast.Call) and ast.unparse(_n.func) == "Claim.set" \
|
||||
and _n.args:
|
||||
_src = _n.args[0]
|
||||
_src = (_src.value if isinstance(_src, ast.Constant)
|
||||
else _consts.get(getattr(_src, "id", ""), None))
|
||||
_rsn = next((k.value for k in _n.keywords if k.arg == "reason"),
|
||||
_n.args[3] if len(_n.args) > 3 else None)
|
||||
_rsn = _rsn.value if isinstance(_rsn, ast.Constant) else ""
|
||||
_SOURCES.setdefault((_src, _rsn), f"{_f.name}:{_n.lineno}")
|
||||
_keys = {why_key(s, [Claim.set(s, 0, 0.0, r)]) for s, r in _SOURCES}
|
||||
_keys |= {why_key("failsafe", []),
|
||||
why_key("failsafe", [Claim.set("loop", 0, 1.0, "tracking")])}
|
||||
check(f"the scan found the claims ({len(_SOURCES)}), including the latched "
|
||||
f"per-inverter stop the 2d test saw as 'Other'",
|
||||
("failsafe", "sign disagreement") in _SOURCES and len(_SOURCES) >= 8)
|
||||
_missing_why = sorted(k for k in _keys if k not in messages.WHY_WINNER)
|
||||
check(f"every winner and safety reason has words in messages.WHY_WINNER "
|
||||
f"(missing: {_missing_why}, keys: {sorted(_keys)})", not _missing_why)
|
||||
check("...so the latched stop reads as a safety stop, not 'Other' "
|
||||
f"({messages.why(why_key('failsafe', [Claim.set('failsafe', 0, 0.0, 'sign disagreement')]), 0)!r})",
|
||||
messages.why(why_key("failsafe", [Claim.set("failsafe", 0, 0.0,
|
||||
"sign disagreement")]), 0)
|
||||
== "Safety stop, power went the wrong way: 0 W")
|
||||
_without = {k: v for k, v in messages.WHY_WINNER.items()
|
||||
if k != "sign disagreement"}
|
||||
check("...and a table that lost that entry is caught",
|
||||
any(k not in _without for k in _keys))
|
||||
|
||||
|
||||
class _H:
|
||||
async def number(self, *a, **k):
|
||||
return None
|
||||
|
||||
async def limits(self, *a):
|
||||
return (-2000.0, 2000.0, 1.0)
|
||||
|
||||
async def call(self, *a, **k):
|
||||
return True
|
||||
|
||||
|
||||
class _S:
|
||||
data = {}
|
||||
|
||||
def set(self, *a):
|
||||
pass
|
||||
|
||||
def get_time(self, *a):
|
||||
return None
|
||||
|
||||
|
||||
class _P:
|
||||
enabled = False
|
||||
|
||||
def publish(self, *a, **k):
|
||||
pass
|
||||
|
||||
|
||||
_c = Controller({"setpoint_entity": "number.sp", "meter_source": "off",
|
||||
"max_w": 2000, "stale_input_s": 15}, _H(), _S(), _P(),
|
||||
stop=asyncio.Event())
|
||||
_c.p1_enabled = True
|
||||
_c.p1 = _p1.P1Ingest(max_age_s=30.0)
|
||||
|
||||
|
||||
def _meter_row():
|
||||
"""The meter row, or a named absence that fails every check below."""
|
||||
rows = [r for r in _c.checks() if r.get("id") == "meter"]
|
||||
return rows[0] if len(rows) == 1 else {
|
||||
"ok": None, "warn": None, "text": f"<{len(rows)} meter rows>"}
|
||||
|
||||
|
||||
_r0 = _meter_row()
|
||||
_c.p1.started_mono -= 31.0
|
||||
_r1 = _meter_row()
|
||||
_c.p1.submit(_p1.make_sample(_p1.SOURCE_HA, 500.0, 0.0, phases=1))
|
||||
_r2 = _meter_row()
|
||||
check(f"right after a start, before the first meter reading and inside its "
|
||||
f"limit, the meter row is amber and waits, not red at 0 s ({_r0})",
|
||||
_r0["warn"] and not _r0["ok"]
|
||||
and _r0["text"] == "Meter: waiting for the first reading, limit 30 "
|
||||
"seconds")
|
||||
check(f"...past the limit with still no reading it is red, as before ({_r1})",
|
||||
not _r1["ok"] and not _r1["warn"]
|
||||
and _r1["text"].startswith("Meter: no reading for 31 seconds"))
|
||||
check(f"...and a reading makes it green ({_r2['text']!r})",
|
||||
_r2["ok"] and _r2["text"].startswith("Meter: 500 W"))
|
||||
|
||||
_c.auto = True
|
||||
_c.p1_enabled = False
|
||||
asyncio.run(_c.cycle())
|
||||
_w0 = _c.why_words
|
||||
_c._why_waiting_since -= _td(seconds=7)
|
||||
_w7 = _c.why_words
|
||||
check(f"'A reading is missing for N seconds' counts while control waits, "
|
||||
f"instead of the age the last cycle saw ({_w0!r} -> {_w7!r})",
|
||||
_w0 == "A reading is missing for 0 seconds, control waits"
|
||||
and _w7 == "A reading is missing for 7 seconds, control waits")
|
||||
_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")
|
||||
|
||||
print()
|
||||
if fails:
|
||||
print(f"{len(fails)} FAILED")
|
||||
|
||||
Reference in New Issue
Block a user