Feature Request: service call contexts

[dlashua]

Right now, when a pyscript performs a service call, the LogBook has an entry like this:

HallDown Occupied turned off by service input_boolean.turn_off

However, when Home Assistant Automations perform an action, the LogBook looks like this:

 halldown_overhead turned off by halldown_occupied_off 

It does this through a context object:

        service_task = self._hass.async_create_task(
            self._hass.services.async_call(
                domain,
                service,
                service_data,
                blocking=True,
                context=self._context,
                limit=limit,
            )
        )

pyscript can create one of these with something like:

from homeassistant.core import Context

# context comes from the state_trigger, time_trigger, etc
parent_id = None if context is None else context.id
new_context = Context(parent_id=parent_id)

I can't find a lot of documentation on how to create context and name the pieces so they show up well in LogBook, but I think this is a start anyway. I think even this small bit of code would make the logbook show that, for instance, the "binary_sensor.dark" in my @state_trigger is what called input_boolean.turn_on. And, even this, is better than what we have now.

The final bit would be to get LogBook to show that binary_sensor.dark activated my pyscript called "halldown_at_dark", and that "halldown_at_dark" is what called input_boolean.turn_on.

[dlashua]

For more "context" to what this whole "context" thing is about (ha!)...

The LogBook is the go-to tool to answer the question "why are these lights on???" and aids in debugging automations. From there I can follow the "traceback" of events.

Maybe the light was turned on in the UI: light was turned on by User (daniel)

Or a service call without any additional context (like pyscript is now): light was turned on by service light.turn_on

Or an automation: light was turned on by name_of_automation_here

And finally, with no context at all (i.e. the light turned on by itself, usually because of local manual control, manipulation via the native app for that device, etc, etc) simply: light was turned on.

For things like automations that turn on a light, you can then follow further to see what triggered the automation. And, if needed, follow that back to see what triggered it, etc, etc.

I ran into this today because I was trying to answer that very question: "why is this light on??". That's when I noticed it was due to "service light.turn_on" and realized it was likely pyscript, dug around for a bit for all pyscripts that might effect that entity_id, found the culprit and fixed the problem. Having it give some indication that "pyscript.file.halldown.halldown_at_dark" was where the call came from would narrow that down much quicker.

[dlashua]

I've made some progress on this...

Home Assistant's logbook stuff, especially in regard to how to annotate a state_change event, is largely undocumented (from what I can find) and much of it is hardcoded to expect Home Assistant built-in automations and scripts to have made the service calls.

But, it's a start.

[dlashua]

In my code to test how this feature would work, I'm manually firing the event Home Assistant needs to get this correctly in the logbook:

@state_trigger('input_boolean.test_1 == "on"')
def follow_on(**params):
    event_notify_trigger(params)
    log.info(params)
    input_boolean.turn_on(entity_id="input_boolean.test_2", context=params["context"])


@state_trigger('input_boolean.test_1 == "off"')
def follow_off(**params):
    event_notify_trigger(params)
    log.info(params)
    input_boolean.turn_off(entity_id="input_boolean.test_2", context=params["context"])


def event_notify_trigger(params):
    data = {}
    data["name"] = f"pyscript module {__name__}"
    data["entity_id"] = f"pyscript.pyscript_module_{__name__}"
    data["source"] = f"state of {params['var_name']} == {params['value']}"
    data["context"] = params["context"]
    event.fire("pyscript_running", **data)

I can't seem to find where in the pyscript code I should fire the event so that it happens just before a pyscript function is run and has access to the parameters that will be passed to the pyscript function. The code you see above is only for state_trigger. I'll need to do this for all three trigger types. @craigbarratt, Can you point me in the right direction?

[dlashua]

The second piece to the puzzle is storing a context to be sent in Function.service_call and Function.event_fire (maybe more). The context needs to be generated just before the pyscript method is called (likely in the same place I should fire the event from) and then held on to and passed in to hass.bus.async_fire and hass.services.async_call. The exact same context would be passed to every async_fire and async_call during a specific execution of the pyscript function.

I'm doing it in the above code by passing the context to the user and having the user pass it back. But, that's cumbersome and ultimately makes this not worth it.

It's simple to create. I'm generating it in state_changed like this:

    async def state_changed(event):
        var_name = event.data["entity_id"]
        # attr = event.data["new_state"].attributes
        if "new_state" not in event.data or event.data["new_state"] is None:
            # state variable has been deleted
            new_val = None
        else:
            new_val = event.data["new_state"].state
        old_val = event.data["old_state"].state if event.data["old_state"] else None
        new_vars = {var_name: new_val, f"{var_name}.old": old_val}
        context = Context(parent_id=event.context.id)
        func_args = {
            "trigger_type": "state",
            "var_name": var_name,
            "value": new_val,
            "old_value": old_val,
            "context": context,
        }
        await State.update(new_vars, func_args)

[craigbarratt]

Thanks for helping me learn about logbook and contexts. I've starting to look at logbook and recorder. Yes, it would be great to have more useful logbook information. I can see that recorder listens to all events, discards excluded ones, and saves the others.

One minor question: I can't yet see how the string you generate in your example:

data["source"] = f"state of {params['var_name']} == {params['value']}"

ends up in the logbook. I don't yet see how an informative string in logbook is delivered via the context.

Here are some initial thoughts. For HASS -> pyscript, it looks like your code fragment above is sending the inbound context for a state change as a variable to the trigger function. Similar things could be done for events and service calls. But I'm not sure how the user-level pyscript code would use that information.

For pyscript -> logbook, we can generate a reason for a trigger, and perhaps the function name being triggered, in the various cases in trigger.py (eg, here), perhaps including the inbound context from the state change or event captured above. A useful str message could be stored by ast_ctx, since there's one of those for every trigger and executing task. Then a subsequent service call, event fire or entity setting could use that reason to create or augment the context that is provided to the corresponding HASS functions.

[dlashua]

Here's what I've learned.

The scenario: User turns on input_boolean.a. pyscript sees this and turns on input_boolean.b.

Here's what we need to do.

When User turns on "A", HASS sends a state changed event that has a context with a unique id (1), and a user id. This happens already.

Before running the trigger function, Pyscript should then send an event (pyscript_running or whatever) that looks like event_notify_trigger in my example. When it sends that event it should include a context with a new unique id (2). This is generated by HASS. However, when the context is created, parent_id should be set to 1. I should also note that the context doesn't get sent as part of the "event_data". Instead, it looks like this:

# function.py
    @classmethod
    async def event_fire(cls, event_type, **kwargs):
        """Implement event.fire()."""

        if "context" in kwargs:
            context = kwargs['context']
            del kwargs['context']
        else:
            context = Context()

        cls.hass.bus.async_fire(event_type, kwargs, context=context)

Then the pyscript runs and it turns on "B". When it issues the service call to turn this on, it should include the SAME context that was included in async_fire. Alternately, it can send a different context, however, the parent_id must be the same as the one from the original state changed event.

The final piece of the puzzle is how to make the logbook show that data. When the log book loads, if it sees an event that has been registered, it calls a function to help display the event. To do that, inside of custom_components/pyscript along side __init__.py and function.py, we have to include a file that looks like this:

"""Describe logbook events."""
from homeassistant.core import callback

from .const import DOMAIN

import logging

_LOGGER = logging.getLogger(__name__)

@callback
def async_describe_events(hass, async_describe_event):  # type: ignore
    """Describe logbook events."""

    @callback
    def async_describe_logbook_event(event):  # type: ignore
        """Describe a logbook event."""
        data = event.data
        message = "has been triggered"
        if "source" in data:
            message = f'{message} by {data["source"]}'
        return {
            "name": data.get('name'),
            "message": message,
            "source": data.get('source'),
            "entity_id": data.get('entity_id'),
        }

    async_describe_event(DOMAIN, "pyscript_running", async_describe_logbook_event)

So while there are a few ways to do it. I think the best way is that when pyscript is about to call a pyscript function it should generate a new context with parent_id of the incoming context (except time triggers, they won't have a parent). Then it should hold on to that context and send the same one with every other service call, event fire, or state set during that particular call to the function.

In the return data for async_describe_logbook_event, it seems that source is thrown away (or, at least not displayed). entity_id has to LOOK like an entity id (domain.name) however, it doesn't have to be a real entity. message is what is displayed in the logbook. Without an entity_id, the subsequent service calls and event fires won't appear tied to this event in the logbook. So it has to be included even though we don't have a REAL entity for every pyscript function.

[Chaotic]

So reading through this and being reminded how much python / homeassistant I don't know.

Would it be possible to get the context in a event trigger inside pyscript? I'm looking into NFC tags now and one piece of the context is user_id and I'd love to have that so I can know which cell phone (each one has its own HA user) scanned the tag so I can alter the automation.

[dlashua]

@Chaotic this is the first legit use case I've seen for providing context to the pyscript method.

Despite the fact that we haven't worked the rest of this out yet, that piece is easy. I'll work on a PR now.

[craigbarratt]

Sorry, I'm just about to commit those changes (inbound context provided to trigger function)... should be ready in a few mins....

[craigbarratt]

I just pushed d0745ea which provides context to state, service and event trigger functions (minimal testing). It also adds context as an optional argument for outbound service calls (untested). context contains user_id, parent_id and id. This is the first step in having what will be the parent context for the context we sent to logbook.

Use the master version if you want to test this.

[dlashua]

Can we do this bit ...

d0745ea#diff-35f81a73bbe8c0273529be5bdce6d1fed5f3efd7e1d14877b0c88dabe41f0f26R175-R180

... on state.set and event.fire as well?

[ceesvanegmond]

@dlashua Did you fix this issue?

[dlashua]

@ceesvanegmond I implemented it, in part, and @craigbarratt helped fill in the gaps.