Ok, I experimented by taking my light switch out of the zigbee group it was in and also removed all of its bindings. I also removed any other switches in the group. When I turn the light switch on, Home Assistant received the button press almost instantly and the shelly switch that I’m trying to control is immediately switched. These are the commands found in the log:
2024-06-09 19:28:09.770 DEBUG (MainThread) [zigpy.zcl] [0xD9EC:2:0x0006]
Received command 0x01 (TSN 48): on()
2024-06-09 19:28:09.776 DEBUG (MainThread) [zigpy.zcl] [0xD9EC:2:0x0008]
Received command 0x04 (TSN 49): move_to_level_with_on_off(level=254, transition_time=5)
2024-06-09 19:28:09.828 DEBUG (MainThread) [zigpy.zcl] [0xD9EC:2:0xfc31]
Received command 0x00 (TSN 50): button_event(button_pressed=2, press_type=0)
So, the switch sends on(), followed by moved_to_level_with_on_off(), followed by button_event(). This takes place in 58ms. It still suggests that if I want to respond as fast as possible, I should listen to the on event, and not the button events.
Then I bound my switch to a single smart bulb. Everything was still fast. I unbound it from the single smart bulb.
Then, I bound my switch to a group for OnOff and LevelControl. This group has about a dozen smart bulbs in it. But, at this point there is nothing other than the smart bulbs (no inovelli switches or anything else). Suddenly, the delay is long again. These are what I think are the relevant commands found in the log:
2024-06-09 20:55:20.380 DEBUG (MainThread) [zigpy.application] Received a packet:
ZigbeePacket(timestamp=datetime.datetime(2024, 6, 10, 0, 55, 20, 380065, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xD9EC), src_ep=2, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=0, profile_id=260, cluster_id=6, data=Serialized[b'\x11[\x01'], tx_options=<TransmitOptions.NONE: 0>, radius=29, non_member_radius=0, lqi=25, rssi=None)
2024-06-09 20:55:20.381 DEBUG (MainThread) [zigpy.zcl] [0xD9EC:2:0x0006]
Received command 0x01 (TSN 91): on()
2024-06-09 20:55:20.420 DEBUG (MainThread) [zigpy.application] Received a packet:
ZigbeePacket(timestamp=datetime.datetime(2024, 6, 10, 0, 55, 20, 420295, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xD9EC), src_ep=2, dst=AddrModeAddress(addr_mode=<AddrMode.Group: 1>, address=0x000B), dst_ep=1, source_route=None, extended_timeout=False, tsn=0, profile_id=260, cluster_id=6, data=Serialized[b'\x11[\x01'], tx_options=<TransmitOptions.NONE: 0>, radius=10, non_member_radius=0, lqi=105, rssi=None)
2024-06-09 20:55:20.421 DEBUG (MainThread) [zigpy.zcl] [0xD9EC:2:0x0006]
Received command 0x01 (TSN 91): on()
2024-06-09 20:55:22.365 DEBUG (MainThread) [zigpy.application]
Received a packet: ZigbeePacket(timestamp=datetime.datetime(2024, 6, 10, 0, 55, 22, 365377, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xD9EC), src_ep=2, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=0, profile_id=260, cluster_id=64561, data=Serialized[b'\x15/\x12]\x00\x02\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=29, non_member_radius=0, lqi=32, rssi=None)
2024-06-09 20:55:22.366 DEBUG (MainThread) [zigpy.zcl] [0xD9EC:2:0xfc31]
Received command 0x00 (TSN 93): button_event(button_pressed=2, press_type=0)
2024-06-09 20:55:22.778 DEBUG (MainThread) [zigpy.application] Received a packet:
ZigbeePacket(timestamp=datetime.datetime(2024, 6, 10, 0, 55, 22, 778242, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xD9EC), src_ep=2, dst=AddrModeAddress(addr_mode=<AddrMode.Group: 1>, address=0x000B), dst_ep=1, source_route=None, extended_timeout=False, tsn=0, profile_id=260, cluster_id=8, data=Serialized[b'\x11\\\x04\xfe\x05\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=11, non_member_radius=0, lqi=18, rssi=None)
2024-06-09 20:55:22.779 DEBUG (MainThread) [zigpy.zcl] [0xD9EC:2:0x0008]
Received command 0x04 (TSN 92): move_to_level_with_on_off(level=254, transition_time=5)
2024-06-09 20:55:22.847 DEBUG (MainThread) [zigpy.application] Received a packet:
ZigbeePacket(timestamp=datetime.datetime(2024, 6, 10, 0, 55, 22, 847682, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xD9EC), src_ep=2, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=0, profile_id=260, cluster_id=8, data=Serialized[b'\x11\\\x04\xfe\x05\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=29, non_member_radius=0, lqi=47, rssi=None)
2024-06-09 20:55:22.848 DEBUG (MainThread) [zigpy.zcl] [0xD9EC:2:0x0008]
Received command 0x04 (TSN 92): move_to_level_with_on_off(level=254, transition_time=5)
The switch seems to be sending two on() and move_to_level_with_on_off() events. I think the separate commands are actually to the group it’s bound to (group 0x000B) and the coordinator, 0x0000), which I suppose makes sense. I’m not sure that’s actually related to the issue.
The button event here seems to come really long after the on events, and then the move_to_level events are processed. This is not fully consistent as some times it is much faster, and also sometimes the order that the commands are received is different. Another time I did the logs, the timing was:
2024-06-09 21:00:57.081 DEBUG (MainThread) [zigpy.zcl] [0xD9EC:2:0x0006]
Received command 0x01 (TSN 103): on()
2024-06-09 21:00:57.504 DEBUG (MainThread) [zigpy.zcl] [0xD9EC:1:0x0008]
Received command 0x0A (TSN 107): Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=uint8_t, value=254))])
2024-06-09 21:00:57.590 DEBUG (MainThread) [zigpy.zcl] [0xD9EC:2:0x0008]
Received command 0x04 (TSN 104): move_to_level_with_on_off(level=254, transition_time=5)
2024-06-09 21:00:57.606 DEBUG (MainThread) [zigpy.zcl] [0xD9EC:1:0x0006]
Received command 0x0A (TSN 106): Report_Attributes(attribute_reports=[Attribute(attrid=0x0000, value=TypeValue(type=Bool, value=<Bool.true: 1>))])
2024-06-09 21:00:57.611 DEBUG (MainThread) [zigpy.zcl] [0xD9EC:2:0xfc31]
Received command 0x00 (TSN 105): button_event(button_pressed=2, press_type=0)
2024-06-09 21:00:57.617 DEBUG (MainThread) [zigpy.zcl] [0xD9EC:2:0x0006]
Received command 0x01 (TSN 103): on()
2024-06-09 21:00:57.629 DEBUG (MainThread) [zigpy.zcl] [0xD9EC:2:0x0008]
Received command 0x04 (TSN 104): move_to_level_with_on_off(level=254, transition_time=5)
I added in the Report_Attribute commands I noticed here in case this is related.
Are the timestamps reported in the zigbee packet added by the switch or ZHA? I think they are added by the switch when the packet is sent, in which case it’s not a ZHA or network issue. However, I will note that this delay is only being noticed when the switch is bound to a zigbee group (in this case, a large group), not when the switch is not bound to anything or when bound to just one or two lights.
I am noticing now these Report_Attributes commands in the log, and it’s making me wonder if the switch is waiting for something to be reported back to it before it sends the button_event (in which case it would take longer for a large group or when there is a bunch of network traffic). Is that possible?