EC sometimes enters blocked state

[llamafilm]

Description

Sometimes after the timer expires, EC enters blocked state and the lights remain on. This doesn't happen every time, and I can't tell what causes it.

Configuration

entity_controller:
  outside_motion_lights:
    sensors:
      - binary_sensor.back_yard_motion_detected
      - binary_sensor.front_yard_motion_detected
    entities:
      - light.patio_string_lights
      - light.front_porch
      - light.south_wall_lights_light
      - light.garage_outdoor_lights
    delay: 120
    start_time: sunset - 00:00:00
    end_time: sunrise + 00:00:00

Steps to reproduce

1. Trigger a motion sensor
2. Turn the motion sensor off after a few seconds

Expected behavior

1. Lights should turn on and EC should change to active_timer
2. After 120s, lights should turn off and EC should go back to idle

Actual Behaviour

1. Lights turn on, but one of them is 5 seconds late
2. EC changes to active_timer for 5 seconds
3. EC changes to blocked and lights stay on forever

Logs

I realize this log snippet only includes 14 seconds of activity, while my delay is set for 120s. Nothing else is logged for several minutes, this is actually the end.

2023-10-29 18:02:04.573 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] sensor_state_change :: 'binary_sensor.front_yard_motion_detected' Sensor state change to: on
2023-10-29 18:02:04.574 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] sensor_state_change :: state: 'idle'
2023-10-29 18:02:04.574 INFO (MainThread) [custom_components.entity_controller.outside_motion_lights] <state light.patio_string_lights=off; supported_color_modes=[<ColorMode.ONOFF: 'onoff'>], off_with_transition=False, off_brightness=None, icon=mdi:string-lights, friendly_name=String lights Light, supported_features=8 @ 2023-10-29T18:01:53.817538-07:00>
2023-10-29 18:02:04.574 INFO (MainThread) [custom_components.entity_controller.outside_motion_lights] <state light.front_porch=off; min_color_temp_kelvin=2000, max_color_temp_kelvin=6535, min_mireds=153, max_mireds=500, effect_list=['colorloop'], supported_color_modes=[<ColorMode.COLOR_TEMP: 'color_temp'>, <ColorMode.XY: 'xy'>], off_with_transition=False, off_brightness=254, icon=mdi:coach-lamp, friendly_name=Front Porch Light, supported_features=44 @ 2023-10-29T18:01:53.867317-07:00>
2023-10-29 18:02:04.575 INFO (MainThread) [custom_components.entity_controller.outside_motion_lights] <state light.south_wall_lights_light=off; supported_color_modes=[<ColorMode.ONOFF: 'onoff'>], off_with_transition=False, off_brightness=None, icon=mdi:coach-lamp, friendly_name=South wall lights, supported_features=8 @ 2023-10-29T18:01:53.886844-07:00>
2023-10-29 18:02:04.575 INFO (MainThread) [custom_components.entity_controller.outside_motion_lights] <state light.garage_outdoor_lights=off; supported_color_modes=[<ColorMode.ONOFF: 'onoff'>], icon=mdi:coach-lamp, friendly_name=Garage outdoor lights, supported_features=0 @ 2023-10-29T18:01:51.782561-07:00>
2023-10-29 18:02:04.575 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] State entities are OFF.
2023-10-29 18:02:04.575 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] Exiting idle
2023-10-29 18:02:04.575 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] on_exit_idle | Performing Transition Behaviour
2023-10-29 18:02:04.575 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] on_exit_idle | Action - ignore
2023-10-29 18:02:04.576 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] Entering active
2023-10-29 18:02:04.576 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] Using DAY MODE parameters: {'delay': 120, 'service_data': None, 'service_data_off': None}
2023-10-29 18:02:04.576 INFO (MainThread) [custom_components.entity_controller.outside_motion_lights] _start_timer :: Light params: {'delay': 120, 'service_data': None, 'service_data_off': None}
2023-10-29 18:02:04.577 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] on_enter_active :: light params before turning on: {'delay': 120, 'service_data': None, 'service_data_off': None}
2023-10-29 18:02:04.578 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] on_enter_active | Performing Transition Behaviour
2023-10-29 18:02:04.578 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] on_enter_active | Action - on
2023-10-29 18:02:04.578 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] on_enter_active | Performing Action - Turning on
2023-10-29 18:02:04.578 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] turn_on_control_entities :: Turning on light.patio_string_lights (no parameters passed to service call)
2023-10-29 18:02:04.578 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] call_service :: Calling service turn_on on light.patio_string_lights
2023-10-29 18:02:04.578 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] turn_on_control_entities :: Turning on light.front_porch (no parameters passed to service call)
2023-10-29 18:02:04.578 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] call_service :: Calling service turn_on on light.front_porch
2023-10-29 18:02:04.578 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] turn_on_control_entities :: Turning on light.south_wall_lights_light (no parameters passed to service call)
2023-10-29 18:02:04.578 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] call_service :: Calling service turn_on on light.south_wall_lights_light
2023-10-29 18:02:04.579 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] turn_on_control_entities :: Turning on light.garage_outdoor_lights (no parameters passed to service call)
2023-10-29 18:02:04.579 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] call_service :: Calling service turn_on on light.garage_outdoor_lights
2023-10-29 18:02:04.700 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] state_entity_state_change :: [ Entity: light.patio_string_lights, Context: <homeassistant.core.Context object at 0x7f61829f80> ]
	Old state: <state light.patio_string_lights=off; supported_color_modes=[<ColorMode.ONOFF: 'onoff'>], off_with_transition=False, off_brightness=None, icon=mdi:string-lights, friendly_name=String lights Light, supported_features=8 @ 2023-10-29T18:01:53.817538-07:00>
	New State: <state light.patio_string_lights=on; supported_color_modes=[<ColorMode.ONOFF: 'onoff'>], color_mode=onoff, off_with_transition=False, off_brightness=None, icon=mdi:string-lights, friendly_name=String lights Light, supported_features=8 @ 2023-10-29T18:02:04.696593-07:00>
2023-10-29 18:02:04.700 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] state_entity_state_change :: Ignoring this state change because it came from ec_a94c7f_5d5b57b0a40fe080
2023-10-29 18:02:04.714 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] state_entity_state_change :: [ Entity: light.south_wall_lights_light, Context: <homeassistant.core.Context object at 0x7f61829f80> ]
	Old state: <state light.south_wall_lights_light=off; supported_color_modes=[<ColorMode.ONOFF: 'onoff'>], off_with_transition=False, off_brightness=None, icon=mdi:coach-lamp, friendly_name=South wall lights, supported_features=8 @ 2023-10-29T18:01:53.886844-07:00>
	New State: <state light.south_wall_lights_light=on; supported_color_modes=[<ColorMode.ONOFF: 'onoff'>], color_mode=onoff, off_with_transition=False, off_brightness=None, icon=mdi:coach-lamp, friendly_name=South wall lights, supported_features=8 @ 2023-10-29T18:02:04.711862-07:00>
2023-10-29 18:02:04.715 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] state_entity_state_change :: Ignoring this state change because it came from ec_a94c7f_5d5b57b0a40fe080
2023-10-29 18:02:04.742 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] state_entity_state_change :: [ Entity: light.garage_outdoor_lights, Context: <homeassistant.core.Context object at 0x7f61829f80> ]
	Old state: <state light.garage_outdoor_lights=off; supported_color_modes=[<ColorMode.ONOFF: 'onoff'>], icon=mdi:coach-lamp, friendly_name=Garage outdoor lights, supported_features=0 @ 2023-10-29T18:01:51.782561-07:00>
	New State: <state light.garage_outdoor_lights=on; supported_color_modes=[<ColorMode.ONOFF: 'onoff'>], color_mode=onoff, icon=mdi:coach-lamp, friendly_name=Garage outdoor lights, supported_features=0 @ 2023-10-29T18:02:04.738077-07:00>
2023-10-29 18:02:04.742 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] state_entity_state_change :: Ignoring this state change because it came from ec_a94c7f_5d5b57b0a40fe080
2023-10-29 18:02:09.833 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] state_entity_state_change :: [ Entity: light.front_porch, Context: <homeassistant.core.Context object at 0x7f5f4ff880> ]
	Old state: <state light.front_porch=off; min_color_temp_kelvin=2000, max_color_temp_kelvin=6535, min_mireds=153, max_mireds=500, effect_list=['colorloop'], supported_color_modes=[<ColorMode.COLOR_TEMP: 'color_temp'>, <ColorMode.XY: 'xy'>], off_with_transition=False, off_brightness=254, icon=mdi:coach-lamp, friendly_name=Front Porch Light, supported_features=44 @ 2023-10-29T18:01:53.867317-07:00>
	New State: <state light.front_porch=on; min_color_temp_kelvin=2000, max_color_temp_kelvin=6535, min_mireds=153, max_mireds=500, effect_list=['colorloop'], supported_color_modes=[<ColorMode.COLOR_TEMP: 'color_temp'>, <ColorMode.XY: 'xy'>], color_mode=color_temp, brightness=254, color_temp_kelvin=2222, color_temp=450, hs_color=(29.719, 83.657), rgb_color=(255, 147, 41), xy_color=(0.577, 0.388), off_with_transition=False, off_brightness=None, icon=mdi:coach-lamp, friendly_name=Front Porch Light, supported_features=44 @ 2023-10-29T18:02:09.830050-07:00>
2023-10-29 18:02:09.833 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] state_entity_state_change :: We are in active timer and the state of observed state entities changed.
2023-10-29 18:02:09.834 INFO (MainThread) [custom_components.entity_controller.outside_motion_lights] <state light.patio_string_lights=on; supported_color_modes=[<ColorMode.ONOFF: 'onoff'>], color_mode=onoff, off_with_transition=False, off_brightness=None, icon=mdi:string-lights, friendly_name=String lights Light, supported_features=8 @ 2023-10-29T18:02:04.696593-07:00>
2023-10-29 18:02:09.834 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] State entities are ON. [light.patio_string_lights]
2023-10-29 18:02:09.834 INFO (MainThread) [custom_components.entity_controller.outside_motion_lights] <state light.patio_string_lights=on; supported_color_modes=[<ColorMode.ONOFF: 'onoff'>], color_mode=onoff, off_with_transition=False, off_brightness=None, icon=mdi:string-lights, friendly_name=String lights Light, supported_features=8 @ 2023-10-29T18:02:04.696593-07:00>
2023-10-29 18:02:09.834 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] State entities are ON. [light.patio_string_lights]
2023-10-29 18:02:09.835 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] Exiting active
2023-10-29 18:02:09.835 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] on_exit_active :: Turning off entities, cancelling timer
2023-10-29 18:02:09.835 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] on_exit_active | Performing Transition Behaviour
2023-10-29 18:02:09.835 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] on_exit_active | Action - ignore
2023-10-29 18:02:09.835 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] Entering blocked
2023-10-29 18:02:09.836 INFO (MainThread) [custom_components.entity_controller.outside_motion_lights] <state light.patio_string_lights=on; supported_color_modes=[<ColorMode.ONOFF: 'onoff'>], color_mode=onoff, off_with_transition=False, off_brightness=None, icon=mdi:string-lights, friendly_name=String lights Light, supported_features=8 @ 2023-10-29T18:02:04.696593-07:00>
2023-10-29 18:02:09.836 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] State entities are ON. [light.patio_string_lights]
2023-10-29 18:02:09.836 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] on_enter_blocked | Performing Transition Behaviour
2023-10-29 18:02:09.836 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] on_enter_blocked | Action - ignore
2023-10-29 18:02:09.837 INFO (MainThread) [custom_components.entity_controller.outside_motion_lights] <state light.patio_string_lights=on; supported_color_modes=[<ColorMode.ONOFF: 'onoff'>], color_mode=onoff, off_with_transition=False, off_brightness=None, icon=mdi:string-lights, friendly_name=String lights Light, supported_features=8 @ 2023-10-29T18:02:04.696593-07:00>
2023-10-29 18:02:09.837 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] State entities are ON. [light.patio_string_lights]
2023-10-29 18:02:18.449 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] sensor_state_change :: 'binary_sensor.front_yard_motion_detected' Sensor state change to: off
2023-10-29 18:02:18.449 DEBUG (MainThread) [custom_components.entity_controller.outside_motion_lights] sensor_state_change :: state: 'blocked'

Version

Entity Controller 9.6.1

I'm using Home Assistant 2023.10.5 but I noticed the same issue on 2023.9.

[llamafilm]

It seems that this issue happens every time one of the controlled entities turn on is delayed. Of the four 4 entities I have controlled here, it's not always the same one which is 5 seconds late.

[Tabisch]

Looks like a duration sensor that you have.
Maybe adding "sensor_type: duration" helps.
Here is some info about the types.
https://danobot.github.io/ec-docs/intro/sensor-types/

[jddayley]

I’m having similar challenges

[Paul-Vdp]

I recently started suffering from the same problem, and it took me a while to figure out the cause.
If you ask me, it's got all to do with what you find in the docs under 'EC goes into blocked state', and the so called 'grace period'.
Presumably the solution would be to extend the default thereof ...

HOWEVER : in the docs it is said 'Unfortunately, it is not possible to detect who called a service in Home Assistant. If that was the case we could simply ignore any service calls originating from EC itself.' As far as I can see this has not been true for quite some time already, as in the logs one can clearly see what/who made a sensor go active, e.g. which entity_controller entity triggered it.
Therefore, @danobot, would it not be best to use that information and thereby getting rid once and for all of this problem - and the need for this 'grace period' parameter ?

[Muppetteer]

I have been seeing the same problem lately. #193 seems to have addressed grace_period already so that probably isn't the cause.

[Paul-Vdp]

Good find ! But it raises the question why this parameter still is being accepted (and used ?) without warning, despite being 'deprecated' years ago - and why the documentation still mentions it, as well as the reason for its creation ...
So, what are we to believe ??

Could it be that the solution mentioned in #193 is no longer working or at least occasionally fails, and should be brought up to date - as on several occasions has happened to other parts of EC ?

[danobot]

All these suggestions sound great, anything to improve the component, make it more reliable or clean up redundant code/features. If anyone would like to have a crask at this id be happy to review a pr.

[tanishqmanuja]

Is there any workaround or solution until this is fixed ?