Automation wont trigger. conditions maybe wrong

[r-j-taylor]

Have you checked the trace for that automation? That should tell you which step it is failing on, so you can make sure the conditions are working as expected.

[123 (Taras)]

Let’s assume the problem is in the condition and you correct it. Now the automation will trigger whenever there’s an a system_log_event, of level WARNING or ERROR, and will record it to the system log using the system_log.write service.

Running that service will produce a system_log_event which will re-trigger the automation. What it wrote to the log contains the phrase that condition looks for (including a level of WARNING) so it will proceed to execute its action. In other words, won’t the first trigger start an endless loop?

[Mariusthvdb (Marius)]

hmm, that might be a correct assumption, but, it is easily mitigated by changing the service…

     - service: system_log.write
        data:
          message: >
            Ikea integration was reloaded because of {{trigger.id}}
          level: warning
          logger: homeassistant.components.tradfri

or something simple

i was wondering about the condition, because elsewhere I found a reference to trigger.event.data.message[0] and that made me think the condition might be incorrect, even though I dont yet see what the [0] would do in my specific situation

[123 (Taras)]

Based on what I have seen, message contains a list.

Automation based on log

If you just added fire_event: true to configuration.yaml don’t forget that you have to restart Home Assistant to register the change you made. Here’s an experiment I performed and you might want to try in order to confirm that the events are being generated. Open two browser tabs, each one connected to your Home Assistant instance. In one tab, go to Developer Tools > Events, enter system_log_event in “Event to subscribe to” then click “Listen to events”. In the other tab, go to Developer Too…

@Mariusthvdb

easily mitigated by changing the service

Then you agree it would become an endless loop unless corrected.

FWIW, I mention this only because I fell into the same trap and created a similar endless loop. Fortunately it was creating persistent notifications so I immediately detected the problem because it was highly visible (about a hundred notifications produced within seconds of the first trigger).

[Mariusthvdb (Marius)]

so, here this happens:

2021-11-16 16:37:50 WARNING (MainThread) [coap] Error received in UDP connection under DTLS: [Errno 111] Connection refused

and the automation didnt trigger.

[Mariusthvdb (Marius)]

and yes, so it was the [0] after all…

I tested in the dev tools services

and see what persistent notification was created:

in the homeassistant log:

2021-11-16 16:52:41 WARNING (MainThread) [homeassistant.components.tradfri] Ikea integration was reloaded because of observation

[123 (Taras)]

@Mariusthvdb

it was the [0] after all

Yup, because message contains a list (as shown in the linked post). Not sure why it’s a list (when do multiple errors/warnings occur in the same message?) but there it is.

[Mariusthvdb (Marius)]

now that I have your brains for a second:
we cant set a variable before the conditions can we?

      - variables:
          data: >
            {{trigger.event.data.message[0]}}

so I can use

{{'[homeassistant.components.tradfri.base_class] Observation failed for' in data}}

probably can move the conditions to the action, but in this case I dont think I want to do that

[123 (Taras)]

I think it works if you set variables at the top of the automation where they should be updated immediately after a trigger fires (i.e. just before the condition is evaluated).

  - alias: Reload Trafdri integration
    id: Reload Trafdri integration
    variables:
      msg0: '{{trigger.event.data.message[0]}}'
    trigger:
     ... etc ...

BTW, Ikea called and asked why are you calling their product Trafdri.

[Mariusthvdb (Marius)]

Hahaha hadn’t noticed

Thanks , I’ll change that….

[Mariusthvdb (Marius)]

have some more details, and maybe I need to change the template. what happened:

Logger: coap
Source: /usr/local/lib/python3.9/site-packages/aiocoap/transports/tinydtls.py:280 
First occurred: 08:29:58 (2 occurrences) 
Last logged: 08:29:59

Error received in UDP connection under DTLS: [Errno 111] Connection refused

was logged and the automation kicked in showing me the notification:

which is very nice. However, as you can see there is much more detail in the log more-info, which I also like to have in my notification. Based on the {{trigger.event.data.message[0]}} I now use in the automation, would another template be able to show me these other details, especially Logger and Source? maybe I need to check a full {{trigger.event.data}} to see what’s available…

note btw the odd mixup in trigger id which is reported to be ‘observation’, and origins a Warning level, while this was an Error, and should have logged id ‘failed’…

update

this is what happens:

Full data: {'name': 'coap', 'message': ['Error received in UDP connection under DTLS: [Errno 111] Connection refused'], 'level': 'WARNING', 'source': ('/usr/local/lib/python3.9/site-packages/aiocoap/transports/tinydtls.py', 280), 'timestamp': 1637155664.0627038, 'exception': '', 'count': 1, 'first_occurred': 1637155664.0627038}

testing:

      - service: persistent_notification.create
        data:
          title: >
            {{trigger.event.data.level}}: Tradfri reloaded
          message: >
            {{now().timestamp()|timestamp_custom('%X')}}: Ikea Tradfri integration was
              reloaded because of {{trigger.id}}:
              Message: {{trigger.event.data.message[0]}},
              Logger: {{trigger.event.data.name}},
              Source: {{trigger.event.data.source}},
              Level: {{trigger.event.data.level}},
              Full data: {{trigger.event.data}}

for now

[Mariusthvdb (Marius)]

need some extra assistance please, somehow the condition wont pass while triggering in

2022-01-13 10:34:34 ERROR (MainThread) [custom_components.tahoma] Authentication failed while fetching device events data: Bad credentials

in:

  - alias: Reload Tahoma integration
    id: Reload Tahoma integration
    mode: restart
    trigger:
      - platform: event
        event_type: system_log_event
        event_data:
          level: ERROR
        id: Error
    condition:
      - >
        {{'[custom_components.tahoma] Authentication failed while fetching device events data: Bad credentials'
          in trigger.event.data.message[0]}}

and it seems the parser doesn’t see the whole string as string:

and

‘events data’ is colored as a reserved field. Or would that be mere optics and do I need to change something else in the condition.

testing the string in template editor:

{% set error =     '[custom_components.tahoma] Authentication failed while fetching device events data: Bad credentials'%}
{{error}}

returns alright, the full string, including [] and :

[petro]

why are you splitting the line? That adds a carriage return.

[Mariusthvdb (Marius)]

I dont, that’s the automation tracer. this is what I have:

    condition:
      - >
        {{'[custom_components.tahoma] Authentication failed while fetching device events data: Bad credentials'
          in trigger.event.data.message}}

[petro]

is message a list or a string?

[Mariusthvdb (Marius)]

according to Taras, and what we found out below that, it is a list Automation wont trigger. conditions maybe wrong - #5 by 123

Its a bit hard to test, because the error can not be forced…

this is where its created ha-tahoma/coordinator.py at 8c2491c06fe97ed3db9220e18c87e5cc6380eca3 · iMicknl/ha-tahoma · GitHub

[petro]

if it’s a list, the error has to match exactly for in to work, unlike the string interpolation where it just needs to contain a fraction of the error.

[Mariusthvdb (Marius)]

yes, I copied the full string from the error, so it should be ok in that regard.

Ive just reloaded the automation without the [0], to see if it still triggers and passes. Can only wait now…

[petro]

@Mariusthvdb

yes, I copied the full string from the error, so it should be ok in that regard.

well, that’s assuming it doesn’t have carriage returns or hidden whitespace

[Mariusthvdb (Marius)]

so Ive managed to catch it:

and in Log:

2022-01-14 14:37:20 ERROR (MainThread) [custom_components.tahoma] Authentication failed while fetching device events data: Bad credentials
2022-01-14 14:37:20 WARNING (MainThread) [custom_components.tahoma] Tahoma issue logged, reloading integration

2022-01-14 14:37:20 WARNING (MainThread) [custom_components.tahoma] Tahoma integration was reloaded because of Error

using the adapted condition:

    condition:
      - >
        {{'Authentication failed while fetching device events data: Bad credentials'
          in trigger.event.data.message[0]}}

reveals the error, and apparently the template chokes on the [custom_components.tahoma] bit of the string. tbh, that feels like a bug, and Ill file an issue on that just to be sure to get the devs opinion on it

full data:

ERROR: Tahoma reloaded
14:37:20: Tahoma integration was
reloaded because of Error:
Message: Authentication failed while fetching device events data: Bad credentials,
Logger: custom_components.tahoma,
Source: ['helpers/update_coordinator.py', 227],
Level: ERROR

Full data: <Event system_log_event[L]: name=custom_components.tahoma, message=['Authentication failed while fetching device events data: Bad credentials'], level=ERROR, source=['helpers/update_coordinator.py', 227], timestamp=1642167440.2023897, exception=, count=1, first_occurred=1642167440.2023897>

in persistent notification created by:

    action:
      - service: system_log.write
        data:
          message: >
            Tahoma issue logged, reloading integration
          level: warning
          logger: custom_components.tahoma
#      - service: script.reload_tahoma_integration
      - service: system_log.write
        data:
          message: >
            Tahoma integration was reloaded because of {{trigger.id}}
          level: warning
          logger: custom_components.tahoma
      - service: persistent_notification.create
        data:
          title: >
            {{trigger.event.data.level}}: Tahoma reloaded
          message: >
            {{now().timestamp()|timestamp_custom('%X')}}: Tahoma integration was
              reloaded because of {{trigger.id}}:
              Message: {{trigger.event.data.message[0]}},
              Logger: {{trigger.event.data.name}},
              Source: {{trigger.event.data.source}},
              Level: {{trigger.event.data.level}}

              Full data: {{trigger.event}}

this would probably catch both?:

    condition:
      - >
        {{trigger.event.data.name == 'custom_components.tahoma' and 
          'Authentication failed while fetching device events data: Bad credentials'
          in trigger.event.data.message[0]}}

string containing [ ] in condition doesnt evaluate to true and blocks automation action