Question regarding debugging/troubleshooting non-triggered automations

Configuration
1

Hello, i have a very simple automation which i would like to troubleshoot why it was not triggered. This happened only two times so far but still rather strange.

Configuration is like this:

alias: Auto Garage Door
description: ''
trigger:
  - platform: state
    entity_id: person.me
    to: home
    from: not_home
condition:
  - condition: template
    value_template: >-
      {{'CC:88:26:C9:A3:18' in
      state_attr('sensor.me_redmi_a11_bluetooth_connection',
      'connected_paired_devices') }}
action:
  - service: cover.open_cover
    target:
      entity_id: cover.garage_door
mode: single

So pretty straightforward. App on my phone is configured to have high accuracy when connected to same bluetooth device as from automation, so location is updated constantly. When i get updated to be at home, and while I’m connected to my car bluetooth unit, it should open garage door, right?

It works in 99.9% of cases but I’m wondering why it didn’t work now, and one other time.

  • Entity person.me was updated at “2021-10-22 21:09:58.480206” when i got home, according to mysql log (logger is set to mysql). This is UTC time i guess
  • Entity sensor.me_redmi_a11_bluetooth_connection had attribute “connected_paired_devices” properly holding my BT device MAC around that time, check the following entry in mysql table which is used as logger
INSERT INTO `states` (`state_id`, `domain`, `entity_id`, `state`, `attributes`, `event_id`, `last_changed`, `last_updated`, `created`, `old_state_id`) VALUES (NULL, 'sensor', 'sensor.me_redmi_a11_bluetooth_connection', '2', '{\"connected_not_paired_devices\":\"[EF:07:14:BB:42:95]\",\"connected_paired_devices\":\"[CC:88:26:C9:A3:18]\",\"paired_devices\":\"[40:40:A7:D0:17:B1, 80:9F:9B:ED:1F:E2, CC:88:26:C9:A3:18]\",\"unit_of_measurement\":\"connection(s)\",\"friendly_name\":\"Me Redmi A11 Bluetooth Connection\",\"icon\":\"mdi:bluetooth\"}', '7066292', '2021-10-22 21:10:08.457052', '2021-10-22 21:10:08.457052', '2021-10-22 21:10:08.457052', '6529079')

And phone was disconnected from that device around 2021-10-22 21:13:50.147133 UTC, so i was at home around that time, yet, automation did not trigger.
Automation was last triggered yesterday:

{"last_triggered":"2021-10-21T14:18:02.555056+00:00","mode":"single","current":0,"id":"1631598980671","friendly_name":"Auto Garage Door"}

True, i haven’t left the house since yesterday but why didn’t it trigger now?

I have another automation which runs python script (it was easier for me to configure loops and conditions there) which is triggered when either I or my wife comes home while nobody is home and it will turn lights, that automation successfully ran. Log doesn’t show ANYTHING around that time, other than standard warning about python script when initiated without arguments.

2021-10-22 22:01:24 WARNING (Thread-11) [pychromecast.socket_client] [TV Dnevna Soba(192.168.0.104):8009] Heartbeat timeout, resetting connection
2021-10-22 22:01:54 ERROR (Thread-11) [pychromecast.socket_client] [TV Dnevna Soba(192.168.0.104):8009] Failed to connect to service ServiceInfo(type='mdns', data='MiTV-MSSP3-2b1196cc15fd92d7374ace9308a15650._googlecast._tcp.local.'), retrying in 5.0s
2021-10-22 23:10:28 WARNING (MainThread) [homeassistant.helpers.template] Template variable warning: 'argument' is undefined when rendering '/config/bin/light-automation.py {% if argument -%} {{ argument }} {%- endif %}'
2021-10-22 23:10:34 WARNING (MainThread) [homeassistant.helpers.template] Template variable warning: 'argument' is undefined when rendering '/config/bin/light-automation.py {% if argument -%} {{ argument }} {%- endif %}'
2021-10-22 23:14:10 WARNING (MainThread) [homeassistant.helpers.template] Template variable warning: 'argument' is undefined when rendering '/config/bin/light-automation.py {% if argument -%} {{ argument }} {%- endif %}'

Log file shows the actual time while database seems to show UTC time but it’s same.

Home assistant is running on Raspberry Pi 3B+
HA Version: core-2021.10.2
OS: 6.4
Supervisor: supervisor-2021.10.0

So… Any ideas? :smiley:

2

Go to Configuration / Automations and search for your automation. in the list. Click on the clock icon to the left of the automation to see a trace for the automation the last time it triggered.

Using this you can determine if the automation failed to trigger or failed to pass the condition.

3

Okay, thanks!
Now I’m getting closer…

It appears it failed on condition:

Executed: October 22, 2021, 11:09:58 PM
Result:
result: false
entities:
  - sensor.me_redmi_a11_bluetooth_connection

Step Config:
condition: template
value_template: >-
  {{'CC:88:26:C9:A3:18' in
  state_attr('sensor.me_redmi_a11_bluetooth_connection',
  'connected_paired_devices') }}

But why…?
Phone did have high accuracy enabled, meaning home assistant phone app did manage to see that I’m connected to car bluetooth. When checking the timestamp when automation triggered and last_changed, last_updated and created fields in MySQL table for that sensor, i can see that sensor got updated just few seconds after automation triggered.

INSERT INTO `states` (`state_id`, `domain`, `entity_id`, `state`, `attributes`, `event_id`, `last_changed`, `last_updated`, `created`, `old_state_id`) VALUES (NULL, 'sensor', 'sensor.mtodoric_redmi_a11_bluetooth_connection', '2', '{\"connected_not_paired_devices\":\"[EF:07:14:BB:42:95]\",\"connected_paired_devices\":\"[CC:88:26:C9:A3:18]\",\"paired_devices\":\"[40:40:A7:D0:17:B1, 80:9F:9B:ED:1F:E2, CC:88:26:C9:A3:18]\",\"unit_of_measurement\":\"connection(s)\",\"friendly_name\":\"MTodoric Redmi A11 Bluetooth Connection\",\"icon\":\"mdi:bluetooth\"}', '7066292', '2021-10-22 21:10:08.457052', '2021-10-22 21:10:08.457052', '2021-10-22 21:10:08.457052', '6529079');

And i was in my car since “2021-10-22 21:03:40.562212”, i can see that by checking update integrity of entity person.me , that’s when it started updating location every few seconds.

So why the sensor entity didn’t get updated on time?