Skip to content

Commit 6172dd0

Browse files
fix(addon): honor web-UI log level; arm kill-signal diagnostics at DEBUG; plumb journald log window (#1734)
* fix(addon): honor web-UI log level in addon logs; arm kill-signal diagnostics at DEBUG The addon's start.py hardcoded logging.basicConfig(level=INFO) and never re-applied the effective settings, so the web Settings UI "Log level" advanced setting could not change addon log verbosity — reporters asked to enable debug logging saw INFO-only output (surfaced in #1721). - start.py now re-applies the resolved settings.log_level (including the /data/feature_flags.json override) to the root logger after ha_mcp becomes importable, and emits a DEBUG-level canary line so logs prove the level took effect. - The confusing "Advanced debug logging" addon toggle is removed from both addon flavors; kill-signal diagnostics now arm whenever the effective log level is DEBUG. Supervisor ignores the stale key in existing options.json with a warning (supervisor/apps/options.py), so no migration shim is needed. - Container regression test boots the addon with a DEBUG override file and asserts the canary + diagnostics arming; unit tests cover the level-resolution fallback paths. - Docker/stdio/pip modes are untouched: changes are confined to the addon entrypoint, addon config schemas, and log-string renames in kill_signal_diagnostics.py. * test(e2e): verify web-UI DEBUG log level end-to-end in the inaddon lane Full user journey against the real dev addon inside HAOS: POST log_level=DEBUG to the settings advanced API, self-restart via hassio.addon_restart (severed response tolerated), then assert the DEBUG canary + kill-signal diagnostics arming lines in the addon's own container log via ha_get_logs(source=supervisor). Restores INFO after. Every MCP call uses a fresh streamable-HTTP client so the test never depends on a connection surviving its own server's restart. * style: ruff format new test files * test: fix CodeQL mixed-import alert; bump per-lane skip ceilings for new inaddon test monkeypatch.setattr takes the dotted-path string form, removing the import-vs-import-from mix CodeQL flagged. Container and haos lanes each gain one skip from the new @inaddon_only debug-log-level e2e test. * test(e2e): narrow polling excepts to transient-error tuple per styleguide Broad 'except Exception' in the restart-recovery loop could swallow real bugs (TypeError/KeyError/AssertionError) and retry to timeout. Use wait_helpers' _POLLING_TRANSIENT_ERRORS plus httpx.HTTPError for the transport dying mid-restart; bugs now propagate. * fix(addon): warn loudly when log-level resolution fails; assert INFO path arms nothing Review findings: the settings-resolution fallback returned INFO with zero operator signal — recreating the silent-no-op class this PR kills; now logs a WARNING with the exception. The default-INFO container test now asserts the DEBUG canary and kill-signal arming/install lines are ABSENT, guarding the arming gate against regressing to always-on. * docs: fix stale kill-signal banner and two inaccurate start.py comments Review findings: the signal-dump banner still named the removed 'Advanced debug logging' toggle; the resolve_effective_log_level docstring claimed Settings construction requires the HA env vars (it doesn't — the real hazard is get_global_settings caching a singleton with placeholder values); 'importable' meant 'imported' in two spots. * test(e2e): fix ha_call_service args in self-restart; require observed down-window The restart call passed service='hassio.addon_restart' instead of domain='hassio' + service='addon_restart', so ha_call_service raised VALIDATION_FAILED — which the severed-call except swallowed as 'expected', the addon never restarted, and the canary assertion failed with a misleading message (first inaddon CI run). Args now match test_addon_lifecycle's _addon_action, and the helper requires observing the HTTP endpoint go DOWN before polling recovery, so any silently failed restart fails fast with the real cause. * test(e2e): rebuild self-restart on the settings /restart endpoint + poll-until-canary Review findings (code-reviewer agent): the hand-rolled GET liveness probe fights FastMCP's transport (documented GET-RST behavior in wait_for_addon_mcp_ready), and a single-shot limit=400 log tail could scroll the boot markers out under DEBUG verbosity. Now mirrors the proven readonly-mode machinery: settings /restart endpoint (200 flushes before the background bounce), wait_for_addon_mcp_ready + fresh client per poll round, poll-until-all-lines with limit=2000 as the positive restart-took-effect signal, retried INFO restore, and shared mcp_client warm-up so later tests on the worker get a live session. Container test now polls briefly for the install-thread's confirmation line instead of racing it. * test(e2e): raise AssertionError instead of pytest.fail in poll helper CodeQL py/mixed-returns: it can't see pytest.fail is NoReturn, so the helper looked like it mixed explicit and implicit returns. Matches the readonly-mode test's raise-AssertionError shape. * test(e2e): assert DEBUG records (scroll-proof) instead of one-shot boot lines; surface backup failure event Round-2 inaddon CI showed why boot-line assertions can't work through Supervisor's /addons/<slug>/logs: it serves only a bounded recent window, and at DEBUG verbosity the start.py boot lines scroll out within seconds. DEBUG-prefixed records regenerate with every request, so their presence (vs a zero-DEBUG baseline asserted pre-restart) is a deterministic proof the web-UI level reached the root logger. The boot lines stay covered by the testcontainer tests, which read complete docker logs. Boy-scout: ha_manage_backup's create-failure paths now include HA's last_action_event in the error context — CI arm failures previously read 'Backup creation failed: Backup creation failed' with nothing to diagnose. * fix: plumb journald ?lines= window through supervisor log fetches ha_get_logs(source=supervisor|system_service) silently returned at most Supervisor's 100-line default window (DEFAULT_LINES in supervisor/api/const.py) regardless of the tool's limit — found via #1721's inaddon e2e, where DEBUG-verbosity boot lines scrolled out of the window within seconds. get_addon_logs and _get_system_service_logs now forward ?lines= on both the Supervisor-direct path (parsed natively by supervisor/api/host.py) and the HA-Core hassio proxy (which forwards request.query upstream). The tool wrappers size the window to the caller's limit, expanding to SUPERVISOR_SEARCH_WINDOW_LINES (2000) when a search filter needs history behind it. The inaddon e2e now asserts the complete proof set: zero-DEBUG INFO baseline, live DEBUG records after the web-UI DEBUG + self-restart, and each start.py boot line (canary, kill-signal arming, install confirmation) located via search over the expanded window — which exercises the new plumbing end-to-end on a real Supervisor. * test(e2e): route supervisor mock on bare path, not path+query The mock matched routes against self.path, which includes the query string, so the new ?lines= window param 404'd every mocked /logs call ('Unknown path: /audio/logs?lines=100'). Real Supervisor's aiohttp router matches the bare path and the handler parses the query — mirror that with urlsplit().path. * test(e2e): drop AssertionError from the proof-polling transient tuple Review (Patch76): AssertionError is a must-propagate bug class per the styleguide section the tuple's own comment cites. The proof-polling loop now propagates it; the finally-block restore/warm loops keep retrying on it via a separate _RESTORE_TRANSIENT tuple, where a 5xx mid-restart legitimately trips the status asserts (same shape as test_readonly_mode's restore set). --------- Co-authored-by: kingpanther13 <kingpanther13@users.noreply.github.com>
1 parent 69bc4d7 commit 6172dd0

17 files changed

Lines changed: 698 additions & 59 deletions

File tree

homeassistant-addon-dev/config.yaml

Lines changed: 0 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -86,6 +86,5 @@ schema:
8686
disabled_tools: str?
8787
pinned_tools: str?
8888
verify_ssl: bool?
89-
advanced_debug_logging: bool?
9089
ports:
9190
9583/tcp: 9583

homeassistant-addon-dev/translations/en.yaml

Lines changed: 0 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -261,10 +261,3 @@ configuration:
261261
certificate or hostname mismatch. Disabling weakens transport
262262
security — leave on unless you know you need it. Requires restart
263263
to take effect.
264-
advanced_debug_logging:
265-
name: Advanced debug logging
266-
description: >-
267-
Captures extra diagnostic info on kill/shutdown — sender PID
268-
and memory state. Useful when reporting unexplained add-on
269-
stops or crash loops. Off by default to keep logs concise.
270-
Requires restart to take effect.

homeassistant-addon/config.yaml

Lines changed: 0 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -70,7 +70,6 @@ schema:
7070
auto_backup_throttle_minutes: int(0,1440)?
7171
auto_backup_retain_per_entity: int(1,10000)?
7272
verify_ssl: bool?
73-
advanced_debug_logging: bool?
7473
# Add-on exposes HTTP port for MCP communication (fixed internal port)
7574
ports:
7675
9583/tcp: 9583

homeassistant-addon/start.py

Lines changed: 51 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -202,6 +202,40 @@ def resolve_bool_option(config: dict[str, Any], key: str, default: bool) -> bool
202202
return default
203203

204204

205+
def resolve_effective_log_level() -> int:
206+
"""Return the root log level from ha-mcp's effective settings.
207+
208+
Reads the web Settings UI "Log level" advanced setting (persisted
209+
under ``/data`` and applied by ``get_global_settings()``) so the
210+
addon log actually honors it — ``main()`` configures logging before
211+
ha-mcp is imported, so it can only hardcode INFO at that point and
212+
must re-apply the real level after the import (#1721).
213+
214+
Call only after ``main()`` has exported ``HOMEASSISTANT_URL`` /
215+
``HOMEASSISTANT_TOKEN``: ``get_global_settings()`` caches a
216+
singleton, so an earlier call would pin placeholder connection
217+
settings for the process. Any failure falls back to INFO — logging
218+
config must never block addon startup.
219+
"""
220+
import logging
221+
222+
try:
223+
from ha_mcp.config import get_global_settings
224+
225+
return getattr(logging, get_global_settings().log_level, logging.INFO)
226+
except Exception as e:
227+
# Loud fallback: without this line, a user who set DEBUG in the
228+
# web UI can't tell "I'm on INFO" from "my DEBUG request crashed
229+
# on load" — the same silent-no-op class this fix exists to kill.
230+
# print-based so it reaches the addon log regardless of logging
231+
# state.
232+
log_warning(
233+
f"Could not resolve effective log level from settings; "
234+
f"defaulting to INFO (web-UI Log level not applied): {e!r}"
235+
)
236+
return logging.INFO
237+
238+
205239
_DEV_ADDON_BETA_KEYS = (
206240
"enable_yaml_config_editing",
207241
# Per-key sub-gates of enable_yaml_config_editing. Kept in lockstep
@@ -353,7 +387,6 @@ def main() -> int:
353387
disabled_tools_raw = "" # default
354388
pinned_tools_raw = "" # default
355389
verify_ssl = True # default
356-
advanced_debug_logging = False # default
357390

358391
if config_file.exists():
359392
try:
@@ -493,9 +526,6 @@ def main() -> int:
493526
raw_pinned = config.get("pinned_tools", "")
494527
pinned_tools_raw = raw_pinned if isinstance(raw_pinned, str) else ""
495528
verify_ssl = resolve_bool_option(config, "verify_ssl", True)
496-
advanced_debug_logging = resolve_bool_option(
497-
config, "advanced_debug_logging", False
498-
)
499529
except Exception as e:
500530
log_error(f"Failed to read config: {e}, using defaults")
501531
# Persistent "you lost your features" line so an operator
@@ -528,7 +558,6 @@ def main() -> int:
528558

529559
log_info(f"Backup hint mode: {backup_hint}")
530560
log_info(f"Verify SSL: {verify_ssl}")
531-
log_info(f"Advanced debug logging: {advanced_debug_logging}")
532561

533562
# Set up environment for ha-mcp
534563
os.environ["HOMEASSISTANT_URL"] = "http://supervisor/core"
@@ -711,7 +740,22 @@ def main() -> int:
711740
# FastMCP surfaces its update notice in these same startup logs.
712741
_log_startup_version()
713742

714-
if advanced_debug_logging:
743+
# Re-apply the effective log level now that ha_mcp is imported —
744+
# the basicConfig above could only hardcode INFO. Without this, the
745+
# web Settings UI "Log level" setting never reaches the addon log
746+
# (#1721).
747+
effective_log_level = resolve_effective_log_level()
748+
logging.getLogger().setLevel(effective_log_level)
749+
# Proof-of-application canary: emitted through the logging system
750+
# (not print), so it reaches the addon log ONLY when the DEBUG level
751+
# actually took effect. Support threads can key on this line to tell
752+
# "user set DEBUG" apart from "DEBUG is really active".
753+
logging.getLogger("addon_start").debug(
754+
"Debug logging active (log_level applied from settings)"
755+
)
756+
757+
if effective_log_level == logging.DEBUG:
758+
log_info("Debug log level active — arming kill-signal diagnostics")
715759
# Defers SA_SIGINFO install until uvicorn's capture_signals has
716760
# run. Otherwise uvicorn's signal.signal() call would overwrite
717761
# our handler before any signal arrived.
@@ -723,7 +767,7 @@ def main() -> int:
723767

724768
schedule_install_after_uvicorn()
725769
except Exception as e:
726-
log_error(f"advanced_debug_logging install failed: {e!r}; continuing")
770+
log_error(f"kill-signal diagnostics install failed: {e!r}; continuing")
727771

728772
register_browser_landing(mcp, secret_path)
729773
# Mount settings UI routes both at root (for HA ingress proxy) and

homeassistant-addon/translations/en.yaml

Lines changed: 0 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -99,13 +99,6 @@ configuration:
9999
certificate or hostname mismatch. Disabling weakens transport
100100
security — leave on unless you know you need it. Requires restart
101101
to take effect.
102-
advanced_debug_logging:
103-
name: Advanced debug logging
104-
description: >-
105-
Captures extra diagnostic info on kill/shutdown — sender PID
106-
and memory state. Useful when reporting unexplained add-on
107-
stops or crash loops. Off by default to keep logs concise.
108-
Requires restart to take effect.
109102
tool_search_max_results:
110103
name: Tool search max results
111104
description: >-

src/ha_mcp/client/rest_client.py

Lines changed: 28 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -606,7 +606,7 @@ async def _is_supervised_install(self) -> bool:
606606
self._supervised_detected = is_supervised
607607
return is_supervised
608608

609-
async def get_addon_logs(self, slug: str) -> str:
609+
async def get_addon_logs(self, slug: str, lines: int | None = None) -> str:
610610
"""Fetch an add-on's container logs.
611611
612612
Branch on ``is_running_in_addon()`` (which keys off ``SUPERVISOR_TOKEN``
@@ -621,6 +621,15 @@ async def get_addon_logs(self, slug: str) -> str:
621621
HA URL), falls back to the HA Core proxy path. That path requires an
622622
admin LLA but works fine when not invoked from the add-on container.
623623
624+
``lines`` sets the journald window Supervisor serves via its
625+
``?lines=`` query param (supervisor/api/host.py). Without it,
626+
Supervisor returns only its default window (``DEFAULT_LINES = 100``
627+
in supervisor/api/const.py) — which silently capped every larger
628+
caller-side limit before this param existed. Both branches carry
629+
it: the direct endpoint parses the query natively, and HA Core's
630+
hassio proxy forwards ``request.query`` upstream
631+
(homeassistant/components/hassio/http.py).
632+
624633
Both branches return ``text/plain`` log content.
625634
626635
Raises:
@@ -633,17 +642,18 @@ async def get_addon_logs(self, slug: str) -> str:
633642
HomeAssistantConnectionError: Network, timeout, or transport error.
634643
"""
635644
if is_running_in_addon():
636-
return await self._get_addon_logs_via_supervisor(slug)
645+
return await self._get_addon_logs_via_supervisor(slug, lines=lines)
637646

638647
logger.debug(f"Fetching addon logs for slug={slug} via HA Core proxy")
639648
response = await self._raw_request(
640649
"GET",
641650
f"/hassio/addons/{slug}/logs",
642651
headers={"Accept": "text/plain"},
652+
params={"lines": lines} if lines is not None else None,
643653
)
644654
return response.text
645655

646-
async def _supervisor_logs_get(self, path: str) -> str:
656+
async def _supervisor_logs_get(self, path: str, lines: int | None = None) -> str:
647657
"""Fetch ``text/plain`` logs from a Supervisor REST endpoint.
648658
649659
``path`` is everything between ``http://supervisor/`` and ``/logs``:
@@ -652,6 +662,9 @@ async def _supervisor_logs_get(self, path: str) -> str:
652662
- ``"<service>"`` (where service ∈ {supervisor, host, core, dns, audio,
653663
cli, multicast, observer}) for system-service logs
654664
665+
``lines`` maps to the endpoint's ``?lines=`` journald-window query
666+
param; omitted → Supervisor's 100-line default window.
667+
655668
Bypasses ``HomeAssistantClient.httpx_client`` because the Supervisor
656669
endpoint uses a different base URL (``http://supervisor``) and a
657670
different token (``SUPERVISOR_TOKEN``) than HA Core REST. Both
@@ -681,9 +694,10 @@ async def _supervisor_logs_get(self, path: str) -> str:
681694

682695
relative_path = f"/{path}/logs"
683696
logger.debug(
684-
"Fetching %s%s via Supervisor direct",
697+
"Fetching %s%s via Supervisor direct (lines=%s)",
685698
get_supervisor_base_url(),
686699
relative_path,
700+
lines,
687701
)
688702

689703
try:
@@ -694,6 +708,7 @@ async def _supervisor_logs_get(self, path: str) -> str:
694708
response = await client.get(
695709
relative_path,
696710
headers={"Accept": "text/plain"},
711+
params={"lines": lines} if lines is not None else None,
697712
)
698713
except httpx.TimeoutException as e:
699714
raise HomeAssistantConnectionError(
@@ -753,7 +768,9 @@ async def _supervisor_logs_get(self, path: str) -> str:
753768
)
754769
return response.text
755770

756-
async def _get_addon_logs_via_supervisor(self, slug: str) -> str:
771+
async def _get_addon_logs_via_supervisor(
772+
self, slug: str, lines: int | None = None
773+
) -> str:
757774
"""Fetch add-on container logs directly from Supervisor's REST API.
758775
759776
Distinct from ``tools_bug_report._fetch_addon_logs``: that helper is
@@ -766,9 +783,11 @@ async def _get_addon_logs_via_supervisor(self, slug: str) -> str:
766783
Delegates to ``_supervisor_logs_get`` so error handling stays in
767784
lockstep with ``_get_system_service_logs``.
768785
"""
769-
return await self._supervisor_logs_get(f"addons/{slug}")
786+
return await self._supervisor_logs_get(f"addons/{slug}", lines=lines)
770787

771-
async def _get_system_service_logs(self, service: str) -> str:
788+
async def _get_system_service_logs(
789+
self, service: str, lines: int | None = None
790+
) -> str:
772791
"""Fetch HA system-service logs.
773792
774793
``service`` must be one of the eight Supervisor-managed services:
@@ -796,13 +815,14 @@ async def _get_system_service_logs(self, service: str) -> str:
796815
logs) call kept working through its own Core-proxy fallback.
797816
"""
798817
if is_running_in_addon():
799-
return await self._supervisor_logs_get(service)
818+
return await self._supervisor_logs_get(service, lines=lines)
800819

801820
logger.debug(f"Fetching {service} logs via HA Core proxy")
802821
response = await self._raw_request(
803822
"GET",
804823
f"/hassio/{service}/logs",
805824
headers={"Accept": "text/plain"},
825+
params={"lines": lines} if lines is not None else None,
806826
)
807827
return response.text
808828

src/ha_mcp/tools/backup.py

Lines changed: 14 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -329,11 +329,19 @@ async def _poll_backup_completion(
329329
)
330330

331331
if event_state == "failed":
332+
# Surface the failure event verbatim — HA's failed event
333+
# carries the cause (e.g. another backup already in
334+
# progress), and dropping it left CI failures reading
335+
# "Backup creation failed: Backup creation failed" with
336+
# nothing to diagnose.
332337
raise_tool_error(
333338
create_error_response(
334339
ErrorCode.SERVICE_CALL_FAILED,
335340
"Backup creation failed",
336-
context={"backup_job_id": backup_job_id},
341+
context={
342+
"backup_job_id": backup_job_id,
343+
"last_action_event": last_event,
344+
},
337345
)
338346
)
339347

@@ -410,7 +418,11 @@ async def _poll_backup_completion(
410418
create_error_response(
411419
ErrorCode.SERVICE_CALL_FAILED,
412420
"Backup creation failed (observed at post-timeout lookup)",
413-
context={"backup_job_id": backup_job_id, "name": name},
421+
context={
422+
"backup_job_id": backup_job_id,
423+
"name": name,
424+
"last_action_event": last_event,
425+
},
414426
)
415427
)
416428
if state != "idle":

src/ha_mcp/tools/tools_utility.py

Lines changed: 25 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -53,6 +53,11 @@
5353

5454
DEFAULT_LIMIT = 50
5555
DEFAULT_LOG_LIMIT = 100
56+
# Journald window to request from Supervisor when a search filter is
57+
# active: matches are found within the fetched window only, so a
58+
# search over the caller's (often small) limit needs more history
59+
# behind it than the limit itself.
60+
SUPERVISOR_SEARCH_WINDOW_LINES = 2000
5661
MAX_LIMIT = 500
5762

5863
# Regex to match log level at the start of a log line
@@ -752,8 +757,18 @@ async def _get_supervisor_log(
752757
limit, default=DEFAULT_LOG_LIMIT, suggestion_example="100"
753758
)
754759

760+
# Request a journald window sized to the caller's limit —
761+
# Supervisor's /logs endpoints default to their last-100-lines
762+
# window, which silently capped any larger limit before ?lines=
763+
# was plumbed through (found via #1721's e2e).
764+
fetch_lines = (
765+
max(effective_limit, SUPERVISOR_SEARCH_WINDOW_LINES)
766+
if search
767+
else effective_limit
768+
)
769+
755770
try:
756-
log_text = await self._client.get_addon_logs(slug)
771+
log_text = await self._client.get_addon_logs(slug, lines=fetch_lines)
757772

758773
lines = log_text.splitlines() if log_text else []
759774

@@ -892,8 +907,16 @@ async def _get_system_service_log(
892907
limit, default=DEFAULT_LOG_LIMIT, suggestion_example="100"
893908
)
894909

910+
fetch_lines = (
911+
max(effective_limit, SUPERVISOR_SEARCH_WINDOW_LINES)
912+
if search
913+
else effective_limit
914+
)
915+
895916
try:
896-
log_text = await self._client._get_system_service_logs(service)
917+
log_text = await self._client._get_system_service_logs(
918+
service, lines=fetch_lines
919+
)
897920

898921
lines = log_text.splitlines() if log_text else []
899922

0 commit comments

Comments
 (0)