Delays in calls to ISY from HA

[shbatm]

Discussed in https://github.com/automicus/PyISY/discussions/389

^{Originally posted by **@sirmeili** July 30, 2023} I have some scenarios where my automations in HA that are triggered by an insteon event and have an insteon action results in the rest call to the ISY in the action having about a 1.5 second delay. I don't know if it's HA, PyISY, or the ISY that's causing the delay. If I trigger the automation manually (no insteon trigger), the rest call is immediate (about 80ms), but if it is triggered by an insteon event from the ISY (i.e. a door was opened/closed) then the rest call/response time is 1.5 seconds or so. I don't know if there are instanced in PyISY that might be throttling the response or if it is known if there is any throttling on the HA or ISY side (I have powers on their respectrve forums asking). I'm just trying to cover my bases. Here are the logs from HA when the event is triggered by a door sensor: - 2023-07-29 22:12:30.246 DEBUG (MainThread) [homeassistant.components.isy994] Sensor None turning On via the Primary node sending a DON command - 2023-07-29 22:12:30.248 DEBUG (MainThread) [homeassistant.components.isy994] Heartbeat timer starting. Now: 2023-07-30 - 02:12:30.247908+00:00 Then: 2023-07-31 03:12:30.247869+00:00 - 2023-07-29 22:12:30.248 DEBUG (MainThread) [pyisy] ISY Node Control Event: NodeProperty(control='DON', value=1, prec='0', uom='', formatted=None, address='32 86 20 1') - 2023-07-29 22:12:30.249 DEBUG (MainThread) [pyisy] ISY Updated Node: 32 86 20 1 - **2023-07-29 22:12:30.262 DEBUG (MainThread) [pyisy] ISY Request: http://10.0.0.172:8080/rest/nodes/50%20D1%207F%201/cmd/DON** - **2023-07-29 22:12:31.873 DEBUG (MainThread) [pyisy] ISY Response Received: /nodes/50%20D1%207F%201/cmd/DON** - 2023-07-29 22:12:31.873 DEBUG (MainThread) [pyisy] ISY command on sent to 50 D1 7F 1. - 2023-07-29 22:12:32.186 DEBUG (MainThread) [pyisy] ISY Updated Node: 50 D1 7F 1 And this is the call if the automation is triggered manually (so no incoming insteon event): - **2023-07-29 22:21:17.173 DEBUG (MainThread) [pyisy] ISY Request: http://10.0.0.172:8080/rest/nodes/50%20D1%207F%201/cmd/DON** - **2023-07-29 22:21:17.181 DEBUG (MainThread) [pyisy] ISY Response Received: /nodes/50%20D1%207F%201/cmd/DON** - 2023-07-29 22:21:17.182 DEBUG (MainThread) [pyisy] ISY command on sent to 50 D1 7F 1. - 2023-07-29 22:21:17.496 DEBUG (MainThread) [pyisy] ISY Updated Node: 50 D1 7F 1

[shbatm]

@sirmeili At first glance this appears to be something on the ISY side since the request (the first bold lines) are sent within 100ms each time. Once sent, there's nothing it can do but wait for the ISY to respond.

The only thing I can think of is if the ISY is busy processing something else when the button is pushed. But this looks like an eisy or polisy, and no other traffic in between. Can you check the ISY logs in the Admin Console and see if there's some other errors or messages?

[sirmeili]

I have tried to check but they don't seem to have any logs related to the rest interface. I can see logs of the devices turning on/off, but that's no helpful if I can't see the logs of the incoming rest requests.

I wasn't sure it was pyisy, I was more thinking HA, but if this won't work I'll have to find another solution outside the isy.

This biggest mystery is why the delay is only ever present in HA automations. Again this might be due to an incoming request when an outgoing is immediately behind it (so could still be on the ISY side).

Thanks for at least checking into it. I'll continue my search.

[shbatm]

Have you tried a complete restart of the ISY (Polisy eisy, whatever you're using)? The only thing I can think of is still that the ISY is backlogged on something, usually checking it's own programs' conditions or something.

You can also try using the HACS integration which uses the Alpha-version successor to this module, pyisyox.

I don't see any delays when firing events like this, so I'm not sure what may be causing the delay.

[sirmeili]

I have tried restarting,updating, etc. Like I said it's only in the automation in ha. I'm going to disable the automation action and open the door and turn on the light manually to see if I still get the delay. Try and limit it to the automation.

Again I can flip lights on/off all day and it's fine but in any automation that includes an isy trigger it exhibits this behavior.

[sirmeili]

I've run quite a few tests today and I think it is in fact the ISY. I don't know why but any first request can finish in mere MS (like 8-10ms), but if you fire them off in quick succession any subsequent ones take as long as 1.5s (1500ms). I can only assume that it is in fact processing and it just limits it. I never had this problem in HomeSeer when talking to the PLM directly. I may have to see if I can control the PLM directly from HA instead of using the ISY or try the other integration that uses the hub (I think I have a hub or 2 in storage).

I don't get why UD thinks that this is acceptable. the Polisy should be more than powerful enough to handle these requests in quick succession.

I don't think it's this integration, just a limitation of the ISY (at least on the Polisy, I never remember this on my isy994 when I had HomeSeer controlling it, but that was many years ago)

[JavierRefuerzo]

I've run quite a few tests today and I think it is in fact the ISY. I don't know why but any first request can finish in mere MS (like 8-10ms), but if you fire them off in quick succession any subsequent ones take as long as 1.5s (1500ms).

This has always been an issue with Insteon. If your issue command in quick succession the Insteon network is flooded and command are either not delivered, or retries which causes delays and more traffic. You can solve some of these issues by placing the device in a scene and issuing a single command.

[sirmeili]

I've run quite a few tests today and I think it is in fact the ISY. I don't know why but any first request can finish in mere MS (like 8-10ms), but if you fire them off in quick succession any subsequent ones take as long as 1.5s (1500ms).

This has always been an issue with Insteon. If your issue command in quick succession the Insteon network is flooded and command are either not delivered, or retries which causes delays and more traffic. You can solve some of these issues by placing the device in a scene and issuing a single command.

But this shouldn't be the case in my scenario.

I open a door - the insteon signal is sent to the ISY.... ISy sends it to HA. HS sends a command back to the ISY to send to the device, it takes 1.5s. That's 2 commands. I can do this in the house with no one else home and reproduce it ever time. Even if I don't use an automation.

I've done more testing and I'm more confused than ever. I can send rapid requests and they work, but if I trigger a sensor first, I get delays. So maybe it's the ISY. I'm not sure. Based on the logs from HA it appears it is sending a request and it doesn't get a response for 1.5 seconds.

[sirmeili]

I've been able to reproduce my issue on the ISY with an ISY program. It appears that at least on my ISY, when a command comes in from a device, it basically is tied up for 1-1.5s until it will accept and process a any other command. This makes little sense to me as the command has already been sent out to HA, so I would think that the ISY is done with any processing.

I have a thread over on the UD forums to see if I can get help over there, but I'm about 99.999999% sure this is on the ISY.

Sorry for the noise.

[sirmeili]

Just in case you're curious. I also was able to reproduce this in the normal Insteon integration using an insteon hub instead of the ISY/PLM. I get the same 1.5 delay from receiving a signal and sending it.

[shbatm]

@sirmeili Thanks for the update. I'm going to close this here since this appears to be an issue on UDI's end.