Scan looped for "TRADFRI control outlet"

[zha-ng]

Scan looped for "TRADFRI control outlet"

[rchovan]

It seems to be error in code, because next scan is looping too, but with another device:

2020-02-16 20:18:05 DEBUG (MainThread) [custom_components.zha_map] Building topology starting from coordinator
2020-02-16 20:18:05 DEBUG (MainThread) [custom_components.zha_map.neighbour] [00:21:2e:ff:ff:04:d4:bb]: neighbor request Status: Status.SUCCESS. Response: <Optional Entries=3 StartIndex=0 NeighborTableList=[<Neighbor PanId=00:21:2e:ff:ff:04:d4:bb IEEEAddr=00:17:88:01:04:cb:a4:c0 NWKAddr=0x7897 NeighborType=37 PermitJoining=1 Depth=1 LQI=143>, <Neighbor PanId=00:21:2e:ff:ff:04:d4:bb IEEEAddr=00:12:4b:00:19:36:7f:7a NWKAddr=0x1ae5 NeighborType=37 PermitJoining=1 Depth=1 LQI=30>]>
2020-02-16 20:18:06 DEBUG (MainThread) [custom_components.zha_map.neighbour] [00:21:2e:ff:ff:04:d4:bb]: Querying next starting at 2
2020-02-16 20:18:06 DEBUG (MainThread) [custom_components.zha_map.neighbour] [00:21:2e:ff:ff:04:d4:bb]: neighbor request Status: Status.SUCCESS. Response: <Optional Entries=3 StartIndex=2 NeighborTableList=[<Neighbor PanId=00:21:2e:ff:ff:04:d4:bb IEEEAddr=00:17:88:01:06:c1:5c:4f NWKAddr=0xc950 NeighborType=37 PermitJoining=1 Depth=1 LQI=26>]>
2020-02-16 20:18:06 DEBUG (MainThread) [custom_components.zha_map.neighbour] [00:21:2e:ff:ff:04:d4:bb]: Done scanning. Total 3 neighbours
2020-02-16 20:18:06 DEBUG (MainThread) [custom_components.zha_map] Adding 00:17:88:01:04:cb:a4:c0 to all neighbours
2020-02-16 20:18:06 DEBUG (MainThread) [custom_components.zha_map] Adding 00:12:4b:00:19:36:7f:7a to all neighbours
2020-02-16 20:18:06 DEBUG (MainThread) [custom_components.zha_map] Adding 00:17:88:01:06:c1:5c:4f to all neighbours
2020-02-16 20:18:06 DEBUG (MainThread) [custom_components.zha_map] Saving /config/neighbours/neighbours_00212effff04d4bb.txt
2020-02-16 20:18:06 DEBUG (MainThread) [custom_components.zha_map] continuing neighbour scan. Neighbours discovered: [00:17:88:01:04:cb:a4:c0, 00:12:4b:00:19:36:7f:7a, 00:17:88:01:06:c1:5c:4f]
2020-02-16 20:18:06 DEBUG (MainThread) [custom_components.zha_map.neighbour] [00:17:88:01:04:cb:a4:c0]: neighbor request Status: Status.SUCCESS. Response: <Optional Entries=11 StartIndex=0 NeighborTableList=[<Neighbor PanId=00:21:2e:ff:ff:04:d4:bb IEEEAddr=00:21:2e:ff:ff:04:d4:bb NWKAddr=0x0000 NeighborType=4 PermitJoining=1 Depth=0 LQI=119>, <Neighbor PanId=00:21:2e:ff:ff:04:d4:bb IEEEAddr=00:17:88:01:06:73:21:79 NWKAddr=0x2726 NeighborType=18 PermitJoining=0 Depth=2 LQI=252>]>
2020-02-16 20:18:07 DEBUG (MainThread) [custom_components.zha_map.neighbour] [00:17:88:01:04:cb:a4:c0]: Querying next starting at 2
2020-02-16 20:18:07 DEBUG (MainThread) [custom_components.zha_map.neighbour] [00:17:88:01:04:cb:a4:c0]: neighbor request Status: Status.SUCCESS. Response: <Optional Entries=11 StartIndex=2 NeighborTableList=[<Neighbor PanId=00:21:2e:ff:ff:04:d4:bb IEEEAddr=00:17:88:01:06:c1:60:e8 NWKAddr=0x934a NeighborType=53 PermitJoining=1 Depth=1 LQI=164>, <Neighbor PanId=00:21:2e:ff:ff:04:d4:bb IEEEAddr=00:15:8d:00:04:4a:67:86 NWKAddr=0x2059 NeighborType=18 PermitJoining=0 Depth=2 LQI=255>]>
2020-02-16 20:18:09 DEBUG (MainThread) [custom_components.zha_map.neighbour] [00:17:88:01:04:cb:a4:c0]: Querying next starting at 4
2020-02-16 20:18:09 DEBUG (MainThread) [custom_components.zha_map.neighbour] [00:17:88:01:04:cb:a4:c0]: neighbor request Status: Status.SUCCESS. Response: <Optional Entries=11 StartIndex=4 NeighborTableList=[<Neighbor PanId=00:21:2e:ff:ff:04:d4:bb IEEEAddr=08:6b:d7:ff:fe:07:7e:0d NWKAddr=0xe278 NeighborType=53 PermitJoining=1 Depth=1 LQI=0>, <Neighbor PanId=00:21:2e:ff:ff:04:d4:bb IEEEAddr=cc:cc:cc:ff:fe:69:e0:f0 NWKAddr=0x6324 NeighborType=18 PermitJoining=0 Depth=2 LQI=174>]>
2020-02-16 20:18:10 DEBUG (MainThread) [custom_components.zha_map.neighbour] [00:17:88:01:04:cb:a4:c0]: Querying next starting at 6
2020-02-16 20:18:10 DEBUG (MainThread) [custom_components.zha_map.neighbour] [00:17:88:01:04:cb:a4:c0]: neighbor request Status: Status.SUCCESS. Response: <Optional Entries=11 StartIndex=6 NeighborTableList=[<Neighbor PanId=00:21:2e:ff:ff:04:d4:bb IEEEAddr=00:12:4b:00:19:36:83:eb NWKAddr=0x2077 NeighborType=53 PermitJoining=1 Depth=1 LQI=24>, <Neighbor PanId=00:21:2e:ff:ff:04:d4:bb IEEEAddr=00:12:4b:00:19:36:7f:7a NWKAddr=0x1ae5 NeighborType=53 PermitJoining=1 Depth=1 LQI=110>]>
2020-02-16 20:18:11 DEBUG (MainThread) [custom_components.zha_map.neighbour] [00:17:88:01:04:cb:a4:c0]: Querying next starting at 8
2020-02-16 20:18:11 DEBUG (MainThread) [custom_components.zha_map.neighbour] [00:17:88:01:04:cb:a4:c0]: neighbor request Status: Status.SUCCESS. Response: <Optional Entries=11 StartIndex=8 NeighborTableList=[<Neighbor PanId=00:21:2e:ff:ff:04:d4:bb IEEEAddr=00:17:88:01:06:c1:5c:4f NWKAddr=0xc950 NeighborType=53 PermitJoining=1 Depth=1 LQI=156>, <Neighbor PanId=00:21:2e:ff:ff:04:d4:bb IEEEAddr=00:15:8d:00:03:f0:f9:26 NWKAddr=0x12b6 NeighborType=18 PermitJoining=0 Depth=2 LQI=73>]>
2020-02-16 20:18:13 DEBUG (MainThread) [custom_components.zha_map.neighbour] [00:17:88:01:04:cb:a4:c0]: Querying next starting at 10
2020-02-16 20:18:13 DEBUG (MainThread) [custom_components.zha_map.neighbour] [00:17:88:01:04:cb:a4:c0]: neighbor request Status: Status.SUCCESS. Response: <Optional Entries=11 StartIndex=10 NeighborTableList=[<Neighbor PanId=00:21:2e:ff:ff:04:d4:bb IEEEAddr=cc:cc:cc:ff:fe:67:cd:2b NWKAddr=0x98bc NeighborType=18 PermitJoining=0 Depth=2 LQI=195>]>
2020-02-16 20:18:13 DEBUG (MainThread) [custom_components.zha_map.neighbour] [00:17:88:01:04:cb:a4:c0]: Done scanning. Total 11 neighbours
2020-02-16 20:18:13 DEBUG (MainThread) [custom_components.zha_map] Adding 00:21:2e:ff:ff:04:d4:bb to all neighbours
2020-02-16 20:18:13 DEBUG (MainThread) [custom_components.zha_map] Adding 00:17:88:01:06:73:21:79 to all neighbours
2020-02-16 20:18:13 DEBUG (MainThread) [custom_components.zha_map] Adding 00:17:88:01:06:c1:60:e8 to all neighbours
2020-02-16 20:18:13 DEBUG (MainThread) [custom_components.zha_map] Adding 00:15:8d:00:04:4a:67:86 to all neighbours
2020-02-16 20:18:13 DEBUG (MainThread) [custom_components.zha_map] Adding 08:6b:d7:ff:fe:07:7e:0d to all neighbours
2020-02-16 20:18:13 DEBUG (MainThread) [custom_components.zha_map] Adding cc:cc:cc:ff:fe:69:e0:f0 to all neighbours
2020-02-16 20:18:13 DEBUG (MainThread) [custom_components.zha_map] Adding 00:12:4b:00:19:36:83:eb to all neighbours
2020-02-16 20:18:13 DEBUG (MainThread) [custom_components.zha_map] Adding 00:15:8d:00:03:f0:f9:26 to all neighbours
2020-02-16 20:18:13 DEBUG (MainThread) [custom_components.zha_map] Adding cc:cc:cc:ff:fe:67:cd:2b to all neighbours
2020-02-16 20:18:13 DEBUG (MainThread) [custom_components.zha_map] Saving /config/neighbours/neighbours_0017880104cba4c0.txt
2020-02-16 20:18:30 DEBUG (MainThread) [custom_components.zha_map.neighbour] [00:12:4b:00:19:36:7f:7a]: 'Mgmt_Lqi_req' timedout
2020-02-16 20:18:30 DEBUG (MainThread) [custom_components.zha_map] Saving /config/neighbours/neighbours_00124b0019367f7a.txt
2020-02-16 20:18:30 DEBUG (MainThread) [custom_components.zha_map.neighbour] [00:17:88:01:06:c1:5c:4f]: neighbor request Status: Status.SUCCESS. Response: <Optional Entries=4 StartIndex=0 NeighborTableList=[<Neighbor PanId=00:21:2e:ff:ff:04:d4:bb IEEEAddr=00:21:2e:ff:ff:04:d4:bb NWKAddr=0x0000 NeighborType=36 PermitJoining=2 Depth=0 LQI=54>, <Neighbor PanId=00:21:2e:ff:ff:04:d4:bb IEEEAddr=00:12:4b:00:19:36:83:eb NWKAddr=0x2077 NeighborType=37 PermitJoining=2 Depth=15 LQI=69>, <Neighbor PanId=00:21:2e:ff:ff:04:d4:bb IEEEAddr=00:17:88:01:04:cb:a4:c0 NWKAddr=0x7897 NeighborType=37 PermitJoining=2 Depth=15 LQI=125>]>
2020-02-16 20:18:31 DEBUG (MainThread) [custom_components.zha_map.neighbour] [00:17:88:01:06:c1:5c:4f]: Querying next starting at 3
2020-02-16 20:18:31 DEBUG (MainThread) [custom_components.zha_map.neighbour] [00:17:88:01:06:c1:5c:4f]: neighbor request Status: Status.SUCCESS. Response: <Optional Entries=4 StartIndex=3 NeighborTableList=[<Neighbor PanId=00:21:2e:ff:ff:04:d4:bb IEEEAddr=00:17:88:01:06:c1:60:e8 NWKAddr=0x934a NeighborType=37 PermitJoining=2 Depth=15 LQI=255>]>
2020-02-16 20:18:31 DEBUG (MainThread) [custom_components.zha_map.neighbour] [00:17:88:01:06:c1:5c:4f]: Done scanning. Total 4 neighbours
2020-02-16 20:18:31 DEBUG (MainThread) [custom_components.zha_map] Saving /config/neighbours/neighbours_0017880106c15c4f.txt

and after some while:

2020-02-16 20:37:14 DEBUG (MainThread) [custom_components.zha_map] continuing neighbour scan. Neighbours discovered: [00:12:4b:00:19:36:7f:7a]
2020-02-16 20:37:31 DEBUG (MainThread) [custom_components.zha_map.neighbour] [00:12:4b:00:19:36:7f:7a]: 'Mgmt_Lqi_req' timedout
2020-02-16 20:37:31 DEBUG (MainThread) [custom_components.zha_map] Saving /config/neighbours/neighbours_00124b0019367f7a.txt
2020-02-16 20:37:31 DEBUG (MainThread) [custom_components.zha_map] continuing neighbour scan. Neighbours discovered: [00:12:4b:00:19:36:7f:7a]
2020-02-16 20:37:48 DEBUG (MainThread) [custom_components.zha_map.neighbour] [00:12:4b:00:19:36:7f:7a]: 'Mgmt_Lqi_req' timedout
2020-02-16 20:37:48 DEBUG (MainThread) [custom_components.zha_map] Saving /config/neighbours/neighbours_00124b0019367f7a.txt
2020-02-16 20:37:48 DEBUG (MainThread) [custom_components.zha_map] continuing neighbour scan. Neighbours discovered: [00:12:4b:00:19:36:7f:7a]
2020-02-16 20:37:55 DEBUG (MainThread) [custom_components.zha_map.neighbour] [00:12:4b:00:19:36:7f:7a]: neighbor request Status: Status.SUCCESS. Response: <Optional Entries=7 StartIndex=0 NeighborTableList=[<Neighbor PanId=00:21:2e:ff:ff:04:d4:bb IEEEAddr=00:21:2e:ff:ff:04:d4:bb NWKAddr=0x0000 NeighborType=8 PermitJoining=2 Depth=0 LQI=2>, <Neighbor PanId=00:21:2e:ff:ff:04:d4:bb IEEEAddr=00:15:8d:00:03:f1:3b:28 NWKAddr=0x0de4 NeighborType=18 PermitJoining=2 Depth=2 LQI=33>, <Neighbor PanId=00:21:2e:ff:ff:04:d4:bb IEEEAddr=00:17:88:01:04:cb:a4:c0 NWKAddr=0x7897 NeighborType=57 PermitJoining=2 Depth=255 LQI=30>]>
2020-02-16 20:37:56 DEBUG (MainThread) [custom_components.zha_map.neighbour] [00:12:4b:00:19:36:7f:7a]: Querying next starting at 3
2020-02-16 20:37:56 DEBUG (MainThread) [custom_components.zha_map.neighbour] [00:12:4b:00:19:36:7f:7a]: neighbor request Status: Status.SUCCESS. Response: <Optional Entries=7 StartIndex=3 NeighborTableList=[<Neighbor PanId=00:21:2e:ff:ff:04:d4:bb IEEEAddr=08:6b:d7:ff:fe:07:7e:0d NWKAddr=0xe278 NeighborType=57 PermitJoining=2 Depth=255 LQI=28>, <Neighbor PanId=00:21:2e:ff:ff:04:d4:bb IEEEAddr=00:12:4b:00:19:36:83:eb NWKAddr=0x2077 NeighborType=57 PermitJoining=2 Depth=255 LQI=8>, <Neighbor PanId=00:21:2e:ff:ff:04:d4:bb IEEEAddr=00:17:88:01:06:c1:5c:4f NWKAddr=0xc950 NeighborType=57 PermitJoining=2 Depth=255 LQI=1>]>
2020-02-16 20:37:57 DEBUG (MainThread) [custom_components.zha_map.neighbour] [00:12:4b:00:19:36:7f:7a]: Querying next starting at 6
2020-02-16 20:37:58 DEBUG (MainThread) [custom_components.zha_map.neighbour] [00:12:4b:00:19:36:7f:7a]: neighbor request Status: Status.SUCCESS. Response: <Optional Entries=7 StartIndex=6 NeighborTableList=[<Neighbor PanId=00:21:2e:ff:ff:04:d4:bb IEEEAddr=00:17:88:01:06:c1:60:e8 NWKAddr=0x934a NeighborType=57 PermitJoining=2 Depth=255 LQI=1>]>
2020-02-16 20:37:58 DEBUG (MainThread) [custom_components.zha_map.neighbour] [00:12:4b:00:19:36:7f:7a]: Done scanning. Total 7 neighbours
2020-02-16 20:37:58 DEBUG (MainThread) [custom_components.zha_map] Adding 00:15:8d:00:03:f1:3b:28 to all neighbours
2020-02-16 20:37:58 DEBUG (MainThread) [custom_components.zha_map] Saving /config/neighbours/neighbours_00124b0019367f7a.txt
2020-02-16 20:37:58 DEBUG (MainThread) [custom_components.zha_map] Finished neighbour scan pass. Failed: [08:6b:d7:ff:fe:07:7e:0d]
2020-02-16 20:37:58 DEBUG (MainThread) [custom_components.zha_map] 00:15:8d:00:03:f1:3b:15 (LUMI lumi.weather) was not found in the neighbours tables
2020-02-16 20:40:17 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/zigpy/device.py", line 187, in request
    self.nwk, dst_ep, cluster
zigpy.exceptions.DeliveryError: [0xe278:0:0x8006]: Message send failure

full log is here:
home-assistant1.log

[rchovan]

@dmulcahey pointed me on timeout values, and instructed me to remove device from network, not unplugging it. After that, scan is done after 30 seconds.

I suggest to add some error correction, if something like this happens, it should try scan several times (maybe configured variable) and then move to next device.

[Adminiuga]

Pushed new update. Do git fetch and git pull. If you can reproduce it then re-open the issue and post full logs again starting with custom_components.zha_map] Building topology starting from coordinator and till the end

[rchovan]

Hi,
I can confirm it, issue solved.
THX.