Please help diagnoze an automation issue

TestAck18 · June 19, 2020, 6:55am

Hi All,

I have a problem and I cannot see what causes it.
I have a sensor which report multiple values, for example light intensity. I have a remote controlled lamp. Both are connected to HA and both are MQTT controlled DIY devices.

I have a rule to turn on the light if the light intensity value is below 10.

The problem is the lamp turns on sometimes with no reason. Or at least I cannot see the reason.

According to its history it turned on today at 7:25:07:

I have cheked the MQTT history and I could find the command to turn on the lamp at that time. Which means the command come from the MQTT and not an issue with the lamp’s software.
Also on the automation page I can see that the rule was fired at 7:25 so it looks like really HA sent the command:

I have cheked the light intensity history.

In the history we can see that the light intensity went up from 0 to 1 at the time when the lamp turned on.
This value is much below the configured threshold which is 10 so I think the lamp shouldn’t turn on.

Any idea what am I missing? Or how to debug? This is not a one time issue. Every time I wake up the lamp is on. However based on the light intensity history HA gets the correct values.

Any idea what to check?

micque · June 19, 2020, 12:52pm

I don’t understand. You set the automation to trigger when the light is below 10. So why do you think a value change from 0 to 1 wouldn’t have triggered the automation? The value is below 10, right? Every time the light level value changes the automation trigger will be evaluated. I count 21 times the automation would have triggered from 7:25 until around 8:34 when the light level clearly goes above 10. The automation is doing what you programmed it to do.

TestAck18 · June 19, 2020, 1:29pm

In this case tha automation should be triggered when the level goes from 10 to 9, then from 9 to 8, 8 to 7… and also when it goes from 0 to 1 then from 1 to 2, etc… But it wasn’t the case. Yesterday I turned off the lamp manually from the HA GUI at 19:13:

I was in the room and I used a different lamp (not a smart one) so I didn’t needed this one. In the light intensity history you can see it was keeping going down:

That means at the next change when the lux went down from 5 to 4 it also should turn on the lamp. But it didn’t. Next time it turned on at 21:36:05 when it changed from 4 to 5. It was on for 2s and turned off again. It was turned on agani at 1:54:23 for 4s. While the light intensity number never was above 10. So according to your description the lapm should be turned on the while time as the light intensity number decreased since about 18:53.

For me it looks like not every change triggers the rule.

micque · June 19, 2020, 1:39pm

You’re right. My mistake. Good question. Maybe a zero value causes unexpected behavior in the algorithm?

123 · June 19, 2020, 4:11pm

That’s not how the Numeric State trigger works.

If the threshold value is below: 10 it means the Numeric State Trigger will trigger when the light intensity’s value decreases and crosses the threshold of 10. The Numeric State Trigger’s job is now done. It will not trigger again if the intensity continues to decrease. It will only trigger when the intensity decreases and crosses the threshold.

That means if the intensity is currently 5, it must first rise to a value higher than 10 then when it decreases below 10 the Numeric State Trigger will trigger.

TestAck18 · June 19, 2020, 4:36pm

That’s exactly what I thought. I just reacted to the previous post to explane why I don’t think that theory is not correct.
But the question remains: why the atuomation triggered when the light intensity increased from 0 to 1 and turned on the lamp?

123 · June 19, 2020, 4:47pm

Before I can comment on that, I need to see the automation. The only thing posted is a screenshot of the automation’s trigger. Please post the automation’s formatted code.

petro · June 19, 2020, 4:50pm

are you sure it went from zero to 1 or did it go from unavailable to 1?

TestAck18 · June 19, 2020, 5:57pm

Here is the code of the automation:

- id: '1591860492108'
  alias: Turn on workbench LED Light
  description: ''
  trigger:
  - below: '10'
    entity_id: sensor.workingroom01_light_intensity
    platform: numeric_state
  condition: []
  action:
  - data: {}
    entity_id: light.workingroom02_led_lamp
    service: light.turn_on

TestAck18 · June 19, 2020, 6:03pm

Yes, I’m sure. In my first post you can see the screenshot when the light was already 1 at 7:25:07

On this screenshit we can check its previous value:

I have tried my best to move along my mouse on that thiny line but I cound find any other change from 0 to anything just when it swithced to 1 at 7:25:07.

Edit: I have checked the values in the DB and its correct. The value went down to 0 at 1:59:59 and then up to 1 at 7:25:07. There was no value change between the two time and they were NOT unknown or unavailable. I have also checked that if the value would be string (like ‘unknown’) the DB would logged it also. So I can clearly say that it was not unavailable.

TestAck18 · June 19, 2020, 10:42pm

Now I was sitting in front of the lamp when it happened:

2020-06-20 00:16:46 DEBUG (MainThread) [homeassistant.components.mqtt] Received message on home/sensors/WorkingRoom/multisensor01: b'{"temperature":"28.0","humidity":"41.09","pressure":"1000.52","altitude":"106.6","lightintensity":"8.0","status":"ON"}'
2020-06-20 00:16:52 DEBUG (MainThread) [homeassistant.components.mqtt] Received message on home/sensors/WorkingRoom/multisensor02: b'{"status":"ON"}'

2020-06-20 00:17:46 DEBUG (MainThread) [homeassistant.components.mqtt] Received message on home/sensors/WorkingRoom/multisensor01: b'{"temperature":"28.0","humidity":"41.19","pressure":"1000.55","altitude":"106.3","lightintensity":"7.0","status":"ON"}'
2020-06-20 00:17:47 INFO (MainThread) [homeassistant.components.automation] Executing Turn on workbench LED Light
2020-06-20 00:17:47 INFO (MainThread) [homeassistant.components.automation] Turn on workbench LED Light: Running script
2020-06-20 00:17:47 INFO (MainThread) [homeassistant.components.automation] Turn on workbench LED Light: Executing step call service
2020-06-20 00:17:47 DEBUG (MainThread) [homeassistant.components.mqtt] Transmitting message on home/sensors/WorkingRoom/multisensor02/LEDSTRIP/set: {"state": "ON"}
2020-06-20 00:17:47 DEBUG (MainThread) [homeassistant.components.mqtt] Received message on home/sensors/WorkingRoom/multisensor02/LEDSTRIP: b'{"state":"ON","brightness":64,"effect":"solid","transition":0}'

‘multisensor2’ is the MQTT lamp.

At 00:16:46 an MQTT message arrived with a light intensity value of 8.
At 00:16:52 (a few seconds later) my lamp sent a keep alive message saying status=ON. Don’t be confused this is status and not (on/off) state.

Then one minute later (at 00:17:46) my sensor reported a value of 7 for light intensity. Immediately the automation was fired.
Then the json message can be seen with information to the lamp what to do.

The behavior currently looks random for me. At least I don’t know in what circumstance it happenes. But definietly it doesn’t happens on all light intensity value change.

123 · June 20, 2020, 12:18am

What is the configuration for sensor.workingroom01_light_intensity?

It appears to be an MQTT Sensor that’s receives a JSON payload.

TestAck18 · June 20, 2020, 10:49am

Thisis an “auto discovered MQTT device”. I’m not sure why is its config important as it works well. The entity sensor.workingroom01_light_intensity works well in the system. Its updating and showing the correct value.

But here is the auto config definition for it if you think it can help:

{
  "device_class": "illuminance",
  "name": "WorkingRoom01 Light Intensity",
  "state_topic": "home/sensors/WorkingRoom/multisensor01",
  "unit_of_measurement": "lux",
  "value_template": "{{ value_json.lightintensity }}",
  "unique_id": "WorkingRoom01_LI",
  "device": {
    "name": "WorkingRoom01",
    "model": "multisensor",
    "manufacturer": "ME",
    "sw_version": "0.1",
    "identifiers": [
      "WorkingRoom01"
    ]
  }
}

Here is the device in HA:

And here is how it looks like on lovelace:

Of courrse I have manually updated the ‘manufacture’ property on the screenshot from my real name to ‘ME’.

From my point of view it looks like the device and its entities are working well. They are stable and updating correctly. For some reason the Automation rule thinks it should fire.

Last night I set the log level from info to debug:

logger:
  default: debug
  logs:
    homeassistant.components.mqtt: debug

But I haven’t seen any addition information regarding the Automation:


2020-06-20 01:06:21 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.2866539536] Sending {'id': 2, 'type': 'event', 'event': <Event state_changed[L]: entity_id=sensor.workingroom01_light_intensity, old_state=<state sensor.workingroom01_light_intensity=3.0; unit_of_measurement=lux, friendly_name=WorkingRoom01 Light Intensity, device_class=illuminance @ 2020-06-20T01:05:26.984948+02:00>, new_state=<state sensor.workingroom01_light_intensity=1.0; unit_of_measurement=lux, friendly_name=WorkingRoom01 Light Intensity, device_class=illuminance @ 2020-06-20T01:06:21.757915+02:00>>}
2020-06-20 01:06:21 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=automation.turn_on_workbenc_led_light, old_state=<state automation.turn_on_workbenc_led_light=on; last_triggered=2020-06-20T00:56:50.648843+02:00, id=1591860492108, friendly_name=Turn on workbench LED Light @ 2020-06-20T01:05:23.566286+02:00>, new_state=<state automation.turn_on_workbenc_led_light=on; last_triggered=2020-06-20T01:06:21.872966+02:00, id=1591860492108, friendly_name=Turn on workbench LED Light @ 2020-06-20T01:05:23.566286+02:00>>
2020-06-20 01:06:21 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event automation_triggered[L]: name=Turn on workbench LED Light, entity_id=automation.turn_on_workbenc_led_light>
2020-06-20 01:06:21 INFO (MainThread) [homeassistant.components.automation] Executing Turn on workbench LED Light
2020-06-20 01:06:21 INFO (MainThread) [homeassistant.components.automation] Turn on workbench LED Light: Running script
2020-06-20 01:06:21 INFO (MainThread) [homeassistant.components.automation] Turn on workbench LED Light: Executing step call service
2020-06-20 01:06:21 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_data=entity_id=['light.workingroom02_led_lamp']>
2020-06-20 01:06:21 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.2934970224] Sending {'id': 2, 'type': 'event', 'event': <Event state_changed[L]: entity_id=automation.turn_on_workbenc_led_light, old_state=<state automation.turn_on_workbenc_led_light=on; last_triggered=2020-06-20T00:56:50.648843+02:00, id=1591860492108, friendly_name=Turn on workbench LED Light @ 2020-06-20T01:05:23.566286+02:00>, new_state=<state automation.turn_on_workbenc_led_light=on; last_triggered=2020-06-20T01:06:21.872966+02:00, id=1591860492108, friendly_name=Turn on workbench LED Light @ 2020-06-20T01:05:23.566286+02:00>>}
2020-06-20 01:06:21 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.2865838544] Sending {'id': 2, 'type': 'event', 'event': <Event state_changed[L]: entity_id=automation.turn_on_workbenc_led_light, old_state=<state automation.turn_on_workbenc_led_light=on; last_triggered=2020-06-20T00:56:50.648843+02:00, id=1591860492108, friendly_name=Turn on workbench LED Light @ 2020-06-20T01:05:23.566286+02:00>, new_state=<state automation.turn_on_workbenc_led_light=on; last_triggered=2020-06-20T01:06:21.872966+02:00, id=1591860492108, friendly_name=Turn on workbench LED Light @ 2020-06-20T01:05:23.566286+02:00>>}
2020-06-20 01:06:21 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.2865838544] Sending {'id': 3, 'type': 'event', 'event': <Event state_changed[L]: entity_id=automation.turn_on_workbenc_led_light, old_state=<state automation.turn_on_workbenc_led_light=on; last_triggered=2020-06-20T00:56:50.648843+02:00, id=1591860492108, friendly_name=Turn on workbench LED Light @ 2020-06-20T01:05:23.566286+02:00>, new_state=<state automation.turn_on_workbenc_led_light=on; last_triggered=2020-06-20T01:06:21.872966+02:00, id=1591860492108, friendly_name=Turn on workbench LED Light @ 2020-06-20T01:05:23.566286+02:00>>}
2020-06-20 01:06:21 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.2866402704] Sending {'id': 2, 'type': 'event', 'event': <Event state_changed[L]: entity_id=automation.turn_on_workbenc_led_light, old_state=<state automation.turn_on_workbenc_led_light=on; last_triggered=2020-06-20T00:56:50.648843+02:00, id=1591860492108, friendly_name=Turn on workbench LED Light @ 2020-06-20T01:05:23.566286+02:00>, new_state=<state automation.turn_on_workbenc_led_light=on; last_triggered=2020-06-20T01:06:21.872966+02:00, id=1591860492108, friendly_name=Turn on workbench LED Light @ 2020-06-20T01:05:23.566286+02:00>>}
2020-06-20 01:06:21 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.2866436592] Sending {'id': 2, 'type': 'event', 'event': <Event state_changed[L]: entity_id=automation.turn_on_workbenc_led_light, old_state=<state automation.turn_on_workbenc_led_light=on; last_triggered=2020-06-20T00:56:50.648843+02:00, id=1591860492108, friendly_name=Turn on workbench LED Light @ 2020-06-20T01:05:23.566286+02:00>, new_state=<state automation.turn_on_workbenc_led_light=on; last_triggered=2020-06-20T01:06:21.872966+02:00, id=1591860492108, friendly_name=Turn on workbench LED Light @ 2020-06-20T01:05:23.566286+02:00>>}
2020-06-20 01:06:21 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.2914844784] Sending {'id': 2, 'type': 'event', 'event': <Event state_changed[L]: entity_id=automation.turn_on_workbenc_led_light, old_state=<state automation.turn_on_workbenc_led_light=on; last_triggered=2020-06-20T00:56:50.648843+02:00, id=1591860492108, friendly_name=Turn on workbench LED Light @ 2020-06-20T01:05:23.566286+02:00>, new_state=<state automation.turn_on_workbenc_led_light=on; last_triggered=2020-06-20T01:06:21.872966+02:00, id=1591860492108, friendly_name=Turn on workbench LED Light @ 2020-06-20T01:05:23.566286+02:00>>}
2020-06-20 01:06:21 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.2866539536] Sending {'id': 2, 'type': 'event', 'event': <Event state_changed[L]: entity_id=automation.turn_on_workbenc_led_light, old_state=<state automation.turn_on_workbenc_led_light=on; last_triggered=2020-06-20T00:56:50.648843+02:00, id=1591860492108, friendly_name=Turn on workbench LED Light @ 2020-06-20T01:05:23.566286+02:00>, new_state=<state automation.turn_on_workbenc_led_light=on; last_triggered=2020-06-20T01:06:21.872966+02:00, id=1591860492108, friendly_name=Turn on workbench LED Light @ 2020-06-20T01:05:23.566286+02:00>>}
2020-06-20 01:06:21 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=mqtt, service=publish, service_data=topic=home/sensors/WorkingRoom/multisensor02/LEDSTRIP/set, qos=0, retain=True, payload={"state": "ON"}>
2020-06-20 01:06:21 DEBUG (MainThread) [homeassistant.components.mqtt] Transmitting message on home/sensors/WorkingRoom/multisensor02/LEDSTRIP/set: {"state": "ON"}
2020-06-20 01:06:22 DEBUG (MainThread) [homeassistant.components.mqtt] Received message on home/sensors/WorkingRoom/multisensor02/LEDSTRIP: b'{"state":"ON","brightness":64,"effect":"solid","transition":0}'
2020-06-20 01:06:22 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.workingroom02_led_lamp, old_state=<state light.workingroom02_led_lamp=off; effect_list=['bpm', 'candy cane', 'confetti', 'cyclon rainbow', 'dots', 'fire', 'glitter', 'juggle', 'lightning', 'noise', 'police all', 'police one', 'rainbow', 'rainbow with glitter', 'ripple', 'sinelon', 'solid', 'twinkle'], friendly_name=WorkingRoom02 LED Lamp, supported_features=61 @ 2020-06-20T01:05:27.000069+02:00>, new_state=<state light.workingroom02_led_lamp=on; effect_list=['bpm', 'candy cane', 'confetti', 'cyclon rainbow', 'dots', 'fire', 'glitter', 'juggle', 'lightning', 'noise', 'police all', 'police one', 'rainbow', 'rainbow with glitter', 'ripple', 'sinelon', 'solid', 'twinkle'], brightness=64, hs_color=(0, 0), rgb_color=(255, 255, 255), xy_color=(0.323, 0.329), effect=solid, friendly_name=WorkingRoom02 LED Lamp, supported_features=61 @ 2020-06-20T01:06:22.045119+02:00>>

According to this, HA thinks the old value is: old_state=<state sensor.workingroom01_light_intensity=3.0
The new value is: new_state=<state sensor.workingroom01_light_intensity=1.0

Then it fires the rule… Based on the previous descriptions in this topic as the value (3.0) was already below the threshold (10) the automation shouldn’t fire again. And it doesn’t fires every time when a values which is less then 10 decreasing more. Its just random…

pnbruckner · June 20, 2020, 11:37am

Does the automation ever get turned off and then on again? Or do the automatons ever get reloaded? Either of those actions can cause this behavior.

TestAck18 · June 20, 2020, 11:44am

Do you mean by hand or accidently?
Since I created the automation the whole rPI was already rebooted by me. So by hand it was abslutely re-read (previously not at the time when the anomaly happened).
I’m not sure if it was reloaded or turned on/off accidently/by some process or crash. Good point. I’ll check the logs. Thanks!

Just to understand correctly: when I set a trigger based automation the rule will register that it triggered. But if I (or the system) re-register/reload the automation for whatever reason, this - let me say: ‘I was already run’ - flag is cleared? Do you think about this?

pnbruckner · June 20, 2020, 12:02pm

Certainly restarting will do this, too. But I was thinking more of actions either via the UI or via service calls.

Since you have debug enabled for homeassistant.core, you can look for state changes to the automation to see if it goes off and back on at any point. And then you can look right before that to see what service call was made. E.g., if the automation was turned off (either via automation or the UI), you should see something like this:

2020-06-20 06:53:56 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=automation, service=turn_off, service_data=entity_id=automation.automation_0>

If automations were reloaded, you should see something like this:

2020-06-20 06:54:07 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=automation, service=reload, service_data=>

Whenever the automation gets turned off and back on, via either of those two methods, or as a result of a HA restart, the “flag”, as you call it, gets reset. Basically it forgets that the trigger fired, so the first state change of sensor.workingroom01_light_intensity after that that meets the criteria (below 10) will cause the automation to fire. After that it needs to change to a value of 10 or more and then back to below 10 to fire again.

BTW, as @petro mentioned, whenever the state of the sensor cannot be interpreted as a number, that will also cause the trigger to “forget” it has already fired.

TestAck18 · June 20, 2020, 12:15pm

Hahh… Great idea. I’ll check the log. I need some time for this. I will report back later.

Thank you very much!

Just a side note: sometimes I experiencing HA UI loading issues:

Or:

(sorry, the browser’s language was my native language at time the screenshot was taken)

That means there maight be correlation between the two issues. Probably something crashes in the background which cases automation to reload -> clearing the ‘flag’, cannot load page during the restart after crash (I think docker or service crash, as not the whole HA is down).
I haven’t solved that issue until now but I’ll considering troubleshooting that one first if it can also cause this problem for me.

Anyway, thanks for the hint! I think you give the right direction where to look for.

123 · June 20, 2020, 1:59pm

Seeing its configuration is important because, to identify the root cause, we need to confirm that all parts involved in this process are configured nominally. In other words, eliminate the “usual suspects” first before exploring any further.

So far, everything the automation and the sensor it relies upon appear to be nominal. Yet it appears to trigger when it should not. That means we must explore the possibility of less obvious causes for triggering the Numeric State Trigger and pnbruckner has already started that investigation. For example, my first question was going to be what was the system doing shortly before the first log entry you posted. As pnbruckner explained, other system events can reset the Numeric State Trigger and then make it appear like it no longer needs to cross its threshold.

The latest information you provided may also be relevant. An unstable system may develop strange symptoms afterwards. However, I don’t want to consider that possibility just yet because it seems too convenient of an excuse to blame the Numeric State Trigger’s behavior on an unstable system.

We need to understand what is happening immediately prior to the unusual trigger activity (i.e. are there any recent restarts or reloads).

TestAck18 · June 20, 2020, 5:41pm

Hi Taras,

Please don’t get me wrong. I really appritiate your help, I provided the requested information. We can now eliminate the “suspects”.

I belive at this point that something resets the trigger. I haven’t seen anything in the logs short before the event as I far as I can remember. Unfortunately I cannot check it now. If I’m right the log file is overwritten when I restart HA. And today I have already restarted HA so I don’t have the logs from the last night. Now I have to wait until the issue is back.

Again, ‘unfortunately’ I’m leaving for a short vacation tomorrom morning so prabably I’ll be back in the middle of the next week. I can move on with this except if the issue is back in the next few hours.

Until Wednesday/Thursday I really want to thank alll of your help. I’ll report back soon when I have the possibility.

Thank you for your help!

TestAck18 · June 25, 2020, 5:37am

You won’t believe what happened while I was away… Yes, nothing!
There was no unexpected automation rule fired. So the only thing I can think on is I mad some rookie mistake. Probably I made something what caused automation to reload and I didn’t know it happened it the background or I simple didn’t know it ‘resets the already fired flag’.

So I consider this as my fault. Currently can’t see other logical option.
Thank you very much your help guys!