Skip to content
This repository has been archived by the owner on Mar 11, 2021. It is now read-only.

Scan looped for "TRADFRI control outlet" #9

Closed
rchovan opened this issue Feb 16, 2020 · 4 comments · Fixed by #10
Closed

Scan looped for "TRADFRI control outlet" #9

rchovan opened this issue Feb 16, 2020 · 4 comments · Fixed by #10
Labels
bug Something isn't working

Comments

@rchovan
Copy link

rchovan commented Feb 16, 2020

Hi,
zha_map.scan service scan all devices in my network, but from unknown reason it continuously scan "TRADFRI control outlet" again and again.

command for raw WS return 0 devices

hass-cli raw ws zha_map/devices

image

and error is created in logs:

2020-02-16 19:08:15 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/websockets/client.py", line 101, in read_http_response
    status_code, reason, headers = await read_response(self.reader)
  File "/usr/local/lib/python3.7/site-packages/websockets/http.py", line 139, in read_response
    status_line = await read_line(stream)
  File "/usr/local/lib/python3.7/site-packages/websockets/http.py", line 213, in read_line
    line = await stream.readline()
  File "/usr/local/lib/python3.7/asyncio/streams.py", line 496, in readline
    line = await self.readuntil(sep)
  File "/usr/local/lib/python3.7/asyncio/streams.py", line 588, in readuntil
    await self._wait_for_data('readuntil')
  File "/usr/local/lib/python3.7/asyncio/streams.py", line 473, in _wait_for_data
    await self._waiter
concurrent.futures._base.CancelledError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/asyncio/tasks.py", line 630, in _wrap_awaitable
    return (yield from awaitable.__await__())
  File "/usr/local/lib/python3.7/site-packages/websockets/client.py", line 547, in __await_impl__
    extra_headers=protocol.extra_headers,
  File "/usr/local/lib/python3.7/site-packages/websockets/client.py", line 290, in handshake
    status_code, response_headers = await self.read_http_response()
  File "/usr/local/lib/python3.7/site-packages/websockets/client.py", line 103, in read_http_response
    raise InvalidMessage("did not receive a valid HTTP response") from exc
websockets.exceptions.InvalidMessage: did not receive a valid HTTP response

When I unplugged that device, scan finished, and devices are visible in WS call

2020-02-16 20:00:46 WARNING (MainThread) [custom_components.zha_map] Couldn't scan 08:6b:d7:ff:fe:07:7e:0d neighbours
2020-02-16 20:00:46 DEBUG (MainThread) [custom_components.zha_map] Finished neighbour scan pass. Failed: [08:6b:d7:ff:fe:07:7e:0d]
2020-02-16 20:00:46 DEBUG (MainThread) [custom_components.zha_map] 00:15:8d:00:03:f1:3b:15 (LUMI lumi.weather) was not found in the neighbours tables

part of the log, full is in attachement

2020-02-16 19:58:59 DEBUG (MainThread) [custom_components.zha_map] continuing neighbour scan. Neighbours discovered: [08:6b:d7:ff:fe:07:7e:0d]
2020-02-16 19:59:16 DEBUG (MainThread) [custom_components.zha_map.neighbour] [08:6b:d7:ff:fe:07:7e:0d]: 'Mgmt_Lqi_req' timedout
2020-02-16 19:59:16 DEBUG (MainThread) [custom_components.zha_map] Saving /config/neighbours/neighbours_086bd7fffe077e0d.txt
2020-02-16 19:59:16 DEBUG (MainThread) [custom_components.zha_map] continuing neighbour scan. Neighbours discovered: [08:6b:d7:ff:fe:07:7e:0d]
2020-02-16 19:59:33 DEBUG (MainThread) [custom_components.zha_map.neighbour] [08:6b:d7:ff:fe:07:7e:0d]: 'Mgmt_Lqi_req' timedout
2020-02-16 19:59:33 DEBUG (MainThread) [custom_components.zha_map] Saving /config/neighbours/neighbours_086bd7fffe077e0d.txt
2020-02-16 19:59:33 DEBUG (MainThread) [custom_components.zha_map] continuing neighbour scan. Neighbours discovered: [08:6b:d7:ff:fe:07:7e:0d]
2020-02-16 19:59:50 DEBUG (MainThread) [custom_components.zha_map.neighbour] [08:6b:d7:ff:fe:07:7e:0d]: 'Mgmt_Lqi_req' timedout
2020-02-16 19:59:50 DEBUG (MainThread) [custom_components.zha_map] Saving /config/neighbours/neighbours_086bd7fffe077e0d.txt
2020-02-16 19:59:50 DEBUG (MainThread) [custom_components.zha_map] continuing neighbour scan. Neighbours discovered: [08:6b:d7:ff:fe:07:7e:0d]
2020-02-16 20:00:07 DEBUG (MainThread) [custom_components.zha_map.neighbour] [08:6b:d7:ff:fe:07:7e:0d]: 'Mgmt_Lqi_req' timedout
2020-02-16 20:00:07 DEBUG (MainThread) [custom_components.zha_map] Saving /config/neighbours/neighbours_086bd7fffe077e0d.txt
2020-02-16 20:00:07 DEBUG (MainThread) [custom_components.zha_map] continuing neighbour scan. Neighbours discovered: [08:6b:d7:ff:fe:07:7e:0d]
2020-02-16 20:00:24 DEBUG (MainThread) [custom_components.zha_map.neighbour] [08:6b:d7:ff:fe:07:7e:0d]: 'Mgmt_Lqi_req' timedout

My versions:

HA is 0.105.4
zha_map is latest

Devices and logs:
neighbours.zip
home-assistant.log
@rchovan
Copy link
Author

rchovan commented Feb 16, 2020 •
edited
Loading

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
Copy link
Author

rchovan commented Feb 16, 2020

@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 Adminiuga added the bug Something isn't working label Feb 16, 2020
@Adminiuga Adminiuga mentioned this issue Feb 16, 2020
Merged
@Adminiuga
Copy link
Member

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
Copy link
Author

rchovan commented Feb 17, 2020

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

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Revert "fix unhandled exception on scan timeout" zha-ng/zha-map
2 participants
@Adminiuga @rchovan