Real-time integration logs for a device

[balloob]

Context

When things go wrong, it's hard to sometimes see what is going on. The best bet is to look if an exception is logged. If that's not the case, the second best option is to look at the debug logs of an integration and then reproduce the broken behavior. To get to the logs, however, is a pain. It requires knowledge of the integration to inspect, the logger integration and how to access it all.

We've worked on this in the past, and each integration already specifies loggers in their manifest that are used for logging data.

In some cases, the integration could also be able to provide their own logs that are interesting for the user. For example, an ESPHome device could stream the logs of what is happening on the actual device.

Being able to see real-time what is happening on the ESPHome device and the ESPHome integration would be a powerful tool to self-help, or be helped to track down issues.

Proposal

We add a new websocket API that allows the frontend to subscribe to logs from a specific config entry + device combo

An integration will add a logger platform with a new method. This is called when the user requests logs for a device and is provided with a callback method to sent logs to the frontend. The method has to return a function when the logging has to be stopped.

async def async_subscribe_device_logs(
    hass: HomeAssistant,
    log_messages: Callable[[list[LogMessage]], None],
    config_entry: ConfigEntry,
    device_id: str
) -> Callable[[], None]

It is up to an integration to subscribe to device specific logs and pass them to log_messages. Log messages is a callback function. The returned unsubscribe function is also a callback function.

Consequences

It will be a lot easier to help people track down issues. We can ask people with problems to download the logs and attach them to issues (the debug logs might be too revealling, but device logs can be more suitable).

[frenck]

We add a new websocket API that allows the frontend to subscribe to logs for a config entry or a integration + device.

Not fully clear to me what this means.

• "for a config entry"
• "or a integration"

What is the difference between the log of an config entry and an integration?

Also: "integration + device"

does that mean those are always mixed up in the log you are looking at? e.g., If I'm viewing the log of an ESPHome device they will mix up logs from the device and HA Python?

[balloob]

I've updated the main description to address the concerns. I meant to differentiate between a config entry and only the logs for a specific device of that config entry.

[Jc2k]

Haven't tried this but could we use something like https://github.com/deansg/py-logging-context (which uses ContextVar to work in async contexts) to attach the config entry id or even the device id to log entries automatically?

When I look at HomeKit device logs they frequently include multiple unrelated devices, so it would be amazing to filter by config entry id.

Maybe we can even use the same to also be able to capture logs for a single config flow using its unique id, and offer a log download for that flow if it fails.

If I understand it correctly and we can actually automatically attach ids to log entries using ContextVars then we might not even need to rely exclusively on the manifest loggers metadata, as it would apply to any logger used within a particular contextvar context?

Another case where this might be useful might be matter and i assume zwave? Eg If we can get matter to emit sufficiently structured json logs we could potentially correlate and filter logs by their node id in the add on, and link to a device id in HA (unfortunately there aren't per device config entries there, so it would be by device and not config entry).

[rytilahti]

This proposal is about adding new WS API endpoints for front-end, so I think your comment is somewhat unrelated. Anyways, I wanted to add that there's also a more popular structlog which also supports contextvars.

That being said, maybe having a logging interface provided by the base class(es) (e.g., self.log.info("blaa")) that attaches the context could be useful for log filtering? In any case, I don't think contextvars will help to solve the issue of figuring out which upstreams loggers should be attached to the logs, as to my understanding that would require them to define the vars to use. Still, perhaps this topic is more suited for another arch discussion?

[bdraco]

For real-time logs, there are cases where we would want to see the HA logs in the same place as the remote device log since there are many cases where an event on the HA side proceeds and an event on the device side and a single combined view is key to understanding the chain of events.

The difficulty is that we don't always know which loggers to enable on the HA side. For example, suppose someone is having a problem connecting to the Bluetooth device. In that case, we need them to turn on the ESPHome loggers, the Bluetooth loggers, and the loggers for the device itself, and hopefully nothing else that generates too much noise. Knowing which loggers to turn on is a skill the user likely lacks, as it requires some basic understanding of the design and which code is run end to end.

[bdraco]

One thought is to have everything for remote devices go to a specific logger for the integration through the standard Python logging API, maybe a sub namespace of the integration. Then we can attach to that logger set and stream it to the UI. We could have specific predefined sets of loggers to turn on that a user could paste in or click through something like my

One potential implementation would be to give them a list of integrations to check off, and it starts debug logging for those integration, the websocket gets connected and sets up a new log handler to go to the websocket with a filter for just those integrations to stream in real time. At the end of the session they can download the streamed log.

Few items to work out:

Do we also save the debug session log to a file?
Do we filter the loggers on the main home-assistant.log while the session is running?
How does the debug log file get cleaned up if we save to a file and not the main log?
What names should we use for the external loggers (we want something short as possible)? integration.esphome ?