Skip to content

Removing device from the network doesn't remove device from the database #17

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
Closed
Adminiuga opened this issue May 11, 2020 · 8 comments
Closed

Removing device from the network doesn't remove device from the database #17

Adminiuga opened this issue May 11, 2020 · 8 comments
Labels
bug Something isn't working

Comments

@Adminiuga
Copy link
Contributor

Removing device from the network doesn't remove device from the internal database/device list.
Here's log of device being removed two times. The device does receive the leave request and leaves the network, but it seems it still being kept in the ControllerApplication.devices dict.

On the second "device removed" I was expecting to see "device not found" message

2020-05-10 22:14:00 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.LeaveInd.Callback(NWK=0x66d6, IEEE=7c:b0:3e:aa:00:a5:e4:7f, Request=<Bool.false: 0>, Remove=<Bool.true: 1>, Rejoin=<Bool.false: 0>)
2020-05-10 22:14:00 INFO (MainThread) [zigpy_znp.zigbee.application] ZDO device left: ZDO.LeaveInd.Callback(NWK=0x66d6, IEEE=7c:b0:3e:aa:00:a5:e4:7f, Request=<Bool.false: 0>, Remove=<Bool.true: 1>, Rejoin=<Bool.false: 0>)
2020-05-10 22:14:00 INFO (MainThread) [zigpy.application] Device 0x66d6 (7c:b0:3e:aa:00:a5:e4:7f) left the network
2020-05-10 22:14:07 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xfab6:1:0x0b04]: async_update
2020-05-10 22:14:07 DEBUG (MainThread) [zigpy.device] [0xfab6] Extending timeout for 0x5b request
2020-05-10 22:14:07 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0xfab6), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=2820, TSN=91, Options=<TransmitOptions.RouteDiscovery: 32>, Radius=30, Data=b'\x00\x5B\x00\x0B\x05')
2020-05-10 22:14:07 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.Success: 0>)
2020-05-10 22:14:07 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.NwkNoRoute: 205>, Endpoint=1, TSN=91)
2020-05-10 22:14:07 DEBUG (MainThread) [zigpy_znp.zigbee.application] Received a data request confirmation: AF.DataConfirm.Callback(Status=<Status.NwkNoRoute: 205>, Endpoint=1, TSN=91)
2020-05-10 22:14:07 DEBUG (MainThread) [zigpy.device] [0xfab6] Delivery error for seq # 0x5b, on endpoint id 1 cluster 0x0b04: Invalid response status
2020-05-10 22:14:15 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=zha, service=remove, service_data=ieee_address=7c:b0:3e:aa:00:a5:e4:7f>
2020-05-10 22:14:15 INFO (MainThread) [homeassistant.components.zha.api] Removing node 7c:b0:3e:aa:00:a5:e4:7f
2020-05-10 22:14:15 INFO (MainThread) [zigpy.application] Removing device 0x66d6 (7c:b0:3e:aa:00:a5:e4:7f)
2020-05-10 22:14:15 DEBUG (MainThread) [zigpy_znp.zigbee.application] Intercepted AP ZDO request and replaced with ZDO.MgmtLeaveReq.Req(DstAddr=0x66d6, IEEE=7c:b0:3e:aa:00:a5:e4:7f, RemoveChildren_Rejoin=<LeaveOptions.RemoveChildren: 2>)/ZDO.MgmtLeaveRsp.Callback(Src=0x66d6, Status=None)
2020-05-10 22:14:15 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.MgmtLeaveReq.Req(DstAddr=0x66d6, IEEE=7c:b0:3e:aa:00:a5:e4:7f, RemoveChildren_Rejoin=<LeaveOptions.RemoveChildren: 2>)
2020-05-10 22:14:15 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MgmtLeaveReq.Rsp(Status=<Status.Success: 0>)
2020-05-10 22:14:25 DEBUG (MainThread) [homeassistant.core] Service did not complete before timeout: <ServiceCall zha.remove (c:f6a4607338844eca94304c1bbdaa938f): ieee_address=7c:b0:3e:aa:00:a5:e4:7f>
2020-05-10 22:14:30 DEBUG (MainThread) [zigpy.application] Sending 'zdo_leave_req' failed: 
2020-05-10 22:14:30 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.MgmtLeaveReq.Req(DstAddr=0x0000, IEEE=7c:b0:3e:aa:00:a5:e4:7f, RemoveChildren_Rejoin=<LeaveOptions.NONE: 0>)
2020-05-10 22:14:30 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MgmtLeaveReq.Rsp(Status=<Status.Success: 0>)
2020-05-10 22:14:30 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MgmtLeaveRsp.Callback(Src=0x0000, Status=<Status.SUCCESS: 0>)
2020-05-10 22:14:30 WARNING (MainThread) [zigpy_znp.api] Received an unhandled command: ZDO.MgmtLeaveRsp.Callback(Src=0x0000, Status=<Status.SUCCESS: 0>)
2020-05-10 22:14:37 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xfab6:1:0x0b04]: async_update
2020-05-10 22:14:37 DEBUG (MainThread) [zigpy.device] [0xfab6] Extending timeout for 0x5d request
2020-05-10 22:14:37 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0xfab6), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=2820, TSN=93, Options=<TransmitOptions.RouteDiscovery: 32>, Radius=30, Data=b'\x00\x5D\x00\x0B\x05')
2020-05-10 22:14:37 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.Success: 0>)
2020-05-10 22:14:37 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.NwkNoRoute: 205>, Endpoint=1, TSN=93)
2020-05-10 22:14:37 DEBUG (MainThread) [zigpy_znp.zigbee.application] Received a data request confirmation: AF.DataConfirm.Callback(Status=<Status.NwkNoRoute: 205>, Endpoint=1, TSN=93)
2020-05-10 22:14:37 DEBUG (MainThread) [zigpy.device] [0xfab6] Delivery error for seq # 0x5d, on endpoint id 1 cluster 0x0b04: Invalid response status
2020-05-10 22:14:43 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=zha, service=remove, service_data=ieee_address=7c:b0:3e:aa:00:a5:e4:7f>
2020-05-10 22:14:43 INFO (MainThread) [homeassistant.components.zha.api] Removing node 7c:b0:3e:aa:00:a5:e4:7f
2020-05-10 22:14:43 INFO (MainThread) [zigpy.application] Removing device 0x66d6 (7c:b0:3e:aa:00:a5:e4:7f)
2020-05-10 22:14:43 DEBUG (MainThread) [zigpy_znp.zigbee.application] Intercepted AP ZDO request and replaced with ZDO.MgmtLeaveReq.Req(DstAddr=0x66d6, IEEE=7c:b0:3e:aa:00:a5:e4:7f, RemoveChildren_Rejoin=<LeaveOptions.RemoveChildren: 2>)/ZDO.MgmtLeaveRsp.Callback(Src=0x66d6, Status=None)
2020-05-10 22:14:43 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.MgmtLeaveReq.Req(DstAddr=0x66d6, IEEE=7c:b0:3e:aa:00:a5:e4:7f, RemoveChildren_Rejoin=<LeaveOptions.RemoveChildren: 2>)
2020-05-10 22:14:43 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MgmtLeaveReq.Rsp(Status=<Status.Success: 0>)
2020-05-10 22:14:53 DEBUG (MainThread) [homeassistant.core] Service did not complete before timeout: <ServiceCall zha.remove (c:ca530e4b4f3d48ed89a26220ba8b2923): ieee_address=7c:b0:3e:aa:00:a5:e4:7f>
2020-05-10 22:14:58 DEBUG (MainThread) [zigpy.application] Sending 'zdo_leave_req' failed: 
2020-05-10 22:14:58 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.MgmtLeaveReq.Req(DstAddr=0x0000, IEEE=7c:b0:3e:aa:00:a5:e4:7f, RemoveChildren_Rejoin=<LeaveOptions.NONE: 0>)
2020-05-10 22:14:58 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MgmtLeaveReq.Rsp(Status=<Status.Success: 0>)
2020-05-10 22:14:58 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MgmtLeaveRsp.Callback(Src=0x0000, Status=<Status.SUCCESS: 0>)
2020-05-10 22:14:58 WARNING (MainThread) [zigpy_znp.api] Received an unhandled command: ZDO.MgmtLeaveRsp.Callback(Src=0x0000, Status=<Status.SUCCESS: 0>)
@Adminiuga Adminiuga added the bug Something isn't working label May 11, 2020
@puddly
Copy link
Collaborator

puddly commented May 12, 2020 •
edited
Loading

The device initially didn't respond to the ZDO leave request so Zigpy used force_remove, which sends a ZDO leave request to the coordinator itself via Zigpy.

In either case, Zigpy's ControllerApplication.remove method should have handled this: https://github.com/zigpy/zigpy/blob/b76922c9591f743aa8982809c812fd60113ca975/zigpy/application.py#L125-L143

At the end, the device is popped from the dictionary of known devices and and device_removed event is sent:

self.devices.pop(ieee, None)
self.listener_event("device_removed", dev)

The ZHA component handles the Zigpy event:

    def device_removed(self, device):
        """Handle device being removed from the network."""
        zha_device = self._devices.pop(device.ieee, None)
        entity_refs = self._device_registry.pop(device.ieee, None)
        if zha_device is not None:
            device_info = zha_device.zha_device_info
            zha_device.async_cleanup_handles()
            async_dispatcher_send(
                self._hass, "{}_{}".format(SIGNAL_REMOVE, str(zha_device.ieee))
            )
            asyncio.ensure_future(self._async_remove_device(zha_device, entity_refs))
            if device_info is not None:
                async_dispatcher_send(
                    self._hass,
                    ZHA_GW_MSG,
                    {
                        ATTR_TYPE: ZHA_GW_MSG_DEVICE_REMOVED,
                        ZHA_GW_MSG_DEVICE_INFO: device_info,
                    },
                )

I don't see any reference to device_removed in your log so it appears that zha_device is either None or was never in self._devices in ZHA.

@Adminiuga
Copy link
Contributor Author

It does makes sense, but I have strong suspicion it never gets to https://github.com/zigpy/zigpy/blob/b76922c9591f743aa8982809c812fd60113ca975/zigpy/application.py#L141-L143
in other words I don't think it is poped from dictionary. Otherwise I would expect to see "Device not found for removal" in the log on the second attempt to remove the device. I'll try to put some breakpoints and check again.

on unrelated note: what's the timeout when there's no response?

2020-05-10 22:14:15 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MgmtLeaveReq.Rsp(Status=<Status.Success: 0>)
...
2020-05-10 22:14:30 DEBUG (MainThread) [zigpy.application] Sending 'zdo_leave_req' failed:

Is it 15s?

@puddly
Copy link
Collaborator

puddly commented May 12, 2020

Yes, it's 15 seconds: https://github.com/zha-ng/zigpy-znp/blob/e6d78b26c1b7ea4337ade6235ad6f259346ef20c/zigpy_znp/zigbee/application.py#L31

@puddly
Copy link
Collaborator

puddly commented May 12, 2020 •
edited
Loading

While a bit non-standard, if you can call logging.getLogger('zigpy_znp').setLevel(logging.DEBUG - 5), you will get quite more verbose logging messages. Unfortunately, Home Assistant's config doesn't seem to take numerical level names so I'm not too sure what the best way to do that would be.

You could also change TRACE = logging.DEBUG - 5 to just TRACE = logging.DEBUG in zigpy_znp/utils.py

@Adminiuga
Copy link
Contributor Author

I don't get why with ZNP they have a separate ZDO interface.
When you send out a request via ZDO interface to the network, do you get a confirmation that far end device did get the request?

@puddly
Copy link
Collaborator

puddly commented May 12, 2020 •
edited
Loading

I think that's what the response callback is for, since it's not always delivered: https://github.com/zha-ng/zigpy-znp/blob/e6d78b26c1b7ea4337ade6235ad6f259346ef20c/zigpy_znp/zigbee/application.py#L36-L78

If you don't use their ZDO commands, Z-Stack still intercepts the message but either sends back a named callback or nothing at all.

@Adminiuga
Copy link
Contributor Author

so the

2020-05-10 22:14:15 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MgmtLeaveReq.Rsp(Status=<Status.Success: 0>)

Is this a response/confirmation that far end received the message (TX confirm in other radios) or is it just indication that ZNP stack received the request?

@puddly
Copy link
Collaborator

puddly commented May 12, 2020 •
edited
Loading

It's just a confirmation from Z-Stack. The response would be the ZDO.MgmtLeaveReq.Callback message. I haven't checked out the exact correspondence between the three messages but that's the only thing that makes sense to me. I'll try this with a sniffer as well.

@puddly puddly closed this as completed in fba89f0 May 15, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@Adminiuga @puddly