Wait for ISY to be ready when retrying commands

[shbatm]

Use the system status reported by the websocket to hold off on retrying a command until the system reports that it is ready.

This will always still try the command first, even if the system has reported it's busy. If the command returns a 404 error, then instead of just failing or using the throttled backoff for the retry, it will wait up to 5 seconds for the ISY to report it is NOT_BUSY before retrying again. If the system is still busy after 5 seconds, an ISYConnectionError is raised.

Fixes #184

[shbatm]

@rccoleman - Would you mind testing this version with Home Assistant?

You'll need to update the following to use pyisy-beta==3.1.12b0 instead of pyisy==3.1.11

./homeassistant/homeassistant/components/isy994/manifest.json
./homeassistant/requirements_all.txt
./homeassistant/requirements_test_all.txt

[shbatm]

@rccoleman Alternatively, test with this branch of Home Assistant: https://github.com/shbatm/home-assistant-core/tree/isy994_wait-for-ready

[rccoleman]

Sure, passes a basic smoke test for me:

2023-02-01 11:57:50.221 INFO (SyncWorker_3) [homeassistant.util.package] Attempting install of pyisy-beta==3.1.12b0

I created the Insteon scene as we discussed and collapsed all that activity down into what should be one command, but I'll temporarily revert and see what happens.

[shbatm]

Thanks, in theory if you overwhelm the network you should see the following in the debug log:

"ISY is busy, waiting for system to be ready"

[rccoleman]

I'm still seeing this (now with debug enabled):

2023-02-01 12:21:17.598 INFO (MainThread) [homeassistant.components.automation.garage_open_turn_on_lights_dark] Garage open turn on lights Dark: Running automation actions
2023-02-01 12:21:17.598 INFO (MainThread) [homeassistant.components.automation.garage_open_turn_on_lights_dark] Garage open turn on lights Dark: Executing step call service
2023-02-01 12:21:17.600 DEBUG (MainThread) [pyisy] ISY Request: http://192.168.1.218:80/rest/nodes/36117/cmd/DON
2023-02-01 12:21:17.602 DEBUG (MainThread) [pyisy] ISY Request: http://192.168.1.218:80/rest/nodes/47494/cmd/DON
2023-02-01 12:21:17.602 DEBUG (MainThread) [pyisy] ISY Request: http://192.168.1.218:80/rest/nodes/20615/cmd/DON
2023-02-01 12:21:17.604 DEBUG (MainThread) [pyisy] ISY Request: http://192.168.1.218:80/rest/nodes/3C%20EB%20EC%201/cmd/DON
2023-02-01 12:21:17.606 DEBUG (MainThread) [pyisy] ISY Request: http://192.168.1.218:80/rest/nodes/40%205C%2062%201/cmd/DON
2023-02-01 12:21:17.668 DEBUG (MainThread) [pyisy] ISY Updated Node: 3C E8 A8 1
2023-02-01 12:21:17.676 INFO (MainThread) [custom_components.pyscript.apps.automatic_light.entity_trigger] dnh_lighting: Triggered: expr=switch.dnh_lights_scene value=on
2023-02-01 12:21:17.678 DEBUG (MainThread) [pyisy] ISY Updated Node: 3C E7 86 1
2023-02-01 12:21:17.680 INFO (MainThread) [custom_components.pyscript.apps.automatic_light.lighting_trigger] dnh_lighting: Lighting trigger: value=on, self.ms_triggered=False
2023-02-01 12:21:17.681 INFO (MainThread) [custom_components.pyscript.apps.automatic_light.lighting_trigger] dnh_lighting: lux=10000.0, self.light_level=10000.0, on? False
2023-02-01 12:21:17.682 INFO (MainThread) [custom_components.pyscript.apps.automatic_light.lighting_trigger] dnh_lighting: Turning on lights
2023-02-01 12:21:17.691 DEBUG (MainThread) [pyisy] ISY Response Received: /nodes/36117/cmd/DON
2023-02-01 12:21:17.691 DEBUG (MainThread) [pyisy] ISY command on sent to 36117.
2023-02-01 12:21:17.696 DEBUG (MainThread) [pyisy] ISY Response Received: /nodes/47494/cmd/DON
2023-02-01 12:21:17.697 DEBUG (MainThread) [pyisy] ISY command on sent to 47494.
2023-02-01 12:21:17.706 DEBUG (MainThread) [pyisy] ISY Response Received: /nodes/20615/cmd/DON
2023-02-01 12:21:17.707 DEBUG (MainThread) [pyisy] ISY command on sent to 20615.
2023-02-01 12:21:17.875 INFO (MainThread) [custom_components.pyscript.apps.automatic_light.entity_trigger] garage_lighting: Triggered: expr=switch.garage_workshop_lights value=on
2023-02-01 12:21:17.888 INFO (MainThread) [custom_components.pyscript.apps.automatic_light.lighting_trigger] garage_lighting: Lighting trigger: value=on, self.ms_triggered=False
2023-02-01 12:21:17.905 INFO (MainThread) [custom_components.pyscript.apps.automatic_light.lighting_trigger] garage_lighting: lux=10000.0, self.light_level=10000.0, on? False
2023-02-01 12:21:17.906 INFO (MainThread) [custom_components.pyscript.apps.automatic_light.lighting_trigger] garage_lighting: Turning on lights
2023-02-01 12:21:17.937 DEBUG (MainThread) [pyisy] ISY Request: http://192.168.1.218:80/rest/nodes/40%205C%2062%201/cmd/DON
2023-02-01 12:21:18.171 DEBUG (MainThread) [pyisy] ISY Updated Node: 3C 45 4C 1
2023-02-01 12:21:18.187 DEBUG (MainThread) [pyisy] ISY Updated Node: 3C DA D1 1
2023-02-01 12:21:18.190 DEBUG (MainThread) [pyisy] ISY Updated Node: 3C EF 16 1
2023-02-01 12:21:18.203 DEBUG (MainThread) [pyisy] ISY Updated Node: 3C DC 50 1
2023-02-01 12:21:18.210 ERROR (MainThread) [pyisy] ISY Reported an Invalid Command Received /nodes/40%205C%2062%201/cmd/DON
2023-02-01 12:21:18.215 DEBUG (MainThread) [pyisy] ISY is busy, waiting for system to be ready
2023-02-01 12:21:18.674 DEBUG (MainThread) [pyisy] ISY Updated Node: 40 5D 77 1
2023-02-01 12:21:18.685 INFO (MainThread) [custom_components.pyscript.apps.automatic_light.entity_trigger] laundry_room_lighting: Triggered: expr=switch.laundryrm_light_scene value=on
2023-02-01 12:21:18.686 DEBUG (MainThread) [pyisy] ISY Updated Node: 40 68 61 1
2023-02-01 12:21:18.689 INFO (MainThread) [custom_components.pyscript.apps.automatic_light.lighting_trigger] laundry_room_lighting: Lighting trigger: value=on, self.ms_triggered=False
2023-02-01 12:21:18.689 INFO (MainThread) [custom_components.pyscript.apps.automatic_light.lighting_trigger] laundry_room_lighting: lux=10000.0, self.light_level=10000.0, on? False
2023-02-01 12:21:18.690 INFO (MainThread) [custom_components.pyscript.apps.automatic_light.lighting_trigger] laundry_room_lighting: Turning on lights
2023-02-01 12:21:18.700 ERROR (MainThread) [pyisy] ISY Reported an Invalid Command Received /nodes/3C%20EB%20EC%201/cmd/DON
2023-02-01 12:21:18.701 WARNING (MainThread) [pyisy] ISY could not send on command to 3C EB EC 1.
2023-02-01 12:21:18.703 DEBUG (MainThread) [custom_components.isy994] Unable to turn on light
2023-02-01 12:21:18.705 ERROR (MainThread) [pyisy] ISY Reported an Invalid Command Received /nodes/40%205C%2062%201/cmd/DON
2023-02-01 12:21:18.706 WARNING (MainThread) [pyisy] ISY could not send on command to 40 5C 62 1.
2023-02-01 12:21:18.707 DEBUG (MainThread) [custom_components.isy994] Unable to turn on light
2023-02-01 12:21:18.709 DEBUG (MainThread) [pyisy] ISY Request: http://192.168.1.218:80/rest/nodes/40%205C%2062%201/cmd/DON
2023-02-01 12:21:19.148 DEBUG (MainThread) [pyisy] ISY Response Received: /nodes/40%205C%2062%201/cmd/DON
2023-02-01 12:21:19.148 DEBUG (MainThread) [pyisy] ISY command on sent to 40 5C 62 1.
2023-02-01 12:21:19.464 DEBUG (MainThread) [pyisy] ISY Updated Node: 40 5C 62 1

[shbatm]

Very strange behavior (by the ISY). This must be something they fixed in the IoX versions because I can't replicate it-even trying to control 20 Insteon devices individually.

The last 4 lines above--was that you retrying the command or it did it just trail behind?

[rccoleman]

I didn't do anything special, just ran the actions of an automation that turns on several ISY scenes in succession. The same thing has been happening for years and I even tried swapping the SD card at one point. I don't know what else I could do to experiment.

For completeness, the action looks like this:

  action:
    - data:
        entity_id:
          - light.garage
          - switch.kit_lights_scene
          - switch.dnh_lights_scene
          - switch.laundryrm_light_scene
          - light.fr
      service: homeassistant.turn_on

where the first is an Insteon device, the next 3 are Insteon scenes, and the last is a light group that contains an Insteon device and a Zigbee group.

I've replaced it with this:

  action:
    - data:
        entity_id:
          - switch.garage_door_open
          - switch.fr_lamp_group
      service: homeassistant.turn_on

which controls an Insteon scene and a Zigbee group. I've so far found the scene to be a bit less reliable, presumably because I don't think devices respond ack/nak to the broadcast scene command, but it probably also means that there's some noise interfering with the Insteon traffic.