timeSinceChangedMs is wrong?

ov1d1u · April 26, 2024, 6:43am

I have a water fountain for my cat which is controlled using a motion sensor. If the water fountain’s power was never “on” for 12h this means that something terrible is going on, so I added a “events:state” node which triggers if the power was off for 12 hours:

[{"id":"cf71d5e69f0612bd","type":"server-state-changed","z":"07a49424fd2285b2","g":"3ac64136848c0b47","name":"Water Fountain Off for >12h","server":"b59d18a8.44b6f8","version":5,"outputs":2,"exposeAsEntityConfig":"","entityId":"switch.water_fountain_power","entityIdType":"exact","outputInitially":false,"stateType":"str","ifState":"off","ifStateType":"str","ifStateOperator":"is","outputOnlyOnStateChange":true,"for":"12","forType":"num","forUnits":"hours","ignorePrevStateNull":false,"ignorePrevStateUnknown":false,"ignorePrevStateUnavailable":false,"ignoreCurrentStateUnknown":false,"ignoreCurrentStateUnavailable":false,"outputProperties":[{"property":"payload","propertyType":"msg","value":"","valueType":"entityState"},{"property":"data","propertyType":"msg","value":"","valueType":"eventData"},{"property":"topic","propertyType":"msg","value":"","valueType":"triggerId"}],"x":200,"y":940,"wires":[["63c192ba02c4d396","7838d1747e44a4c0"],[]]},{"id":"b59d18a8.44b6f8","type":"server","name":"Home Assistant","version":5,"addon":true,"rejectUnauthorizedCerts":true,"ha_boolean":"y|yes|true|on|home|open","connectionDelay":true,"cacheJson":true,"heartbeat":false,"heartbeatInterval":30,"areaSelector":"friendlyName","deviceSelector":"friendlyName","entitySelector":"friendlyName","statusSeparator":"at: ","statusYear":"hidden","statusMonth":"short","statusDay":"numeric","statusHourCycle":"h23","statusTimeFormat":"h:m","enableGlobalContextStore":true}]

The issue is that the node occasionally triggers even if this condition was not met. I logged such an event:

{
  "payload": "off",
  "data": {
    "entity_id": "switch.water_fountain_power",
    "old_state": {
      "entity_id": "switch.water_fountain_power",
      "state": "on",
      "attributes": {
        "raw_state": true,
        "friendly_name": "Alimentare"
      },
      "last_changed": "2024-04-25T11:10:51.372065+00:00",
      "last_reported": "2024-04-25T11:10:51.372065+00:00",
      "last_updated": "2024-04-25T11:10:51.372065+00:00",
      "context": {
        "id": "01HWAF6XBGEP1GX8TW5CQMZ806",
        "parent_id": null,
        "user_id": "ab68d1be25df460989aef4e617528995"
      }
    },
    "new_state": {
      "entity_id": "switch.water_fountain_power",
      "state": "off",
      "attributes": {
        "raw_state": false,
        "friendly_name": "Alimentare"
      },
      "last_changed": "2024-04-25T11:12:54.703425+00:00",
      "last_reported": "2024-04-25T11:12:54.703425+00:00",
      "last_updated": "2024-04-25T11:12:54.703425+00:00",
      "context": {
        "id": "01HWAFANSS7YQHYZHZDE3XHJBB",
        "parent_id": null,
        "user_id": "ab68d1be25df460989aef4e617528995"
      },
      "timeSinceChangedMs": 43200010
    }
  },
  "topic": "switch.water_fountain_power"
}

You can see that old_state was on at 2024-04-25T11:10:51.372065+00:00, then the node triggered two minutes later at 2024-04-25T11:12:54.703425+00:00, with timeSinceChangedMs showing that there were 12 hours since the last change, which is incorrect. Am I misunderstanding what the “For” parameters in “events: state” node means or what’s going on here?

Mikefila · April 26, 2024, 10:51am

It seems the problem lies in the way the switch reports. In developer tools this should give you time since last changed.

{{ (as_timestamp(now()) - as_timestamp(states.switch.water_fountain_power.last_changed)) | timestamp_custom("%H:%M:%S", false) }}

If it’s the same result then it is the way the switch is reporting, the problem is in HA and not NR.

Biscuit · April 26, 2024, 11:10am

There is nothing quite like a simple experiment to test this and find out what is going on.

I could not wait 12 hours, so I set the ‘For’ time to 12 seconds, and used an input Boolean (switch).

Turn switch “on” - node fires from the ‘fail’ lower output (as the condition 'is off’ is not true).

Turn switch “off” - node fires (condition is met) and goes into timing mode - waiting 12 seconds. If the state changes back to “on” during this time, the timer will be cancelled.

If the state remains as “off” for the duration of the time period, a message will appear at the upper ‘success’ output as a) the state is “off” and b) it has been “off” for 12 seconds.

The points to note are that, output only appears at the end of the successful timer period, and that the prior and current states reflect the prior ‘on’ and current ‘off’ state switching times, and (big drum roll) the time since last changed will be 12 seconds (12000 milli seconds) since the node has waited 12 seconds to output, and that is the time since state change last happened.

If you look very closely at my debug output - the switch changed to “off” at 2024-04-26T10:46:53.655996+00:00 (or 11:46:54 local time as I am in the UK on UTC+1)

The debug reports the output was captured at 11:47:07, which is near enough 12 seconds later.

My conclusion is:
You don’t state at what time your debug was captured, and my guess is that it was 12 hours after the state change to “off”, therefore this is doing what I would expect it to do.

With a “For a given time” condition, the ‘last changed’ for the triggering state in the node output will always be (approximately) the time.

ov1d1u · April 26, 2024, 11:31am

I’m not logging the time but I can see at what time the node that sends the notification was triggered, and that was at Apr 26, 02:12. This is similar with the date modified attribute of the log file, which is Apr 26 02:12:54 2024, so this confirms that timeSinceChangedMs is correct when you compare with the data in the event, since this is about 12 hours (- timezone offset of 3 hours) after new_state.last_updated property (2024-04-25T11:12:54.703425+00:00).

Something’s off with the reporting itself, then. According to the logbook (and real life observations), the switch changed its state a lot after 2024-04-25T11:12:54.703425+00:00:

(note that entries above April 25, 2024 are from April 26, 2024)

Am I missing something here?

Biscuit · April 26, 2024, 12:02pm

These things can be tricky to debug when timing for just 12 seconds - 12 hours makes it hard work!

And, as with all these stories, if you only post descriptions of what you think is happening, it can be a wild goose chase to try and pin down what the “problem” is.

So, I think we can be safe to assume that the node is doing what it was designed to do, and is indeed waiting 12 hours from a state change to “off” before sending a message.

And I just tested that, if it goes “off” then “on” within 12 seconds, the node cancels timing, so yes you must surely have a full 12 hours of “off” happening. If your switch is indeed going “on” - “off” regularly within a 12 hour period (ie never “off” for a full 12 hours) then the node as you have it should not be sending messages.

After that, I would personally look at the switch state changes, and examine the rest of the flow. You appear to be turning on a switch using a service call, but where does that come from? I assume you are using a ‘device’ like a WiFi motion sensor, and these are well known for going on/off/unavailable more often than you might realise.

You can change the settings in the Event: state node to ignore current/previous state is unknown/unavailable - that may help with some of the false “turn off”.

You could also turn the problem on its head. You are testing for “never on for 12 hours” by looking at “off for 12 hours”, when you probably really want “not on at least once during the last 12 hours” - there are ways of looking at just “on” over the past (rolling) 12 hours (history) that would ignore “off” / “unavailable” / “unknown” / “gone for a tea break”. That might be a more reliable test.

ov1d1u · April 26, 2024, 12:20pm

It’s a Zigbee motion sensor, which I understand that it can go unavailable, but this still does not change the fact that the status of the switch was on multiple times and more recent than 12h before the node triggered.

I have this issue for a while and it only appear sporadically, so I’m trying to pin down what happens. I’m not expecting others to solve my problems, all I wanted was a confirmation that I correctly understand the “For” parameter of the “event: state” node. For now, thanks to your help, I discovered that the node triggered as expected according to the data in the event, but it’s the data in the event which seems to be wrong for a reason. I added some more data into the logs so I’m waiting for the issue to happen again, hopefully with more data to help debugging it.

Biscuit · April 27, 2024, 4:55pm

Understood - I am inclined to think the question is one of how the ‘for’ timer should operate, once a timer has been initiated (condition becomes true) when there are later changes to the state.

My expectation is that:
when state changes so that condition test first becomes true, the timer starts
when state changes but condition test still evaluates to ‘true’, the timer continues unchanged
when state changes and condition test now evaluates to false, the timer is cancelled

I found the following (old closed) issue discussion on GitHub, which deals with a case where the timer was restarting on state change, and the state change condition was from ‘true’ to ‘true’. The HA automation behaviour apparently is that a condition timer only restarts when state condition test goes from true to false and back to true again, and I assume that kermit modified the node behaviour at that time to match this.

https://github.com/zachowj/node-red-contrib-home-assistant-websocket/issues/277

If you are seeing a documentable case where the state changes, the condition test goes to true, the timer starts, and then subsequently the state changes and condition test goes to false, but the timer continues and the node later triggers an output message, then I would suggest raising that as a potential issue.