Group binding does not work for rwl021

[Jsl-1]

Hi

I have just migrated from zigpy-zigate to zigpy-znp with CC2652RB device and I try to bind my philips RWL021 to a specific group.
I use dev branch to unbind coordinator first ( 62de24d , #54)

I am not sure witch one of bind unbind failed first, but it's not working for me

Log for unbind coordinator : https://pastebin.com/6BrNmeLC
Log for bind remote to group: https://pastebin.com/7S7Ai5Sr

I'ts working before with zigpy-zigate by doing this:

• unbind coordinator and press button remote
• bind group and press button on remote

Does anyone had success with this ?

[TheJulianJES]

If i recall correctly, it also worked with the bellows library with the Elelabs stick I used before.
The issue seems to be that the dimmer is not correctly unbound from the coordinator, as I'm still getting zha_events when pressing a button.

[puddly]

Hmm. I tested this out with a bulb and a sniffer when adding the command and both the bind and unbind commands were sent over the air.

Your first log shows the coordinator sending the bind request a few times but it never receives a reply. The second log with the unbind request shows that it does work and the device replies to the unbind request with a NO_ENTRY status.

Is the dimmer joined directly to the coordinator as a child?

I don't have Hue devices but I will try this with a battery operated IKEA dimmer and see what happens.

[Jsl-1]

Hi @puddly

Thank you very much for your help.

I confirm, the dimmer is joined directly to the coordinator. I have tried to disconnect all router devices, reset remote, rejoin. No more luck.

[Jsl-1]

Hi,

I manage to unbind coordinator by using zha_custom.execute with data from this comment :
zigpy/zha-device-handlers#336 (comment)

Group binding is now working.

I call zha_custom.execute with data:

ieee: ieee_address_of_rwl021_remote
command: unbind_coordinator
command_data: 6

ieee: ieee_address_of_rwl021_remote
command: unbind_coordinator
command_data: 8

ieee: ieee_address_of_rwl021_remote
command: unbind_coordinator
command_data: 5

[MattWestb]

Great that you was getting it working !!

I don't understand way your attempt using unbind in the device card cluster commands was not working and you can doing it successful zha_custum commands.

I was for 3 days ago rejoining my after one firmware update on EZSP NCP without doing backup (NOT by the book) and was losing the network.

I was only selecting the coordinator and on/off, level and scene cluster and unbind from device and then the the same cluster with bind groupe and the prefered groupe and it was working.

My RWL021 is connected to one good router in the network if it can giving one clue and the coordinator is EZSP one.

One thing with controlling device is that it can being necessary sending one "configure this device" from device card then attribute reporting is being broken after new binding is done and also the pull control can being problems and your device is draining the battery

@puddly IKEA controllers is normally no problem doing one new groupe binding without unbind then there is new joined but the RWL021 is not accepting any new binds until its being compleet unbinded from the coordinator (i think the RWL021 is adding the 0x0000 as default then being reseted = binding table is populated and the IKEA is not adding it but is defaulting to 0x0000 after being reseted = binding table is not populated). I have testing it in Tasmota and adding binds command is working OK (the device is replaying OK) but its not working until sending one unbind from the default bonded coordinator then its start sending the commands to the new groupe.
I also remember the NO_ENTRY replay you is getting then sending the unbind command the second time and the first time the replay is SUCCESS.

@TheJulianJES I think you is having one new TI coordinator and the dimmer.
Do it working OK for you doing device unbinding from device card and and groupe binding of the RWL021 ??
You is writing partly in pressens and also like you is still having the problem so little confusing.

[Jsl-1]

Hi @MattWestb ,

Maybe it's not working because i use zha_custom.execute. I'm not sure but maybe it's working because I use unbind coordinator on endpoint 0xFC00 (or maybe is it a coincidence)

I tried to start from zero again :

• Remove RWL021 FROM ZHA
• Factory Reset RWL021
• Restart HA
• Re-pair RWL021
• Bind to group (OnOff/LevelControl/Scene) (from cluster management GUI)

2021-01-18 10:39:34 DEBUG (MainThread) [zigpy.zdo] [0x200d:zdo] 0x200d: Bind_req 00:17:88:01:04:ef:c7:b4, ep: 1, cluster: 8 to group: 0x0002 completed: [<Status.SUCCESS: 0>]
2021-01-18 10:39:34 DEBUG (MainThread) [zigpy.zdo] [0x200d:zdo] 0x200d: Bind_req 00:17:88:01:04:ef:c7:b4, ep: 1, cluster: 6 to group: 0x0002 failed: [0x200d:0:0x0021]: Message send failure
2021-01-18 10:39:34 DEBUG (MainThread) [zigpy.zdo] [0x200d:zdo] 0x200d: Bind_req 00:17:88:01:04:ef:c7:b4, ep: 1, cluster: 5 to group: 0x0002 failed: [0x200d:0:0x0021]: Message send failure

Full log : https://pastebin.ubuntu.com/p/Tdwp7dBt33/

• Call Unbind on coordinator (from cluster management GUI)

2021-01-18 10:45:34 DEBUG (MainThread) [zigpy.zdo] [0x200d:zdo] processing cluster: 6 Unbind_req --> [00:12:4b:00:21:cc:41:f3]
2021-01-18 10:45:34 DEBUG (MainThread) [zigpy.zdo] [0x200d:zdo] processing cluster: 8 Unbind_req --> [00:12:4b:00:21:cc:41:f3]
2021-01-18 10:45:34 DEBUG (MainThread) [zigpy.device] [0x200d] Extending timeout for 0x78 request
2021-01-18 10:45:34 DEBUG (MainThread) [zigpy.device] [0x200d] Extending timeout for 0x79 request
2021-01-18 10:45:49 DEBUG (MainThread) [zigpy.zdo] [0x200d:zdo] cluster: 6 Unbind_req --> [00:12:4b:00:21:cc:41:f3] failed:
2021-01-18 10:45:49 DEBUG (MainThread) [zigpy.zdo] [0x200d:zdo] cluster: 8 Unbind_req --> [00:12:4b:00:21:cc:41:f3] failed:

Full log : https://pastebin.ubuntu.com/p/cx82VSmm6s/

• Call unbind on coordinator (from zha_custom.execute)

ieee: 00:17:88:01:04:ef:c7:b4
command: unbind_coordinator
command_data: 6

ieee: 00:17:88:01:04:ef:c7:b4
command: unbind_coordinator
command_data: 8

ieee: 00:17:88:01:04:ef:c7:b4
command: unbind_coordinator
command_data: 5

2021-01-18 10:53:05 INFO (MainThread) [custom_components.zha_custom] Running custom service: <ServiceCall zha_custom.execute (c:d0cc6014abb05c97b29ebcfc8fcc496e): ieee=00:17:88:01:04:ef:c7:b4, command=unbind_coordinator, command_data=6>
2021-01-18 10:53:05 DEBUG (MainThread) [zigpy.device] [0x200d] Extending timeout for 0xae request
2021-01-18 10:53:05 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.ExtRouteChk.Req(Dst=0x200D, RtStatus=<RouteStatus.ACTIVE: 1>, Options=<RouteOptions.NO_ROUTE_CACHE|MTO_ROUTE: 3>)
2021-01-18 10:53:05 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ExtRouteChk.Rsp(Status=<RoutingStatus.SUCCESS: 0>)
2021-01-18 10:53:05 DEBUG (MainThread) [zigpy_znp.zigbee.application] Intercepted a ZDO request: dst_addr=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x200D), dst_ep=0, src_ep=0, cluster=ZDOCmd.Unbind_req, sequence=174, options=TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST, radius=30, data=b'\xae\xb4\xc7\xef\x04\x01\x88\x17\x00\x01\x06\x00\x03\xf3A\xcc!\x00K\x12\x00\x02'
2021-01-18 10:53:05 DEBUG (MainThread) [zigpy_znp.zigbee.application] Intercepted AP ZDO request ZDOCmd.Unbind_req({'SrcAddress': 00:17:88:01:04:ef:c7:b4, 'SrcEndpoint': 1, 'ClusterID': 6, 'DstAddress': MultiAddress(addrmode=3, ieee=00:12:4b:00:21:cc:41:f3, endpoint=2)}) and replaced with ZDO.UnBindReq.Req(Dst=0x200D, Src=00:17:88:01:04:ef:c7:b4, SrcEndpoint=1, ClusterId=6, Address=MultiAddress(addrmode=3, ieee=00:12:4b:00:21:cc:41:f3, endpoint=2))
2021-01-18 10:53:05 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.UnBindReq.Req(Dst=0x200D, Src=00:17:88:01:04:ef:c7:b4, SrcEndpoint=1, ClusterId=6, Address=MultiAddress(addrmode=3, ieee=00:12:4b:00:21:cc:41:f3, endpoint=2))
2021-01-18 10:53:05 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.UnBindReq.Rsp(Status=<Status.SUCCESS: 0>)
2021-01-18 10:53:07 DEBUG (MainThread) [zigpy.util] Tries remaining: 1
2021-01-18 10:53:07 DEBUG (MainThread) [zigpy.device] [0x75e6] Extending timeout for 0xaf request
2021-01-18 10:53:07 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.ExtRouteChk.Req(Dst=0x75E6, RtStatus=<RouteStatus.ACTIVE: 1>, Options=<RouteOptions.NO_ROUTE_CACHE|MTO_ROUTE: 3>)
2021-01-18 10:53:07 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ExtRouteChk.Rsp(Status=<RoutingStatus.FAIL: 1>)
2021-01-18 10:53:07 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.ExtRouteDisc.Req(Dst=0x75E6, Options=<RouteDiscoveryOptions.UNICAST: 0>, Radius=30)
2021-01-18 10:53:07 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ExtRouteDisc.Rsp(Status=<Status.SUCCESS: 0>)
2021-01-18 10:53:07 DEBUG (MainThread) [zigpy_znp.zigbee.application] Intercepted a ZDO request: dst_addr=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x75E6), dst_ep=0, src_ep=0, cluster=ZDOCmd.Mgmt_Lqi_req, sequence=175, options=TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST, radius=30, data=b'\xaf\x00'
2021-01-18 10:53:07 DEBUG (MainThread) [zigpy_znp.zigbee.application] Intercepted AP ZDO request ZDOCmd.Mgmt_Lqi_req({'StartIndex': 0}) and replaced with ZDO.MgmtLqiReq.Req(Dst=0x75E6, StartIndex=0)
2021-01-18 10:53:07 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.MgmtLqiReq.Req(Dst=0x75E6, StartIndex=0)
2021-01-18 10:53:07 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MgmtLqiReq.Rsp(Status=<Status.SUCCESS: 0>)
2021-01-18 10:53:11 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=zha_custom, service=execute, service_data=ieee=00:17:88:01:04:ef:c7:b4, command=unbind_coordinator, command_data=8>
2021-01-18 10:53:11 INFO (MainThread) [custom_components.zha_custom] Running custom service: <ServiceCall zha_custom.execute (c:723b8086029cbdeb023e279de2aea0ce): ieee=00:17:88:01:04:ef:c7:b4, command=unbind_coordinator, command_data=8>
2021-01-18 10:53:11 DEBUG (MainThread) [zigpy.device] [0x200d] Extending timeout for 0xb0 request
2021-01-18 10:53:11 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.ExtRouteChk.Req(Dst=0x200D, RtStatus=<RouteStatus.ACTIVE: 1>, Options=<RouteOptions.NO_ROUTE_CACHE|MTO_ROUTE: 3>)
2021-01-18 10:53:11 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ExtRouteChk.Rsp(Status=<RoutingStatus.SUCCESS: 0>)
2021-01-18 10:53:11 DEBUG (MainThread) [zigpy_znp.zigbee.application] Intercepted a ZDO request: dst_addr=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x200D), dst_ep=0, src_ep=0, cluster=ZDOCmd.Unbind_req, sequence=176, options=TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST, radius=30, data=b'\xb0\xb4\xc7\xef\x04\x01\x88\x17\x00\x01\x08\x00\x03\xf3A\xcc!\x00K\x12\x00\x02'
2021-01-18 10:53:11 DEBUG (MainThread) [zigpy_znp.zigbee.application] Intercepted AP ZDO request ZDOCmd.Unbind_req({'SrcAddress': 00:17:88:01:04:ef:c7:b4, 'SrcEndpoint': 1, 'ClusterID': 8, 'DstAddress': MultiAddress(addrmode=3, ieee=00:12:4b:00:21:cc:41:f3, endpoint=2)}) and replaced with ZDO.UnBindReq.Req(Dst=0x200D, Src=00:17:88:01:04:ef:c7:b4, SrcEndpoint=1, ClusterId=8, Address=MultiAddress(addrmode=3, ieee=00:12:4b:00:21:cc:41:f3, endpoint=2))
2021-01-18 10:53:11 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.UnBindReq.Req(Dst=0x200D, Src=00:17:88:01:04:ef:c7:b4, SrcEndpoint=1, ClusterId=8, Address=MultiAddress(addrmode=3, ieee=00:12:4b:00:21:cc:41:f3, endpoint=2))
2021-01-18 10:53:11 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.UnBindReq.Rsp(Status=<Status.SUCCESS: 0>)
2021-01-18 10:53:15 DEBUG (MainThread) [homeassistant.core] Service did not complete before timeout: <ServiceCall zha_custom.execute (c:d0cc6014abb05c97b29ebcfc8fcc496e): ieee=00:17:88:01:04:ef:c7:b4, command=unbind_coordinator, command_data=6>
2021-01-18 10:53:15 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=zha_custom, service=execute, service_data=ieee=00:17:88:01:04:ef:c7:b4, command=unbind_coordinator, command_data=5>
2021-01-18 10:53:15 INFO (MainThread) [custom_components.zha_custom] Running custom service: <ServiceCall zha_custom.execute (c:bc78adace665046efbf8a1ebff905534): ieee=00:17:88:01:04:ef:c7:b4, command=unbind_coordinator, command_data=5>
2021-01-18 10:53:15 DEBUG (MainThread) [zigpy.device] [0x200d] Extending timeout for 0xb1 request
2021-01-18 10:53:15 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.ExtRouteChk.Req(Dst=0x200D, RtStatus=<RouteStatus.ACTIVE: 1>, Options=<RouteOptions.NO_ROUTE_CACHE|MTO_ROUTE: 3>)
2021-01-18 10:53:15 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ExtRouteChk.Rsp(Status=<RoutingStatus.SUCCESS: 0>)
2021-01-18 10:53:15 DEBUG (MainThread) [zigpy_znp.zigbee.application] Intercepted a ZDO request: dst_addr=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x200D), dst_ep=0, src_ep=0, cluster=ZDOCmd.Unbind_req, sequence=177, options=TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST, radius=30, data=b'\xb1\xb4\xc7\xef\x04\x01\x88\x17\x00\x01\x05\x00\x03\xf3A\xcc!\x00K\x12\x00\x02'
2021-01-18 10:53:15 DEBUG (MainThread) [zigpy_znp.zigbee.application] Intercepted AP ZDO request ZDOCmd.Unbind_req({'SrcAddress': 00:17:88:01:04:ef:c7:b4, 'SrcEndpoint': 1, 'ClusterID': 5, 'DstAddress': MultiAddress(addrmode=3, ieee=00:12:4b:00:21:cc:41:f3, endpoint=2)}) and replaced with ZDO.UnBindReq.Req(Dst=0x200D, Src=00:17:88:01:04:ef:c7:b4, SrcEndpoint=1, ClusterId=5, Address=MultiAddress(addrmode=3, ieee=00:12:4b:00:21:cc:41:f3, endpoint=2))
2021-01-18 10:53:15 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.UnBindReq.Req(Dst=0x200D, Src=00:17:88:01:04:ef:c7:b4, SrcEndpoint=1, ClusterId=5, Address=MultiAddress(addrmode=3, ieee=00:12:4b:00:21:cc:41:f3, endpoint=2))
2021-01-18 10:53:15 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.UnBindReq.Rsp(Status=<Status.SUCCESS: 0>)

Full log : https://pastebin.ubuntu.com/p/p89Hv3bzKV/

• Bind group again

2021-01-18 10:57:02 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.BindReq.Req(Dst=0x200D, Src=00:17:88:01:04:ef:c7:b4, SrcEndpoint=1, ClusterId=8, Address=MultiAddress(addrmode=1, nwk=2))
2021-01-18 10:57:02 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.BindReq.Rsp(Status=<Status.SUCCESS: 0>)
2021-01-18 10:57:02 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.BindReq.Req(Dst=0x200D, Src=00:17:88:01:04:ef:c7:b4, SrcEndpoint=1, ClusterId=6, Address=MultiAddress(addrmode=1, nwk=2))
2021-01-18 10:57:02 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.BindReq.Rsp(Status=<Status.SUCCESS: 0>)
2021-01-18 10:57:02 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.BindReq.Req(Dst=0x200D, Src=00:17:88:01:04:ef:c7:b4, SrcEndpoint=1, ClusterId=5, Address=MultiAddress(addrmode=1, nwk=2))
2021-01-18 10:57:02 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.BindReq.Rsp(Status=<Status.SUCCESS: 0>)

I though it is ok, but my remote does not work and has no effect on the group

Maybe because i have not seen that 😇

2021-01-18 10:57:17 DEBUG (MainThread) [zigpy.zdo] [0x200d:zdo] 0x200d: Bind_req 00:17:88:01:04:ef:c7:b4, ep: 1, cluster: 8 to group: 0x0002 failed:
2021-01-18 10:57:17 DEBUG (MainThread) [zigpy.zdo] [0x200d:zdo] 0x200d: Bind_req 00:17:88:01:04:ef:c7:b4, ep: 1, cluster: 6 to group: 0x0002 failed:
2021-01-18 10:57:17 DEBUG (MainThread) [zigpy.zdo] [0x200d:zdo] 0x200d: Bind_req 00:17:88:01:04:ef:c7:b4, ep: 1, cluster: 5 to group: 0x0002 failed:

So i tried again to unbind coordinator from remote endpoint 0xFC00 with this data (because i have done that the last time , when i get remote
working with group)

ieee: 00:17:88:01:04:ef:c7:b4
command: unbind_coordinator
command_data: 0xfc00

and do again all unbinding coordinator / binding group many times because it's not working.

And finally its working :/
All this other stuff logs should be in : https://pastebin.ubuntu.com/p/XpcnQhYQks/

I don't have the skill to understand...

[TheJulianJES]

@TheJulianJES I think you is having one new TI coordinator and the dimmer.
Do it working OK for you doing device unbinding from device card and and groupe binding of the RWL021 ??
You is writing partly in pressens and also like you is still having the problem so little confusing.

@MattWestb
I migrated my network from an Elelabs stick to a ZZH stick (with an awesome script by puddly).
I thought that unbinding the dimmer from the Zigbee coordinator worked with my Elelabs stick and now just doesn't work on my ZZH stick, but perhaps it also never worked with the Elelabs stick (in that case this issue wouldn't be the fault of zigpy_znp).
All in all, I'm currently unable to unbind the dimmer from the coordinator with the latest commits on dev. I guess I could try with zha_custom though.

[MattWestb]

@Jsl-1 You have doing great logging but the past bin is little wrong but i think its no problems.
You is getting time out many times then the system is trying sending commands to the remote.
Its one sleeping end devices and its need to being waked up little before you is sending one command to it (normally only pressing one button on the remote and then clicking on (un)bind.

You can see in your log if the commons wos ok received by the device if its sending one SUCCESS.

And if you is getting this [zigpy_znp.api] Received command: ZDO.BindRsp.Callback(Src=0x200D, Status=<Status.TABLE_FULL: 140>) then trying to binding the unbinding wos not working and try unbinding it one more time before try binding the cluster.

@TheJulianJES I deleting my remote and trying to joining it and binding with my EZSP for see is its only one TI problem or one zigpy / ZHA one.
I'll be back !!!

[MattWestb]

@TheJulianJES I was deleting it and joining it (hardware reset thru pinhole on the back side for 10 seconds) OK.
Unbind "IKEA Billy EZSP" (its my coordinator) OK
Bind On/Off, Level and Scene to groupe "Essecke Licht" = not working.
Sending reconfig to the remote = not working.
More bind and unbind = not working.

Deleting and joining OK.
Unbind Billy OK
Bind to the groupe level and on/off (not the scenes cluster !) = OK working !!!
Sending one reconfigure this device = OK

I can remember that the scene cluster (0x0008) have making troubles before and should not being bonded and its braking the other (perhaps its cant handle so many different bindings ?).

[Jsl-1]

Thank you @MattWestb for your time and explanations.

I close this issue as it's not related to zigpy-znp.

I will try later with another RWL021 and read the log more carefully when doing bind/unbind ;)

Thank you all for your help !