Open shbatm opened 1 year ago
@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
@rccoleman Alternatively, test with this branch of Home Assistant: https://github.com/shbatm/home-assistant-core/tree/isy994_wait-for-ready
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.
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"
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
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?
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.
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 isNOT_BUSY
before retrying again. If the system is still busy after 5 seconds, an ISYConnectionError is raised.Fixes #184