# A silent, per-operation debug “flight recorder” for custom integrations

Development
, ,
1

A silent, per-operation debug “flight recorder” for custom integrations

Every bug report starts the same way: “Please share debug logs.” Then the user has to edit logger:, restart, reproduce, and fish the relevant lines out of a home-assistant.log full of everything else — and paste back a giant blob. It’s a papercut for both sides, and the logs you get are rarely scoped to the thing that actually broke.

I built a small flight recorder for my integration to fix this, and it turned out clean enough that I think the pattern might be worth sharing (and maybe generalizing). Sharing the technique here to see how others handle this — and whether a reusable version would be welcome.

What it does:

  • Captures only my integration’s DEBUG into a bounded in-memory ring — without touching home-assistant.log. Silent by default, zero cost when off.
  • Optionally scopes the capture to one service call, so “reproduce the bug” gives you just that operation’s logs.
  • Dumps on demand to a file you can hand over.

Real before/after from my integration: a global capture of a zone-clean was a 10 MB file (mostly base64 map payloads). The same clean, scoped to the one service, was three lines:

▶▶ start_zone_clean  in={'zones': [[0.814, 0.533, 0.875, 0.594]], 'clean_times': 1, 'map_id': '6'}
   start_zone_clean complete: {'status': 'dispatched', 'zone_count': 1}
◀◀ start_zone_clean  done in 10ms  out={'status': 'dispatched', 'zone_count': 1}

The core trick: propagate = False + an INFO passthrough

The reason plain logger: <my_integration>: debug floods the main log is that DEBUG records propagate up to the root handlers. So the whole thing hinges on one property of Python logging — propagation — and re-injecting the levels you do want:

import collections, logging

class RingHandler(logging.Handler):
    def __init__(self, capacity):
        super().__init__(level=logging.DEBUG)
        self.records = collections.deque(maxlen=capacity)
    def emit(self, record):
        self.records.append(self.format(record))   # (truncate long messages here)

class PassthroughHandler(logging.Handler):
    """Re-emit INFO+ to the root handlers so normal logs still hit home-assistant.log."""
    def __init__(self):
        super().__init__(level=logging.INFO)
    def emit(self, record):
        logging.getLogger().handle(record)

def start(package_logger):
    ring, passthrough = RingHandler(3000), PassthroughHandler()
    log = logging.getLogger(package_logger)          # e.g. "custom_components.my_integration"
    prior = (log.level, log.propagate)
    log.setLevel(logging.DEBUG)
    log.propagate = False                            # <-- DEBUG never reaches the main log
    log.addHandler(ring); log.addHandler(passthrough)
    return ring, passthrough, prior                  # keep these to restore on stop

While it’s active:

  • DEBUG goes only to the ring (the main log stays clean at whatever level it’s on).
  • INFO / WARNING / ERROR still reach home-assistant.log via the passthrough — so you don’t go blind on a real error while capturing. (In my testing, a genuine “zone drawn too small” warning surfaced in the main log exactly as it should, while the DEBUG stayed silent.)

Stop removes the two handlers and restores the prior level + propagate — but only if they’re still the values it installed, so it won’t clobber a logger: change you made mid-capture.

One caveat worth stating up front: the passthrough injects INFO+ directly at the root handlers, which isn’t identical to normal propagation — handlers attached to intermediate loggers (custom_components, custom_components.<you>) are bypassed while capture is active. Ordinary installs don’t have any, but the honest description is: DEBUG is diverted into the recorder; INFO+ continues through the root handlers, not the full ancestry.

Two small refinements that mattered in practice:

  • Truncate individual records. A single line can be a base64 map image or a full state dict. Capping each message (I use ~2 kB, eliding the rest) is what actually killed the multi-MB dumps.
  • Bounded ring. deque(maxlen=…) caps memory; an optional “stop when full” freezes at N instead of evicting, and an optional timer auto-stops after N minutes.
  • Redact + write atomically. Secrets (token / password / api_key / bearer / …) are masked before a record is stored, and the dump is written to a temp file then renamed — so a shared file doesn’t leak, and a reader can’t catch a half-written one.

Per-operation scoping: a @debug_traceable decorator

The bigger win is scoping capture to one service call. A decorator flags a handler and brackets it; when a capture is armed for that service, the ring records only while inside its span:

@debug_traceable("start_zone_clean")
async def start_zone_clean(call):
    ...

Armed with services=["start_zone_clean"], the ring records only between the ▶▶/◀◀ markers of that call — so you reproduce the one action and get exactly its logs (and everything it triggered), not the surrounding poll spam. That’s the 10 MB → 3 lines above.

Scoping is a ContextVar set on entry, not a global flag — so only this operation’s async context is recorded, and unrelated concurrent work (polling, another service) stays out even if it overlaps a slow call. A useful side effect: asyncio copies the context into tasks created inside the handler, so fire-and-forget follow-through keeps recording under the same operation — the dispatch that finishes after the handler returns still lands in the trace. (Executor-thread logs are the exception; contextvars don’t cross into the thread pool.)

Packaging: a drop-in

I ended up making it a single integration-agnostic file. Adopting it is:

from .debug_capture import register_debug_services
register_debug_services(hass, domain=DOMAIN)     # registers 4 services; package_logger
                                                 # defaults to custom_components.<domain>

…plus copying four debug_capture_* service blocks into services.yaml, and optionally decorating noisy handlers. There’s also an optional switch (on = start, off = auto-write the dump) and a select to pick the scope. The switch defaults to capturing all flagged services at once, so a workflow of handlers that fire together is all captured with no picking; the select narrows to one service, one area, or a full unfiltered capture. A toggle + dropdown instead of Dev Tools calls.

Where this sits — a third tier, not a replacement

Three logging tiers now, and each is genuinely the best tool for a different job — this isn’t “replace the built-in”:

Tier Best when Its edge
Full home-assistant.log you don’t yet know what you’re looking for broad — everything, always on
Built-in per-integration debug you want the whole session, including startup retroactive — it’s running before your own service even loads, so it catches setup/boot-time issues the recorder can’t
The flight recorder you know the operation and want only it the magnifying glass — silent, scoped, three lines — but only once it’s armed (it can’t see boot)

So they’re complementary. The built-in’s retroactivity is a real strength: it captures what happened before anything of mine is even running. The recorder is deliberately the opposite — nothing until you point it at one operation. I keep both.

The question for the room

HA has a built-in “enable debug logging” toggle per integration, and it’s genuinely useful — I use it. But it’s worth being precise about what it does, because I checked. It doesn’t capture a window: it flips your integration’s loggers to DEBUG in the always-on home-assistant.log, and the file it hands you on disable is the whole log file. I turned it on for about five seconds — the download was 2.8 MB, 433 lines, spanning 67 minutes back to startup, every other component in it, with my integration’s 258 DEBUG lines (several multi-kilobyte base64) baked permanently into that shared log. It’s retroactive by nature, and not scoped to the operation — or even to the integration. The recorder’s scoped capture of the same operation was three lines.

So I’m curious:

  1. How do you all handle “please share debug logs” today — is the noise/flooding a problem for you, or am I over-solving it?
  2. Is the silent (propagate-off) + per-operation behavior worth a shared helper rather than everyone re-inventing it? It really factors into three primitives that could each stand alone — a bounded, redactable logging handler; a temporary logger-routing context manager; and a ContextVar operation-correlation gate — with the four services + switch/select being more of a reference implementation on top. Would the primitives be welcome in homeassistant.helpers, or is that too niche?
  3. Any footguns I’m missing with the propagate=False + passthrough approach (e.g. filters/handlers people put mid-tree)?

Gist for anyone who is intrested

1 Like