Problematic Automation causing state not to being recorded or they may be deleted

_dev_null · March 13, 2024, 7:01pm

Hi,

This one is pulling my hair out

So I’ve got an Aqara door sensor which have been running solid for a year, records open and close events perfectly and hasn’t faulted once until I created an automation

So the problem is that within HA the door sensor is not registered open or close when I disable the automation everything is running smoothly again

The automation itself is simply but I can’t understand why it is having this effect. Has it got anything to do with the ‘timer start action’ ? I’m going to disable that shortly to see

Automation

alias: "Porch Light: Activate Timer"
description: ""
trigger:
  - platform: state
    entity_id:
      - binary_sensor.porch_main_all_occupancy
    to: "off"
    from: "on"
  - platform: state
    entity_id:
      - binary_sensor.lumi_lumi_sensor_magnet_aq2_opening
    to: "off"
    from: "on"
condition: []
action:
  - service: logbook.log
    metadata: {}
    data:
      name: PorchLight
      message: Timeout timer activated
  - service: timer.start
    metadata: {}
    data:
      duration: "00:01:00"
    target:
      entity_id: timer.porch_light_timeout
    enabled: true
mode: single

A bizarre event that occurred is when the logbook clearly shows the events but they are deleted moments later when I refresh the page !

Any advice warmly welcome

Thanks

_dev_null · March 13, 2024, 7:10pm

Update…

Disabling the timer seems to not have any adverse effects but why would the timer interfere with the state of the device ?

alias: "Porch Light: Activate Timer"
description: ""
trigger:
  - platform: state
    entity_id:
      - binary_sensor.porch_main_all_occupancy
    to: "off"
    from: "on"
  - platform: state
    entity_id:
      - binary_sensor.lumi_lumi_sensor_magnet_aq2_opening
    to: "off"
    from: "on"
condition: []
action:
  - service: logbook.log
    metadata: {}
    data:
      name: PorchLight
      message: Timeout timer activated
  - service: timer.start
    metadata: {}
    data:
      duration: "00:01:00"
    target:
      entity_id: timer.porch_light_timeout
    enabled: false
mode: single

_dev_null · March 13, 2024, 11:34pm

deleted

The automation when transferred to NodeRed has exactly the same symptoms

WallyR · March 14, 2024, 12:10am

This just a guess!

But the print outs from the logbooks could just be cache effects.
The first one shows the result from your database + the lines in the write cache on HA, which is used to prevent excessive writing on the disk.
The next one shows the result from your database and no lines are present in the write cache on HA.
The reason it is missing is that the first call made the database server cache the result in the database server read cache and it is serving that result instead of the real one. Doing the same call a bit later should return the correct result, because the read cache on the database server has timed out.

The reason for the cache issue is that the write cache is on the HA server, so it can read it and incorporate it into its views, where as the read cache is on the database server and not accessible for HA.

_dev_null · March 14, 2024, 12:24am

It’s a good shout but inspecting the entity states beg to differ.

I thought I had solved the issue by using NR and all looked good

but then I thought I’d try opening and closing the door again and all I got was this

It’s as if the door was never opened or closed. It’s like the event is being consumed somewhere and not registering a state change.

SOOOoooo frustrating trying to track down what is going on

Now I’m going to disable the NR flow and I’m 100% sure everything will be recorded correctly as it has been for months

WallyR · March 14, 2024, 2:04am

Look at the event bus in HA.
There might be other event types than what you expect or the event might be the same as the earlier one, so no updates in HA.

WallyR · March 14, 2024, 2:40am

And where does " enabled: true" come from??
I can not find anything related to that attribute. What does the logs say?

_dev_null · March 14, 2024, 9:18am

Thanks @WallyR
I enabled debug logs last night and am trying to figure out what is going on

So this morning the front door was opened and closed four times which can be seen on the Bus

grep 'lumi.sensor_magnet.aq2' home-assistant.log | grep Bus:Handling | egrep -v 'automation|binary_sensor.alarm_sensors'

2024-03-14 08:20:31.129 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=binary_sensor.lumi_lumi_sensor_magnet_aq2_opening, old_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=off; device_class=opening, friendly_name=Front Door @ 2024-03-14T00:49:42.838462+00:00>, new_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=on; device_class=opening, friendly_name=Front Door @ 2024-03-14T08:20:31.129684+00:00>>
2024-03-14 08:20:39.943 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=binary_sensor.lumi_lumi_sensor_magnet_aq2_opening, old_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=on; device_class=opening, friendly_name=Front Door @ 2024-03-14T08:20:31.129684+00:00>, new_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=off; device_class=opening, friendly_name=Front Door @ 2024-03-14T08:20:39.943535+00:00>>
2024-03-14 08:20:49.036 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=binary_sensor.lumi_lumi_sensor_magnet_aq2_opening, old_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=off; device_class=opening, friendly_name=Front Door @ 2024-03-14T08:20:39.943535+00:00>, new_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=on; device_class=opening, friendly_name=Front Door @ 2024-03-14T08:20:49.035987+00:00>>
2024-03-14 08:20:55.121 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=binary_sensor.lumi_lumi_sensor_magnet_aq2_opening, old_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=on; device_class=opening, friendly_name=Front Door @ 2024-03-14T08:20:49.035987+00:00>, new_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=off; device_class=opening, friendly_name=Front Door @ 2024-03-14T08:20:55.121138+00:00>>
2024-03-14 08:26:02.580 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=binary_sensor.lumi_lumi_sensor_magnet_aq2_opening, old_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=off; device_class=opening, friendly_name=Front Door @ 2024-03-14T08:20:55.121138+00:00>, new_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=on; device_class=opening, friendly_name=Front Door @ 2024-03-14T08:26:02.580725+00:00>>
2024-03-14 08:26:10.354 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=binary_sensor.lumi_lumi_sensor_magnet_aq2_opening, old_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=on; device_class=opening, friendly_name=Front Door @ 2024-03-14T08:26:02.580725+00:00>, new_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=off; device_class=opening, friendly_name=Front Door @ 2024-03-14T08:26:10.354496+00:00>>
2024-03-14 08:50:32.622 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=binary_sensor.lumi_lumi_sensor_magnet_aq2_opening, old_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=off; device_class=opening, friendly_name=Front Door @ 2024-03-14T08:26:10.354496+00:00>, new_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=on; device_class=opening, friendly_name=Front Door @ 2024-03-14T08:50:32.622735+00:00>>
2024-03-14 08:50:39.073 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=binary_sensor.lumi_lumi_sensor_magnet_aq2_opening, old_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=on; device_class=opening, friendly_name=Front Door @ 2024-03-14T08:50:32.622735+00:00>, new_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=off; device_class=opening, friendly_name=Front Door @ 2024-03-14T08:50:39.072950+00:00>>

There were a total of 8 events but HA thinks that the door is still open and has only recorded 3 of the events

So the bus appears to be working correctly but the events seem to be deleted or lost ?

How do I debug further ?

Many thanks

WallyR · March 14, 2024, 9:25am

I think you are hitting a rate limit feature in ZHA to prevent accidental toggles from multiple messages in the Zigbee mesh network.
You might have to ask the devs, either on discord or on the GitHub of HA.

It looks like up to three messages are cut of in a cool down time after first message or a cool down time of around 20 seconds after the first message, where no other message than the first one is accepted.
This can of course be tested by opening and closing the door mutliple times fitting the pattern you want to test for.

Troon · March 14, 2024, 9:51am

Separate from the rate-limiting question, but:

Is it possible that the sensor is unknown or unavailable during the changeover? This trigger will only fire if the state directly changes from on to off.

Try it without the from: line.

_dev_null · March 14, 2024, 10:50am

Thanks @Troon for mucking in, I’m really at a loss here

The problem is not the trigger but the service call to the timer, when enabled I’m losing the states on the door sensor ! How that happens I just do not know

For example here is the difference between the service call enabled and disabled

The event bus sees all transactions correctly, and the automation is triggered correctly

2024-03-14 08:20:31.129 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=binary_sensor.lumi_lumi_sensor_magnet_aq2_opening, old_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=off; device_class=opening, friendly_name=Front Door @ 2024-03-14T00:49:42.838462+00:00>, new_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=on; device_class=opening, friendly_name=Front Door @ 2024-03-14T08:20:31.129684+00:00>>
2024-03-14 08:20:39.943 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=binary_sensor.lumi_lumi_sensor_magnet_aq2_opening, old_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=on; device_class=opening, friendly_name=Front Door @ 2024-03-14T08:20:31.129684+00:00>, new_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=off; device_class=opening, friendly_name=Front Door @ 2024-03-14T08:20:39.943535+00:00>>
2024-03-14 08:20:49.036 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=binary_sensor.lumi_lumi_sensor_magnet_aq2_opening, old_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=off; device_class=opening, friendly_name=Front Door @ 2024-03-14T08:20:39.943535+00:00>, new_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=on; device_class=opening, friendly_name=Front Door @ 2024-03-14T08:20:49.035987+00:00>>
2024-03-14 08:20:55.121 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=binary_sensor.lumi_lumi_sensor_magnet_aq2_opening, old_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=on; device_class=opening, friendly_name=Front Door @ 2024-03-14T08:20:49.035987+00:00>, new_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=off; device_class=opening, friendly_name=Front Door @ 2024-03-14T08:20:55.121138+00:00>>
2024-03-14 08:26:02.580 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=binary_sensor.lumi_lumi_sensor_magnet_aq2_opening, old_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=off; device_class=opening, friendly_name=Front Door @ 2024-03-14T08:20:55.121138+00:00>, new_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=on; device_class=opening, friendly_name=Front Door @ 2024-03-14T08:26:02.580725+00:00>>
2024-03-14 08:26:10.354 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=binary_sensor.lumi_lumi_sensor_magnet_aq2_opening, old_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=on; device_class=opening, friendly_name=Front Door @ 2024-03-14T08:26:02.580725+00:00>, new_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=off; device_class=opening, friendly_name=Front Door @ 2024-03-14T08:26:10.354496+00:00>>
2024-03-14 08:50:32.622 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=binary_sensor.lumi_lumi_sensor_magnet_aq2_opening, old_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=off; device_class=opening, friendly_name=Front Door @ 2024-03-14T08:26:10.354496+00:00>, new_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=on; device_class=opening, friendly_name=Front Door @ 2024-03-14T08:50:32.622735+00:00>>
2024-03-14 08:50:39.073 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=binary_sensor.lumi_lumi_sensor_magnet_aq2_opening, old_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=on; device_class=opening, friendly_name=Front Door @ 2024-03-14T08:50:32.622735+00:00>, new_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=off; device_class=opening, friendly_name=Front Door @ 2024-03-14T08:50:39.072950+00:00>>
2024-03-14 10:06:46.186 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=binary_sensor.lumi_lumi_sensor_magnet_aq2_opening, old_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=off; device_class=opening, friendly_name=Front Door @ 2024-03-14T08:50:39.072950+00:00>, new_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=on; device_class=opening, friendly_name=Front Door @ 2024-03-14T10:06:46.186483+00:00>>
2024-03-14 10:06:49.194 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=binary_sensor.lumi_lumi_sensor_magnet_aq2_opening, old_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=on; device_class=opening, friendly_name=Front Door @ 2024-03-14T10:06:46.186483+00:00>, new_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=off; device_class=opening, friendly_name=Front Door @ 2024-03-14T10:06:49.194476+00:00>>
2024-03-14 10:27:56.292 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=binary_sensor.lumi_lumi_sensor_magnet_aq2_opening, old_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=off; device_class=opening, friendly_name=Front Door @ 2024-03-14T10:06:49.194476+00:00>, new_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=on; device_class=opening, friendly_name=Front Door @ 2024-03-14T10:27:56.292871+00:00>>
2024-03-14 10:27:58.488 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=binary_sensor.lumi_lumi_sensor_magnet_aq2_opening, old_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=on; device_class=opening, friendly_name=Front Door @ 2024-03-14T10:27:56.292871+00:00>, new_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=off; device_class=opening, friendly_name=Front Door @ 2024-03-14T10:27:58.488435+00:00>>
2024-03-14 10:28:00.899 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=binary_sensor.lumi_lumi_sensor_magnet_aq2_opening, old_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=off; device_class=opening, friendly_name=Front Door @ 2024-03-14T10:27:58.488435+00:00>, new_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=on; device_class=opening, friendly_name=Front Door @ 2024-03-14T10:28:00.899295+00:00>>
2024-03-14 10:28:03.381 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=binary_sensor.lumi_lumi_sensor_magnet_aq2_opening, old_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=on; device_class=opening, friendly_name=Front Door @ 2024-03-14T10:28:00.899295+00:00>, new_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=off; device_class=opening, friendly_name=Front Door @ 2024-03-14T10:28:03.381792+00:00>>
2024-03-14 10:28:06.154 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=binary_sensor.lumi_lumi_sensor_magnet_aq2_opening, old_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=off; device_class=opening, friendly_name=Front Door @ 2024-03-14T10:28:03.381792+00:00>, new_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=on; device_class=opening, friendly_name=Front Door @ 2024-03-14T10:28:06.154678+00:00>>
2024-03-14 10:28:08.113 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=binary_sensor.lumi_lumi_sensor_magnet_aq2_opening, old_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=on; device_class=opening, friendly_name=Front Door @ 2024-03-14T10:28:06.154678+00:00>, new_state=<state binary_sensor.lumi_lumi_sensor_magnet_aq2_opening=off; device_class=opening, friendly_name=Front Door @ 2024-03-14T10:28:08.112831+00:00>>

_dev_null · March 14, 2024, 10:53am

Basically everything works as normal if I disable the timer service call

WallyR · March 14, 2024, 11:03am

What about that enabled setting I mentioned earlier?
Where did you find the documentation for that?

_dev_null · March 14, 2024, 11:12am

Enabling and disabling the automation or functions within the automation via the GUI
It’s well documented AFAIK

WallyR · March 14, 2024, 11:14am

But it seems to be listed under the service call to start.timer

Troon · March 14, 2024, 11:15am

It’s fine. See “Disabling an action”:

WallyR · March 14, 2024, 11:15am

okay, thanks!

WallyR · March 14, 2024, 11:18am

Could it be that the mode of the automation is set to single and the duration of the timer has not expired yet?

joostlek · March 14, 2024, 12:09pm

I just looked into this for a bit. I can’t seem to replicate it on my development environment. Can you maybe try to reproduce this using random binary sensors instead of ZHA? Curious if that could have to do with it (as I don’t have ZHA)

joostlek · March 14, 2024, 12:11pm

Oh and if you check the history instead of the logbook, do you see any change?