search

jseidl / hass-magic_areas

Areas with batteries included for Home Assistant
MIT License
273 stars 28 forks source link

Area got locked to "occupied" state when sensor sends a sequence of "off" states. #318

Closed juacas closed 5 months ago

juacas commented 8 months ago

Describe the bug

When a presence sensor sends a sequence of "off" states faster than the "timeout" of the MagisArea the timeout never occurs. Aparently, there is a wrong transition from state "clear" to state "clear" that resets the timeout.

To Reproduce Steps to reproduce the behavior:

  1. Add a presence sensor that meets the former conditions to a MagicArea.
  2. Configure the MagicArea to react to that sensor.
  3. Make the sensor to go to state "off".
  4. Send events "change_state" with "off" state every few seconds.
  5. Wait the timeout of the MagicArea to expire.
  6. Never expires.
  7. Stop sending events.
  8. MagicArea goes "clear" after the timeout.

Expected behavior

An event that doen't change state should not fire the state change nor timeout reset.

Additional context

Version: MagicAreas 3.0.2, HA2024.2.0

Logs:

2024-02-16 10:09:20.662 DEBUG (SyncWorker_10) [custom_components.magic_areas.base] Area (Despacho): sensor 'binary_sensor.radar_presencia_1_presence' changed to off
2024-02-16 10:09:20.662 DEBUG (SyncWorker_10) [custom_components.magic_areas.base] [Area: despacho] Updating state. (Valid states: ['home', 'on'])
2024-02-16 10:09:20.663 DEBUG (SyncWorker_10) [custom_components.magic_areas.base] [Area: despacho] Sensor binary_sensor.radar_presencia_1_presence state: off
2024-02-16 10:09:20.664 DEBUG (SyncWorker_10) [custom_components.magic_areas.base] [Area: despacho] Active sensors: []
2024-02-16 10:09:20.664 DEBUG (SyncWorker_10) [custom_components.magic_areas.binary_sensor] Despacho: Area is on timeout
2024-02-16 10:09:20.664 DEBUG (SyncWorker_10) [custom_components.magic_areas.binary_sensor] Despacho: States updated. New states: [] / Lost states: []
2024-02-16 10:09:20.669 DEBUG (SyncWorker_10) [custom_components.magic_areas.binary_sensor] Reporting state change for Despacho (new states: []/lost states: [])
2024-02-16 10:09:20.691 DEBUG (SyncWorker_26) [custom_components.magic_areas.base] Area (Despacho): sensor 'binary_sensor.radar_presencia_1_presence' changed to off
2024-02-16 10:09:20.691 DEBUG (SyncWorker_26) [custom_components.magic_areas.base] [Area: despacho] Updating state. (Valid states: ['home', 'on'])
2024-02-16 10:09:20.693 DEBUG (SyncWorker_26) [custom_components.magic_areas.base] [Area: despacho] Sensor binary_sensor.radar_presencia_1_presence state: off
2024-02-16 10:09:20.693 DEBUG (SyncWorker_26) [custom_components.magic_areas.base] [Area: despacho] Active sensors: []
2024-02-16 10:09:20.693 DEBUG (SyncWorker_26) [custom_components.magic_areas.binary_sensor] Despacho: Area is on timeout
2024-02-16 10:09:20.693 DEBUG (SyncWorker_26) [custom_components.magic_areas.binary_sensor] Despacho: States updated. New states: [] / Lost states: []
2024-02-16 10:09:20.694 DEBUG (SyncWorker_26) [custom_components.magic_areas.binary_sensor] Reporting state change for Despacho (new states: []/lost states: [])
2024-02-16 10:09:20.694 DEBUG (SyncWorker_26) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: kitchen)
2024-02-16 10:09:20.696 DEBUG (SyncWorker_47) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: vestibulo)
2024-02-16 10:09:20.697 DEBUG (SyncWorker_47) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: vestibulo)
2024-02-16 10:09:20.697 DEBUG (SyncWorker_47) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: frente)
2024-02-16 10:09:20.698 DEBUG (SyncWorker_47) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: frente)
2024-02-16 10:09:20.699 DEBUG (SyncWorker_47) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: zapatero)
2024-02-16 10:09:20.699 DEBUG (SyncWorker_47) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: zapatero)
2024-02-16 10:09:20.700 DEBUG (SyncWorker_4) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: zapatero)
2024-02-16 10:09:20.700 DEBUG (SyncWorker_4) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: cochera)
2024-02-16 10:09:20.701 DEBUG (SyncWorker_4) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: cochera)
2024-02-16 10:09:20.701 DEBUG (SyncWorker_4) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: escalera)
2024-02-16 10:09:20.701 DEBUG (SyncWorker_4) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: escalera)
2024-02-16 10:09:20.701 DEBUG (SyncWorker_4) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: salon)
2024-02-16 10:09:20.702 DEBUG (SyncWorker_29) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: salon)
2024-02-16 10:09:20.712 DEBUG (SyncWorker_11) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: kitchen)
2024-02-16 10:09:20.725 DEBUG (SyncWorker_62) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: vestibulo)
2024-02-16 10:09:20.725 DEBUG (SyncWorker_62) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: vestibulo)
2024-02-16 10:09:20.726 DEBUG (SyncWorker_62) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: frente)
2024-02-16 10:09:20.726 DEBUG (SyncWorker_62) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: frente)
2024-02-16 10:09:20.727 DEBUG (SyncWorker_62) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: zapatero)
2024-02-16 10:09:20.727 DEBUG (SyncWorker_62) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: zapatero)
2024-02-16 10:09:20.727 DEBUG (SyncWorker_62) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: zapatero)
2024-02-16 10:09:20.727 DEBUG (SyncWorker_62) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: cochera)
2024-02-16 10:09:20.727 DEBUG (SyncWorker_62) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: cochera)
2024-02-16 10:09:20.728 DEBUG (SyncWorker_62) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: escalera)
2024-02-16 10:09:20.728 DEBUG (SyncWorker_62) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: escalera)
2024-02-16 10:09:20.729 DEBUG (SyncWorker_57) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: salon)
2024-02-16 10:09:20.729 DEBUG (SyncWorker_57) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: salon)
2024-02-16 10:09:20.731 DEBUG (SyncWorker_11) [custom_components.magic_areas.base] Area (Despacho): sensor 'binary_sensor.radar_presencia_1_presence' changed to off
2024-02-16 10:09:20.731 DEBUG (SyncWorker_11) [custom_components.magic_areas.base] [Area: despacho] Updating state. (Valid states: ['home', 'on'])
2024-02-16 10:09:20.732 DEBUG (SyncWorker_11) [custom_components.magic_areas.base] [Area: despacho] Sensor binary_sensor.radar_presencia_1_presence state: off
2024-02-16 10:09:20.732 DEBUG (SyncWorker_11) [custom_components.magic_areas.base] [Area: despacho] Active sensors: []
2024-02-16 10:09:20.732 DEBUG (SyncWorker_11) [custom_components.magic_areas.binary_sensor] Despacho: Area is on timeout
2024-02-16 10:09:20.732 DEBUG (SyncWorker_11) [custom_components.magic_areas.binary_sensor] Despacho: States updated. New states: [] / Lost states: []
2024-02-16 10:09:20.734 DEBUG (SyncWorker_11) [custom_components.magic_areas.binary_sensor] Reporting state change for Despacho (new states: []/lost states: [])
2024-02-16 10:09:20.737 DEBUG (SyncWorker_18) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: kitchen)
2024-02-16 10:09:20.737 DEBUG (SyncWorker_18) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: vestibulo)
2024-02-16 10:09:20.738 DEBUG (SyncWorker_37) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: vestibulo)
2024-02-16 10:09:20.738 DEBUG (SyncWorker_18) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: frente)
2024-02-16 10:09:20.738 DEBUG (SyncWorker_18) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: frente)
2024-02-16 10:09:20.739 DEBUG (SyncWorker_18) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: zapatero)
2024-02-16 10:09:20.739 DEBUG (SyncWorker_18) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: zapatero)
2024-02-16 10:09:20.739 DEBUG (SyncWorker_25) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: zapatero)
2024-02-16 10:09:20.739 DEBUG (SyncWorker_25) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: cochera)
2024-02-16 10:09:20.740 DEBUG (SyncWorker_25) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: cochera)
2024-02-16 10:09:20.740 DEBUG (SyncWorker_51) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: escalera)
2024-02-16 10:09:20.740 DEBUG (SyncWorker_51) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: escalera)
2024-02-16 10:09:20.741 DEBUG (SyncWorker_51) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: salon)
2024-02-16 10:09:20.741 DEBUG (SyncWorker_25) [custom_components.magic_areas.light] Area state change event not for us. Skipping. (req: despacho/self: salon)
2024-02-16 10:09:21.377 DEBUG (SyncWorker_46) [custom_components.magic_areas.base] Area (Despacho): sensor 'binary_sensor.radar_presencia_1_presence' changed to off
2024-02-16 10:09:21.378 DEBUG (SyncWorker_46) [custom_components.magic_areas.base] [Area: despacho] Updating state. (Valid states: ['home', 'on'])
2024-02-16 10:09:21.379 DEBUG (SyncWorker_46) [custom_components.magic_areas.base] [Area: despacho] Sensor binary_sensor.radar_presencia_1_presence state: off
2024-02-16 10:09:21.379 DEBUG (SyncWorker_46) [custom_components.magic_areas.base] [Area: despacho] Active sensors: []
2024-02-16 10:09:21.379 DEBUG (SyncWorker_46) [custom_components.magic_areas.binary_sensor] Despacho: Area is on timeout
2024-02-16 10:09:21.379 DEBUG (SyncWorker_46) [custom_components.magic_areas.binary_sensor] Despacho: States updated. New states: [] / Lost states: []
2024-02-16 10:09:21.382 DEBUG (SyncWorker_46) [custom_components.magic_areas.binary_sensor] Reporting state change for Despacho (new states: []/lost states: [])
jseidl commented 8 months ago

That is weird. I know that bug exists because I've felt it but was never able to trace it.

The code that is supposed to prevent what you're saying from happening is https://github.com/jseidl/hass-magic_areas/blob/main/custom_components/magic_areas/binary_sensor.py#L406 which does the "Area is on timeout" message but does not refresh it.

I still can't find the bug but I'm chasing it.

jseidl commented 6 months ago

OK I think I've found the bug.

The issue is that the last sensor to go off updates the last_off_time thus keeping the area indefinitely on cooldown. See https://github.com/jseidl/hass-magic_areas/blob/main/custom_components/magic_areas/base/entities.py#L135-L136

I've added a check to see if is a state transition or a state report https://github.com/jseidl/hass-magic_areas/blob/enhancement/merge-integration-blueprint/custom_components/magic_areas/base/entities.py#L134-L136

You can manually add those lines to your current entities.py and shall solve this problem while I finish working on this next release.

jseidl commented 5 months ago

Fixed by #326