Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Implement Command Retry Methods when ISY Overwhelms Insteon Network #184

Open
shbatm opened this issue May 17, 2021 · 15 comments · May be fixed by #380
Open

Implement Command Retry Methods when ISY Overwhelms Insteon Network #184

shbatm opened this issue May 17, 2021 · 15 comments · May be fixed by #380

Comments

@shbatm
Copy link
Collaborator

shbatm commented May 17, 2021

Reference from #145

Thanks for the pointer to this discussion. It does seem like the retry mechanism that you're discussing would help with the issue that I'm seeing, but unrelated to the issue above. The typical case for me is that turning on a bunch of lights causes the ISY to sporadically respond with "404" (not found) errors via REST, resulting in the light not being turned on and the error mentioned in that issue. It's been happening forever with no indication that UDI will change the behavior, and it seems like an inappropriate error message to indicate that the Insteon network is "busy" (as UDI has diagnosed). In any case, I look forward to having commands retried if they fail.

Originally posted by @rccoleman in #145 (comment)
@shbatm shbatm mentioned this issue May 17, 2021
Closed
@rccoleman
Copy link
Contributor

I've been using a slightly modified version of pyisy that supports retries for quite a while and it really improves the reliability of the integration. All the retry logic is already in place, it's just inactive because you're returning here. Simply removing that line causes the retry logic later in the function to kick in.

I had temporarily reverted to the released pyisy when changes in the 2023.2.0 beta made mine incompatible and immediately started seeing lights not turning on as expected due to the ISY rejecting the commands. I'm going to remove that return statement and see if it goes back to "normal" for me.

@shbatm
Copy link
Collaborator Author

shbatm commented Jan 30, 2023 •
edited
Loading

A few questions:

  1. What hardware are you using? Is this still an ISY or is it a Polisy/eisy?
  2. How many lights are you trying to trigger at a single time?
  3. Can you confirm the ISY is giving you a 404 error when it's getting overwhelmed? (I thought it was supposed to be a 400 or 503 error when busy).

Just removing the return statement there has some knock-on effects elsewhere, so the proper fix is to add an argument (like ok404=True, but one that forces retries) to the send_cmd function.

The general recommended method is still going to be to use Scenes or ISY Programs to trigger the bulk changes, because there are times when you want it to fail immediately and not keep retrying 5 times (e.g. a command we know is bad or sent to the wrong address)--it's not possible (currently) to tell those apart from brute-forcing the Insteon network if they both return 404.

Also, coming in the next version, the module will listen to System Busy events, so in theory it will be able to throttle commands if the ISY is busy.

@rccoleman
Copy link
Contributor

rccoleman commented Jan 30, 2023 •
edited
Loading

What hardware are you using? Is this still an ISY or is it a Polisy/eisy?

It's still an ISY994 running 5.3.4.

How many lights are you trying to trigger at a single time?

It's only 4 or 5, including a couple of scenes for 3-way switches. It's really not a lot, but I can clearly see ISY Reported an Invalid Command Received in the log, which only comes from HTTP_NOT_FOUND. I agree that scenes are useful when controlling multiple lights, but I'm really not trying to light up the world, and I would generally prefer to keep my ISY config minimal and handle grouping in HA when response time isn't critical.

Can you confirm the ISY is giving you a 404 error when it's getting overwhelmed? (I thought it was supposed to be a 400 or 503 error when busy).

Yes, it gives me a 404, which has always seemed like the wrong response code. It's been like this for many, many years. I agree that it seems like 503 is the right response, but there didn't seem to be much appetite to address it at UDI when I brought this up on their forum years ago. The "ok, ok, ok, I have no idea what device you're talking about" response sequence is just bizarre.

It looks like ok404 is being used for things like "ping", rather than a command that really should get a valid response. Maybe we need some other retry404 flag.

@shbatm
Copy link
Collaborator Author

shbatm commented Jan 30, 2023

Thanks for the details.

It looks like ok404 is being used for things like "ping", rather than a command that really should get a valid response. Maybe we need some other retry404 flag.

Yes, it needs to be a new parameter, since ok404 won't trigger a retry.

Let me make some more progress on v4--I'd like to just resolve this with watching for the ISY being busy if I can.

If you have the capability -- you could test v4 running separately from Home Assistant and see if it's correctly flagging "Busy" in the log when you try and control the lights from HA. You just need a computer with Python 3.9+ on it:

python3 -m pip install pyisy-beta==4.0.0.dev5
python3 -m pyisy http://your-isy-ip admin "yourpassword"

You should see it show something like below:

2023-01-30 22:32:17 DEBUG [pyisy.events.websocket] ISY HEARTBEAT: 2023-01-30T22:32:17.108252
2023-01-30 22:32:39 INFO [__main__] System Status Changed: Busy
2023-01-30 22:32:39 INFO [__main__] System Status Changed: Not Busy

@rccoleman
Copy link
Contributor

rccoleman commented Jan 30, 2023 •
edited
Loading

Sure, I'm happy to help test. I'll run that separately and see if the logs are correlated.

Edit: I just kicked that off and I'm getting a ton of errors at startup, but it seems to have settled down. Things like:

2023-01-30 14:40:49 DEBUG [pyisy] Response received: /nodes
2023-01-30 14:40:50 ERROR [pyisy] Error loading nodes: __init__() got an unexpected keyword argument 'e_l_k__i_d'
Traceback (most recent call last):
  File "/home/rcoleman/.local/lib/python3.9/site-packages/pyisy/nodes/__init__.py", line 133, in parse_node_entity
    entity = Node(self, address, name, NodeDetail(**feature))
TypeError: __init__() got an unexpected keyword argument 'e_l_k__i_d'

and

2023-01-30 14:40:50 ERROR [pyisy] Error loading nodes: '3C F6 83 1'
Traceback (most recent call last):
  File "/home/rcoleman/.local/lib/python3.9/site-packages/pyisy/nodes/__init__.py", line 147, in parse_group_entity
    entity = Group(self, address, name, GroupDetail(**feature))
  File "/home/rcoleman/.local/lib/python3.9/site-packages/pyisy/nodes/group.py", line 73, in __init__
    self._members_handlers = [
  File "/home/rcoleman/.local/lib/python3.9/site-packages/pyisy/nodes/group.py", line 74, in <listcomp>
    self.platform.entities[m].status_events.subscribe(self.update_callback)
KeyError: '3C F6 83 1'
Exception ignored in: <function Group.__del__ at 0x7f0dde785ee0>
Traceback (most recent call last):
  File "/home/rcoleman/.local/lib/python3.9/site-packages/pyisy/nodes/group.py", line 83, in __del__
    for handler in self._members_handlers:
AttributeError: 'Group' object has no attribute '_members_handlers'

and

2023-01-30 14:40:57 ERROR [asyncio] Task exception was never retrieved
future: <Task finished name='Task-60' coro=<Nodes.update_node() done, defined at /home/rcoleman/.local/lib/python3.9/site-packages/pyisy/nodes/__init__.py:251> exception=KeyError('3C F6 83 1')>
Traceback (most recent call last):
  File "/home/rcoleman/.local/lib/python3.9/site-packages/pyisy/nodes/__init__.py", line 280, in update_node
    entity = cast(Node, self.entities[address])
KeyError: '3C F6 83 1'
2023-01-30 14:40:57 DEBUG [pyisy] Response received: /nodes/3C 45 4C 3?members=true

I'll keep an eye on it

@shbatm
Copy link
Collaborator Author

shbatm commented Jan 31, 2023

Thanks for testing... this should take care of a few of those errors:

pip install pyisy-beta==4.0.0a1

@rccoleman
Copy link
Contributor

rccoleman commented Jan 31, 2023 •
edited
Loading

Yep, that helped. I just triggered the automation that typically exhibits the issue and sure enough, I got this:

2023-01-30 18:59:10.256 ERROR (MainThread) [pyisy] ISY Reported an Invalid Command Received /nodes/40%205C%2062%201/cmd/DON
2023-01-30 18:59:10.913 ERROR (MainThread) [pyisy] ISY Reported an Invalid Command Received /nodes/3C%20EB%20EC%201/cmd/DON
2023-01-30 18:59:10.915 ERROR (MainThread) [pyisy] ISY Reported an Invalid Command Received /nodes/40%205C%2062%201/cmd/DON
2023-01-30 18:59:10.916 ERROR (MainThread) [pyisy] ISY Reported an Invalid Command Received /nodes/40%205C%2062%201/cmd/DON
2023-01-30 18:59:10.925 INFO (MainThread) [custom_components.pyscript.apps.automatic_light.entity_trigger] laundry_room_lighting: Triggered: expr=switch.laundryrm_light_scene value=on
2023-01-30 18:59:10.925 INFO (MainThread) [custom_components.pyscript.apps.automatic_light.lighting_trigger] laundry_room_lighting: Lighting trigger: value=on, self.ms_triggered=False
2023-01-30 18:59:10.926 INFO (MainThread) [custom_components.pyscript.apps.automatic_light.lighting_trigger] laundry_room_lighting: lux=10000.0, self.light_level=10000.0, on? False
2023-01-30 18:59:10.926 INFO (MainThread) [custom_components.pyscript.apps.automatic_light.lighting_trigger] laundry_room_lighting: Turning on lights
2023-01-30 18:59:11.195 ERROR (MainThread) [pyisy] ISY Reported an Invalid Command Received /nodes/3C%20EB%20EC%201/cmd/DON

Over that same period of time, I got this with pyisy-beta:

2023-01-30 18:58:51 INFO [__main__] System Status Changed: Busy
2023-01-30 18:58:51 INFO [__main__] System Status Changed: Not Busy
2023-01-30 18:58:51 DEBUG [pyisy] Updated node state: Kitchen Table Light (3C F6 83 1), changed=state
2023-01-30 18:59:02 DEBUG [pyisy.events.websocket] ISY HEARTBEAT: 2023-01-30T18:59:02.328965
2023-01-30 18:59:09 INFO [__main__] System Status Changed: Busy
2023-01-30 18:59:09 INFO [__main__] System Status Changed: Not Busy
2023-01-30 18:59:09 DEBUG [pyisy] Updated node state: Recessed Light (Bar) (3C E8 A8 1), changed=state
2023-01-30 18:59:09 DEBUG [pyisy] Updated node state: Recessed Light (Foyer) (3C E7 86 1), changed=state
2023-01-30 18:59:09 INFO [__main__] System Status Changed: Busy
2023-01-30 18:59:09 INFO [__main__] System Status Changed: Not Busy
2023-01-30 18:59:09 INFO [__main__] System Status Changed: Busy
2023-01-30 18:59:09 INFO [__main__] System Status Changed: Not Busy
2023-01-30 18:59:09 INFO [__main__] System Status Changed: Busy
2023-01-30 18:59:10 DEBUG [pyisy] Updated node state: Kitchen Lights (3C 45 4C 1), changed=state
2023-01-30 18:59:10 DEBUG [pyisy] Updated node state: Lights (Dining) (3C DA D1 1), changed=state
2023-01-30 18:59:10 DEBUG [pyisy] Updated node state: Pendant Lights (3C EF 16 1), changed=state
2023-01-30 18:59:10 DEBUG [pyisy] Updated node state: Sink Light (3C DC 50 1), changed=state
2023-01-30 18:59:10 DEBUG [pyisy] Updated node state: Recessed Light (Hallway) (40 5D 77 1), changed=state
2023-01-30 18:59:10 DEBUG [pyisy] Updated node state: Recessed Light (Garage) (40 68 61 1), changed=state
2023-01-30 18:59:10 INFO [__main__] System Status Changed: Not Busy
2023-01-30 18:59:10 INFO [__main__] System Status Changed: Busy
2023-01-30 18:59:11 INFO [__main__] System Status Changed: Not Busy
2023-01-30 18:59:11 INFO [__main__] System Status Changed: Busy
2023-01-30 18:59:11 DEBUG [pyisy] Updated node state: Garage Lights (40 5C 62 1), changed=state
2023-01-30 18:59:12 INFO [__main__] System Status Changed: Not Busy
2023-01-30 18:59:12 DEBUG [pyisy] Updated node state: Torchiere Lights (3C EB EC 1), changed=state
2023-01-30 18:59:27 DEBUG [pyisy.events.websocket] ISY HEARTBEAT: 2023-01-30T18:59:27.320459
2023-01-30 18:59:52 DEBUG [pyisy.events.websocket] ISY HEARTBEAT: 2023-01-30T18:59:52.312193
2023-01-30 19:00:17 DEBUG [pyisy.events.websocket] ISY HEARTBEAT: 2023-01-30T19:00:17.303642
2023-01-30 19:00:42 DEBUG [pyisy.events.websocket] ISY HEARTBEAT: 2023-01-30T19:00:42.295191
2023-01-30 19:01:07 DEBUG [pyisy.events.websocket] ISY HEARTBEAT: 2023-01-30T19:01:07.286772
2023-01-30 19:01:09 INFO [__main__] System Status Changed: Busy
2023-01-30 19:01:09 INFO [__main__] System Status Changed: Not Busy
2023-01-30 19:01:09 DEBUG [pyisy] Updated node state: Recessed Light (Bar) (3C E8 A8 1), changed=state
2023-01-30 19:01:09 DEBUG [pyisy] Updated node state: Recessed Light (Foyer) (3C E7 86 1), changed=state
2023-01-30 19:01:10 INFO [__main__] System Status Changed: Busy
2023-01-30 19:01:10 INFO [__main__] System Status Changed: Not Busy
2023-01-30 19:01:10 DEBUG [pyisy] Updated node state: Recessed Light (Hallway) (40 5D 77 1), changed=state
2023-01-30 19:01:10 DEBUG [pyisy] Updated node state: Recessed Light (Garage) (40 68 61 1), changed=state

Eventually all the lights did come on, but this one came on a bit later and I'm sure wouldn't have come on at all if I didn't have retries in place. It's usually the one that stays off.

2023-01-30 18:59:10.913 ERROR (MainThread) [pyisy] ISY Reported an Invalid Command Received /nodes/3C%20EB%20EC%201/cmd/DON

That corresponds with this line, where it succeeded a couple of seconds later:

2023-01-30 18:59:12 DEBUG [pyisy] Updated node state: Torchiere Lights (3C EB EC 1), changed=state

It definitely was busy doing stuff at 18:59:10 and it looks like it executed 6 commands while rejecting the others. It also looks like it retries Garage Lights (40 5C 62 1) many times in rapid succession for some reason. I'll see if I can figure out if that's coming from my automation.

@shbatm
Copy link
Collaborator Author

shbatm commented Jan 31, 2023

Ok. So it's definitely registering that's its busy. I can work with that. It does seem like it's getting overloaded very easily though, and I don't know if that's a function of the Insteon network or the ISY994 (FWIW, I just switched to polisy and holy crap is there a speed difference--~15s load time to <2s)

Can you do the same test again, but run the pyisy-beta command with a -v flag after your password? That will dump the raw output from the socket.

@rccoleman
Copy link
Contributor

rccoleman commented Jan 31, 2023 •
edited
Loading

Sure. Here are the HA logs:

2023-01-30 19:21:00.217 INFO (MainThread) [homeassistant.components.automation.garage_open_turn_on_lights_dark] Garage open turn on lights Dark: Running automation actions
2023-01-30 19:21:00.217 INFO (MainThread) [homeassistant.components.automation.garage_open_turn_on_lights_dark] Garage open turn on lights Dark: Executing step call service
2023-01-30 19:21:00.217 INFO (MainThread) [homeassistant.components.automation.door_opened] Door Opened: Running automation actions
2023-01-30 19:21:00.217 INFO (MainThread) [homeassistant.components.automation.door_opened] Door Opened: Executing step call service
2023-01-30 19:21:00.269 INFO (MainThread) [homeassistant.components.automation.door_opened] Door Opened: Executing step call service
2023-01-30 19:21:00.606 INFO (MainThread) [custom_components.pyscript.apps.automatic_light.entity_trigger] garage_lighting: Triggered: expr=light.garage_lights value=on
2023-01-30 19:21:00.607 INFO (MainThread) [custom_components.pyscript.apps.automatic_light.lighting_trigger] garage_lighting: Lighting trigger: value=on, self.ms_triggered=False
2023-01-30 19:21:00.608 INFO (MainThread) [custom_components.pyscript.apps.automatic_light.lighting_trigger] garage_lighting: lux=10000.0, self.light_level=10000.0, on? False
2023-01-30 19:21:00.609 INFO (MainThread) [custom_components.pyscript.apps.automatic_light.lighting_trigger] garage_lighting: Turning on lights
2023-01-30 19:21:00.826 INFO (MainThread) [custom_components.pyscript.apps.automatic_light.entity_trigger] garage_lighting: Triggered: expr=switch.garage_workshop_lights value=on
2023-01-30 19:21:00.827 INFO (MainThread) [custom_components.pyscript.apps.automatic_light.lighting_trigger] garage_lighting: Lighting trigger: value=on, self.ms_triggered=False
2023-01-30 19:21:01.104 ERROR (MainThread) [pyisy] ISY Reported an Invalid Command Received /nodes/3C%20EB%20EC%201/cmd/DON
2023-01-30 19:21:01.646 ERROR (MainThread) [pyisy] ISY Reported an Invalid Command Received /nodes/3C%20EB%20EC%201/cmd/DON
2023-01-30 19:21:02.122 INFO (MainThread) [custom_components.pyscript.apps.automatic_light.entity_trigger] laundry_room_lighting: Triggered: expr=switch.laundryrm_light_scene value=on
2023-01-30 19:21:02.124 INFO (MainThread) [custom_components.pyscript.apps.automatic_light.lighting_trigger] laundry_room_lighting: Lighting trigger: value=on, self.ms_triggered=False
2023-01-30 19:21:02.125 INFO (MainThread) [custom_components.pyscript.apps.automatic_light.lighting_trigger] laundry_room_lighting: lux=10000.0, self.light_level=10000.0, on? False
2023-01-30 19:21:02.126 INFO (MainThread) [custom_components.pyscript.apps.automatic_light.lighting_trigger] laundry_room_lighting: Turning on lights
2023-01-30 19:21:02.150 ERROR (MainThread) [pyisy] ISY Reported an Invalid Command Received /nodes/3C%20EB%20EC%201/cmd/DON
2023-01-30 19:21:05.210 INFO (MainThread) [homeassistant.components.automation.garage_door_open_announcement] Garage Door Open Announcement: Running automation actions
2023-01-30 19:21:05.210 INFO (MainThread) [homeassistant.components.automation.garage_door_open_announcement] Garage Door Open Announcement: Executing step call service

And the output from the pyisy-beta:

2023-01-30 19:21:00 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="199" sid="uuid:937"><control>_5</control><action>1</action><node></node><eventInfo></eventInfo></Event>
2023-01-30 19:21:00 INFO [__main__] System Status Changed: Busy
2023-01-30 19:21:00 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="200" sid="uuid:937"><control>_5</control><action>0</action><node></node><eventInfo></eventInfo></Event>
2023-01-30 19:21:00 INFO [__main__] System Status Changed: Not Busy
2023-01-30 19:21:00 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="201" sid="uuid:937"><control>_5</control><action>1</action><node></node><eventInfo></eventInfo></Event>
2023-01-30 19:21:00 INFO [__main__] System Status Changed: Busy
2023-01-30 19:21:00 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="202" sid="uuid:937"><control>_5</control><action>0</action><node></node><eventInfo></eventInfo></Event>
2023-01-30 19:21:00 INFO [__main__] System Status Changed: Not Busy
2023-01-30 19:21:00 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="203" sid="uuid:937"><control>_5</control><action>1</action><node></node><eventInfo></eventInfo></Event>
2023-01-30 19:21:00 INFO [__main__] System Status Changed: Busy
2023-01-30 19:21:00 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="204" sid="uuid:937"><control>_5</control><action>0</action><node></node><eventInfo></eventInfo></Event>
2023-01-30 19:21:00 INFO [__main__] System Status Changed: Not Busy
2023-01-30 19:21:00 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="205" sid="uuid:937"><control>ST</control><action uom="100" prec="0">255</action><node>40 5C 62 1</node><eventInfo></eventInfo><fmtAct>100%</fmtAct></Event>
2023-01-30 19:21:00 DEBUG [pyisy] Updated node state: Garage Lights (40 5C 62 1), changed=state
2023-01-30 19:21:00 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="206" sid="uuid:937"><control>_5</control><action>1</action><node></node><eventInfo></eventInfo></Event>
2023-01-30 19:21:00 INFO [__main__] System Status Changed: Busy
2023-01-30 19:21:00 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="207" sid="uuid:937"><control>_5</control><action>0</action><node></node><eventInfo></eventInfo></Event>
2023-01-30 19:21:00 INFO [__main__] System Status Changed: Not Busy
2023-01-30 19:21:00 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="208" sid="uuid:937"><control>_5</control><action>1</action><node></node><eventInfo></eventInfo></Event>
2023-01-30 19:21:00 INFO [__main__] System Status Changed: Busy
2023-01-30 19:21:01 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="209" sid="uuid:937"><control>_5</control><action>0</action><node></node><eventInfo></eventInfo></Event>
2023-01-30 19:21:01 INFO [__main__] System Status Changed: Not Busy
2023-01-30 19:21:01 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="210" sid="uuid:937"><control>_5</control><action>1</action><node></node><eventInfo></eventInfo></Event>
2023-01-30 19:21:01 INFO [__main__] System Status Changed: Busy
2023-01-30 19:21:01 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="211" sid="uuid:937"><control>_1</control><action>3</action><node></node><eventInfo>[  40 5C 62 1]       ST 255 (uom=100 prec=0)</eventInfo></Event>
2023-01-30 19:21:01 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="212" sid="uuid:937"><control>ST</control><action uom="100" prec="0">255</action><node>3C 45 4C 1</node><eventInfo></eventInfo><fmtAct>100%</fmtAct></Event>
2023-01-30 19:21:01 DEBUG [pyisy] Updated node state: Kitchen Lights (3C 45 4C 1), changed=state
2023-01-30 19:21:01 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="213" sid="uuid:937"><control>ST</control><action uom="100" prec="0">255</action><node>3C DA D1 1</node><eventInfo></eventInfo><fmtAct>100%</fmtAct></Event>
2023-01-30 19:21:01 DEBUG [pyisy] Updated node state: Lights (Dining) (3C DA D1 1), changed=state
2023-01-30 19:21:01 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="214" sid="uuid:937"><control>ST</control><action uom="100" prec="0">255</action><node>3C EF 16 1</node><eventInfo></eventInfo><fmtAct>100%</fmtAct></Event>
2023-01-30 19:21:01 DEBUG [pyisy] Updated node state: Pendant Lights (3C EF 16 1), changed=state
2023-01-30 19:21:01 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="215" sid="uuid:937"><control>ST</control><action uom="100" prec="0">255</action><node>3C DC 50 1</node><eventInfo></eventInfo><fmtAct>100%</fmtAct></Event>
2023-01-30 19:21:01 DEBUG [pyisy] Updated node state: Sink Light (3C DC 50 1), changed=state
2023-01-30 19:21:01 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="216" sid="uuid:937"><control>_5</control><action>0</action><node></node><eventInfo></eventInfo></Event>
2023-01-30 19:21:01 INFO [__main__] System Status Changed: Not Busy
2023-01-30 19:21:01 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="217" sid="uuid:937"><control>_5</control><action>1</action><node></node><eventInfo></eventInfo></Event>
2023-01-30 19:21:01 INFO [__main__] System Status Changed: Busy
2023-01-30 19:21:02 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="218" sid="uuid:937"><control>_1</control><action>3</action><node></node><eventInfo>[  3C 45 4C 1]       ST 255 (uom=100 prec=0)</eventInfo></Event>
2023-01-30 19:21:02 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="219" sid="uuid:937"><control>_1</control><action>3</action><node></node><eventInfo>[  3C DA D1 1]       ST 255 (uom=100 prec=0)</eventInfo></Event>
2023-01-30 19:21:02 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="220" sid="uuid:937"><control>ST</control><action uom="100" prec="0">255</action><node>40 5D 77 1</node><eventInfo></eventInfo><fmtAct>100%</fmtAct></Event>
2023-01-30 19:21:02 DEBUG [pyisy] Updated node state: Recessed Light (Hallway) (40 5D 77 1), changed=state
2023-01-30 19:21:02 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="221" sid="uuid:937"><control>ST</control><action uom="100" prec="0">255</action><node>40 68 61 1</node><eventInfo></eventInfo><fmtAct>100%</fmtAct></Event>
2023-01-30 19:21:02 DEBUG [pyisy] Updated node state: Recessed Light (Garage) (40 68 61 1), changed=state
2023-01-30 19:21:02 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="222" sid="uuid:937"><control>_1</control><action>3</action><node></node><eventInfo>[  3C EF 16 1]       ST 255 (uom=100 prec=0)</eventInfo></Event>
2023-01-30 19:21:02 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="223" sid="uuid:937"><control>_1</control><action>3</action><node></node><eventInfo>[  3C DC 50 1]       ST 255 (uom=100 prec=0)</eventInfo></Event>
2023-01-30 19:21:02 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="224" sid="uuid:937"><control>_1</control><action>3</action><node></node><eventInfo>[  40 5D 77 1]       ST 255 (uom=100 prec=0)</eventInfo></Event>
2023-01-30 19:21:02 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="225" sid="uuid:937"><control>_1</control><action>3</action><node></node><eventInfo>[  40 68 61 1]       ST 255 (uom=100 prec=0)</eventInfo></Event>
2023-01-30 19:21:02 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="226" sid="uuid:937"><control>_5</control><action>0</action><node></node><eventInfo></eventInfo></Event>
2023-01-30 19:21:02 INFO [__main__] System Status Changed: Not Busy
2023-01-30 19:21:02 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="227" sid="uuid:937"><control>_5</control><action>1</action><node></node><eventInfo></eventInfo></Event>
2023-01-30 19:21:02 INFO [__main__] System Status Changed: Busy
2023-01-30 19:21:02 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="228" sid="uuid:937"><control>_5</control><action>0</action><node></node><eventInfo></eventInfo></Event>
2023-01-30 19:21:02 INFO [__main__] System Status Changed: Not Busy
2023-01-30 19:21:02 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="229" sid="uuid:937"><control>ST</control><action uom="100" prec="0">128</action><node>3C EB EC 1</node><eventInfo></eventInfo><fmtAct>50%</fmtAct></Event>
2023-01-30 19:21:02 DEBUG [pyisy] Updated node state: Torchiere Lights (3C EB EC 1), changed=state
2023-01-30 19:21:02 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="230" sid="uuid:937"><control>_1</control><action>3</action><node></node><eventInfo>[  3C EB EC 1]       ST 128 (uom=100 prec=0)</eventInfo></Event>
2023-01-30 19:21:06 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="231" sid="uuid:937"><control>_0</control><action>120</action><node></node><eventInfo></eventInfo></Event>
2023-01-30 19:21:06 DEBUG [pyisy.events.websocket] ISY HEARTBEAT: 2023-01-30T19:21:06.484691
2023-01-30 19:21:31 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="232" sid="uuid:937"><control>_0</control><action>120</action><node></node><eventInfo></eventInfo></Event>
2023-01-30 19:21:31 DEBUG [pyisy.events.websocket] ISY HEARTBEAT: 2023-01-30T19:21:31.476790
2023-01-30 19:21:45 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="233" sid="uuid:937"><control>_5</control><action>1</action><node></node><eventInfo></eventInfo></Event>
2023-01-30 19:21:45 INFO [__main__] System Status Changed: Busy
2023-01-30 19:21:45 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="234" sid="uuid:937"><control>_5</control><action>0</action><node></node><eventInfo></eventInfo></Event>
2023-01-30 19:21:45 INFO [__main__] System Status Changed: Not Busy
2023-01-30 19:21:45 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="235" sid="uuid:937"><control>ST</control><action uom="100" prec="0">0</action><node>3C E8 A8 1</node><eventInfo></eventInfo><fmtAct>Off</fmtAct></Event>
2023-01-30 19:21:45 DEBUG [pyisy] Updated node state: Recessed Light (Bar) (3C E8 A8 1), changed=state
2023-01-30 19:21:45 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="236" sid="uuid:937"><control>ST</control><action uom="100" prec="0">0</action><node>3C E7 86 1</node><eventInfo></eventInfo><fmtAct>Off</fmtAct></Event>
2023-01-30 19:21:45 DEBUG [pyisy] Updated node state: Recessed Light (Foyer) (3C E7 86 1), changed=state
2023-01-30 19:21:45 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="237" sid="uuid:937"><control>_1</control><action>3</action><node></node><eventInfo>[  3C E8 A8 1]       ST   0 (uom=100 prec=0)</eventInfo></Event>
2023-01-30 19:21:45 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="238" sid="uuid:937"><control>_1</control><action>3</action><node></node><eventInfo>[  3C E7 86 1]       ST   0 (uom=100 prec=0)</eventInfo></Event>
2023-01-30 19:21:51 VERBOSE [pyisy.events.router] <?xml version="1.0"?><Event seqnum="239" sid="uuid:937"><control>_0</control><action>120</action><node></node><eventInfo></eventInfo></Event>
2023-01-30 19:21:51 DEBUG [pyisy.events.websocket] ISY HEARTBEAT: 2023-01-30T19:21:51.470409

I also made a small change to my automation to reduce the spam a bit. I have two lights in my garage and a PyScript app that turns the other one on if one turns on, so it can get a little spammy if they're both turned on as a group (which I was doing). I still saw the typical several second delay in the torchiere lights turning on, though, undoubtedly due to the retries.

@shbatm
Copy link
Collaborator Author

shbatm commented Jan 31, 2023

Thanks. I don't see anything out of the ordinary doing additional work, but something is bogging down your ISY more than it needs to be--it should be able to handle that traffic.

For reference, I just tested 7 Insteon devices, tied to several different programs and variable updates, and it didn't balk... There was a 2s delay, but no errors. Maybe there's better tolerance and buffer on the Polisy side.

2023-01-31 03:55:35.710 DEBUG (MainThread) [pyisy] ISY Request: http://192.168.30.9:8080/rest/nodes/57%202F%20F2%201/cmd/DON
2023-01-31 03:55:35.711 DEBUG (MainThread) [pyisy] ISY Request: http://192.168.30.9:8080/rest/nodes/23%20B5%2068%201/cmd/DON
2023-01-31 03:55:35.711 DEBUG (MainThread) [pyisy] ISY Request: http://192.168.30.9:8080/rest/nodes/42%20B4%201C%201/cmd/DON
2023-01-31 03:55:35.711 DEBUG (MainThread) [pyisy] ISY Request: http://192.168.30.9:8080/rest/nodes/23%20B5%2098%201/cmd/DON
2023-01-31 03:55:35.712 DEBUG (MainThread) [pyisy] ISY Request: http://192.168.30.9:8080/rest/nodes/23%20D5%206%201/cmd/DON
2023-01-31 03:55:35.712 DEBUG (MainThread) [pyisy] ISY Request: http://192.168.30.9:8080/rest/nodes/25%209%208B%201/cmd/DON
2023-01-31 03:55:35.712 DEBUG (MainThread) [pyisy] ISY Request: http://192.168.30.9:8080/rest/nodes/57%203B%20C5%201/cmd/DON
2023-01-31 03:55:35.728 DEBUG (MainThread) [pyisy] ISY Response Received: /nodes/57%202F%20F2%201/cmd/DON
2023-01-31 03:55:35.728 DEBUG (MainThread) [pyisy] ISY command on sent to 57 2F F2 1.
2023-01-31 03:55:35.728 DEBUG (MainThread) [pyisy] ISY Response Received: /nodes/23%20B5%2068%201/cmd/DON
2023-01-31 03:55:35.728 DEBUG (MainThread) [pyisy] ISY command on sent to 23 B5 68 1.
2023-01-31 03:55:35.730 DEBUG (MainThread) [pyisy] ISY Response Received: /nodes/42%20B4%201C%201/cmd/DON
2023-01-31 03:55:35.730 DEBUG (MainThread) [pyisy] ISY command on sent to 42 B4 1C 1.
2023-01-31 03:55:36.048 DEBUG (MainThread) [pyisy] ISY Updated Node: 57 2F F2 1
2023-01-31 03:55:36.050 DEBUG (MainThread) [pyisy] ISY Updated Program: 0016
2023-01-31 03:55:36.053 DEBUG (MainThread) [pyisy] ISY Updated Program: 0015
2023-01-31 03:55:36.055 DEBUG (MainThread) [pyisy] ISY Updated Program: 000B
2023-01-31 03:55:36.056 DEBUG (MainThread) [pyisy] ISY Updated Program: 000B
2023-01-31 03:55:36.056 DEBUG (MainThread) [pyisy] ISY Updated Variable: 2.17
2023-01-31 03:55:36.097 DEBUG (MainThread) [pyisy] ISY Updated Program: 000B
2023-01-31 03:55:36.097 DEBUG (MainThread) [pyisy] ISY Updated Program: 000C
2023-01-31 03:55:36.640 DEBUG (MainThread) [pyisy] ISY Updated Node: 23 B5 68 1
2023-01-31 03:55:36.641 DEBUG (MainThread) [pyisy] ISY Updated Program: 006E
2023-01-31 03:55:37.124 DEBUG (MainThread) [pyisy] ISY Updated Node: 42 B4 1C 1
2023-01-31 03:55:37.127 DEBUG (MainThread) [pyisy] ISY Updated Program: 009F
2023-01-31 03:55:37.128 DEBUG (MainThread) [pyisy] ISY Updated Program: 0046
2023-01-31 03:55:37.130 DEBUG (MainThread) [pyisy] ISY Updated Program: 00A0
2023-01-31 03:55:37.131 DEBUG (MainThread) [pyisy] ISY Updated Program: 0046
2023-01-31 03:55:37.133 DEBUG (MainThread) [pyisy] ISY Updated Variable: 2.24
2023-01-31 03:55:37.165 DEBUG (MainThread) [pyisy] ISY Updated Program: 0046
2023-01-31 03:55:37.167 DEBUG (MainThread) [pyisy] ISY Updated Program: 006E
2023-01-31 03:55:37.785 DEBUG (MainThread) [pyisy] ISY Response Received: /nodes/23%20B5%2098%201/cmd/DON
2023-01-31 03:55:37.785 DEBUG (MainThread) [pyisy] ISY command on sent to 23 B5 98 1.
2023-01-31 03:55:37.785 DEBUG (MainThread) [pyisy] ISY Response Received: /nodes/23%20D5%206%201/cmd/DON
2023-01-31 03:55:37.785 DEBUG (MainThread) [pyisy] ISY command on sent to 23 D5 6 1.
2023-01-31 03:55:37.786 DEBUG (MainThread) [pyisy] ISY Response Received: /nodes/25%209%208B%201/cmd/DON
2023-01-31 03:55:37.786 DEBUG (MainThread) [pyisy] ISY command on sent to 25 9 8B 1.
2023-01-31 03:55:38.108 DEBUG (MainThread) [pyisy] ISY Updated Node: 23 D5 6 1
2023-01-31 03:55:38.110 DEBUG (MainThread) [pyisy] ISY Updated Program: 009F
2023-01-31 03:55:38.112 DEBUG (MainThread) [pyisy] ISY Updated Program: 00A0
2023-01-31 03:55:38.114 DEBUG (MainThread) [pyisy] ISY Updated Program: 0041
2023-01-31 03:55:38.115 DEBUG (MainThread) [pyisy] ISY Updated Program: 0040
2023-01-31 03:55:38.149 DEBUG (MainThread) [pyisy] ISY Updated Program: 0015
2023-01-31 03:55:38.688 DEBUG (MainThread) [pyisy] ISY Updated Node: 23 B5 98 1
2023-01-31 03:55:39.207 DEBUG (MainThread) [pyisy] ISY Updated Node: 25 9 8B 1
2023-01-31 03:55:39.620 DEBUG (MainThread) [pyisy] ISY Response Received: /nodes/57%203B%20C5%201/cmd/DON
2023-01-31 03:55:39.620 DEBUG (MainThread) [pyisy] ISY command on sent to 57 3B C5 1.
2023-01-31 03:55:39.626 DEBUG (MainThread) [pyisy] ISY Updated Program: 000C
2023-01-31 03:55:39.627 DEBUG (MainThread) [pyisy] ISY Updated Program: 0041
2023-01-31 03:55:39.628 DEBUG (MainThread) [pyisy] ISY Updated Program: 0040
2023-01-31 03:55:39.629 DEBUG (MainThread) [pyisy] ISY Updated Program: 0041
2023-01-31 03:55:39.630 DEBUG (MainThread) [pyisy] ISY Updated Program: 0040
2023-01-31 03:55:39.993 DEBUG (MainThread) [pyisy] ISY Updated Node: 22 E5 E5 1
2023-01-31 03:55:39.995 DEBUG (MainThread) [pyisy] ISY Updated Program: 000C
2023-01-31 03:55:40.159 DEBUG (MainThread) [pyisy.events.websocket] ISY HEARTBEAT: 2023-01-31T03:55:40.159691
2023-01-31 03:55:40.473 DEBUG (MainThread) [pyisy] ISY Updated Node: 57 3B C5 1
2023-01-31 03:55:41.186 DEBUG (MainThread) [pyisy] ISY Updated Node: 25 8 20 1
2023-01-31 03:55:41.187 DEBUG (MainThread) [pyisy] ISY Updated Program: 000C
2023-01-31 03:55:41.189 DEBUG (MainThread) [pyisy] ISY Updated Node: 56 D3 A5 6
2023-01-31 03:55:41.190 DEBUG (MainThread) [pyisy] ISY Updated Program: 0016
2023-01-31 03:55:41.191 DEBUG (MainThread) [pyisy] ISY Updated Program: 0015
2023-01-31 03:55:42.269 DEBUG (MainThread) [pyisy] ISY Updated Program: 00A0
2023-01-31 03:55:42.272 DEBUG (MainThread) [pyisy] ISY Updated Node: 25 9 8B 3
2023-01-31 03:55:42.274 DEBUG (MainThread) [pyisy] ISY Updated Program: 009F
2023-01-31 03:55:42.274 DEBUG (MainThread) [pyisy] ISY Updated Program: 00A0
2023-01-31 03:56:10.183 DEBUG (MainThread) [pyisy.events.websocket] ISY HEARTBEAT: 2023-01-31T03:56:10.183024

Also, for PyScript, just an FYI but you can set your own context for a call and check to see if it was called by your script to make sure you don't have any duplicate calls (see attached), and in general, I make sure anything that is just a status update (e.g. a slave dimmer with no load) has a 1-2 second delay to get out of the way of the other traffic.

living_room_fan.py.txt

@rccoleman
Copy link
Contributor

Yeah, it does seem to get bogged down easily. I moved all the logic to HA a long time ago, so there are no programs or anything that should be taxing it. Because of that, I would seriously consider just moving to the PLM integration rather than spending money on updated UDI equipment at this point. But if the isy994 can be made to work more reliably, I'll stick with it. It's just a glorified PLM for me with a UI to manage devices and scenes.

@shbatm
Copy link
Collaborator Author

shbatm commented Jan 31, 2023

It's just a glorified PLM for me with a UI to manage devices and scenes.

This is all mine is now (the Polisy was bought during the first batch before I was all in for HA).

I know you're trying to keep the ISY side minimal, but if you have anything you control in a group of 2 or more devices you're going to have significantly better reliability by making them a Scene, even if there's no controller beside the PLM/ISY. Those scenes are stored in the devices themselves as 1 link, so it's not only a single command to the ISY, but a single command to the Insteon network as well. If they aren't something I need exposed in Home Assistant, I add them in the ISY then make them Hidden in Home Assistant to just use them for the automations.

I'm slowly working on getting rid of the need for the ISY console, but i haven't gotten to group updates yet.

About the only other thing I use the ISY for now is programs that 'sync' other insteon device statuses (e.g. Update a slave KPL button when the load is directly controlled from HA).

@rccoleman
Copy link
Contributor

I suppose I can create very custom scenes for specific use cases. It's annoying because I typically have mixed Insteon, ZWave, and Zigbee devices that need to be controlled, and all of the latter two are only in HA. So I'll need to create a group that includes that special scene + any non-Insteon devices. Doable, just cumbersome.

@shbatm
Copy link
Collaborator Author

shbatm commented Jan 31, 2023

So I'll need to create a group that includes that special scene + any non-Insteon devices. Doable, just cumbersome.

Yep, that's essentially what I do. Insteon and Zigbee use native groups wherever possible for response time (Zigbee groups function the same as Insteon scenes--single command to multiple devices), then add in anything else that HA controls.

If it's something that I want to control from Insteon (like from a KPL button) I have a second group that excludes the Insteon scene and an automation that listens for the isy994_control event from the button--this lets the Insteon scene controller natively do it's thing on the Insteon network, and then HA picks up the rest. So for the example below: "all_off_exit" would be what I control with/expose to a user in Home Assistant, and all_off_exit_hass gets triggered by the isy994_control for the 2 KPL buttons by the front and back doors--those buttons are controllers for the All Off Exit scene in the ISY.

# Groups without _hass include ISY Scenes.
# These allow control repsonse from an ISY All Off without duplicating
# the Insteon traffic

group:
  all_off_exit:
    name: All Off Exit
    entities:
      - switch.all_off_exit # ISY Scene
      - group.all_off_exit_hass

  all_off_exit_hass:
    name: All Off Exit Hass
    entities:
      - light.zb_all_off_exit  # Zigbee native group
      - group.all_off_exit_zwave  # Manual HA Z-Wave Group
      - light.living_room_lamps
      - light.mirror_art
      - light.game_room_tv_leds
      - light.living_room_tv_leds

More convoluted than I'd like, but response time is damn-near instantaneous. Hitting the all-off button on a KPL will kill all the Insteon lights and Zigbee Lights (100+ devices) in <1s, with the Z-Wave tailing a bit behind because of the individual commands required.

@rccoleman
Copy link
Contributor

with the Z-Wave tailing a bit behind because of the individual commands required.

I created a script sequence to initiate multicast commands for ZWave and then a template switch to call them so that it could be included in a group. I've since moved to Zigbee (which is super-fast with native groups), but that's one way to improve the ZWave performance and make it more like Zigbee groups & Insteon scenes.

In any case, I agree that scenes are preferable and I'll see how I can optimize my ISY communication this weekend. The basic problem will still remain, and but may can wait for pyisy4 for a long-term solution.

This was referenced Feb 1, 2023
Open
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Wait for ISY to be ready when retrying commands automicus/PyISY
2 participants
@rccoleman @shbatm