search

home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
71.06k stars 29.72k forks source link

coordinator does not work with ZHA but works with Z2M #93799

Closed Tarik2142 closed 1 year ago

Tarik2142 commented 1 year ago

The problem

Сoordinator does not work with ZHA but works with Z2M. If coordinator first connects to Z2M and then in ZHA selects "Keep radio network settings", the network will start successfully, if choose "Create a network", the network will not start, there will be an Error.

What version of Home Assistant Core has the issue?

core-2023.5.4

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant Container

Integration causing the issue

ZHA

Link to integration documentation on our website

https://www.home-assistant.io/integrations/zha/

Diagnostics information

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

Logger: aiohttp.server
Source: components/zha/radio_manager.py:224
First occurred: 3:24:16 PM (1 occurrences)
Last logged: 3:24:16 PM

Error handling request
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/zigpy_znp/api.py", line 1058, in request_callback_rsp
    return await callback_rsp
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/zigpy_znp/api.py", line 253, in start_network
    commissioning_rsp = await self.request_callback_rsp(
  File "/usr/local/lib/python3.10/site-packages/zigpy_znp/api.py", line 1055, in request_callback_rsp
    async with async_timeout.timeout(timeout):
  File "/usr/local/lib/python3.10/site-packages/async_timeout/__init__.py", line 129, in __aexit__
    self._do_exit(exc_type)
  File "/usr/local/lib/python3.10/site-packages/async_timeout/__init__.py", line 212, in _do_exit
    raise asyncio.TimeoutError
asyncio.exceptions.TimeoutError

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

Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/aiohttp/web_protocol.py", line 433, in _handle_request
    resp = await request_handler(request)
  File "/usr/local/lib/python3.10/site-packages/aiohttp/web_app.py", line 504, in _handle
    resp = await handler(request)
  File "/usr/local/lib/python3.10/site-packages/aiohttp/web_middlewares.py", line 117, in impl
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/security_filter.py", line 85, in security_filter_middleware
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/forwarded.py", line 100, in forwarded_middleware
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/request_context.py", line 28, in request_context_middleware
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/ban.py", line 80, in ban_middleware
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/auth.py", line 235, in auth_middleware
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/view.py", line 146, in handle
    result = await result
  File "/usr/src/homeassistant/homeassistant/components/config/config_entries.py", line 180, in post
    return await super().post(request, flow_id)
  File "/usr/src/homeassistant/homeassistant/components/http/data_validator.py", line 72, in wrapper
    result = await method(view, request, data, *args, **kwargs)
  File "/usr/src/homeassistant/homeassistant/helpers/data_entry_flow.py", line 110, in post
    result = await self._flow_mgr.async_configure(flow_id, data)
  File "/usr/src/homeassistant/homeassistant/data_entry_flow.py", line 267, in async_configure
    result = await self._async_handle_step(
  File "/usr/src/homeassistant/homeassistant/data_entry_flow.py", line 367, in _async_handle_step
    result: FlowResult = await getattr(flow, method)(user_input)
  File "/usr/src/homeassistant/homeassistant/components/zha/config_flow.py", line 370, in async_step_form_initial_network
    return await self.async_step_form_new_network(user_input)
  File "/usr/src/homeassistant/homeassistant/components/zha/config_flow.py", line 376, in async_step_form_new_network
    await self._radio_mgr.async_form_network()
  File "/usr/src/homeassistant/homeassistant/components/zha/radio_manager.py", line 224, in async_form_network
    await app.form_network()
  File "/usr/local/lib/python3.10/site-packages/zigpy/application.py", line 333, in form_network
    await self.form_network(fast=True)
  File "/usr/local/lib/python3.10/contextlib.py", line 217, in __aexit__
    await self.gen.athrow(typ, value, traceback)
  File "/usr/local/lib/python3.10/site-packages/zigpy_znp/api.py", line 875, in capture_responses
    yield queue
  File "/usr/local/lib/python3.10/site-packages/zigpy_znp/api.py", line 291, in start_network
    raise zigpy.exceptions.FormationFailure(
zigpy.exceptions.FormationFailure: Network formation refused: there is too much RF interference. Make sure your coordinator is on a USB 2.0 extension cable and away from any sources of interference, like USB 3.0 ports, SSDs, 2.4GHz routers, motherboards, etc.

Additional information

image

ZHA "Create a network" device log

 00 3b c0 02 10 00 00 00 00 11 c9 01 00 78
[3313339] -> fe 05 21 32 01 04 00 00 00 13
[3313346] <- fe 04 61 32 14 00 00 00 43
[3313351] -> fe 08 21 33 01 04 00 00 00 00 00 14 0b
[3313361] <- fe 16 61 33 00 14 d7 0a 00 00 00 00 00 00 0b 32 65 75 df 38 c1 a4 02 00 01 00 25
[3313365] -> fe 02 21 13 21 00 11
[3313373] <- fe 02 61 13 74 00 04
[3313378] -> fe 04 21 1c 21 00 00 00 18
[3313402] <- fe 76 61 1c 00 74 5e 05 02 65 0f 65 00 1e 00 00 00 01 05 01 8f 00 07 00 02 0d 02 00 00 00 0b 00 00 00 00 00 00 00 00 00 00 00 62 1a 08 00 00 08 00 00 0f 0f 04 00 01 00 00 00 01 00 00 00 00 09 28 d1 26 00 4b 12 00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 0f 05 00 01 3c 0a 01 00 00 00 2e 00 00 00 5c
[3313411] -> fe 02 21 13 55 00 65
[3313420] <- fe 02 61 13 01 00 71
[3313423] -> fe 04 21 1c 55 00 00 00 6c
[3313437] <- fe 03 61 1c 00 01 01 7e
[3313440] -> fe 02 21 13 01 00 31
[3313448] <- fe 02 61 13 08 00 78
[3313451] -> fe 04 21 1c 01 00 00 00 38
[3313465] <- fe 0a 61 1c 00 08 09 28 d1 26 00 4b 12 00 f0
[3313470] -> fe 02 21 13 87 00 b7
[3313480] <- fe 02 61 13 01 00 71
[3313490] -> fe 04 21 1c 87 00 00 00 be
[3313506] <- fe 03 61 1c 00 01 00 7f
[3313510] -> fe 02 21 13 3a 00 0a
[3313519] <- fe 02 61 13 11 00 61
[3313522] -> fe 04 21 1c 3a 00 00 00 03
[3313539] <- fe 13 61 1c 00 11 00 01 03 05 07 09 0b 0d 0f 00 02 04 06 08 0a 0c 0d 7c
[3313544] -> fe 05 21 32 01 07 00 00 00 10
[3313549] <- fe 04 61 32 0c 00 00 00 5b
[3313552] -> fe 08 21 33 01 07 00 00 00 00 00 0c 10
[3313558] <- fe 0e 61 33 00 0c ca 3a 02 00 09 28 d1 26 00 4b 12 00 2d
[3313562] -> fe 00 21 02 23
[3313566] <- fe 0a 61 02 02 01 02 07 01 2a 8d 34 01 00 fc
[3313575] -> fe 02 21 13 01 01 30
[3313583] <- fe 02 61 13 10 00 60
[3313588] -> fe 04 21 1c 01 01 00 00 39
[3313604] <- fe 12 61 1c 00 10 f3 a8 ba f8 6f 2c d7 1c 88 e2 d2 d9 48 c2 e1 ff 1b
[3313608] -> fe 02 21 13 5f 00 6f
[3313612] <- fe 02 61 13 01 00 71
[3313614] -> fe 04 21 1c 5f 00 00 00 66
[3313621] <- fe 03 61 1c 00 01 01 7e
[3313624] -> fe 02 21 13 87 00 b7
[3313634] <- fe 02 61 13 01 00 71
[3313636] -> fe 04 21 1c 87 00 00 00 be
[3313653] <- fe 03 61 1c 00 01 00 7f
[3313656] -> fe 02 21 13 32 00 02
[3313665] <- fe 02 61 13 01 00 71
[3313667] -> fe 04 21 1c 32 00 00 00 0b
[3313684] <- fe 03 61 1c 00 01 01 7e
[3313689] -> fe 02 21 13 33 00 03
[3313693] <- fe 02 61 13 01 00 71
[3313696] -> fe 04 21 1c 33 00 00 00 0a
[3313702] <- fe 03 61 1c 00 01 78 07
[3313705] -> fe 02 21 13 36 00 06
[3313714] <- fe 02 61 13 01 00 71
[3313717] -> fe 04 21 1c 36 00 00 00 0f
[3313733] <- fe 03 61 1c 00 01 01 7e
[3313736] -> fe 02 21 13 38 00 08
[3313741] <- fe 02 61 13 01 00 71
[3313744] -> fe 04 21 1c 38 00 00 00 01
[3313750] <- fe 03 61 1c 00 01 ff 80
[3313753] -> fe 02 21 13 3e 00 0e
[3313762] <- fe 02 61 13 01 00 71
[3313765] -> fe 04 21 1c 3e 00 00 00 07
[3313781] <- fe 03 61 1c 00 01 00 7f
[3313786] -> fe 02 21 13 30 00 00
[3313795] <- fe 02 61 13 01 00 71
[3313798] -> fe 04 21 1c 30 00 00 00 09
[3313814] <- fe 03 61 1c 00 01 1e 61
[3313817] -> fe 02 21 13 8f 00 bf
[3313827] <- fe 02 61 13 01 00 71
[3313830] -> fe 04 21 1c 8f 00 00 00 b6
[3313847] <- fe 03 61 1c 00 01 01 7e
[3313850] -> fe 01 41 00 01 41
[3316655] <- 00
[3316658] <- fe 06 41 80 00 02 01 02 07 01 c0
[3316663] -> fe 01 2f 05 04 2f
[3319994] <- fe 01 6f 05 00 6b
[3319997] <- fe 01 45 c0 09 8d fe 03 4f 80 0d 00 04 c5
[3320194] <- fe 03 4f 80 08 02 00 c6
[3320198] -> fe 02 21 13 21 00 11
[3320202] <- fe 02 61 13 74 00 04
[3320204] -> fe 04 21 1c 21 00 00 00 18
[3320221] <- fe 76 61 1c 00 74 5e 05 02 65 0f 65 00 1e 00 00 00 01 05 01 8f 00 07 00 02 0d 02 00 00 00 0b 00 00 00 00 00 00 00 00 00 00 00 62 1a 08 00 00 08 00 00 0f 0f 04 00 01 00 00 00 01 00 00 00 00 09 28 d1 26 00 4b 12 00 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 0f 05 00 01 3c 0a 01 00 00 00 2e 00 00 00 5c
[3320227] -> fe 00 21 02 23
[3320231] <- fe 0a 61 02 02 01 02 07 01 2a 8d 34 01 00 fc
[3320233] -> fe 02 27 0a ff 00 d0
[3320237] <- fe 01 67 0a 00 6c
[3320240] -> fe 1b 24 00 01 04 01 00 04 00 00 05 00 00 06 00 0a 00 19 00 01 05 04 01 00 20 00 00 05 02 05 0c
[3320245] <- fe 01 64 00 00 65
[3320248] -> fe 0b 24 00 02 5e c0 20 08 00 00 01 00 00 00 9a
[3320252] <- fe 01 64 00 00 65
[3320255] -> fe 02 25 3e ff ff 19
[3320258] <- fe 01 65 3e 00 5a
[3320263] -> fe 17 24 02 02 00 00 00 00 00 00 00 00 00 00 00 00 02 00 01 20 00 03 00 01 00 00 12
[3320269] <- fe 01 64 02 00 67
[3320272] <- fe 12 45 82 00 00 00 00 00 00 40 8f 00 00 50 a0 00 01 2c a0 00 00 67
[3320276] <- fe 19 45 ff 00 00 00 02 80 00 01 00 00 00 00 00 00 40 8f 00 00 50 a0 00 01 2c a0 00 00 92
[3320282] -> fe 17 24 02 02 00 00 00 00 00 00 00 00 00 00 00 00 05 00 02 20 00 03 00 02 00 00 15
[3320288] <- fe 01 64 02 00 67
[3320292] <- fe 08 45 85 00 00 00 00 00 02 02 01 c9 fe 0f 45 ff 00 00 00 05 80 00 02 00 00 00 00 00 02 02 01 33
[3320310] -> fe 18 24 02 02 00 00 00 00 00 00 00 00 00 00 00 00 04 00 03 20 00 04 00 03 00 00 02 1e
[3320317] <- fe 01 64 02 00 67
[3320321] <- fe 10 45 84 00 00 00 00 00 0a 02 5e c0 20 08 00 01 00 00 00 6e fe 17 45 ff 00 00 00 04 80 00 03 00 00 00 00 00 0a 02 5e c0 20 08 00 01 00 00 00 95
[3320326] -> fe 18 24 02 02 00 00 00 00 00 00 00 00 00 00 00 00 04 00 04 20 00 04 00 04 00 00 01 1d
[3320332] <- fe 01 64 02 00 67
[3320342] <- fe 20 45 84 00 00 00 00 00 1a 01 04 01 00 04 00 05 00 00 06 00 0a 00 19 00 01 05 04 01 00 20 00 00 05 02 05 c8 fe 27 45 ff 00 00 00 04 80 00 04 00 00 00 00 00 1a 01 04 01 00 04 00 05 00 00 06 00 0a 00 19 00 01 05 04 01 00 20 00 00 05 02 05 34
[3320373] -> fe 1b 24 02 02 00 00 00 00 00 00 00 00 00 00 00 00 38 00 05 20 00 07 00 05 00 f8 ff 07 04 01 25
[3320380] <- fe 01 64 02 00 67
[3324991] <- fe 1c 45 b8 00 00 00 00 f8 ff 07 2e 00 00 00 10 78 99 a7 6d 53 20 00 50 00 2b 19 2f 4c 95 0e 00 1d
[3324995] <- fe 23 45 ff 00 00 00 38 80 00 05 00 00 00 00 f8 ff 07 2e 00 00 00 10 78 99 a7 6d 53 20 00 50 00 2b 19 2f 4c 95 0e 00 d8
[3325005] -> fe 02 21 13 00 0f 3f
[3325008] <- fe 02 61 13 00 00 70
[3325011] -> fe 02 21 13 60 00 50
[3325020] <- fe 02 61 13 01 00 71
[3325023] -> fe 04 21 12 60 00 01 00 56
[3325042] <- fe 01 61 12 00 72
[3325045] -> fe 02 21 13 5f 00 6f
[3325053] <- fe 02 61 13 01 00 71
[3325055] -> fe 04 21 12 5f 00 01 00 69
[3325075] <- fe 01 61 12 00 72
[3325078] -> fe 02 21 13 55 00 65
[3325083] <- fe 02 61 13 01 00 71
[3325088] -> fe 04 21 12 55 00 01 00 63
[3325102] <- fe 01 61 12 00 72
[3325105] -> fe 02 21 13 03 00 33
[3325108] <- fe 02 61 13 01 00 71
[3325111] -> fe 07 21 1d 03 00 00 00 01 00 03 3a
[3325115] <- fe 01 61 1d 00 7d
[3325118] -> fe 01 41 00 01 41
[3327472] <- 00
[3327475] <- fe 06 41 80 00 02 01 02 07 01 c0
[3327480] -> fe 02 21 13 83 00 b3
[3327484] <- fe 02 61 13 02 00 72
[3327489] -> fe 08 21 1d 83 00 00 00 02 00 ff ff b5
[3327495] <- fe 01 61 1d 00 7d
[3327500] -> fe 02 21 13 47 00 77
[3327504] <- fe 02 61 13 08 00 78
[3327509] -> fe 0e 21 1d 47 00 00 00 08 00 b9 7e 6b 18 39 8d 3c 3b 7a
[3327516] <- fe 01 61 1d 00 7d
[3327519] -> fe 02 21 13 62 00 52
[3327523] <- fe 02 61 13 10 00 60
[3327526] -> fe 16 21 1d 62 00 00 00 10 00 ff 29 f3 5e a7 75 92 aa fc 0a 91 51 f3 b9 8d 80 b8
[3327533] <- fe 01 61 1d 00 7d
[3327536] -> fe 02 21 13 63 00 53
[3327540] <- fe 02 61 13 01 00 71
[3327545] -> fe 07 21 1d 63 00 00 00 01 00 00 59
[3327551] <- fe 01 61 1d 00 7d
[3327556] -> fe 02 21 13 84 00 b4
[3327560] <- fe 02 61 13 04 00 74
[3327565] -> fe 0a 21 1d 84 00 00 00 04 00 00 80 10 02 24
[3327572] <- fe 01 61 1d 00 7d
[3327577] -> fe 05 2f 08 01 00 80 10 02 b1
[3327580] <- fe 01 6f 08 00 66
[3327585] -> fe 05 2f 08 00 00 00 00 00 22
[3327588] <- fe 01 6f 08 00 66
[3327592] -> fe 01 2f 05 04 2f       - APP_CNF_BDB_START_COMMISSIONING 0x04 Network Formation
[3332322] <- fe 01 6f 05 00 6b       - SRSP Success (0) 
             fe 03 4f 80 01 02 04 cb - APP_CNF_BDB_COMMISSIONING_NOTIFICATION BDB_COMMISSIONING_IN_PROGRESS BDB_COMMISSIONING_FORMATION BDB_COMMISSIONING_MODE_NWK_FORMATION 
[3332554] <- fe 01 45 c0 08 8c       - ZDO_STATE_CHANGE_IND COORD_STARTING
[3350378] -> fe 00 21 01 20          - SYS_PING
[3350381] <- fe 02 61 01 59 06 3d    - SYS_PING response
[3380386] -> fe 00 21 01 20          - SYS_PING
[3380389] <- fe 02 61 01 59 06 3d    - SYS_PING response
[3387594] -> fe 01 41 00 01 41       - SYS_RESET_REQ
[3391402] <- 00                      - device reset
[3391404] <- fe 06 41 80 00 02 01 02 07 01 c0

Z2M successful start of the same device, standard settings

00 00 00 14 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 de
[6093286] <- fe 01 61 34 00 54
[6093289] -> fe 05 21 32 01 04 00 c7 00 d4
[6093298] <- fe 04 61 32 14 00 00 00 43
[6093301] -> fe 1c 21 34 01 04 00 c7 00 00 00 14 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 df
[6093313] <- fe 01 61 34 00 54
[6093315] -> fe 02 21 13 03 00 33
[6093321] <- fe 02 61 13 01 00 71
[6093324] -> fe 04 21 1c 03 00 00 00 3a
[6093332] <- fe 03 61 1c 00 01 00 7f
[6093334] -> fe 02 21 13 87 00 b7
[6093343] <- fe 02 61 13 01 00 71
[6093346] -> fe 04 21 1c 87 00 00 00 be
[6093361] <- fe 03 61 1c 00 01 00 7f
[6093363] -> fe 02 21 13 8f 00 bf
[6093372] <- fe 02 61 13 01 00 71
[6093375] -> fe 04 21 1c 8f 00 00 00 b6
[6093390] <- fe 03 61 1c 00 01 01 7e
[6093393] -> fe 02 21 13 84 00 b4
[6093401] <- fe 02 61 13 04 00 74
[6093404] -> fe 04 21 1c 84 00 00 00 bd
[6093419] <- fe 06 61 1c 00 04 00 00 04 00 7b
[6093422] -> fe 02 21 13 84 00 b4
[6093431] <- fe 02 61 13 04 00 74
[6093434] -> fe 0a 21 1d 84 00 00 00 04 00 00 08 00 00 be
[6093449] <- fe 01 61 1d 00 7d
[6093452] -> fe 02 21 13 83 00 b3
[6093460] <- fe 02 61 13 02 00 72
[6093463] -> fe 04 21 1c 83 00 00 00 ba
[6093477] <- fe 04 61 1c 00 02 00 b6 cd
[6093480] -> fe 02 21 13 83 00 b3
[6093488] <- fe 02 61 13 02 00 72
[6093491] -> fe 08 21 1d 83 00 00 00 02 00 62 1a cd
[6093506] <- fe 01 61 1d 00 7d
[6093509] -> fe 02 21 13 2d 00 1d
[6093518] <- fe 02 61 13 08 00 78
[6093521] -> fe 04 21 1c 2d 00 00 00 14
[6093536] <- fe 0a 61 1c 00 08 c4 d4 ad 82 80 55 68 37 ca
[6093539] -> fe 02 21 13 2d 00 1d
[6093548] <- fe 02 61 13 08 00 78
[6093551] -> fe 0e 21 1d 2d 00 00 00 08 00 09 28 d1 26 00 4b 12 00 98
[6093567] <- fe 01 61 1d 00 7d
[6093570] -> fe 02 21 13 47 00 77
[6093579] <- fe 02 61 13 08 00 78
[6093582] -> fe 04 21 1c 47 00 00 00 7e
[6093597] <- fe 0a 61 1c 00 08 c4 d4 ad 82 80 55 68 37 ca
[6093599] -> fe 02 21 13 47 00 77
[6093608] <- fe 02 61 13 08 00 78
[6093610] -> fe 0e 21 1d 47 00 00 00 08 00 09 28 d1 26 00 4b 12 00 f2
[6093626] <- fe 01 61 1d 00 7d
[6093628] -> fe 02 21 13 63 00 53
[6093637] <- fe 02 61 13 01 00 71
[6093640] -> fe 04 21 1c 63 00 00 00 5a
[6093673] <- fe 03 61 1c 00 01 00 7f
[6093676] -> fe 02 21 13 62 00 52
[6093685] <- fe 02 61 13 10 00 60
[6093688] -> fe 04 21 1c 62 00 00 00 5b
[6093705] <- fe 12 61 1c 00 10 2b fe d8 bf a4 51 80 84 5f 75 84 09 26 13 90 36 08
[6093706] -> fe 02 21 13 62 00 52
[6093715] <- fe 02 61 13 10 00 60
[6093718] -> fe 16 21 1d 62 00 00 00 10 00 01 03 05 07 09 0b 0d 0f 00 02 04 06 08 0a 0c 0d 5b
[6093735] <- fe 01 61 1d 00 7d
[6094739] -> fe 01 41 00 01 41
[6097516] <- 00
[6097519] <- fe 06 41 80 00 02 01 02 07 01 c0
[6097522] -> fe 00 27 00 27
[6097533] <- fe 0e 67 00 00 09 28 d1 26 00 4b 12 00 fe ff 07 00 00 e0
[6097538] -> fe 02 25 40 64 00 03
[6100845] <- fe 01 65 40 00 24 fe 01 45 c0 09 8d fe 03 4f 80 0d 00 04 c5
[6100850] -> fe 02 21 13 60 00 50
[6100859] <- fe 02 61 13 00 00 70
[6100864] -> fe 06 21 07 60 00 01 00 01 55 15
[6100880] <- fe 01 61 07 09 6e
[6100884] -> fe 07 21 1d 60 00 00 00 01 00 55 0f
[6100888] <- fe 01 61 1d 00 7d
[6100891] -> fe 04 25 05 00 00 00 00 24
[6100895] <- fe 01 65 05 00 61
[6100898] <- fe 06 45 85 00 00 00 00 00 00 c6
[6100901] -> fe 09 24 00 01 04 01 05 00 00 00 00 00 2c
[6100905] <- fe 01 64 00 00 65
[6100908] -> fe 09 24 00 02 01 01 05 00 00 00 00 00 2a
[6100912] <- fe 01 64 00 00 65
[6100915] -> fe 09 24 00 03 04 01 05 00 00 00 00 00 2e
[6100919] <- fe 01 64 00 00 65
[6100922] -> fe 09 24 00 04 07 01 05 00 00 00 00 00 2a
[6100926] <- fe 01 64 00 00 65
[6100929] -> fe 09 24 00 05 08 01 05 00 00 00 00 00 24
[6100933] <- fe 01 64 00 00 65
[6100936] -> fe 09 24 00 06 09 01 05 00 00 00 00 00 26
[6100940] <- fe 01 64 00 00 65
[6100943] -> fe 09 24 00 08 04 01 05 00 00 00 00 00 25
[6100956] <- fe 01 64 00 00 65
[6100959] -> fe 09 24 00 0a 04 01 05 00 00 00 00 00 27
[6100963] <- fe 01 64 00 00 65
[6100966] -> fe 11 24 00 0b 04 01 00 04 00 00 02 01 05 0a 00 02 00 05 02 05 33
[6100971] <- fe 01 64 00 00 65
[6100974] -> fe 09 24 00 6e 04 01 05 00 00 00 00 00 43
[6100978] <- fe 01 64 00 00 65
[6100982] -> fe 09 24 00 0c 5e c0 05 00 00 00 00 00 ba
[6100986] <- fe 01 64 00 00 65
[6100989] -> fe 0b 24 00 0d 04 01 05 00 00 00 01 19 00 00 3a
[6100993] <- fe 01 64 00 00 65
[6100996] -> fe 09 24 00 2f 04 01 05 00 00 00 00 00 02
[6101000] <- fe 01 64 00 00 65
[6101003] -> fe 09 24 00 f2 e0 a1 05 00 00 00 00 00 9b
[6101007] <- fe 01 64 00 00 65
[6101010] -> fe 03 25 4a f2 84 0b 11
[6101016] <- fe 13 65 4a 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3d
[6101020] -> fe 04 25 4b f2 84 0b 00 17
[6101030] <- fe 01 65 4b 00 2f
[6101036] -> fe 04 25 05 00 00 00 00 24
[6101040] <- fe 01 65 05 00 61
[6101044] <- fe 14 45 85 00 00 00 00 00 0e f2 2f 0d 0c 6e 0b 0a 08 06 05 04 03 02 01 66 fe 03 4f 80 08 02 00 c6
[6101047] -> fe 00 27 00 27
[6101057] <- fe 0e 67 00 00 09 28 d1 26 00 4b 12 00 00 00 07 09 00 e8
[6101059] -> fe 05 25 04 00 00 00 00 f2 d6
[6101064] <- fe 01 65 04 00 60
[6101067] <- fe 0e 45 84 00 00 00 00 00 08 f2 e0 a1 05 00 00 00 00 71
[6101071] -> fe 05 25 04 00 00 00 00 2f 0b
[6101075] <- fe 01 65 04 00 60
[6101078] <- fe 0e 45 84 00 00 00 00 00 08 2f 04 01 05 00 00 00 00 e8
[6101080] -> fe 05 25 04 00 00 00 00 0d 29
[6101085] <- fe 01 65 04 00 60
[6101088] <- fe 10 45 84 00 00 00 00 00 0a 0d 04 01 05 00 00 01 19 00 00 ce
[6101090] -> fe 05 25 04 00 00 00 00 0c 28
[6101094] <- fe 01 65 04 00 60
[6101097] <- fe 0e 45 84 00 00 00 00 00 08 0c 5e c0 05 00 00 00 00 50
[6101099] -> fe 05 25 04 00 00 00 00 6e 4a
[6101104] <- fe 01 65 04 00 60
[6101107] <- fe 0e 45 84 00 00 00 00 00 08 6e 04 01 05 00 00 00 00 a9
[6101109] -> fe 05 25 04 00 00 00 00 0b 2f
[6101113] <- fe 01 65 04 00 60
[6101117] <- fe 16 45 84 00 00 00 00 00 10 0b 04 01 00 04 00 02 01 05 0a 00 02 00 05 02 05 c1
[6101118] -> fe 05 25 04 00 00 00 00 0a 2e
[6101123] <- fe 01 65 04 00 60
[6101126] <- fe 0e 45 84 00 00 00 00 00 08 0a 04 01 05 00 00 00 00 cd
[6101129] -> fe 05 25 04 00 00 00 00 08 2c
[6101133] <- fe 01 65 04 00 60
[6101136] <- fe 0e 45 84 00 00 00 00 00 08 08 04 01 05 00 00 00 00 cf
[6101138] -> fe 05 25 04 00 00 00 00 06 22
[6101142] <- fe 01 65 04 00 60
[6101146] <- fe 0e 45 84 00 00 00 00 00 08 06 09 01 05 00 00 00 00 cc
[6101147] -> fe 05 25 04 00 00 00 00 05 21
[6101154] <- fe 01 65 04 00 60 fe 0e 45 84 00 00 00 00 00 08 05 08 01 05 00 00 00 00 ce
[6101155] -> fe 05 25 04 00 00 00 00 04 20
[6101160] <- fe 01 65 04 00 60
[6101163] <- fe 0e 45 84 00 00 00 00 00 08 04 07 01 05 00 00 00 00 c0
[6101165] -> fe 05 25 04 00 00 00 00 03 27
[6101169] <- fe 01 65 04 00 60
[6101172] <- fe 0e 45 84 00 00 00 00 00 08 03 04 01 05 00 00 00 00 c4
[6101174] -> fe 05 25 04 00 00 00 00 02 26
[6101178] <- fe 01 65 04 00 60
[6101181] <- fe 0e 45 84 00 00 00 00 00 08 02 01 01 05 00 00 00 00 c0
[6101183] -> fe 05 25 04 00 00 00 00 01 25
[6101187] <- fe 01 65 04 00 60
[6101190] <- fe 0e 45 84 00 00 00 00 00 08 01 04 01 05 00 00 00 00 c6
[6101211] -> fe 00 25 50 75
[6101217] <- fe 18 65 50 00 00 09 62 1a 00 00 09 28 d1 26 00 4b 12 00 00 00 00 00 00 00 00 00 0b d8
[6101245] -> fe 05 25 36 0f fc ff fe 00 e4
[6101262] <- fe 01 65 36 00 52
[6101265] <- fe 03 45 b6 00 00 00 f0
[6101275] -> fe 1a 24 02 02 fd ff 00 00 00 00 00 00 f2 00 00 f2 21 00 01 00 1e 06 00 19 02 02 0b fe 00 e8
[6101293] <- fe 01 64 02 00 67
[6101297] <- fe 03 44 80 00 f2 01 34
[6101737] -> fe 17 24 01 c7 9e 01 01 00 ef 02 00 1e 0d 01 03 24 08 00 64 75 ec de 64 76 17 0e 93
[6101756] <- fe 01 64 01 00 64
[6103256] <- fe 03 44 80 cd 01 02 09
[6105263] -> fe 17 24 01 c7 9e 01 01 00 ef 03 00 1e 0d 01 03 24 08 00 64 75 ec de 64 76 17 0e 92
[6105269] <- fe 01 64 01 00 64
[6106842] <- fe 03 44 80 cd 01 03 08
[6106847] -> fe 04 25 45 c7 9e 00 1e 23
[6106850] <- fe 01 65 45 00 21
[6109856] -> fe 17 24 01 c7 9e 01 01 00 ef 04 00 1e 0d 01 03 24 08 00 64 75 ec de 64 76 17 0e 95
[6109862] <- fe 01 64 01 00 64
[6111417] <- fe 03 44 80 cd 01 04 0f
[6111421] -> fe 0a 25 00 0b 32 65 75 df 38 c1 a4 00 00 84
[6111425] <- fe 01 65 00 00 64
home-assistant[bot] commented 1 year ago

Hey there @dmulcahey, @adminiuga, @puddly, mind taking a look at this issue as it has been labeled with an integration (zha) you are listed as a code owner for? Thanks!

Code owner commands Code owners of `zha` can trigger bot actions by commenting: - `@home-assistant close` Closes the issue. - `@home-assistant rename Awesome new title` Renames the issue. - `@home-assistant reopen` Reopen the issue. - `@home-assistant unassign zha` Removes the current integration label and assignees on the issue, add the integration domain after the command.

(message by CodeOwnersMention)

zha documentation zha source (message by IssueLinks)

Tarik2142 commented 1 year ago

image After changing the channel to 11 (it is used by Z2M), the network starts successfully when selecting the "Create a network" option. Device log:

42651] -> fe 04 21 1c 21 00 00 00 18
[1542680] <- fe 76 61 1c 00 74 2a 05 02 65 0f 65 00 1e 00 00 00 01 05 01 8f 00 07 00 02 0d 02 00 00 00 0b 00 00 00 00 00 00 00 00 00 00 00 84 54 08 00 00 08 00 00 0f 0f 04 00 01 00 00 00 01 00 00 00 00 ea d6 af 4b ce 65 5e 98 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 0f 05 00 01 3c 0a 01 00 00 00 04 00 00 00 90
[1542686] -> fe 02 21 13 55 00 65
[1542693] <- fe 02 61 13 01 00 71
[1542695] -> fe 04 21 1c 55 00 00 00 6c
[1542704] <- fe 03 61 1c 00 01 01 7e
[1542706] -> fe 02 21 13 01 00 31
[1542711] <- fe 02 61 13 08 00 78
[1542713] -> fe 04 21 1c 01 00 00 00 38
[1542719] <- fe 0a 61 1c 00 08 09 28 d1 26 00 4b 12 00 f0
[1542721] -> fe 02 21 13 87 00 b7
[1542731] <- fe 02 61 13 01 00 71
[1542733] -> fe 04 21 1c 87 00 00 00 be
[1542749] <- fe 03 61 1c 00 01 00 7f
[1542751] -> fe 02 21 13 3a 00 0a
[1542761] <- fe 02 61 13 11 00 61
[1542763] -> fe 04 21 1c 3a 00 00 00 03
[1542781] <- fe 13 61 1c 00 11 00 c8 49 27 8d 47 aa ba e4 59 47 e2 da c8 47 6e 16 36
[1542785] -> fe 05 21 32 01 07 00 00 00 10
[1542794] <- fe 04 61 32 0c 00 00 00 5b
[1542796] -> fe 08 21 33 01 07 00 00 00 00 00 0c 10
[1542808] <- fe 0e 61 33 00 0c 00 00 00 00 ea d6 af 4b ce 65 5e 98 e5
[1542810] -> fe 00 21 02 23
[1542814] <- fe 0a 61 02 02 01 02 07 01 2a 8d 34 01 00 fc
[1542820] -> fe 02 21 13 01 01 30
[1542830] <- fe 02 61 13 10 00 60
[1542832] -> fe 04 21 1c 01 01 00 00 39
[1542850] <- fe 12 61 1c 00 10 bc 2f 29 ca 67 df e2 9f e9 71 1f 7b 25 c2 a7 d6 a0
[1542852] -> fe 02 21 13 5f 00 6f
[1542856] <- fe 02 61 13 01 00 71
[1542858] -> fe 04 21 1c 5f 00 00 00 66
[1542864] <- fe 03 61 1c 00 01 01 7e
[1542866] -> fe 02 21 13 87 00 b7
[1542876] <- fe 02 61 13 01 00 71
[1542878] -> fe 04 21 1c 87 00 00 00 be
[1542894] <- fe 03 61 1c 00 01 00 7f
[1542896] -> fe 02 21 13 32 00 02
[1542903] <- fe 02 61 13 01 00 71
[1542905] -> fe 04 21 1c 32 00 00 00 0b
[1542915] <- fe 03 61 1c 00 01 01 7e
[1542917] -> fe 02 21 13 33 00 03
[1542924] <- fe 02 61 13 01 00 71
[1542926] -> fe 04 21 1c 33 00 00 00 0a
[1542936] <- fe 03 61 1c 00 01 3c 43
[1542938] -> fe 02 21 13 33 00 03
[1542945] <- fe 02 61 13 01 00 71
[1542947] -> fe 07 21 1d 33 00 00 00 01 00 78 71
[1542958] <- fe 01 61 1d 00 7d
[1542961] -> fe 02 21 13 36 00 06
[1542967] <- fe 02 61 13 01 00 71
[1542969] -> fe 04 21 1c 36 00 00 00 0f
[1542979] <- fe 03 61 1c 00 01 01 7e
[1542981] -> fe 02 21 13 38 00 08
[1542988] <- fe 02 61 13 01 00 71
[1542990] -> fe 04 21 1c 38 00 00 00 01
[1543000] <- fe 03 61 1c 00 01 02 7d
[1543002] -> fe 02 21 13 38 00 08
[1543009] <- fe 02 61 13 01 00 71
[1543011] -> fe 07 21 1d 38 00 00 00 01 00 ff fd
[1543022] <- fe 01 61 1d 00 7d
[1543025] -> fe 02 21 13 3e 00 0e
[1543031] <- fe 02 61 13 01 00 71
[1543033] -> fe 04 21 1c 3e 00 00 00 07
[1543043] <- fe 03 61 1c 00 01 00 7f
[1543045] -> fe 02 21 13 30 00 00
[1543052] <- fe 02 61 13 01 00 71
[1543054] -> fe 04 21 1c 30 00 00 00 09
[1543064] <- fe 03 61 1c 00 01 1e 61
[1543066] -> fe 02 21 13 8f 00 bf
[1543073] <- fe 02 61 13 01 00 71
[1543075] -> fe 04 21 1c 8f 00 00 00 b6
[1543086] <- fe 03 61 1c 00 01 01 7e
[1543089] -> fe 01 41 00 01 41
[1545663] <- 00
[1545666] <- fe 06 41 80 00 02 01 02 07 01 c0
[1545671] -> fe 01 2f 05 04 2f
[1549272] <- fe 01 6f 05 00 6b fe 01 45 c0 09 8d
[1549275] <- fe 03 4f 80 0d 00 04 c5
[1549472] <- fe 03 4f 80 08 02 00 c6
[1549478] -> fe 02 21 13 21 00 11
[1549483] <- fe 02 61 13 74 00 04
[1549488] -> fe 04 21 1c 21 00 00 00 18
[1549508] <- fe 76 61 1c 00 74 2a 05 02 65 0f 65 00 1e 00 00 00 01 05 01 8f 00 07 00 02 0d 02 00 00 00 0b 00 00 00 00 00 00 00 00 00 00 00 84 54 08 00 00 08 00 00 0f 0f 04 00 01 00 00 00 01 00 00 00 00 ea d6 af 4b ce 65 5e 98 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 0f 05 00 01 3c 0a 01 00 00 00 04 00 00 00 90
[1549520] -> fe 00 21 02 23
[1549524] <- fe 0a 61 02 02 01 02 07 01 2a 8d 34 01 00 fc
[1549530] -> fe 02 27 0a ff 00 d0
[1549533] <- fe 01 67 0a 00 6c
[1549539] -> fe 1b 24 00 01 04 01 00 04 00 00 05 00 00 06 00 0a 00 19 00 01 05 04 01 00 20 00 00 05 02 05 0c
[1549545] <- fe 01 64 00 00 65
[1549551] -> fe 0b 24 00 02 5e c0 20 08 00 00 01 00 00 00 9a
[1549555] <- fe 01 64 00 00 65
[1549560] -> fe 02 25 3e ff ff 19
[1549563] <- fe 01 65 3e 00 5a
[1549571] -> fe 17 24 02 02 00 00 00 00 00 00 00 00 00 00 00 00 02 00 01 20 00 03 00 01 00 00 12
[1549577] <- fe 01 64 02 00 67
[1549580] <- fe 12 45 82 00 00 00 00 00 00 40 8f 00 00 50 a0 00 01 2c a0 00 00 67
[1549584] <- fe 19 45 ff 00 00 00 02 80 00 01 00 00 00 00 00 00 40 8f 00 00 50 a0 00 01 2c a0 00 00 92
[1549593] -> fe 17 24 02 02 00 00 00 00 00 00 00 00 00 00 00 00 05 00 02 20 00 03 00 02 00 00 15
[1549599] <- fe 01 64 02 00 67
[1549603] <- fe 08 45 85 00 00 00 00 00 02 02 01 c9 fe 0f 45 ff 00 00 00 05 80 00 02 00 00 00 00 00 02 02 01 33
[1549609] -> fe 18 24 02 02 00 00 00 00 00 00 00 00 00 00 00 00 04 00 03 20 00 04 00 03 00 00 02 1e
[1549615] <- fe 01 64 02 00 67
[1549618] <- fe 10 45 84 00 00 00 00 00 0a 02 5e c0 20 08 00 01 00 00 00 6e
[1549622] <- fe 17 45 ff 00 00 00 04 80 00 03 00 00 00 00 00 0a 02 5e c0 20 08 00 01 00 00 00 95
[1549630] -> fe 18 24 02 02 00 00 00 00 00 00 00 00 00 00 00 00 04 00 04 20 00 04 00 04 00 00 01 1d
[1549636] <- fe 01 64 02 00 67
[1549645] <- fe 20 45 84 00 00 00 00 00 1a 01 04 01 00 04 00 05 00 00 06 00 0a 00 19 00 01 05 04 01 00 20 00 00 05 02 05 c8 fe 27 45 ff 00 00 00 04 80 00 04 00 00 00 00 00 1a 01 04 01 00 04 00 05 00 00 06 00 0a 00 19 00 01 05 04 01 00 20 00 00 05 02 05 34
[1549653] -> fe 05 25 36 02 00 00 00 01 15
[1549658] <- fe 01 65 36 00 52 fe 03 45 b6 00 00 00 f0
[1549661] <- fe 0a 45 ff 00 00 00 36 80 00 00 00 00 00 06
[1549666] -> fe 05 25 36 0f fc ff 00 00 1a
[1549676] <- fe 01 65 36 00 52 fe 03 45 b6 00 00 00 f0
[1549680] <- fe 0a 45 ff 00 00 00 36 80 00 01 00 00 00 07
[1549682] -> fe 17 24 02 0f fc ff 00 00 00 00 00 00 00 00 00 00 36 00 05 20 00 03 00 05 00 00 28
[1549688] <- fe 01 64 02 00 67
[1549693] -> fe 1b 24 02 02 00 00 00 00 00 00 00 00 00 00 00 00 38 00 06 20 00 07 00 06 00 f8 ff 07 04 01 25
[1549699] <- fe 01 64 02 00 67
[1554315] <- fe 1c 45 b8 00 00 00 00 f8 ff 07 04 00 00 00 10 70 9c a0 6d 69 62 3a 0a 0e 28 12 1d 1d 2f 7f 1d 96
[1554319] <- fe 23 45 ff 00 00 00 38 80 00 06 00 00 00 00 f8 ff 07 04 00 00 00 10 70 9c a0 6d 69 62 3a 0a 0e 28 12 1d 1d 2f 7f 1d 50
[1554330] -> fe 02 21 13 21 00 11
[1554333] <- fe 02 61 13 74 00 04
[1554342] -> fe 04 21 1c 21 00 00 00 18
[1554357] <- fe 76 61 1c 00 74 2d 05 02 65 0f 65 00 1e 00 00 00 01 05 01 8f 00 07 00 02 0d 02 00 00 00 0b 00 00 00 00 00 00 00 00 00 00 00 84 54 08 00 00 08 00 00 0f 0f 04 00 01 00 00 00 01 00 00 00 00 ea d6 af 4b ce 65 5e 98 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 0f 05 00 01 3c 0a 01 00 00 00 04 00 00 00 97
[1554365] -> fe 02 21 13 55 00 65
[1554374] <- fe 02 61 13 01 00 71
[1554376] -> fe 04 21 1c 55 00 00 00 6c
[1554392] <- fe 03 61 1c 00 01 01 7e
[1554396] -> fe 02 21 13 01 00 31
[1554403] <- fe 02 61 13 08 00 78
[1554405] -> fe 04 21 1c 01 00 00 00 38
[1554418] <- fe 0a 61 1c 00 08 09 28 d1 26 00 4b 12 00 f0
[1554420] -> fe 02 21 13 87 00 b7
[1554426] <- fe 02 61 13 01 00 71
[1554428] -> fe 04 21 1c 87 00 00 00 be
[1554437] <- fe 03 61 1c 00 01 00 7f
[1554439] -> fe 02 21 13 3a 00 0a
[1554445] <- fe 02 61 13 11 00 61
[1554447] -> fe 04 21 1c 3a 00 00 00 03
[1554458] <- fe 13 61 1c 00 11 00 c8 49 27 8d 47 aa ba e4 59 47 e2 da c8 47 6e 16 36
[1554460] -> fe 05 21 32 01 07 00 00 00 10
[1554464] <- fe 04 61 32 0c 00 00 00 5b
[1554466] -> fe 08 21 33 01 07 00 00 00 00 00 0c 10
[1554471] <- fe 0e 61 33 00 0c e2 04 00 00 ea d6 af 4b ce 65 5e 98 03
[1554474] -> fe 00 21 02 23
[1554478] <- fe 0a 61 02 02 01 02 07 01 2a 8d 34 01 00 fc
[1554485] -> fe 02 21 13 01 01 30
[1554490] <- fe 02 61 13 10 00 60
[1554492] -> fe 04 21 1c 01 01 00 00 39
[1554503] <- fe 12 61 1c 00 10 bc 2f 29 ca 67 df e2 9f e9 71 1f 7b 25 c2 a7 d6 a0
Adminiuga commented 1 year ago

From the log: Network formation refused: there is too much RF interference. Make sure your coordinator is on a USB 2.0 extension cable and away from any sources of interference, like USB 3.0 ports, SSDs, 2.4GHz routers, motherboards, etc.

In other words, that channel is not the best and/or you have too much RF noise

Tarik2142 commented 1 year ago

Maybe improve the error text? Add a recommendation to change the ZB channel.

puddly commented 1 year ago

ZHA performs an energy scan when forming a new network. From the UART log (it would be much easier for you to include the ZHA debug log here, since the commands will be parsed https://www.home-assistant.io/integrations/zha/#debug-logging), the energy scan looks like this:

{
    11: 120,
    12: 153,
    13: 167,
    14: 109,
    15:  83,
    16:  32,
    17:   0,
    18:  80,
    19:   0,
    20:  43,
    21:  25,
    22:  47,
    23:  76,
    24: 149,
    25:  14,  # best channel
    26:   0,
}

Initially forming a network is done by letting Z-Stack pick its own settings and channel, from channels 15, 20, or 25 (11 is avoided due to its overlap with WiFi channel 1), and then the actual channel selection is written directly to NVRAM. What's happening here is that Z-Stack refuses to form a network and times out, likely because there is just too much interference somewhere.

I'm not sure why channel 11 works here, since the energy scan clearly shows channel 11 having more noise than 15, 20, and 25.

Try adding 11 to the list here and see if that helps: https://github.com/zigpy/zigpy-znp/blob/c4db8d1151b5a999ead73480faea4ea01b7cb7d7/zigpy_znp/const.py#L28. I still consider this an environmental problem though, perhaps the RF noise is periodic and wasn't picked up during the application-initiated energy scan, but instead during the Z-Stack internal energy scan.

Tarik2142 commented 1 year ago

Thanks, I've enabled logging. ZHA selected channel 20 but won't start again. I will experiment with the channels, it seems to me that the network does not start on channels greater than 11 or something like that, so it may be a zb firmware problem

2023-05-30 18:04:02.203 DEBUG (MainThread) [zigpy_znp.uart] Connecting to socket://192.168.0.125:6638 at 115200 baud
2023-05-30 18:04:02.209 DEBUG (MainThread) [zigpy_znp.uart] Opened socket://192.168.0.125:6638 serial port
2023-05-30 18:04:02.211 DEBUG (MainThread) [zigpy_znp.uart] Connected to socket://192.168.0.125:6638 at 115200 baud
2023-05-30 18:04:02.212 DEBUG (MainThread) [zigpy_znp.api] Toggling RTS/DTR pins to skip bootloader or reset chip
2023-05-30 18:04:02.665 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Ping.Req()
2023-05-30 18:04:02.676 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.Ping.Rsp(Capabilities=<MTCapabilities.APP_CNF|GP|UTIL|ZDO|AF|SYS: 1625>)
2023-05-30 18:04:02.680 DEBUG (MainThread) [zigpy_znp.api] Radio is alive: SYS.Ping.Rsp(Capabilities=<MTCapabilities.APP_CNF|GP|UTIL|ZDO|AF|SYS: 1625>)
2023-05-30 18:04:02.681 DEBUG (MainThread) [zigpy_znp.nvram] Detecting struct alignment
2023-05-30 18:04:02.682 DEBUG (MainThread) [zigpy_znp.api] Sending request: UTIL.AssocFindDevice.Req(Index=0)
2023-05-30 18:04:02.694 DEBUG (MainThread) [zigpy_znp.api] Received command: UTIL.AssocFindDevice.Rsp(Device=b'\xFE\xFF\x02\x10\x08\x01\x00\x20\x00\x00\x00\x00\x28\xFE\x00\x20\x63\xDF\x02\x10\x20\x00\x00\x00\x3B\xC0\x02\x10\x00\x00\x00\x00\x11\xC9\x01\x00')
2023-05-30 18:04:02.698 DEBUG (MainThread) [zigpy_znp.nvram] Detected struct alignment: True
2023-05-30 18:04:02.699 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.TCLK_TABLE: 4>, SubId=0)
2023-05-30 18:04:02.714 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=20)
2023-05-30 18:04:02.718 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVRead.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.TCLK_TABLE: 4>, SubId=0, Offset=0, Length=20)
2023-05-30 18:04:02.735 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVRead.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x1E\x32\x00\x00\x00\x00\x00\x00\x0B\x32\x65\x75\xDF\x38\xC1\xA4\x02\x00\x01\x00')
2023-05-30 18:04:02.739 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM[NvSysIds.ZSTACK][ExNvIds.TCLK_TABLE][0x0000] = b'\x1E\x32\x00\x00\x00\x00\x00\x00\x0B\x32\x65\x75\xDF\x38\xC1\xA4\x02\x00\x01\x00'
2023-05-30 18:04:02.739 DEBUG (MainThread) [zigpy_znp.api] Detected Z-Stack 3.3
2023-05-30 18:04:02.739 DEBUG (MainThread) [zigpy_znp.api] Connected to socket://192.168.0.125:6638
2023-05-30 18:04:02.741 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.ResetReq.Req(Type=<ResetType.Soft: 1>)
2023-05-30 18:04:02.747 DEBUG (MainThread) [zigpy_znp.api] Request has no response, not waiting for one.
2023-05-30 18:04:02.748 DEBUG (MainThread) [zigpy_znp.uart] Closing serial port
2023-05-30 18:04:02.772 DEBUG (MainThread) [zigpy.appdb] Current database version is v11 (table version v11)
2023-05-30 18:04:02.774 DEBUG (MainThread) [zigpy.appdb] Loading application state
2023-05-30 18:04:02.787 DEBUG (MainThread) [zigpy.quirks.registry] Checking quirks for None None (00:12:4b:00:26:d1:28:09)
2023-05-30 18:04:02.798 DEBUG (MainThread) [zigpy.backups] Adding a new backup NetworkBackup(backup_time=datetime.datetime(2023, 5, 30, 14, 5, 19, 431569, tzinfo=datetime.timezone.utc), network_info=NetworkInfo(extended_pan_id=a6:f5:9e:02:db:e6:c1:65, pan_id=0x2F00, nwk_update_id=0, nwk_manager_id=0x0000, channel=11, channel_mask=<Channels.CHANNEL_11: 2048>, security_level=5, network_key=Key(key=bd:a7:b8:96:12:a3:44:fc:1c:67:32:0c:a6:55:82:c4, tx_counter=1250, rx_counter=0, seq=0, partner_ieee=00:12:4b:00:26:d1:28:09), tc_link_key=Key(key=5a:69:67:42:65:65:41:6c:6c:69:61:6e:63:65:30:39, tx_counter=0, rx_counter=0, seq=0, partner_ieee=00:12:4b:00:26:d1:28:09), key_table=[], children=[], nwk_addresses={}, stack_specific={'zstack': {'tclk_seed': 'a44c406d5e758a1d86d97dad11db4cc9'}}, metadata={'zstack': {'TransportRev': 2, 'ProductId': 1, 'MajorRel': 2, 'MinorRel': 7, 'MaintRel': 1, 'CodeRevision': 20221226, 'BootloaderBuildType': 0, 'BootloaderRevision': None}}, source='zigpy-znp@0.11.1'), node_info=NodeInfo(nwk=0x0000, ieee=00:12:4b:00:26:d1:28:09, logical_type=<LogicalType.Coordinator: 0>))
2023-05-30 18:04:02.800 DEBUG (MainThread) [zigpy.backups] Adding a new backup NetworkBackup(backup_time=datetime.datetime(2023, 5, 30, 14, 14, 43, 326611, tzinfo=datetime.timezone.utc), network_info=NetworkInfo(extended_pan_id=98:5e:65:ce:4b:af:d6:ea, pan_id=0x5484, nwk_update_id=0, nwk_manager_id=0x0000, channel=11, channel_mask=<Channels.CHANNEL_11: 2048>, security_level=5, network_key=Key(key=c8:49:27:8d:47:aa:ba:e4:59:47:e2:da:c8:47:6e:16, tx_counter=1250, rx_counter=0, seq=0, partner_ieee=00:12:4b:00:26:d1:28:09), tc_link_key=Key(key=5a:69:67:42:65:65:41:6c:6c:69:61:6e:63:65:30:39, tx_counter=0, rx_counter=0, seq=0, partner_ieee=00:12:4b:00:26:d1:28:09), key_table=[], children=[], nwk_addresses={}, stack_specific={'zstack': {'tclk_seed': 'bc2f29ca67dfe29fe9711f7b25c2a7d6'}}, metadata={'zstack': {'TransportRev': 2, 'ProductId': 1, 'MajorRel': 2, 'MinorRel': 7, 'MaintRel': 1, 'CodeRevision': 20221226, 'BootloaderBuildType': 0, 'BootloaderRevision': None}}, source='zigpy-znp@0.11.1'), node_info=NodeInfo(nwk=0x0000, ieee=00:12:4b:00:26:d1:28:09, logical_type=<LogicalType.Coordinator: 0>))
2023-05-30 18:04:02.801 DEBUG (MainThread) [zigpy_znp.uart] Connecting to socket://192.168.0.125:6638 at 115200 baud
2023-05-30 18:04:02.804 DEBUG (MainThread) [zigpy_znp.uart] Opened socket://192.168.0.125:6638 serial port
2023-05-30 18:04:02.805 DEBUG (MainThread) [zigpy_znp.uart] Connected to socket://192.168.0.125:6638 at 115200 baud
2023-05-30 18:04:02.805 DEBUG (MainThread) [zigpy_znp.api] Toggling RTS/DTR pins to skip bootloader or reset chip
2023-05-30 18:04:03.257 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Ping.Req()
2023-05-30 18:04:03.758 DEBUG (MainThread) [zigpy_znp.api] Sending CC253x bootloader skip bytes
2023-05-30 18:04:05.754 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.ResetInd.Callback(Reason=<ResetReason.PowerUp: 0>, TransportRev=2, ProductId=1, MajorRel=2, MinorRel=7, MaintRel=1)
2023-05-30 18:04:05.756 DEBUG (MainThread) [zigpy_znp.api] Radio is alive: SYS.ResetInd.Callback(Reason=<ResetReason.PowerUp: 0>, TransportRev=2, ProductId=1, MajorRel=2, MinorRel=7, MaintRel=1)
2023-05-30 18:04:05.756 DEBUG (MainThread) [zigpy_znp.api] Giving ping task 0.50s to finish
2023-05-30 18:04:06.258 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Ping.Req()
2023-05-30 18:04:06.263 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.Ping.Rsp(Capabilities=<MTCapabilities.APP_CNF|GP|UTIL|ZDO|AF|SYS: 1625>)
2023-05-30 18:04:06.264 DEBUG (MainThread) [zigpy_znp.nvram] Detecting struct alignment
2023-05-30 18:04:06.264 DEBUG (MainThread) [zigpy_znp.api] Sending request: UTIL.AssocFindDevice.Req(Index=0)
2023-05-30 18:04:06.275 DEBUG (MainThread) [zigpy_znp.api] Received command: UTIL.AssocFindDevice.Rsp(Device=b'\xFE\xFF\x02\x10\x08\x01\x00\x20\x00\x00\x00\x00\x28\xFE\x00\x20\x63\xDF\x02\x10\x20\x00\x00\x00\x3B\xC0\x02\x10\x00\x00\x00\x00\x11\xC9\x01\x00')
2023-05-30 18:04:06.275 DEBUG (MainThread) [zigpy_znp.nvram] Detected struct alignment: True
2023-05-30 18:04:06.276 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.TCLK_TABLE: 4>, SubId=0)
2023-05-30 18:04:06.283 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=20)
2023-05-30 18:04:06.284 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVRead.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.TCLK_TABLE: 4>, SubId=0, Offset=0, Length=20)
2023-05-30 18:04:06.295 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVRead.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x29\x32\x00\x00\x00\x00\x00\x00\x0B\x32\x65\x75\xDF\x38\xC1\xA4\x02\x00\x01\x00')
2023-05-30 18:04:06.295 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM[NvSysIds.ZSTACK][ExNvIds.TCLK_TABLE][0x0000] = b'\x29\x32\x00\x00\x00\x00\x00\x00\x0B\x32\x65\x75\xDF\x38\xC1\xA4\x02\x00\x01\x00'
2023-05-30 18:04:06.295 DEBUG (MainThread) [zigpy_znp.api] Detected Z-Stack 3.3
2023-05-30 18:04:06.296 DEBUG (MainThread) [zigpy_znp.api] Connected to socket://192.168.0.125:6638
2023-05-30 18:04:06.304 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.NIB: 33>)
2023-05-30 18:04:06.314 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=116)
2023-05-30 18:04:06.317 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.NIB: 33>, Offset=0)
2023-05-30 18:04:06.346 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x6B\x05\x02\x65\x0F\x65\x00\x1E\x00\x00\x00\x01\x05\x01\x8F\x00\x07\x00\x02\x0D\x02\x00\x00\x00\x0B\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x62\x1A\x08\x00\x00\x08\x00\x00\x0F\x0F\x04\x00\x01\x00\x00\x00\x01\x00\x00\x00\x00\x09\x28\xD1\x26\x00\x4B\x12\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x0F\x05\x00\x01\x3C\x0A\x01\x00\x00\x00\x1E\x00\x00\x00')
2023-05-30 18:04:06.351 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM["LEGACY"][0x0021] = NIB(SequenceNum=107, PassiveAckTimeout=5, MaxBroadcastRetries=2, MaxChildren=101, MaxDepth=15, MaxRouters=101, dummyNeighborTable=0, BroadcastDeliveryTime=30, ReportConstantCost=0, RouteDiscRetries=0, dummyRoutingTable=0, SecureAllFrames=1, SecurityLevel=5, SymLink=1, CapabilityFlags=143, TransactionPersistenceTime=7, nwkProtocolVersion=2, RouteDiscoveryTime=13, RouteExpiryTime=2, nwkDevAddress=0x0000, nwkLogicalChannel=11, nwkCoordAddress=0x0000, nwkCoordExtAddress=00:00:00:00:00:00:00:00, nwkPanId=6754, nwkState=<NwkState.NWK_ROUTER: 8>, channelList=<Channels.CHANNEL_11: 2048>, beaconOrder=15, superFrameOrder=15, scanDuration=4, battLifeExt=0, allocatedRouterAddresses=1, allocatedEndDeviceAddresses=1, nodeDepth=0, extendedPANID=00:12:4b:00:26:d1:28:09, nwkKeyLoaded=<Bool.true: 1>, spare1=NwkKeyDesc(KeySeqNum=0, Key=00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00), spare2=NwkKeyDesc(KeySeqNum=0, Key=00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00), spare3=0, spare4=0, nwkLinkStatusPeriod=15, nwkRouterAgeLimit=5, nwkUseMultiCast=<Bool.false: 0>, nwkIsConcentrator=<Bool.true: 1>, nwkConcentratorDiscoveryTime=60, nwkConcentratorRadius=10, nwkAllFresh=1, nwkManagerAddr=0x0000, nwkTotalTransmissions=30, nwkUpdateId=0)
2023-05-30 18:04:06.352 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.BDBNODEISONANETWORK: 85>)
2023-05-30 18:04:06.361 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2023-05-30 18:04:06.362 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.BDBNODEISONANETWORK: 85>, Offset=0)
2023-05-30 18:04:06.372 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x01')
2023-05-30 18:04:06.373 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM["LEGACY"][0x0055] = 1
2023-05-30 18:04:06.373 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.EXTADDR: 1>)
2023-05-30 18:04:06.382 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=8)
2023-05-30 18:04:06.383 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.EXTADDR: 1>, Offset=0)
2023-05-30 18:04:06.394 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x09\x28\xD1\x26\x00\x4B\x12\x00')
2023-05-30 18:04:06.396 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM["LEGACY"][0x0001] = 00:12:4b:00:26:d1:28:09
2023-05-30 18:04:06.396 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.LOGICAL_TYPE: 135>)
2023-05-30 18:04:06.407 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2023-05-30 18:04:06.408 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.LOGICAL_TYPE: 135>, Offset=0)
2023-05-30 18:04:06.426 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x00')
2023-05-30 18:04:06.427 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM["LEGACY"][0x0087] = <DeviceLogicalType.Coordinator: 0>
2023-05-30 18:04:06.427 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.NWK_ACTIVE_KEY_INFO: 58>)
2023-05-30 18:04:06.435 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=17)
2023-05-30 18:04:06.436 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.NWK_ACTIVE_KEY_INFO: 58>, Offset=0)
2023-05-30 18:04:06.449 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x00\x01\x03\x05\x07\x09\x0B\x0D\x0F\x00\x02\x04\x06\x08\x0A\x0C\x0D')
2023-05-30 18:04:06.449 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM["LEGACY"][0x003a] = NwkKeyDesc(KeySeqNum=0, Key=01:03:05:07:09:0b:0d:0f:00:02:04:06:08:0a:0c:0d)
2023-05-30 18:04:06.450 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.NWK_SEC_MATERIAL_TABLE: 7>, SubId=0)
2023-05-30 18:04:06.460 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2023-05-30 18:04:06.461 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVRead.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.NWK_SEC_MATERIAL_TABLE: 7>, SubId=0, Offset=0, Length=12)
2023-05-30 18:04:06.474 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVRead.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x44\x7A\x02\x00\x09\x28\xD1\x26\x00\x4B\x12\x00')
2023-05-30 18:04:06.475 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM[NvSysIds.ZSTACK][ExNvIds.NWK_SEC_MATERIAL_TABLE][0x0000] = NwkSecMaterialDesc(FrameCounter=162372, ExtendedPanID=00:12:4b:00:26:d1:28:09)
2023-05-30 18:04:06.476 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Version.Req()
2023-05-30 18:04:06.484 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.Version.Rsp(TransportRev=2, ProductId=1, MajorRel=2, MinorRel=7, MaintRel=1, CodeRevision=20221226, BootloaderBuildType=<BootloaderBuildType.NON_BOOTLOADER_BUILD: 0>, BootloaderRevision=None)
2023-05-30 18:04:06.490 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.TCLK_SEED: 257>)
2023-05-30 18:04:06.499 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=16)
2023-05-30 18:04:06.500 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.TCLK_SEED: 257>, Offset=0)
2023-05-30 18:04:06.512 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\xF3\xA8\xBA\xF8\x6F\x2C\xD7\x1C\x88\xE2\xD2\xD9\x48\xC2\xE1\xFF')
2023-05-30 18:04:06.513 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM["LEGACY"][0x0101] = f3:a8:ba:f8:6f:2c:d7:1c:88:e2:d2:d9:48:c2:e1:ff
2023-05-30 18:04:06.513 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.ResetReq.Req(Type=<ResetType.Soft: 1>)
2023-05-30 18:04:06.514 DEBUG (MainThread) [zigpy_znp.api] Request has no response, not waiting for one.
2023-05-30 18:04:06.514 DEBUG (MainThread) [zigpy_znp.uart] Closing serial port
2023-05-30 18:04:10.229 DEBUG (MainThread) [zigpy.appdb] Current database version is v11 (table version v11)
2023-05-30 18:04:10.235 DEBUG (MainThread) [zigpy.appdb] Loading application state
2023-05-30 18:04:10.267 DEBUG (MainThread) [zigpy.quirks.registry] Checking quirks for None None (00:12:4b:00:26:d1:28:09)
2023-05-30 18:04:10.292 DEBUG (MainThread) [zigpy.backups] Adding a new backup NetworkBackup(backup_time=datetime.datetime(2023, 5, 30, 14, 5, 19, 431569, tzinfo=datetime.timezone.utc), network_info=NetworkInfo(extended_pan_id=a6:f5:9e:02:db:e6:c1:65, pan_id=0x2F00, nwk_update_id=0, nwk_manager_id=0x0000, channel=11, channel_mask=<Channels.CHANNEL_11: 2048>, security_level=5, network_key=Key(key=bd:a7:b8:96:12:a3:44:fc:1c:67:32:0c:a6:55:82:c4, tx_counter=1250, rx_counter=0, seq=0, partner_ieee=00:12:4b:00:26:d1:28:09), tc_link_key=Key(key=5a:69:67:42:65:65:41:6c:6c:69:61:6e:63:65:30:39, tx_counter=0, rx_counter=0, seq=0, partner_ieee=00:12:4b:00:26:d1:28:09), key_table=[], children=[], nwk_addresses={}, stack_specific={'zstack': {'tclk_seed': 'a44c406d5e758a1d86d97dad11db4cc9'}}, metadata={'zstack': {'TransportRev': 2, 'ProductId': 1, 'MajorRel': 2, 'MinorRel': 7, 'MaintRel': 1, 'CodeRevision': 20221226, 'BootloaderBuildType': 0, 'BootloaderRevision': None}}, source='zigpy-znp@0.11.1'), node_info=NodeInfo(nwk=0x0000, ieee=00:12:4b:00:26:d1:28:09, logical_type=<LogicalType.Coordinator: 0>))
2023-05-30 18:04:10.292 DEBUG (MainThread) [zigpy.backups] Adding a new backup NetworkBackup(backup_time=datetime.datetime(2023, 5, 30, 14, 14, 43, 326611, tzinfo=datetime.timezone.utc), network_info=NetworkInfo(extended_pan_id=98:5e:65:ce:4b:af:d6:ea, pan_id=0x5484, nwk_update_id=0, nwk_manager_id=0x0000, channel=11, channel_mask=<Channels.CHANNEL_11: 2048>, security_level=5, network_key=Key(key=c8:49:27:8d:47:aa:ba:e4:59:47:e2:da:c8:47:6e:16, tx_counter=1250, rx_counter=0, seq=0, partner_ieee=00:12:4b:00:26:d1:28:09), tc_link_key=Key(key=5a:69:67:42:65:65:41:6c:6c:69:61:6e:63:65:30:39, tx_counter=0, rx_counter=0, seq=0, partner_ieee=00:12:4b:00:26:d1:28:09), key_table=[], children=[], nwk_addresses={}, stack_specific={'zstack': {'tclk_seed': 'bc2f29ca67dfe29fe9711f7b25c2a7d6'}}, metadata={'zstack': {'TransportRev': 2, 'ProductId': 1, 'MajorRel': 2, 'MinorRel': 7, 'MaintRel': 1, 'CodeRevision': 20221226, 'BootloaderBuildType': 0, 'BootloaderRevision': None}}, source='zigpy-znp@0.11.1'), node_info=NodeInfo(nwk=0x0000, ieee=00:12:4b:00:26:d1:28:09, logical_type=<LogicalType.Coordinator: 0>))
2023-05-30 18:04:10.293 DEBUG (MainThread) [zigpy_znp.uart] Connecting to socket://192.168.0.125:6638 at 115200 baud
2023-05-30 18:04:10.299 DEBUG (MainThread) [zigpy_znp.uart] Opened socket://192.168.0.125:6638 serial port
2023-05-30 18:04:10.299 DEBUG (MainThread) [zigpy_znp.uart] Connected to socket://192.168.0.125:6638 at 115200 baud
2023-05-30 18:04:10.300 DEBUG (MainThread) [zigpy_znp.api] Toggling RTS/DTR pins to skip bootloader or reset chip
2023-05-30 18:04:10.754 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Ping.Req()
2023-05-30 18:04:10.763 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.Ping.Rsp(Capabilities=<MTCapabilities.APP_CNF|GP|UTIL|ZDO|AF|SYS: 1625>)
2023-05-30 18:04:10.765 DEBUG (MainThread) [zigpy_znp.api] Radio is alive: SYS.Ping.Rsp(Capabilities=<MTCapabilities.APP_CNF|GP|UTIL|ZDO|AF|SYS: 1625>)
2023-05-30 18:04:10.765 DEBUG (MainThread) [zigpy_znp.nvram] Detecting struct alignment
2023-05-30 18:04:10.766 DEBUG (MainThread) [zigpy_znp.api] Sending request: UTIL.AssocFindDevice.Req(Index=0)
2023-05-30 18:04:10.776 DEBUG (MainThread) [zigpy_znp.api] Received command: UTIL.AssocFindDevice.Rsp(Device=b'\xFE\xFF\x02\x10\x08\x01\x00\x20\x00\x00\x00\x00\x28\xFE\x00\x20\x63\xDF\x02\x10\x20\x00\x00\x00\x3B\xC0\x02\x10\x00\x00\x00\x00\x11\xC9\x01\x00')
2023-05-30 18:04:10.777 DEBUG (MainThread) [zigpy_znp.nvram] Detected struct alignment: True
2023-05-30 18:04:10.777 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.TCLK_TABLE: 4>, SubId=0)
2023-05-30 18:04:10.790 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=20)
2023-05-30 18:04:10.791 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVRead.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.TCLK_TABLE: 4>, SubId=0, Offset=0, Length=20)
2023-05-30 18:04:10.805 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVRead.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x34\x32\x00\x00\x00\x00\x00\x00\x0B\x32\x65\x75\xDF\x38\xC1\xA4\x02\x00\x01\x00')
2023-05-30 18:04:10.806 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM[NvSysIds.ZSTACK][ExNvIds.TCLK_TABLE][0x0000] = b'\x34\x32\x00\x00\x00\x00\x00\x00\x0B\x32\x65\x75\xDF\x38\xC1\xA4\x02\x00\x01\x00'
2023-05-30 18:04:10.807 DEBUG (MainThread) [zigpy_znp.api] Detected Z-Stack 3.3
2023-05-30 18:04:10.807 DEBUG (MainThread) [zigpy_znp.api] Connected to socket://192.168.0.125:6638
2023-05-30 18:04:10.809 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.NIB: 33>)
2023-05-30 18:04:10.816 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=116)
2023-05-30 18:04:10.817 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.NIB: 33>, Offset=0)
2023-05-30 18:04:10.837 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x6B\x05\x02\x65\x0F\x65\x00\x1E\x00\x00\x00\x01\x05\x01\x8F\x00\x07\x00\x02\x0D\x02\x00\x00\x00\x0B\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x62\x1A\x08\x00\x00\x08\x00\x00\x0F\x0F\x04\x00\x01\x00\x00\x00\x01\x00\x00\x00\x00\x09\x28\xD1\x26\x00\x4B\x12\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x0F\x05\x00\x01\x3C\x0A\x01\x00\x00\x00\x1E\x00\x00\x00')
2023-05-30 18:04:10.846 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM["LEGACY"][0x0021] = NIB(SequenceNum=107, PassiveAckTimeout=5, MaxBroadcastRetries=2, MaxChildren=101, MaxDepth=15, MaxRouters=101, dummyNeighborTable=0, BroadcastDeliveryTime=30, ReportConstantCost=0, RouteDiscRetries=0, dummyRoutingTable=0, SecureAllFrames=1, SecurityLevel=5, SymLink=1, CapabilityFlags=143, TransactionPersistenceTime=7, nwkProtocolVersion=2, RouteDiscoveryTime=13, RouteExpiryTime=2, nwkDevAddress=0x0000, nwkLogicalChannel=11, nwkCoordAddress=0x0000, nwkCoordExtAddress=00:00:00:00:00:00:00:00, nwkPanId=6754, nwkState=<NwkState.NWK_ROUTER: 8>, channelList=<Channels.CHANNEL_11: 2048>, beaconOrder=15, superFrameOrder=15, scanDuration=4, battLifeExt=0, allocatedRouterAddresses=1, allocatedEndDeviceAddresses=1, nodeDepth=0, extendedPANID=00:12:4b:00:26:d1:28:09, nwkKeyLoaded=<Bool.true: 1>, spare1=NwkKeyDesc(KeySeqNum=0, Key=00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00), spare2=NwkKeyDesc(KeySeqNum=0, Key=00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00), spare3=0, spare4=0, nwkLinkStatusPeriod=15, nwkRouterAgeLimit=5, nwkUseMultiCast=<Bool.false: 0>, nwkIsConcentrator=<Bool.true: 1>, nwkConcentratorDiscoveryTime=60, nwkConcentratorRadius=10, nwkAllFresh=1, nwkManagerAddr=0x0000, nwkTotalTransmissions=30, nwkUpdateId=0)
2023-05-30 18:04:10.848 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.BDBNODEISONANETWORK: 85>)
2023-05-30 18:04:10.862 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2023-05-30 18:04:10.863 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.BDBNODEISONANETWORK: 85>, Offset=0)
2023-05-30 18:04:10.881 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x01')
2023-05-30 18:04:10.882 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM["LEGACY"][0x0055] = 1
2023-05-30 18:04:10.883 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.EXTADDR: 1>)
2023-05-30 18:04:10.896 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=8)
2023-05-30 18:04:10.897 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.EXTADDR: 1>, Offset=0)
2023-05-30 18:04:10.916 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x09\x28\xD1\x26\x00\x4B\x12\x00')
2023-05-30 18:04:10.917 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM["LEGACY"][0x0001] = 00:12:4b:00:26:d1:28:09
2023-05-30 18:04:10.917 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.LOGICAL_TYPE: 135>)
2023-05-30 18:04:10.927 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2023-05-30 18:04:10.928 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.LOGICAL_TYPE: 135>, Offset=0)
2023-05-30 18:04:10.940 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x00')
2023-05-30 18:04:10.941 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM["LEGACY"][0x0087] = <DeviceLogicalType.Coordinator: 0>
2023-05-30 18:04:10.942 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.NWK_ACTIVE_KEY_INFO: 58>)
2023-05-30 18:04:10.953 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=17)
2023-05-30 18:04:10.955 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.NWK_ACTIVE_KEY_INFO: 58>, Offset=0)
2023-05-30 18:04:10.975 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x00\x01\x03\x05\x07\x09\x0B\x0D\x0F\x00\x02\x04\x06\x08\x0A\x0C\x0D')
2023-05-30 18:04:10.977 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM["LEGACY"][0x003a] = NwkKeyDesc(KeySeqNum=0, Key=01:03:05:07:09:0b:0d:0f:00:02:04:06:08:0a:0c:0d)
2023-05-30 18:04:10.977 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.NWK_SEC_MATERIAL_TABLE: 7>, SubId=0)
2023-05-30 18:04:10.986 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2023-05-30 18:04:10.987 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVRead.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.NWK_SEC_MATERIAL_TABLE: 7>, SubId=0, Offset=0, Length=12)
2023-05-30 18:04:10.997 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVRead.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x44\x7A\x02\x00\x09\x28\xD1\x26\x00\x4B\x12\x00')
2023-05-30 18:04:10.998 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM[NvSysIds.ZSTACK][ExNvIds.NWK_SEC_MATERIAL_TABLE][0x0000] = NwkSecMaterialDesc(FrameCounter=162372, ExtendedPanID=00:12:4b:00:26:d1:28:09)
2023-05-30 18:04:11.001 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Version.Req()
2023-05-30 18:04:11.009 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.Version.Rsp(TransportRev=2, ProductId=1, MajorRel=2, MinorRel=7, MaintRel=1, CodeRevision=20221226, BootloaderBuildType=<BootloaderBuildType.NON_BOOTLOADER_BUILD: 0>, BootloaderRevision=None)
2023-05-30 18:04:11.015 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.TCLK_SEED: 257>)
2023-05-30 18:04:11.028 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=16)
2023-05-30 18:04:11.029 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.TCLK_SEED: 257>, Offset=0)
2023-05-30 18:04:11.050 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\xF3\xA8\xBA\xF8\x6F\x2C\xD7\x1C\x88\xE2\xD2\xD9\x48\xC2\xE1\xFF')
2023-05-30 18:04:11.051 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM["LEGACY"][0x0101] = f3:a8:ba:f8:6f:2c:d7:1c:88:e2:d2:d9:48:c2:e1:ff
2023-05-30 18:04:11.052 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.ZIGPY_ZNP_MIGRATION_ID: 95>)
2023-05-30 18:04:11.061 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2023-05-30 18:04:11.062 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.ZIGPY_ZNP_MIGRATION_ID: 95>, Offset=0)
2023-05-30 18:04:11.076 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x01')
2023-05-30 18:04:11.077 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM["LEGACY"][0x005f] = 1
2023-05-30 18:04:11.077 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.LOGICAL_TYPE: 135>)
2023-05-30 18:04:11.088 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2023-05-30 18:04:11.089 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.LOGICAL_TYPE: 135>, Offset=0)
2023-05-30 18:04:11.103 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x00')
2023-05-30 18:04:11.104 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM["LEGACY"][0x0087] = 0
2023-05-30 18:04:11.104 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.CONCENTRATOR_ENABLE: 50>)
2023-05-30 18:04:11.112 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2023-05-30 18:04:11.114 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.CONCENTRATOR_ENABLE: 50>, Offset=0)
2023-05-30 18:04:11.128 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x01')
2023-05-30 18:04:11.129 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM["LEGACY"][0x0032] = <Bool.true: 1>
2023-05-30 18:04:11.130 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.CONCENTRATOR_DISCOVERY: 51>)
2023-05-30 18:04:11.141 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2023-05-30 18:04:11.142 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.CONCENTRATOR_DISCOVERY: 51>, Offset=0)
2023-05-30 18:04:11.156 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x3C')
2023-05-30 18:04:11.157 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM["LEGACY"][0x0033] = 60
2023-05-30 18:04:11.157 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.CONCENTRATOR_DISCOVERY: 51>)
2023-05-30 18:04:11.166 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2023-05-30 18:04:11.167 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVWriteExt.Req(Id=<OsalNvIds.CONCENTRATOR_DISCOVERY: 51>, Offset=0, Value=b'\x78')
2023-05-30 18:04:11.182 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVWriteExt.Rsp(Status=<Status.SUCCESS: 0>)
2023-05-30 18:04:11.185 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.CONCENTRATOR_RC: 54>)
2023-05-30 18:04:11.195 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2023-05-30 18:04:11.196 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.CONCENTRATOR_RC: 54>, Offset=0)
2023-05-30 18:04:11.209 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x01')
2023-05-30 18:04:11.210 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM["LEGACY"][0x0036] = <Bool.true: 1>
2023-05-30 18:04:11.211 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.SRC_RTG_EXPIRY_TIME: 56>)
2023-05-30 18:04:11.219 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2023-05-30 18:04:11.220 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.SRC_RTG_EXPIRY_TIME: 56>, Offset=0)
2023-05-30 18:04:11.233 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x02')
2023-05-30 18:04:11.234 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM["LEGACY"][0x0038] = 2
2023-05-30 18:04:11.235 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.SRC_RTG_EXPIRY_TIME: 56>)
2023-05-30 18:04:11.243 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2023-05-30 18:04:11.244 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVWriteExt.Req(Id=<OsalNvIds.SRC_RTG_EXPIRY_TIME: 56>, Offset=0, Value=b'\xFF')
2023-05-30 18:04:11.256 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVWriteExt.Rsp(Status=<Status.SUCCESS: 0>)
2023-05-30 18:04:11.257 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.NWK_CHILD_AGE_ENABLE: 62>)
2023-05-30 18:04:11.265 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2023-05-30 18:04:11.266 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.NWK_CHILD_AGE_ENABLE: 62>, Offset=0)
2023-05-30 18:04:11.278 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x00')
2023-05-30 18:04:11.279 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM["LEGACY"][0x003e] = <Bool.false: 0>
2023-05-30 18:04:11.279 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.BCAST_DELIVERY_TIME: 48>)
2023-05-30 18:04:11.290 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2023-05-30 18:04:11.291 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.BCAST_DELIVERY_TIME: 48>, Offset=0)
2023-05-30 18:04:11.303 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x1E')
2023-05-30 18:04:11.304 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM["LEGACY"][0x0030] = 30
2023-05-30 18:04:11.304 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.ZDO_DIRECT_CB: 143>)
2023-05-30 18:04:11.313 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2023-05-30 18:04:11.314 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.ZDO_DIRECT_CB: 143>, Offset=0)
2023-05-30 18:04:11.326 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x01')
2023-05-30 18:04:11.327 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM["LEGACY"][0x008f] = <Bool.true: 1>
2023-05-30 18:04:11.327 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.ResetReq.Req(Type=<ResetType.Soft: 1>)
2023-05-30 18:04:11.328 DEBUG (MainThread) [zigpy_znp.api] Request has no response, not waiting for one.
2023-05-30 18:04:13.885 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.ResetInd.Callback(Reason=<ResetReason.PowerUp: 0>, TransportRev=2, ProductId=1, MajorRel=2, MinorRel=7, MaintRel=1)
2023-05-30 18:04:13.887 DEBUG (MainThread) [zigpy_znp.api] Sending request: AppConfig.BDBStartCommissioning.Req(Mode=<BDBCommissioningMode.NwkFormation: 4>)
2023-05-30 18:04:17.331 DEBUG (MainThread) [zigpy_znp.api] Received command: AppConfig.BDBStartCommissioning.Rsp(Status=<Status.SUCCESS: 0>)
2023-05-30 18:04:17.336 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.StateChangeInd.Callback(State=<DeviceState.StartedAsCoordinator: 9>)
2023-05-30 18:04:17.340 DEBUG (MainThread) [zigpy_znp.api] Received command: AppConfig.BDBCommissioningNotification.Callback(Status=<BDBCommissioningStatus.NetworkRestored: 13>, Mode=<BDBCommissioningMode.NONE: 0>, RemainingModes=<BDBCommissioningMode.NwkFormation: 4>)
2023-05-30 18:04:17.343 DEBUG (MainThread) [zigpy_znp.api] Command was not handled
2023-05-30 18:04:17.532 DEBUG (MainThread) [zigpy_znp.api] Received command: AppConfig.BDBCommissioningNotification.Callback(Status=<BDBCommissioningStatus.FormationFailure: 8>, Mode=<BDBCommissioningMode.NwkSteering: 2>, RemainingModes=<BDBCommissioningMode.NONE: 0>)
2023-05-30 18:04:17.533 DEBUG (MainThread) [zigpy_znp.api] Waiting for NIB to stabilize
2023-05-30 18:04:17.534 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.NIB: 33>)
2023-05-30 18:04:17.543 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=116)
2023-05-30 18:04:17.544 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.NIB: 33>, Offset=0)
2023-05-30 18:04:17.567 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x6B\x05\x02\x65\x0F\x65\x00\x1E\x00\x00\x00\x01\x05\x01\x8F\x00\x07\x00\x02\x0D\x02\x00\x00\x00\x0B\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x62\x1A\x08\x00\x00\x08\x00\x00\x0F\x0F\x04\x00\x01\x00\x00\x00\x01\x00\x00\x00\x00\x09\x28\xD1\x26\x00\x4B\x12\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x0F\x05\x00\x01\x3C\x0A\x01\x00\x00\x00\x1E\x00\x00\x00')
2023-05-30 18:04:17.576 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM["LEGACY"][0x0021] = NIB(SequenceNum=107, PassiveAckTimeout=5, MaxBroadcastRetries=2, MaxChildren=101, MaxDepth=15, MaxRouters=101, dummyNeighborTable=0, BroadcastDeliveryTime=30, ReportConstantCost=0, RouteDiscRetries=0, dummyRoutingTable=0, SecureAllFrames=1, SecurityLevel=5, SymLink=1, CapabilityFlags=143, TransactionPersistenceTime=7, nwkProtocolVersion=2, RouteDiscoveryTime=13, RouteExpiryTime=2, nwkDevAddress=0x0000, nwkLogicalChannel=11, nwkCoordAddress=0x0000, nwkCoordExtAddress=00:00:00:00:00:00:00:00, nwkPanId=6754, nwkState=<NwkState.NWK_ROUTER: 8>, channelList=<Channels.CHANNEL_11: 2048>, beaconOrder=15, superFrameOrder=15, scanDuration=4, battLifeExt=0, allocatedRouterAddresses=1, allocatedEndDeviceAddresses=1, nodeDepth=0, extendedPANID=00:12:4b:00:26:d1:28:09, nwkKeyLoaded=<Bool.true: 1>, spare1=NwkKeyDesc(KeySeqNum=0, Key=00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00), spare2=NwkKeyDesc(KeySeqNum=0, Key=00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00), spare3=0, spare4=0, nwkLinkStatusPeriod=15, nwkRouterAgeLimit=5, nwkUseMultiCast=<Bool.false: 0>, nwkIsConcentrator=<Bool.true: 1>, nwkConcentratorDiscoveryTime=60, nwkConcentratorRadius=10, nwkAllFresh=1, nwkManagerAddr=0x0000, nwkTotalTransmissions=30, nwkUpdateId=0)
2023-05-30 18:04:17.576 DEBUG (MainThread) [zigpy_znp.api] Current NIB is NIB(SequenceNum=107, PassiveAckTimeout=5, MaxBroadcastRetries=2, MaxChildren=101, MaxDepth=15, MaxRouters=101, dummyNeighborTable=0, BroadcastDeliveryTime=30, ReportConstantCost=0, RouteDiscRetries=0, dummyRoutingTable=0, SecureAllFrames=1, SecurityLevel=5, SymLink=1, CapabilityFlags=143, TransactionPersistenceTime=7, nwkProtocolVersion=2, RouteDiscoveryTime=13, RouteExpiryTime=2, nwkDevAddress=0x0000, nwkLogicalChannel=11, nwkCoordAddress=0x0000, nwkCoordExtAddress=00:00:00:00:00:00:00:00, nwkPanId=6754, nwkState=<NwkState.NWK_ROUTER: 8>, channelList=<Channels.CHANNEL_11: 2048>, beaconOrder=15, superFrameOrder=15, scanDuration=4, battLifeExt=0, allocatedRouterAddresses=1, allocatedEndDeviceAddresses=1, nodeDepth=0, extendedPANID=00:12:4b:00:26:d1:28:09, nwkKeyLoaded=<Bool.true: 1>, spare1=NwkKeyDesc(KeySeqNum=0, Key=00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00), spare2=NwkKeyDesc(KeySeqNum=0, Key=00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00), spare3=0, spare4=0, nwkLinkStatusPeriod=15, nwkRouterAgeLimit=5, nwkUseMultiCast=<Bool.false: 0>, nwkIsConcentrator=<Bool.true: 1>, nwkConcentratorDiscoveryTime=60, nwkConcentratorRadius=10, nwkAllFresh=1, nwkManagerAddr=0x0000, nwkTotalTransmissions=30, nwkUpdateId=0)
2023-05-30 18:04:17.580 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Version.Req()
2023-05-30 18:04:17.588 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.Version.Rsp(TransportRev=2, ProductId=1, MajorRel=2, MinorRel=7, MaintRel=1, CodeRevision=20221226, BootloaderBuildType=<BootloaderBuildType.NON_BOOTLOADER_BUILD: 0>, BootloaderRevision=None)
2023-05-30 18:04:17.590 DEBUG (MainThread) [zigpy_znp.api] Sending request: UTIL.LEDControl.Req(LED=255, Mode=<LEDMode.OFF: 0>)
2023-05-30 18:04:17.600 DEBUG (MainThread) [zigpy_znp.api] Received command: UTIL.LEDControl.Rsp(Status=<Status.SUCCESS: 0>)
2023-05-30 18:04:17.604 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.Register.Req(Endpoint=1, ProfileId=260, DeviceId=1024, DeviceVersion=0, LatencyReq=<LatencyReq.NoLatencyReqs: 0>, InputClusters=[0, 6, 10, 25, 1281], OutputClusters=[1, 32, 1280, 1282])
2023-05-30 18:04:17.618 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!
2023-05-30 18:04:17.615 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.Register.Rsp(Status=<Status.SUCCESS: 0>)
2023-05-30 18:04:17.630 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.Register.Req(Endpoint=2, ProfileId=49246, DeviceId=2080, DeviceVersion=0, LatencyReq=<LatencyReq.NoLatencyReqs: 0>, InputClusters=[0], OutputClusters=[])
2023-05-30 18:04:17.638 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.Register.Rsp(Status=<Status.SUCCESS: 0>)
2023-05-30 18:04:17.639 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.MsgCallbackRegister.Req(ClusterId=65535)
2023-05-30 18:04:17.647 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MsgCallbackRegister.Rsp(Status=<Status.SUCCESS: 0>)
2023-05-30 18:04:17.651 DEBUG (MainThread) [zigpy.device] [0x0000] Scheduling initialization
2023-05-30 18:04:17.653 DEBUG (MainThread) [zigpy.util] Tries remaining: 3
2023-05-30 18:04:17.654 INFO (MainThread) [zigpy.device] [0x0000] Requesting 'Node Descriptor'
2023-05-30 18:04:17.654 DEBUG (MainThread) [zigpy.util] Tries remaining: 2
2023-05-30 18:04:17.654 DEBUG (MainThread) [zigpy.device] [0x0000] Extending timeout for 0x01 request
2023-05-30 18:04:17.655 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=True, tsn=1, profile_id=0, cluster_id=<ZDOCmd.Node_Desc_req: 0x0002>, data=Serialized[b'\x01\x00\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-05-30 18:04:17.658 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=1, profile_id=0, cluster_id=<ZDOCmd.Node_Desc_req: 0x0002>, data=Serialized[b'\x01\x00\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-05-30 18:04:17.659 DEBUG (MainThread) [zigpy.application] Received frame on uninitialized device <ZNPCoordinator model='CC1352/CC2652, Z-Stack 3.30+ (build 20221226)' manuf='Texas Instruments' nwk=0x0000 ieee=00:12:4b:00:26:d1:28:09 is_initialized=False> from ep 0 to ep 0, cluster ZDOCmd.Node_Desc_req: b'\x01\x00\x00'
2023-05-30 18:04:17.659 DEBUG (MainThread) [zigpy.zdo] [0x0000:zdo] ZDO request ZDOCmd.Node_Desc_req: [0x0000]
2023-05-30 18:04:17.660 DEBUG (MainThread) [zigpy.zdo] [0x0000:zdo] No handler for ZDO request:ZDOCmd.Node_Desc_req([0x0000])
2023-05-30 18:04:17.660 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x0000), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=2, TSN=1, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK: 32>, Radius=0, Data=b'\x01\x00\x00')
2023-05-30 18:04:17.672 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2023-05-30 18:04:17.678 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.NodeDescRsp.Callback(Src=0x0000, Status=<Status.SUCCESS: 0>, NWK=0x0000, NodeDescriptor=NullableNodeDescriptor(logical_type=<LogicalType.Coordinator: 0>, complex_descriptor_available=0, user_descriptor_available=0, reserved=0, aps_flags=0, frequency_band=<FrequencyBand.Freq2400MHz: 8>, mac_capability_flags=<MACCapabilityFlags.AllocateAddress|RxOnWhenIdle|MainsPowered|FullFunctionDevice|AlternatePanCoordinator: 143>, manufacturer_code=0, maximum_buffer_size=80, maximum_incoming_transfer_size=160, server_mask=11265, maximum_outgoing_transfer_size=160, descriptor_capability_field=<DescriptorCapability.NONE: 0>, *allocate_address=True, *is_alternate_pan_coordinator=True, *is_coordinator=True, *is_end_device=False, *is_full_function_device=True, *is_mains_powered=True, *is_receiver_on_when_idle=True, *is_router=False, *is_security_capable=False))
2023-05-30 18:04:17.680 DEBUG (MainThread) [zigpy_znp.api] Command was not handled
2023-05-30 18:04:17.682 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MsgCbIncoming.Callback(Src=0x0000, IsBroadcast=<Bool.false: 0>, ClusterId=32770, SecurityUse=0, TSN=1, MacDst=0x0000, Data=b'\x00\x00\x00\x00\x40\x8F\x00\x00\x50\xA0\x00\x01\x2C\xA0\x00\x00')
2023-05-30 18:04:17.686 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=1, profile_id=0, cluster_id=32770, data=Serialized[b'\x01\x00\x00\x00\x00@\x8f\x00\x00P\xa0\x00\x01,\xa0\x00\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-05-30 18:04:17.687 DEBUG (MainThread) [zigpy.application] Received frame on uninitialized device <ZNPCoordinator model='CC1352/CC2652, Z-Stack 3.30+ (build 20221226)' manuf='Texas Instruments' nwk=0x0000 ieee=00:12:4b:00:26:d1:28:09 is_initialized=False> from ep 0 to ep 0, cluster 32770: b'\x01\x00\x00\x00\x00@\x8f\x00\x00P\xa0\x00\x01,\xa0\x00\x00'
2023-05-30 18:04:17.689 INFO (MainThread) [zigpy.device] [0x0000] Got Node Descriptor: NodeDescriptor(logical_type=<LogicalType.Coordinator: 0>, complex_descriptor_available=0, user_descriptor_available=0, reserved=0, aps_flags=0, frequency_band=<FrequencyBand.Freq2400MHz: 8>, mac_capability_flags=<MACCapabilityFlags.AllocateAddress|RxOnWhenIdle|MainsPowered|FullFunctionDevice|AlternatePanCoordinator: 143>, manufacturer_code=0, maximum_buffer_size=80, maximum_incoming_transfer_size=160, server_mask=11265, maximum_outgoing_transfer_size=160, descriptor_capability_field=<DescriptorCapability.NONE: 0>, *allocate_address=True, *is_alternate_pan_coordinator=True, *is_coordinator=True, *is_end_device=False, *is_full_function_device=True, *is_mains_powered=True, *is_receiver_on_when_idle=True, *is_router=False, *is_security_capable=False)
2023-05-30 18:04:17.689 INFO (MainThread) [zigpy.device] [0x0000] Discovering endpoints
2023-05-30 18:04:17.689 DEBUG (MainThread) [zigpy.util] Tries remaining: 3
2023-05-30 18:04:17.690 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=2, profile_id=0, cluster_id=<ZDOCmd.Active_EP_req: 0x0005>, data=Serialized[b'\x02\x00\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-05-30 18:04:17.690 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=2, profile_id=0, cluster_id=<ZDOCmd.Active_EP_req: 0x0005>, data=Serialized[b'\x02\x00\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-05-30 18:04:17.691 DEBUG (MainThread) [zigpy.application] Received frame on uninitialized device <ZNPCoordinator model='CC1352/CC2652, Z-Stack 3.30+ (build 20221226)' manuf='Texas Instruments' nwk=0x0000 ieee=00:12:4b:00:26:d1:28:09 is_initialized=False> from ep 0 to ep 0, cluster ZDOCmd.Active_EP_req: b'\x02\x00\x00'
2023-05-30 18:04:17.691 DEBUG (MainThread) [zigpy.zdo] [0x0000:zdo] ZDO request ZDOCmd.Active_EP_req: [0x0000]
2023-05-30 18:04:17.691 DEBUG (MainThread) [zigpy.zdo] [0x0000:zdo] No handler for ZDO request:ZDOCmd.Active_EP_req([0x0000])
2023-05-30 18:04:17.692 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x0000), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=5, TSN=2, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK: 32>, Radius=0, Data=b'\x02\x00\x00')
2023-05-30 18:04:17.702 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2023-05-30 18:04:17.705 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ActiveEpRsp.Callback(Src=0x0000, Status=<Status.SUCCESS: 0>, NWK=0x0000, ActiveEndpoints=[2, 1])
2023-05-30 18:04:17.706 DEBUG (MainThread) [zigpy_znp.api] Command was not handled
2023-05-30 18:04:17.707 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MsgCbIncoming.Callback(Src=0x0000, IsBroadcast=<Bool.false: 0>, ClusterId=32773, SecurityUse=0, TSN=2, MacDst=0x0000, Data=b'\x00\x00\x00\x02\x02\x01')
2023-05-30 18:04:17.708 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=2, profile_id=0, cluster_id=32773, data=Serialized[b'\x02\x00\x00\x00\x02\x02\x01'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-05-30 18:04:17.708 DEBUG (MainThread) [zigpy.application] Received frame on uninitialized device <ZNPCoordinator model='CC1352/CC2652, Z-Stack 3.30+ (build 20221226)' manuf='Texas Instruments' nwk=0x0000 ieee=00:12:4b:00:26:d1:28:09 is_initialized=False> from ep 0 to ep 0, cluster 32773: b'\x02\x00\x00\x00\x02\x02\x01'
2023-05-30 18:04:17.709 INFO (MainThread) [zigpy.device] [0x0000] Discovered endpoints: [2, 1]
2023-05-30 18:04:17.709 INFO (MainThread) [zigpy.device] [0x0000] Initializing endpoints [<Endpoint id=2 in=[] out=[] status=<Status.NEW: 0>>, <Endpoint id=1 in=[] out=[] status=<Status.NEW: 0>>]
2023-05-30 18:04:17.709 INFO (MainThread) [zigpy.endpoint] [0x0000:2] Discovering endpoint information
2023-05-30 18:04:17.709 DEBUG (MainThread) [zigpy.util] Tries remaining: 3
2023-05-30 18:04:17.709 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=3, profile_id=0, cluster_id=<ZDOCmd.Simple_Desc_req: 0x0004>, data=Serialized[b'\x03\x00\x00\x02'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-05-30 18:04:17.710 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=3, profile_id=0, cluster_id=<ZDOCmd.Simple_Desc_req: 0x0004>, data=Serialized[b'\x03\x00\x00\x02'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-05-30 18:04:17.710 DEBUG (MainThread) [zigpy.application] Received frame on uninitialized device <ZNPCoordinator model='CC1352/CC2652, Z-Stack 3.30+ (build 20221226)' manuf='Texas Instruments' nwk=0x0000 ieee=00:12:4b:00:26:d1:28:09 is_initialized=False> from ep 0 to ep 0, cluster ZDOCmd.Simple_Desc_req: b'\x03\x00\x00\x02'
2023-05-30 18:04:17.711 DEBUG (MainThread) [zigpy.zdo] [0x0000:zdo] ZDO request ZDOCmd.Simple_Desc_req: [0x0000, 2]
2023-05-30 18:04:17.711 DEBUG (MainThread) [zigpy.zdo] [0x0000:zdo] No handler for ZDO request:ZDOCmd.Simple_Desc_req([0x0000, 2])
2023-05-30 18:04:17.711 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x0000), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=4, TSN=3, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK: 32>, Radius=0, Data=b'\x03\x00\x00\x02')
2023-05-30 18:04:17.721 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2023-05-30 18:04:17.724 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.SimpleDescRsp.Callback(Src=0x0000, Status=<Status.SUCCESS: 0>, NWK=0x0000, SimpleDescriptor=SizePrefixedSimpleDescriptor(endpoint=2, profile=49246, device_type=2080, device_version=0, input_clusters=[0], output_clusters=[]))
2023-05-30 18:04:17.726 DEBUG (MainThread) [zigpy_znp.api] Command was not handled
2023-05-30 18:04:17.727 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MsgCbIncoming.Callback(Src=0x0000, IsBroadcast=<Bool.false: 0>, ClusterId=32772, SecurityUse=0, TSN=3, MacDst=0x0000, Data=b'\x00\x00\x00\x0A\x02\x5E\xC0\x20\x08\x00\x01\x00\x00\x00')
2023-05-30 18:04:17.728 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=3, profile_id=0, cluster_id=32772, data=Serialized[b'\x03\x00\x00\x00\n\x02^\xc0 \x08\x00\x01\x00\x00\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-05-30 18:04:17.729 DEBUG (MainThread) [zigpy.application] Received frame on uninitialized device <ZNPCoordinator model='CC1352/CC2652, Z-Stack 3.30+ (build 20221226)' manuf='Texas Instruments' nwk=0x0000 ieee=00:12:4b:00:26:d1:28:09 is_initialized=False> from ep 0 to ep 0, cluster 32772: b'\x03\x00\x00\x00\n\x02^\xc0 \x08\x00\x01\x00\x00\x00'
2023-05-30 18:04:17.730 INFO (MainThread) [zigpy.endpoint] [0x0000:2] Discovered endpoint information: SizePrefixedSimpleDescriptor(endpoint=2, profile=49246, device_type=2080, device_version=0, input_clusters=[0], output_clusters=[])
2023-05-30 18:04:17.730 INFO (MainThread) [zigpy.endpoint] [0x0000:1] Discovering endpoint information
2023-05-30 18:04:17.730 DEBUG (MainThread) [zigpy.util] Tries remaining: 3
2023-05-30 18:04:17.731 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=4, profile_id=0, cluster_id=<ZDOCmd.Simple_Desc_req: 0x0004>, data=Serialized[b'\x04\x00\x00\x01'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-05-30 18:04:17.731 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=4, profile_id=0, cluster_id=<ZDOCmd.Simple_Desc_req: 0x0004>, data=Serialized[b'\x04\x00\x00\x01'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-05-30 18:04:17.732 DEBUG (MainThread) [zigpy.application] Received frame on uninitialized device <ZNPCoordinator model='CC1352/CC2652, Z-Stack 3.30+ (build 20221226)' manuf='Texas Instruments' nwk=0x0000 ieee=00:12:4b:00:26:d1:28:09 is_initialized=False> from ep 0 to ep 0, cluster ZDOCmd.Simple_Desc_req: b'\x04\x00\x00\x01'
2023-05-30 18:04:17.732 DEBUG (MainThread) [zigpy.zdo] [0x0000:zdo] ZDO request ZDOCmd.Simple_Desc_req: [0x0000, 1]
2023-05-30 18:04:17.732 DEBUG (MainThread) [zigpy.zdo] [0x0000:zdo] No handler for ZDO request:ZDOCmd.Simple_Desc_req([0x0000, 1])
2023-05-30 18:04:17.733 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x0000), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=4, TSN=4, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK: 32>, Radius=0, Data=b'\x04\x00\x00\x01')
2023-05-30 18:04:17.741 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2023-05-30 18:04:17.750 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.SimpleDescRsp.Callback(Src=0x0000, Status=<Status.SUCCESS: 0>, NWK=0x0000, SimpleDescriptor=SizePrefixedSimpleDescriptor(endpoint=1, profile=260, device_type=1024, device_version=0, input_clusters=[0, 6, 10, 25, 1281], output_clusters=[1, 32, 1280, 1282]))
2023-05-30 18:04:17.751 DEBUG (MainThread) [zigpy_znp.api] Command was not handled
2023-05-30 18:04:17.751 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MsgCbIncoming.Callback(Src=0x0000, IsBroadcast=<Bool.false: 0>, ClusterId=32772, SecurityUse=0, TSN=4, MacDst=0x0000, Data=b'\x00\x00\x00\x1A\x01\x04\x01\x00\x04\x00\x05\x00\x00\x06\x00\x0A\x00\x19\x00\x01\x05\x04\x01\x00\x20\x00\x00\x05\x02\x05')
2023-05-30 18:04:17.752 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=4, profile_id=0, cluster_id=32772, data=Serialized[b'\x04\x00\x00\x00\x1a\x01\x04\x01\x00\x04\x00\x05\x00\x00\x06\x00\n\x00\x19\x00\x01\x05\x04\x01\x00 \x00\x00\x05\x02\x05'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-05-30 18:04:17.753 DEBUG (MainThread) [zigpy.application] Received frame on uninitialized device <ZNPCoordinator model='CC1352/CC2652, Z-Stack 3.30+ (build 20221226)' manuf='Texas Instruments' nwk=0x0000 ieee=00:12:4b:00:26:d1:28:09 is_initialized=False> from ep 0 to ep 0, cluster 32772: b'\x04\x00\x00\x00\x1a\x01\x04\x01\x00\x04\x00\x05\x00\x00\x06\x00\n\x00\x19\x00\x01\x05\x04\x01\x00 \x00\x00\x05\x02\x05'
2023-05-30 18:04:17.754 INFO (MainThread) [zigpy.endpoint] [0x0000:1] Discovered endpoint information: SizePrefixedSimpleDescriptor(endpoint=1, profile=260, device_type=1024, device_version=0, input_clusters=[0, 6, 10, 25, 1281], output_clusters=[1, 32, 1280, 1282])
2023-05-30 18:04:17.755 INFO (MainThread) [zigpy.device] [0x0000] Already have model and manufacturer info
2023-05-30 18:04:17.755 INFO (MainThread) [zigpy.device] [0x0000] Discovered basic device information for <ZNPCoordinator model='CC1352/CC2652, Z-Stack 3.30+ (build 20221226)' manuf='Texas Instruments' nwk=0x0000 ieee=00:12:4b:00:26:d1:28:09 is_initialized=True>
2023-05-30 18:04:17.755 DEBUG (MainThread) [zigpy.application] Device is initialized <ZNPCoordinator model='CC1352/CC2652, Z-Stack 3.30+ (build 20221226)' manuf='Texas Instruments' nwk=0x0000 ieee=00:12:4b:00:26:d1:28:09 is_initialized=True>
2023-05-30 18:04:17.756 DEBUG (MainThread) [zigpy.quirks.registry] Checking quirks for Texas Instruments CC1352/CC2652, Z-Stack 3.30+ (build 20221226) (00:12:4b:00:26:d1:28:09)
2023-05-30 18:04:17.757 WARNING (MainThread) [zigpy_znp.zigbee.application] Your network is using the insecure Zigbee2MQTT network key!
2023-05-30 18:04:17.773 DEBUG (MainThread) [zigpy_znp.zigbee.application] Sending packet ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=5, profile_id=0, cluster_id=<ZDOCmd.Mgmt_NWK_Update_req: 0x0038>, data=Serialized[b'\x05\x00\xf8\xff\x07\x04\x01'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-05-30 18:04:17.774 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=5, profile_id=0, cluster_id=<ZDOCmd.Mgmt_NWK_Update_req: 0x0038>, data=Serialized[b'\x05\x00\xf8\xff\x07\x04\x01'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-05-30 18:04:17.775 DEBUG (MainThread) [zigpy.zdo] [0x0000:zdo] ZDO request ZDOCmd.Mgmt_NWK_Update_req: [NwkUpdate(ScanChannels=<Channels.ALL_CHANNELS: 134215680>, ScanDuration=4, ScanCount=1)]
2023-05-30 18:04:17.775 DEBUG (MainThread) [zigpy.zdo] [0x0000:zdo] No handler for ZDO request:ZDOCmd.Mgmt_NWK_Update_req([NwkUpdate(ScanChannels=<Channels.ALL_CHANNELS: 134215680>, ScanDuration=4, ScanCount=1)])
2023-05-30 18:04:17.776 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x0000), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=56, TSN=5, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK: 32>, Radius=0, Data=b'\x05\x00\xF8\xFF\x07\x04\x01')
2023-05-30 18:04:17.777 DEBUG (MainThread) [zigpy_znp.zigbee.application] Starting watchdog loop
2023-05-30 18:04:17.784 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2023-05-30 18:04:22.428 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MgmtNWKUpdateNotify.Callback(Src=0x0000, Status=<Status.SUCCESS: 0>, ScannedChannels=<Channels.ALL_CHANNELS: 134215680>, TotalTransmissions=30, TransmissionFailures=0, EnergyValues=[116, 156, 160, 112, 43, 25, 0, 43, 10, 40, 21, 40, 61, 131, 51, 65])
2023-05-30 18:04:22.429 DEBUG (MainThread) [zigpy_znp.api] Command was not handled
2023-05-30 18:04:22.432 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MsgCbIncoming.Callback(Src=0x0000, IsBroadcast=<Bool.false: 0>, ClusterId=32824, SecurityUse=0, TSN=5, MacDst=0x0000, Data=b'\x00\x00\xF8\xFF\x07\x1E\x00\x00\x00\x10\x74\x9C\xA0\x70\x2B\x19\x00\x2B\x0A\x28\x15\x28\x3D\x83\x33\x41')
2023-05-30 18:04:22.433 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=5, profile_id=0, cluster_id=32824, data=Serialized[b'\x05\x00\x00\xf8\xff\x07\x1e\x00\x00\x00\x10t\x9c\xa0p+\x19\x00+\n(\x15(=\x833A'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2023-05-30 18:04:22.437 INFO (MainThread) [zigpy.util] Optimal channel is 20
2023-05-30 18:04:22.437 DEBUG (MainThread) [zigpy.util] Channel scores: {11: 793.2, 12: 1421.4, 13: 1412.7, 14: 1033.8000000000002, 15: 171.5, 16: 264.0, 17: 120.89999999999999, 18: 295.5, 19: 193.79999999999998, 20: 104.8, 21: 270.29999999999995, 22: 417.29999999999995, 23: 647.0999999999999, 24: 988.5, 25: 213.6, 26: 417.2}
2023-05-30 18:04:22.437 DEBUG (MainThread) [zigpy.application] Forming a new network
2023-05-30 18:04:22.437 DEBUG (MainThread) [zigpy.backups] Restoring backup NetworkBackup(backup_time=datetime.datetime(2023, 5, 30, 15, 4, 22, 437800, tzinfo=datetime.timezone.utc), network_info=NetworkInfo(extended_pan_id=4e:8d:73:fe:a3:ba:e2:61, pan_id=9523, nwk_update_id=0, nwk_manager_id=0, channel=20, channel_mask=<Channels.CHANNEL_20: 1048576>, security_level=5, network_key=Key(key=ae:ae:5b:3f:00:42:3e:13:33:02:80:5a:27:c9:ba:69, tx_counter=0, rx_counter=0, seq=0, partner_ieee=ff:ff:ff:ff:ff:ff:ff:ff), tc_link_key=Key(key=5a:69:67:42:65:65:41:6c:6c:69:61:6e:63:65:30:39, tx_counter=0, rx_counter=0, seq=0, partner_ieee=ff:ff:ff:ff:ff:ff:ff:ff), key_table=[], children=[], nwk_addresses={}, stack_specific={}, metadata={}, source=None), node_info=NodeInfo(nwk=0, ieee=ff:ff:ff:ff:ff:ff:ff:ff, logical_type=<LogicalType.Coordinator: 0>))
2023-05-30 18:04:22.438 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.HAS_CONFIGURED_ZSTACK1: 3840>)
2023-05-30 18:04:22.444 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=0)
2023-05-30 18:04:22.445 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.HAS_CONFIGURED_ZSTACK3: 96>)
2023-05-30 18:04:22.452 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2023-05-30 18:04:22.453 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVDelete.Req(Id=<OsalNvIds.HAS_CONFIGURED_ZSTACK3: 96>, ItemLen=1)
2023-05-30 18:04:22.470 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVDelete.Rsp(Status=<Status.SUCCESS: 0>)
2023-05-30 18:04:22.473 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.ZIGPY_ZNP_MIGRATION_ID: 95>)
2023-05-30 18:04:22.482 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2023-05-30 18:04:22.483 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVDelete.Req(Id=<OsalNvIds.ZIGPY_ZNP_MIGRATION_ID: 95>, ItemLen=1)
2023-05-30 18:04:22.503 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVDelete.Rsp(Status=<Status.SUCCESS: 0>)
2023-05-30 18:04:22.503 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.BDBNODEISONANETWORK: 85>)
2023-05-30 18:04:22.515 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2023-05-30 18:04:22.515 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVDelete.Req(Id=<OsalNvIds.BDBNODEISONANETWORK: 85>, ItemLen=1)
2023-05-30 18:04:22.540 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVDelete.Rsp(Status=<Status.SUCCESS: 0>)
2023-05-30 18:04:22.541 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.STARTUP_OPTION: 3>)
2023-05-30 18:04:22.547 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2023-05-30 18:04:22.547 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVWriteExt.Req(Id=<OsalNvIds.STARTUP_OPTION: 3>, Offset=0, Value=b'\x03')
2023-05-30 18:04:22.556 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVWriteExt.Rsp(Status=<Status.SUCCESS: 0>)
2023-05-30 18:04:22.556 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.ResetReq.Req(Type=<ResetType.Soft: 1>)
2023-05-30 18:04:22.557 DEBUG (MainThread) [zigpy_znp.api] Request has no response, not waiting for one.
2023-05-30 18:04:25.616 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.ResetInd.Callback(Reason=<ResetReason.PowerUp: 0>, TransportRev=2, ProductId=1, MajorRel=2, MinorRel=7, MaintRel=1)
2023-05-30 18:04:25.619 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.PANID: 131>)
2023-05-30 18:04:25.627 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=2)
2023-05-30 18:04:25.629 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVWriteExt.Req(Id=<OsalNvIds.PANID: 131>, Offset=0, Value=b'\xFF\xFF')
2023-05-30 18:04:25.640 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVWriteExt.Rsp(Status=<Status.SUCCESS: 0>)
2023-05-30 18:04:25.642 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.APS_USE_EXT_PANID: 71>)
2023-05-30 18:04:25.651 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=8)
2023-05-30 18:04:25.653 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVWriteExt.Req(Id=<OsalNvIds.APS_USE_EXT_PANID: 71>, Offset=0, Value=b'\x20\xBB\x3A\x16\x66\x3A\x1E\x54')
2023-05-30 18:04:25.665 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVWriteExt.Rsp(Status=<Status.SUCCESS: 0>)
2023-05-30 18:04:25.667 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.PRECFGKEY: 98>)
2023-05-30 18:04:25.676 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=16)
2023-05-30 18:04:25.678 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVWriteExt.Req(Id=<OsalNvIds.PRECFGKEY: 98>, Offset=0, Value=b'\x55\xC1\xAD\xC4\x59\x28\x95\x1B\x96\x87\xCD\x23\xDA\x71\xB3\x00')
2023-05-30 18:04:25.691 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVWriteExt.Rsp(Status=<Status.SUCCESS: 0>)
2023-05-30 18:04:25.693 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.PRECFGKEYS_ENABLE: 99>)
2023-05-30 18:04:25.700 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2023-05-30 18:04:25.700 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVWriteExt.Req(Id=<OsalNvIds.PRECFGKEYS_ENABLE: 99>, Offset=0, Value=b'\x00')
2023-05-30 18:04:25.711 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVWriteExt.Rsp(Status=<Status.SUCCESS: 0>)
2023-05-30 18:04:25.711 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.CHANLIST: 132>)
2023-05-30 18:04:25.720 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=4)
2023-05-30 18:04:25.720 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVWriteExt.Req(Id=<OsalNvIds.CHANLIST: 132>, Offset=0, Value=b'\x00\x80\x10\x02')
2023-05-30 18:04:25.731 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVWriteExt.Rsp(Status=<Status.SUCCESS: 0>)
2023-05-30 18:04:25.732 DEBUG (MainThread) [zigpy_znp.api] Sending request: AppConfig.BDBSetChannel.Req(IsPrimary=<Bool.true: 1>, Channel=<Channels.CHANNEL_25|CHANNEL_20|CHANNEL_15: 34635776>)
2023-05-30 18:04:25.741 DEBUG (MainThread) [zigpy_znp.api] Received command: AppConfig.BDBSetChannel.Rsp(Status=<Status.SUCCESS: 0>)
2023-05-30 18:04:25.743 DEBUG (MainThread) [zigpy_znp.api] Sending request: AppConfig.BDBSetChannel.Req(IsPrimary=<Bool.false: 0>, Channel=<Channels.NO_CHANNELS: 0>)
2023-05-30 18:04:25.751 DEBUG (MainThread) [zigpy_znp.api] Received command: AppConfig.BDBSetChannel.Rsp(Status=<Status.SUCCESS: 0>)
2023-05-30 18:04:25.752 DEBUG (MainThread) [zigpy_znp.api] Forming temporary network
2023-05-30 18:04:25.752 DEBUG (MainThread) [zigpy_znp.api] Sending request: AppConfig.BDBStartCommissioning.Req(Mode=<BDBCommissioningMode.NwkFormation: 4>)
2023-05-30 18:04:30.569 DEBUG (MainThread) [zigpy_znp.api] Received command: AppConfig.BDBStartCommissioning.Rsp(Status=<Status.SUCCESS: 0>)
2023-05-30 18:04:30.572 DEBUG (MainThread) [zigpy_znp.api] Received command: AppConfig.BDBCommissioningNotification.Callback(Status=<BDBCommissioningStatus.InProgress: 1>, Mode=<BDBCommissioningMode.NwkSteering: 2>, RemainingModes=<BDBCommissioningMode.NwkFormation: 4>)
2023-05-30 18:04:30.776 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.StateChangeInd.Callback(State=<DeviceState.StartingAsCoordinator: 8>)
2023-05-30 18:04:47.779 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Ping.Req()
2023-05-30 18:04:47.787 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.Ping.Rsp(Capabilities=<MTCapabilities.APP_CNF|GP|UTIL|ZDO|AF|SYS: 1625>)
2023-05-30 18:05:10.083 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event recorder_5min_statistics_generated[L]>
2023-05-30 18:05:17.793 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Ping.Req()
2023-05-30 18:05:17.804 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.Ping.Rsp(Capabilities=<MTCapabilities.APP_CNF|GP|UTIL|ZDO|AF|SYS: 1625>)
2023-05-30 18:05:25.755 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.ResetReq.Req(Type=<ResetType.Soft: 1>)
2023-05-30 18:05:25.755 DEBUG (MainThread) [zigpy_znp.api] Request has no response, not waiting for one.
2023-05-30 18:05:25.757 DEBUG (MainThread) [zigpy_znp.uart] Closing serial port
2023-05-30 18:05:26.759 ERROR (MainThread) [aiohttp.server] Error handling request
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/zigpy_znp/api.py", line 1058, in request_callback_rsp
    return await callback_rsp
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/zigpy_znp/api.py", line 253, in start_network
    commissioning_rsp = await self.request_callback_rsp(
  File "/usr/local/lib/python3.10/site-packages/zigpy_znp/api.py", line 1055, in request_callback_rsp
    async with async_timeout.timeout(timeout):
  File "/usr/local/lib/python3.10/site-packages/async_timeout/__init__.py", line 129, in __aexit__
    self._do_exit(exc_type)
  File "/usr/local/lib/python3.10/site-packages/async_timeout/__init__.py", line 212, in _do_exit
    raise asyncio.TimeoutError
asyncio.exceptions.TimeoutError

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

Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/aiohttp/web_protocol.py", line 433, in _handle_request
    resp = await request_handler(request)
  File "/usr/local/lib/python3.10/site-packages/aiohttp/web_app.py", line 504, in _handle
    resp = await handler(request)
  File "/usr/local/lib/python3.10/site-packages/aiohttp/web_middlewares.py", line 117, in impl
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/security_filter.py", line 85, in security_filter_middleware
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/forwarded.py", line 100, in forwarded_middleware
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/request_context.py", line 28, in request_context_middleware
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/ban.py", line 80, in ban_middleware
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/auth.py", line 235, in auth_middleware
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/view.py", line 146, in handle
    result = await result
  File "/usr/src/homeassistant/homeassistant/components/config/config_entries.py", line 180, in post
    return await super().post(request, flow_id)
  File "/usr/src/homeassistant/homeassistant/components/http/data_validator.py", line 72, in wrapper
    result = await method(view, request, data, *args, **kwargs)
  File "/usr/src/homeassistant/homeassistant/helpers/data_entry_flow.py", line 110, in post
    result = await self._flow_mgr.async_configure(flow_id, data)
  File "/usr/src/homeassistant/homeassistant/data_entry_flow.py", line 267, in async_configure
    result = await self._async_handle_step(
  File "/usr/src/homeassistant/homeassistant/data_entry_flow.py", line 367, in _async_handle_step
    result: FlowResult = await getattr(flow, method)(user_input)
  File "/usr/src/homeassistant/homeassistant/components/zha/config_flow.py", line 376, in async_step_form_new_network
    await self._radio_mgr.async_form_network()
  File "/usr/src/homeassistant/homeassistant/components/zha/radio_manager.py", line 224, in async_form_network
    await app.form_network()
  File "/usr/local/lib/python3.10/site-packages/zigpy/application.py", line 386, in form_network
    await self.backups.restore_backup(
  File "/usr/local/lib/python3.10/site-packages/zigpy/backups.py", line 151, in restore_backup
    await self.app.write_network_info(
  File "/usr/local/lib/python3.10/site-packages/zigpy_znp/zigbee/application.py", line 187, in write_network_info
    await self._znp.write_network_info(
  File "/usr/local/lib/python3.10/site-packages/zigpy_znp/api.py", line 378, in write_network_info
    await self.start_network()
  File "/usr/local/lib/python3.10/site-packages/zigpy_znp/api.py", line 291, in start_network
    raise zigpy.exceptions.FormationFailure(
zigpy.exceptions.FormationFailure: Network formation refused: there is too much RF interference. Make sure your coordinator is on a USB 2.0 extension cable and away from any sources of interference, like USB 3.0 ports, SSDs, 2.4GHz routers, motherboards, etc.
puddly commented 1 year ago

There isn't much you need to do with channel configuration, this should all be done automatically. Try patching the above library (https://github.com/zigpy/zigpy-znp/blob/c4db8d1151b5a999ead73480faea4ea01b7cb7d7/zigpy_znp/const.py#L28) and add 11 to the list, it should work after that. What I'm curious to know is if the network will actually be functional on the higher channels.

Tarik2142 commented 1 year ago

Ok, I'll write result after the patch

Tarik2142 commented 1 year ago

Unfortunately, I could not add the channel as you wrote. Failed to start the test environment. image But I successfully run Z2M on channel 20, after that I tried to run ZHA on channel 20 but got the same error. I think that the problem in ZHA

puddly commented 1 year ago

If you're developing your own firmware and coordinator hardware I cannot debug this without your help: it's not a problem I can reproduce. I've posted above my theory on what you can do to fix this.

In lieu of running Home Assistant Core, you can just run zigpy-cli in any virtualenv on any platform to test the change, it does exactly the same thing:

virtualenv -p 3.9 venv
source venv/bin/activate
pip install zigpy-cli
git clone https://github.com/zigpy/zigpy-znp
pip install -e ./zigpy-znp
# edit zigpy-znp/zigpy_znp/const.py
zigpy -vvv radio znp /dev/serial/by-id/... form
Tarik2142 commented 1 year ago

this not working pip install zigpy-cli image

Tarik2142 commented 1 year ago

I could not find out what the problem was, but now it has disappeared, now the device works on any channel. A few days ago I turned off the electricity in the house, maybe that helped