Skip to content

Instantly share code, notes, and snippets.

@kmassada

kmassada/failure.log

Last active April 7, 2021 19:49
Show Gist options
  • Save kmassada/61d57ae4ca7116f3ebd852210798fca8 to your computer and use it in GitHub Desktop.
Save kmassada/61d57ae4ca7116f3ebd852210798fca8 to your computer and use it in GitHub Desktop.
Download ZIP
zzh cannot connect logs
Raw
failure.log
2021-04-07 07:23:15 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event timer_out_of_sync[L]: seconds=1.8326559760000123>
2021-04-07 07:23:19 DEBUG (MainThread) [zigpy_znp.zigbee.application] Probing /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0
2021-04-07 07:23:19 DEBUG (MainThread) [zigpy_znp.uart] Connecting to /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0 at 115200 baud
2021-04-07 07:23:19 DEBUG (MainThread) [zigpy_znp.uart] Opened /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0 serial port
2021-04-07 07:23:19 DEBUG (MainThread) [zigpy_znp.uart] Toggling RTS/CTS to skip CC2652R bootloader
2021-04-07 07:23:19 DEBUG (MainThread) [zigpy_znp.uart] Connected to /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0 at 115200 baud
2021-04-07 07:23:19 DEBUG (MainThread) [zigpy_znp.api] Waiting 1s before sending anything
2021-04-07 07:23:20 DEBUG (MainThread) [zigpy_znp.api] Sending bootloader skip byte
2021-04-07 07:23:20 DEBUG (MainThread) [zigpy_znp.api] Waiting 1s or until a reset indication is received
2021-04-07 07:23:21 DEBUG (MainThread) [zigpy_znp.api] Testing connection to /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0
2021-04-07 07:23:21 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Ping.Req()
2021-04-07 07:23:24 DEBUG (MainThread) [zigpy_znp.api] Connection to /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0 failed, cleaning up
2021-04-07 07:23:24 DEBUG (MainThread) [zigpy_znp.uart] Closing serial port
2021-04-07 07:23:24 DEBUG (MainThread) [zigpy_znp.zigbee.application] Failed to probe ZNP radio with config {'path': '/dev/serial/by-id/usb-1a86_USB_Seri
al-if00-port0', 'flow_control': None, 'baudrate': 115200}
Traceback (most recent call last):
File "/usr/local/lib/python3.8/site-packages/zigpy_znp/zigbee/application.py", line 159, in probe
await znp.connect()
File "/usr/local/lib/python3.8/site-packages/zigpy_znp/api.py", line 259, in connect
self.capabilities = (await self.request(c.SYS.Ping.Req())).Capabilities
File "/usr/local/lib/python3.8/site-packages/zigpy_znp/api.py", line 532, in request
response = await response_future
asyncio.exceptions.CancelledError
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/usr/local/lib/python3.8/site-packages/zigpy_znp/zigbee/application.py", line 159, in probe
await znp.connect()
File "/usr/local/lib/python3.8/site-packages/async_timeout/__init__.py", line 55, in __aexit__
self._do_exit(exc_type)
File "/usr/local/lib/python3.8/site-packages/async_timeout/__init__.py", line 92, in _do_exit
raise asyncio.TimeoutError
asyncio.exceptions.TimeoutError
2021-04-07 07:23:24 DEBUG (MainThread) [bellows.ezsp] Resetting EZSP
2021-04-07 07:23:27 DEBUG (MainThread) [bellows.ezsp] Unsuccessful radio probe of '/dev/serial/by-id/usb-1a86_USB_Serial-if00-port0' port
Traceback (most recent call last):
File "/usr/local/lib/python3.8/site-packages/bellows/ezsp/__init__.py", line 55, in probe
await asyncio.wait_for(ezsp._probe(), timeout=PROBE_TIMEOUT)
File "/usr/local/lib/python3.8/asyncio/tasks.py", line 501, in wait_for
raise exceptions.TimeoutError()
asyncio.exceptions.TimeoutError
2021-04-07 07:23:27 DEBUG (MainThread) [zigpy_deconz.api] Command Command.device_state (0, 0, 0)
2021-04-07 07:23:28 WARNING (MainThread) [zigpy_deconz.api] No response to 'Command.device_state' command with seq id '0x02'
2021-04-07 07:23:28 DEBUG (MainThread) [zigpy_deconz.api] Unsuccessful radio probe of '/dev/serial/by-id/usb-1a86_USB_Serial-if00-port0' port
Traceback (most recent call last):
File "/usr/local/lib/python3.8/site-packages/zigpy_deconz/api.py", line 380, in probe
await asyncio.wait_for(api._probe(), timeout=PROBE_TIMEOUT)
File "/usr/local/lib/python3.8/asyncio/tasks.py", line 494, in wait_for
return fut.result()
File "/usr/local/lib/python3.8/site-packages/zigpy_deconz/api.py", line 396, in _probe
await self.device_state()
File "/usr/local/lib/python3.8/site-packages/zigpy_deconz/api.py", line 305, in _command
return await asyncio.wait_for(fut, timeout=COMMAND_TIMEOUT)
File "/usr/local/lib/python3.8/asyncio/tasks.py", line 501, in wait_for
raise exceptions.TimeoutError()
asyncio.exceptions.TimeoutError
2021-04-07 07:23:28 DEBUG (MainThread) [zigpy_cc.uart] Connecting on port /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0 with boudrate 115200
2021-04-07 07:23:28 DEBUG (MainThread) [zigpy_cc.uart] Connection made
2021-04-07 07:23:29 DEBUG (MainThread) [zigpy_cc.api] --> SREQ SYS version tsn: None {}
2021-04-07 07:23:29 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x00!\x02#'
2021-04-07 07:23:30 DEBUG (MainThread) [zigpy_cc.api] Unsuccessful radio probe of '/dev/serial/by-id/usb-1a86_USB_Serial-if00-port0' port
Traceback (most recent call last):
File "/usr/local/lib/python3.8/site-packages/zigpy_cc/api.py", line 279, in probe
await asyncio.wait_for(api._probe(), timeout=COMMAND_TIMEOUT)
File "/usr/local/lib/python3.8/asyncio/tasks.py", line 501, in wait_for
raise exceptions.TimeoutError()
asyncio.exceptions.TimeoutError
2021-04-07 07:23:30 DEBUG (MainThread) [zigpy_zigate.uart] Connection made
2021-04-07 07:23:30 DEBUG (MainThread) [zigpy_zigate.uart] Send: 0x0002 b'01'
2021-04-07 07:23:30 DEBUG (MainThread) [zigpy_zigate.uart] Frame to send: b'\x00\x02\x00\x01\x02\x01'
2021-04-07 07:23:30 DEBUG (MainThread) [zigpy_zigate.uart] Frame escaped: b'\x02\x10\x02\x12\x02\x10\x02\x11\x02\x12\x02\x11'
2021-04-07 07:23:32 WARNING (MainThread) [zigpy_zigate.api] No response to command 0x0002
2021-04-07 07:23:32 WARNING (MainThread) [zigpy_zigate.api] Retry command 0x0002
2021-04-07 07:23:32 DEBUG (MainThread) [zigpy_zigate.uart] Send: 0x0002 b'01'
2021-04-07 07:23:32 DEBUG (MainThread) [zigpy_zigate.uart] Frame to send: b'\x00\x02\x00\x01\x02\x01'
2021-04-07 07:23:32 DEBUG (MainThread) [zigpy_zigate.uart] Frame escaped: b'\x02\x10\x02\x12\x02\x10\x02\x11\x02\x12\x02\x11'
2021-04-07 07:23:33 DEBUG (MainThread) [zigpy_zigate.api] Unsuccessful radio probe of '/dev/serial/by-id/usb-1a86_USB_Serial-if00-port0' port
Traceback (most recent call last):
File "/usr/local/lib/python3.8/site-packages/zigpy_zigate/api.py", line 258, in probe
await asyncio.wait_for(api._probe(), timeout=PROBE_TIMEOUT)
File "/usr/local/lib/python3.8/asyncio/tasks.py", line 501, in wait_for
raise exceptions.TimeoutError()
asyncio.exceptions.TimeoutError
2021-04-07 07:23:33 DEBUG (MainThread) [zigpy_xbee.api] at command: AP (2,)
2021-04-07 07:23:33 DEBUG (MainThread) [zigpy_xbee.api] Command at (b'AP', b'\x02')
2021-04-07 07:23:34 WARNING (MainThread) [zigpy_xbee.api] at: No response to AP command
2021-04-07 07:23:36 WARNING (MainThread) [zigpy_cc.api] No response for: SRSP SYS version {}
2021-04-07 07:23:38 DEBUG (MainThread) [zigpy_xbee.api] Command mode no response to AT '+++' command
2021-04-07 07:23:38 DEBUG (MainThread) [zigpy_xbee.api] Failed to enter AT command mode at 57600bps, trying 1200 next
2021-04-07 07:23:41 DEBUG (MainThread) [zigpy_xbee.api] Command mode no response to AT '+++' command
2021-04-07 07:23:41 DEBUG (MainThread) [zigpy_xbee.api] Failed to enter AT command mode at 1200bps, trying 2400 next
2021-04-07 07:23:43 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event panels_updated[L]>
2021-04-07 07:23:44 DEBUG (MainThread) [zigpy_xbee.api] Command mode no response to AT '+++' command
2021-04-07 07:23:44 DEBUG (MainThread) [zigpy_xbee.api] Failed to enter AT command mode at 2400bps, trying 4800 next
2021-04-07 07:23:47 DEBUG (MainThread) [zigpy_xbee.api] Command mode no response to AT '+++' command
2021-04-07 07:23:47 DEBUG (MainThread) [zigpy_xbee.api] Failed to enter AT command mode at 4800bps, trying 9600 next
2021-04-07 07:23:50 DEBUG (MainThread) [zigpy_xbee.api] Command mode no response to AT '+++' command
2021-04-07 07:23:50 DEBUG (MainThread) [zigpy_xbee.api] Failed to enter AT command mode at 9600bps, trying 19200 next
2021-04-07 07:23:54 DEBUG (MainThread) [zigpy_xbee.api] Command mode no response to AT '+++' command
2021-04-07 07:23:54 DEBUG (MainThread) [zigpy_xbee.api] Failed to enter AT command mode at 19200bps, trying 38400 next
2021-04-07 07:23:57 DEBUG (MainThread) [zigpy_xbee.api] Command mode no response to AT '+++' command
2021-04-07 07:23:57 DEBUG (MainThread) [zigpy_xbee.api] Failed to enter AT command mode at 38400bps, trying 57600 next
2021-04-07 07:24:00 DEBUG (MainThread) [zigpy_xbee.api] Command mode no response to AT '+++' command
2021-04-07 07:24:00 DEBUG (MainThread) [zigpy_xbee.api] Failed to enter AT command mode at 57600bps, trying 115200 next
2021-04-07 07:24:03 DEBUG (MainThread) [zigpy_xbee.api] Command mode no response to AT '+++' command
2021-04-07 07:24:03 DEBUG (MainThread) [zigpy_xbee.api] Failed to enter AT command mode at 115200bps, trying 230400 next
2021-04-07 07:24:04 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sun.sun, old_state=<state sun.sun=above_horizon; next_dawn=2021-04-08T13:02:23+00:00, next_dusk=2021-04-08T03:18:19+00:00, next_midnight=2021-04-08T08:10:52+00:00, next_noon=2021-04-07T20:11:23+00:00, next_rising=2021-04-08T13:34:08+00:00, next_setting=2021-04-08T02:46:39+00:00, elevation=7.34, azimuth=87.11, rising=True, friendly_name=Sun @ 2021-04-07T07:20:04.724034-07:00>, new_state=<state sun.sun=above_horizon; next_dawn=2021-04-08T13:02:23+00:00, next_dusk=2021-04-08T03:18:19+00:00, next_midnight=2021-04-08T08:10:52+00:00, next_noon=2021-04-07T20:11:23+00:00, next_rising=2021-04-08T13:34:08+00:00, next_setting=2021-04-08T02:46:39+00:00, elevation=7.68, azimuth=87.47, rising=True, friendly_name=Sun @ 2021-04-07T07:20:04.724034-07:00>>
2021-04-07 07:24:07 DEBUG (MainThread) [zigpy_xbee.api] Command mode no response to AT '+++' command
2021-04-07 07:24:07 DEBUG (MainThread) [zigpy_xbee.api] Couldn't enter AT command mode at any known baudrate.Configure XBee manually for escaped API mode ATAP2
2021-04-07 07:24:07 DEBUG (MainThread) [zigpy_xbee.api] Unsuccessful radio probe of '/dev/serial/by-id/usb-1a86_USB_Serial-if00-port0' port
Traceback (most recent call last):
File "/usr/local/lib/python3.8/site-packages/zigpy_xbee/api.py", line 597, in _probe
await self._at_command("AP", 2)
File "/usr/local/lib/python3.8/site-packages/zigpy_xbee/api.py", line 385, in _at_partial
return await asyncio.wait_for(
File "/usr/local/lib/python3.8/asyncio/tasks.py", line 501, in wait_for
raise exceptions.TimeoutError()
asyncio.exceptions.TimeoutError
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/usr/local/lib/python3.8/site-packages/zigpy_xbee/api.py", line 579, in probe
await asyncio.wait_for(api._probe(), timeout=PROBE_TIMEOUT)
File "/usr/local/lib/python3.8/asyncio/tasks.py", line 494, in wait_for
return fut.result()
File "/usr/local/lib/python3.8/site-packages/zigpy_xbee/api.py", line 600, in _probe
raise APIException("Failed to configure XBee for API mode")
zigpy.exceptions.APIException: Failed to configure XBee for API mode
2021-04-07 07:25:43 DEBUG (MainThread) [zigpy_znp.zigbee.application] Probing /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0
2021-04-07 07:25:43 DEBUG (MainThread) [zigpy_znp.uart] Connecting to /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0 at 115200 baud
2021-04-07 07:25:43 DEBUG (MainThread) [zigpy_znp.uart] Opened /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0 serial port
2021-04-07 07:25:43 DEBUG (MainThread) [zigpy_znp.uart] Toggling RTS/CTS to skip CC2652R bootloader
2021-04-07 07:25:43 DEBUG (MainThread) [zigpy_znp.uart] Connected to /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0 at 115200 baud
2021-04-07 07:25:43 DEBUG (MainThread) [zigpy_znp.api] Waiting 1s before sending anything
2021-04-07 07:25:44 DEBUG (MainThread) [zigpy_znp.api] Sending bootloader skip byte
2021-04-07 07:25:44 DEBUG (MainThread) [zigpy_znp.api] Waiting 1s or until a reset indication is received
2021-04-07 07:25:45 DEBUG (MainThread) [zigpy_znp.api] Testing connection to /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0
2021-04-07 07:25:45 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Ping.Req()
2021-04-07 07:25:48 DEBUG (MainThread) [zigpy_znp.api] Connection to /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0 failed, cleaning up
2021-04-07 07:25:48 DEBUG (MainThread) [zigpy_znp.uart] Closing serial port
2021-04-07 07:25:48 DEBUG (MainThread) [zigpy_znp.zigbee.application] Failed to probe ZNP radio with config {'path': '/dev/serial/by-id/usb-1a86_USB_Serial-if00-port0', 'baudrate': 115200, 'flow_control': None}
Traceback (most recent call last):
File "/usr/local/lib/python3.8/site-packages/zigpy_znp/zigbee/application.py", line 159, in probe
await znp.connect()
File "/usr/local/lib/python3.8/site-packages/zigpy_znp/api.py", line 259, in connect
self.capabilities = (await self.request(c.SYS.Ping.Req())).Capabilities
File "/usr/local/lib/python3.8/site-packages/zigpy_znp/api.py", line 532, in request
response = await response_future
asyncio.exceptions.CancelledError
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/usr/local/lib/python3.8/site-packages/zigpy_znp/zigbee/application.py", line 159, in probe
await znp.connect()
File "/usr/local/lib/python3.8/site-packages/async_timeout/__init__.py", line 55, in __aexit__
self._do_exit(exc_type)
File "/usr/local/lib/python3.8/site-packages/async_timeout/__init__.py", line 92, in _do_exit
raise asyncio.TimeoutError
asyncio.exceptions.TimeoutError
2021-04-07 07:26:04 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sun.sun, old_state=<state sun.sun=above_horizon; next_dawn=2021-04-08T13:02:23+00:00, next_dusk=2021-04-08T03:18:19+00:00, next_midnight=2021-04-08T08:10:52+00:00, next_noon=2021-04-07T20:11:23+00:00, next_rising=2021-04-08T13:34:08+00:00, next_setting=2021-04-08T02:46:39+00:00, elevation=7.68, azimuth=87.47, rising=True, friendly_name=Sun @ 2021-04-07T07:20:04.724034-07:00>, new_state=<state sun.sun=above_horizon; next_dawn=2021-04-08T13:02:23+00:00, next_dusk=2021-04-08T03:18:19+00:00, next_midnig
ht=2021-04-08T08:10:52+00:00, next_noon=2021-04-07T20:11:23+00:00, next_rising=2021-04-08T13:34:08+00:00, next_setting=2021-04-08T02:46:39+00:00, elevation=8.01, azimuth=87.84, rising=True, friendly_name=Sun @ 2021-04-07T07:20:04.724034-07:00>>
2021-04-07 07:28:04 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sun.sun, old_state=<state sun.sun=above_horizon; next_dawn=2021-04-08T13:02:23+00:00, next_dusk=2021-04-08T03:18:19+00:00, next_midnight=2021-04-08T08:10:52+00:00, next_noon=2021-04-07T20:11:23+00:00, next_rising=2021-04-08T13:34:08+00:00, next_setting=2021-04-08T02:46:39+00:00, elevation=8.01, azimuth=87.84, rising=True, friendly_name=Sun @ 2021-04-07T07:20:04.724034-07:00>, new_state=<state sun.sun=above_horizon; next_dawn=2021-04-08T13:02:23+00:00, next_dusk=2021-04-08T03:18:19+00:00, next_midnight=2021-04-08T08:10:52+00:00, next_noon=2021-04-07T20:11:23+00:00, next_rising=2021-04-08T13:34:08+00:00, next_setting=2021-04-08T02:46:39+00:00, elevation=8.34, azimuth=88.21, rising=True, friendly_name=Sun @ 2021-04-07T07:20:04.724034-07:00>>
2021-04-07 07:30:04 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sun.sun, old_state=<state sun.sun=above_horizon; next_dawn=2021-04-08T13:02:23+00:00, next_dusk=2021-04-08T03:18:19+00:00, next_midnight=2021-04-08T08:10:52+00:00, next_noon=2021-04-07T20:11:23+00:00, next_rising=2021-04-08T13:34:08+00:00, next_setting=2021-04-08T02:46:39+00:00, elevation=8.34, azimuth=88.21, rising=True, friendly_name=Sun @ 2021-04-07T07:20:04.724034-07:00>, new_state=<state sun.sun=above_horizon; next_dawn=2021-04-08T13:02:23+00:00, next_dusk=2021-04-08T03:18:19+00:00, next_midnight=2021-04-08T08:10:52+00:00, next_noon=2021-04-07T20:11:23+00:00, next_rising=2021-04-08T13:34:08+00:00, next_setting=2021-04-08T02:46:39+00:00, elevation=8.68, azimuth=88.58, rising=True, friendly_name=Sun @ 2021-04-07T07:20:04.724034-07:00>>
2021-04-07 07:32:04 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sun.sun, old_state=<state sun.sun=above_horizon; next_dawn=2021-04-08T13:02:23+00:00, next_dusk=2021-04-08T03:18:19+00:00, next_midnight=2021-04-08T08:10:52+00:00, next_noon=2021-04-07T20:11:23+00:00, next_rising=2021-04-08T13:34:08+00:00, next_setting=2021-04-08T02:46:39+00:00, elevation=8.68, azimuth=88.58, rising=True, friendly_name=Sun @ 2021-04-07T07:20:04.724034-07:00>, new_state=<state sun.sun=above_horizon; next_dawn=2021-04-08T13:02:23+00:00, next_dusk=2021-04-08T03:18:19+00:00, next_midnight=2021-04-08T08:10:52+00:00, next_noon=2021-04-07T20:11:23+00:00, next_rising=2021-04-08T13:34:08+00:00, next_setting=2021-04-08T02:46:39+00:00, elevation=9.01, azimuth=88.95, rising=True, friendly_name=Sun @ 2021-04-07T07:20:04.724034-07:00>>
2021-04-07 07:34:04 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sun.sun, old_state=<state sun.sun=above_horizon; next_dawn=2021-04-08T13:02:23+00:00, next_dusk=2021-04-08T03:18:19+00:00, next_midnight=2021-04-08T08:10:52+00:00, next_noon=2021-04-07T20:11:23+00:0
0, next_rising=2021-04-08T13:34:08+00:00, next_setting=2021-04-08T02:46:39+00:00, elevation=9.01, azimuth=88.95, rising=True, friendly_name=Sun @ 2021-04-07T07:20:04.724034-07:00>, new_state=<state sun.sun=above_horizon; next_dawn=2021-04-08T13:02:23+00:00, next_dusk=2021-04-08T03:18:19+00:00, next_midnight=2021-04-08T08:10:52+00:00, next_noon=2021-04-07T20:11:23+00:00, next_rising=2021-04-08T13:34:08+00:00, next_setting=2021-04-08T02:46:39+00:00, elevation=9.34, azimuth=89.31, rising=True, friendly_name=Sun @ 2021-04-07T07:20:04.724034-07:00>>
2021-04-07 07:36:04 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sun.sun, old_state=<state sun.sun=above_horizon; next_dawn=2021-04-08T13:02:23+00:00, next_dusk=2021-04-08T03:18:19+00:00, next_midnight=2021-04-08T08:10:52+00:00, next_noon=2021-04-07T20:11:23+00:00, next_rising=2021-04-08T13:34:08+00:00, next_setting=2021-04-08T02:46:39+00:00, elevation=9.34, azimuth=89.31, rising=True, friendly_name=Sun @ 2021-04-07T07:20:04.724034-07:00>, new_state=<state sun.sun=above_horizon; next_dawn=2021-04-08T13:02:23+00:00, next_dusk=2021-04-08T03:18:19+00:00, next_midnight=2021-04-08T08:10:52+00:00, next_noon=2021-04-07T20:11:23+00:00, next_rising=2021-04-08T13:34:08+00:00, next_setting=2021-04-08T02:46:39+00:00, elevation=9.68, azimuth=89.68, rising=True, friendly_name=Sun @ 2021-04-07T07:20:04.724034-07:00>>
2021-04-07 07:38:04 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sun.sun, old_state=<state sun.sun=above_horizon; next_dawn=2021-04-08T13:02:23+00:00, next_dusk=2021-04-08T03:18:19+00:00, next_midnight=2021-04-08T08:10:52+00:00, next_noon=2021-04-07T20:11:23+00:00, next_rising=2021-04-08T13:34:08+00:00, next_setting=2021-04-08T02:46:39+00:00, elevation=9.68, azimuth=89.68, rising=True, friendly_name=Sun @ 2021-04-07T07:20:04.724034-07:00>, new_state=<state sun.sun=above_horizon; next_dawn=2021-04-08T13:02:23+00:00, next_dusk=2021-04-08T03:18:19+00:00, next_midnight=2021-04-08T08:10:52+00:00, next_noon=2021-04-07T20:11:23+00:00, next_rising=2021-04-08T13:34:08+00:00, next_setting=2021-04-08T02:46:39+00:00, elevation=10.01, azimuth=90.05, rising=True, friendly_name=Sun @ 2021-04-07T07:20:04.724034-07:00>>
2021-04-07 07:40:04 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sun.sun, old_state=<state sun.sun=above_horizon; next_dawn=2021-04-08T13:02:23+00:00, next_dusk=2021-04-08T03:18:19+00:00, next_midnight=2021-04-08T08:10:52+00:00, next_noon=2021-04-07T20:11:23+00:00, next_rising=2021-04-08T13:34:08+00:00, next_setting=2021-04-08T02:46:39+00:00, elevation=10.01, azimuth=90.05, rising=True, friendly_name=Sun @ 2021-04-07T07:20:04.724034-07:00>, new_state=<state sun.sun=above_horizon; next_dawn=2021-04-08T13:02:23+00:00, next_dusk=2021-04-08T03:18:19+00:00, next_midnight=2021-04-08T08:10:52+00:00, next_noon=2021-04-07T20:11:23+00:00, next_rising=2021-04-08T13:34:08+00:00, next_setting=2021-04-08T02:46:39+00:00, elevation=10.35, azimuth=90.42, rising=True, friendly_name=Sun @ 2021-04-07T07:20:04.724034-07:00>>
2021-04-07 07:40:51 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sun.sun, old_state=<state sun.sun=above_horiz2021-04-07 07:20:04 INFO (MainThread) [homeassistant.setup] Setting up media_source
2021-04-07 07:20:04 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event panels_updated[L]>
2021-04-07 07:20:05 INFO (MainThread) [homeassistant.setup] Setting up dhcp
2021-04-07 07:20:05 INFO (MainThread) [homeassistant.setup] Setup of domain dhcp took 0.0 seconds
:
2021-04-07 07:20:04 INFO (MainThread) [homeassistant.setup] Setting up my
2021-04-07 07:20:04 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event panels_updated[L]>
2021-04-07 07:20:04 INFO (MainThread) [homeassistant.setup] Setup of domain my took 0.0 seconds
2021-04-07 07:20:04 INFO (MainThread) [homeassistant.setup] Setting up map
t_midnight=2021-04-08T08:10:52+00:00, next_noon=2021-04-07T20:11:23+00:00, next_rising=2021-04-08T13:34:08+00:00, next_setting=2021-04-08T02:46:39+00:00, elevation=11.15, azimuth=91.31, rising=True, friendly_name=Sun @ 2021-04-07T07:20:04.724034-07:00>, new_state=<state sun.sun=above_horizon; next_dawn=2021-04-08T13:02:23+00:00, next_dusk=2021-04-08T03:18:19+00:00, next_midnight=2021-04-08T08:10:52+00:00, next_noon=2021-04-07T20:11:23+00:00, next_rising=2021-04-08T13:34:08+00:00, next_setting=2021-04-08T02:46:39+00:00, elevation=11.82, azimuth=92.05, rising=True, friendly_name=Sun @ 2021-04-07T07:20:04.724034-07:00>>
2021-04-07 07:52:51 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sun.sun, old_state=<state sun.sun=above_horizon; next_dawn=2021-04-08T13:02:23+00:00, next_dusk=2021-04-08T03:18:19+00:00, next_midnight=2021-04-08T08:10:52+00:00, next_noon=2021-04-07T20:11:23+00:00, next_rising=2021-04-08T13:34:08+00:00, next_setting=2021-04-08T02:46:39+00:00, elevation=11.82, azimuth=92.05, rising=True, friendly_name=Sun @ 2021-04-07T07:20:04.724034-07:00>, new_state=<state sun.sun=above_horizon; next_dawn=2021-04-08T13:02:23+00:00, next_dusk=2021-04-08T03:18:19+00:00, next_midnight=2021-04-08T08:10:52+00:00, next_noon=2021-04-07T20:11:23+00:00, next_rising=2021-04-08T13:34:08+00:00, next_setting=2021-04-08T02:46:39+00:00, elevation=12.49, azimuth=92.79, rising=True, friendly_name=Sun @ 2021-04-07T07:20:04.724034-07:00>>
2021-04-07 07:56:51 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sun.sun, old_state=<state sun.sun=above_horizon; next_dawn=2021-04-08T13:02:23+00:00, next_dusk=2021-04-08T03:18:19+00:00, next_midnight=2021-04-08T08:10:52+00:00, next_noon=2021-04-07T20:11:23+00:00, next_rising=2021-04-08T13:34:08+00:00, next_setting=2021-04-08T02:46:39+00:00, elevation=12.49, azimuth=92.79, rising=True, friendly_name=Sun @ 2021-04-07T07:20:04.724034-07:00>, new_state=<state sun.sun=above_horizon; next_dawn=2021-04-08T13:02:23+00:00, next_dusk=2021-04-08T03:18:19+00:00, next_midnight=2021-04-08T08:10:52+00:00, next_noon=2021-04-07T20:11:23+00:00, next_rising=2021-04-08T13:34:08+00:00, next_setting=2021-04-08T02:46:39+00:00, elevation=13.16, azimuth=93.54, rising=True, friendly_name=Sun @ 2021-04-07T07:20:04.724034-07:00>>
2021-04-07 08:00:51 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sun.sun, old_state=<state sun.sun=above_horizon; next_dawn=2021-04-08T13:02:23+00:00, next_dusk=2021-04-08T03:18:19+00:00, next_midnight=2021-04-08T08:10:52+00:00, next_noon=2021-04-07T20:11:23+00:00, next_rising=2021-04-08T13:34:08+00:00, next_setting=2021-04-08T02:46:39+00:00, elevation=13.16, azimuth=93.54, rising=True, friendly_name=Sun @ 2021-04-07T07:20:04.724034-07:00>, new_state=<state sun.sun=above_horizon; next_dawn=2021-04-08T13:02:23+00:00, next_dusk=2021-04-08T03:18:19+00:00, next_midnight=2021-04-08T08:10:52+00:00, next_noon=2021-04-07T20:11:23+00:00, next_rising=2021-04-08T13:34:08+00:00, next_setting=2021-04-08T02:46:39+00:00, elevation=13.83, azimuth=94.29, rising=True, friendly_name=Sun @ 2021-04-07T07:20:04.724034-07:00>>
2021-04-07 08:04:51 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sun.sun, old_state=<state sun.sun=above_horizon; next_dawn=2021-04-08T13:02:23+00:00, next_dusk=2021-04-08T03:18:19+00:00, next_midnight=2021-04-08T08:10:52+00:00, next_noon=2021-04-07T20:11:23+00:00, next_rising=2021-04-08T13:34:08+00:00, next_setting=2021-04-08T02:46:39+00:00, elevation=13.83, azimuth=94.29, rising=True, friendly_name=Sun @ 2021-04-07T07:20:04.724034-07:00>, new_state=<state sun.sun=above_horizon; next_dawn=2021-04-08T13:02:23+00:00, next_dusk=2021-04-08T03:18:19+00:00, next_midnight=2021-04-08T08:10:52+00:00, next_noon=2021-04-07T20:11:23+00:00, next_rising=2021-04-08T13:34:08+00:00, next_setting=2021-04-08T02:46:39+00:00, elevation=14.5, azimuth=95.04, rising=True, friendly_name=Sun @ 2021-04-07T07:20:04.724034-07:00>>
Raw
success.log
2021-04-07 12:47:43 DEBUG (MainThread) [zigpy_znp.zigbee.application] Probing /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0
2021-04-07 12:47:43 DEBUG (MainThread) [zigpy_znp.uart] Connecting to /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0 at 115200 baud
2021-04-07 12:47:43 DEBUG (MainThread) [zigpy_znp.uart] Opened /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0 serial port
2021-04-07 12:47:43 DEBUG (MainThread) [zigpy_znp.uart] Toggling RTS/CTS to skip CC2652R bootloader
2021-04-07 12:47:44 DEBUG (MainThread) [zigpy_znp.uart] Connected to /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0 at 115200 baud
2021-04-07 12:47:44 DEBUG (MainThread) [zigpy_znp.api] Waiting 1s before sending anything
2021-04-07 12:47:45 DEBUG (MainThread) [zigpy_znp.api] Sending bootloader skip byte
2021-04-07 12:47:45 DEBUG (MainThread) [zigpy_znp.api] Waiting 1s or until a reset indication is received
2021-04-07 12:47:46 DEBUG (MainThread) [zigpy_znp.api] Testing connection to /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0
2021-04-07 12:47:46 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Ping.Req()
2021-04-07 12:47:46 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.Ping.Rsp(Capabilities=<MTCapabilities.CAP_APP_CNF|CAP_GP|CAP_UTIL|CAP_ZDO|CAP_AF|CAP_SYS: 1625>)
2021-04-07 12:47:46 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.TCLK_TABLE: 4>, SubId=0)
2021-04-07 12:47:46 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=20)
2021-04-07 12:47:46 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)
2021-04-07 12:47:46 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVRead.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xFF\x00\x00\x00')
2021-04-07 12:47:46 DEBUG (MainThread) [zigpy_znp.api] Detected Z-Stack 3.3
2021-04-07 12:47:46 DEBUG (MainThread) [zigpy_znp.api] Connected to /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0 at 115200 baud
2021-04-07 12:47:46 DEBUG (MainThread) [zigpy_znp.uart] Closing serial port
2021-04-07 12:47:46 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=persistent_notification, service=dismiss, service_data=notification_id=config_entry_discovery>
2021-04-07 12:47:46 INFO (MainThread) [homeassistant.setup] Setting up zha
2021-04-07 12:47:46 INFO (MainThread) [homeassistant.setup] Setup of domain zha took 0.0 seconds
2021-04-07 12:47:46 DEBUG (MainThread) [zigpy.appdb] Loading application state from %s
2021-04-07 12:47:46 DEBUG (MainThread) [zigpy_znp.uart] Connecting to /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0 at 115200 baud
2021-04-07 12:47:46 DEBUG (MainThread) [zigpy_znp.uart] Opened /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0 serial port
2021-04-07 12:47:46 DEBUG (MainThread) [zigpy_znp.uart] Toggling RTS/CTS to skip CC2652R bootloader
2021-04-07 12:47:47 DEBUG (MainThread) [zigpy_znp.uart] Connected to /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0 at 115200 baud
2021-04-07 12:47:47 DEBUG (MainThread) [zigpy_znp.api] Waiting 1s before sending anything
2021-04-07 12:47:48 DEBUG (MainThread) [zigpy_znp.api] Sending bootloader skip byte
2021-04-07 12:47:48 DEBUG (MainThread) [zigpy_znp.api] Waiting 1s or until a reset indication is received
2021-04-07 12:47:49 DEBUG (MainThread) [zigpy_znp.api] Testing connection to /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0
2021-04-07 12:47:49 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Ping.Req()
2021-04-07 12:47:49 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.Ping.Rsp(Capabilities=<MTCapabilities.CAP_APP_CNF|CAP_GP|CAP_UTIL|CAP_ZDO|CAP_AF|CAP_SYS: 1625>)
2021-04-07 12:47:49 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.TCLK_TABLE: 4>, SubId=0)
2021-04-07 12:47:49 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=20)
2021-04-07 12:47:49 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)
2021-04-07 12:47:49 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVRead.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xFF\x00\x00\x00')
2021-04-07 12:47:49 DEBUG (MainThread) [zigpy_znp.api] Detected Z-Stack 3.3
2021-04-07 12:47:49 DEBUG (MainThread) [zigpy_znp.api] Connected to /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0 at 115200 baud
2021-04-07 12:47:49 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.HAS_CONFIGURED_ZSTACK3: 96>)
2021-04-07 12:47:49 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=0)
2021-04-07 12:47:49 INFO (MainThread) [zigpy_znp.zigbee.application] ZNP is not configured, forming a new network
2021-04-07 12:47:49 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.HAS_CONFIGURED_ZSTACK1: 3840>)
2021-04-07 12:47:49 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=0)
2021-04-07 12:47:49 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.HAS_CONFIGURED_ZSTACK3: 96>)
2021-04-07 12:47:49 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=0)
2021-04-07 12:47:49 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.STARTUP_OPTION: 3>)
2021-04-07 12:47:49 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2021-04-07 12:47:49 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVWriteExt.Req(Id=<OsalNvIds.STARTUP_OPTION: 3>, Offset=0, Value=b'\x03')
2021-04-07 12:47:49 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVWriteExt.Rsp(Status=<Status.SUCCESS: 0>)
2021-04-07 12:47:49 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.ResetReq.Req(Type=<ResetType.Soft: 1>)
2021-04-07 12:47:49 DEBUG (MainThread) [zigpy_znp.api] Request has no response, not waiting for one.
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.ResetInd.Callback(Reason=<ResetReason.PowerUp: 0>, TransportRev=2, ProductId=1, MajorRel=2, MinorRel=7, MaintRel=1)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.zigbee.application] Updating network settings
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.LOGICAL_TYPE: 135>)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.LOGICAL_TYPE: 135>, Offset=0)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x00')
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.CONCENTRATOR_ENABLE: 50>)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.CONCENTRATOR_ENABLE: 50>, Offset=0)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x01')
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.CONCENTRATOR_DISCOVERY: 51>)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.CONCENTRATOR_DISCOVERY: 51>, Offset=0)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x64')
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.CONCENTRATOR_DISCOVERY: 51>)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVWriteExt.Req(Id=<OsalNvIds.CONCENTRATOR_DISCOVERY: 51>, Offset=0, Value=b'\x78')
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVWriteExt.Rsp(Status=<Status.SUCCESS: 0>)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.CONCENTRATOR_RC: 54>)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.CONCENTRATOR_RC: 54>, Offset=0)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x01')
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.SRC_RTG_EXPIRY_TIME: 56>)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.SRC_RTG_EXPIRY_TIME: 56>, Offset=0)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x02')
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.SRC_RTG_EXPIRY_TIME: 56>)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVWriteExt.Req(Id=<OsalNvIds.SRC_RTG_EXPIRY_TIME: 56>, Offset=0, Value=b'\xFF')
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVWriteExt.Rsp(Status=<Status.SUCCESS: 0>)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.NWK_CHILD_AGE_ENABLE: 62>)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.NWK_CHILD_AGE_ENABLE: 62>, Offset=0)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x00')
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.BCAST_DELIVERY_TIME: 48>)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.BCAST_DELIVERY_TIME: 48>, Offset=0)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x1E')
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.ZDO_DIRECT_CB: 143>)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.ZDO_DIRECT_CB: 143>, Offset=0)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x01')
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.PANID: 131>)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=2)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVWriteExt.Req(Id=<OsalNvIds.PANID: 131>, Offset=0, Value=b'\xFF\xFF')
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVWriteExt.Rsp(Status=<Status.SUCCESS: 0>)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.APS_USE_EXT_PANID: 71>)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=8)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVWriteExt.Req(Id=<OsalNvIds.APS_USE_EXT_PANID: 71>, Offset=0, Value=b'\x05\x9E\xB6\xFC\xF8\x90\x6E\xFF')
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVWriteExt.Rsp(Status=<Status.SUCCESS: 0>)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.PRECFGKEY: 98>)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=16)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVWriteExt.Req(Id=<OsalNvIds.PRECFGKEY: 98>, Offset=0, Value=b'\x10\xF4\xFC\xAA\x40\x11\xB7\x45\xB5\xD9\x5B\x26\xAC\xAF\x19\x42')
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVWriteExt.Rsp(Status=<Status.SUCCESS: 0>)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.PRECFGKEYS_ENABLE: 99>)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVWriteExt.Req(Id=<OsalNvIds.PRECFGKEYS_ENABLE: 99>, Offset=0, Value=b'\x01')
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVWriteExt.Rsp(Status=<Status.SUCCESS: 0>)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.CHANLIST: 132>)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=4)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVWriteExt.Req(Id=<OsalNvIds.CHANLIST: 132>, Offset=0, Value=b'\x00\x80\x00\x00')
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVWriteExt.Rsp(Status=<Status.SUCCESS: 0>)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Sending request: AppConfig.BDBSetChannel.Req(IsPrimary=<Bool.true: 1>, Channel=<Channels.CHANNEL_15: 32768>)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Received command: AppConfig.BDBSetChannel.Rsp(Status=<Status.SUCCESS: 0>)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Sending request: AppConfig.BDBSetChannel.Req(IsPrimary=<Bool.false: 0>, Channel=<Channels.NO_CHANNELS: 0>)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Received command: AppConfig.BDBSetChannel.Rsp(Status=<Status.SUCCESS: 0>)
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.zigbee.application] Forming the network
2021-04-07 12:47:51 DEBUG (MainThread) [zigpy_znp.api] Sending request: AppConfig.BDBStartCommissioning.Req(Mode=<BDBCommissioningMode.NwkFormation: 4>)
2021-04-07 12:47:56 DEBUG (MainThread) [zigpy_znp.api] Received command: AppConfig.BDBStartCommissioning.Rsp(Status=<Status.SUCCESS: 0>)
2021-04-07 12:47:56 DEBUG (MainThread) [zigpy_znp.api] Received command: AppConfig.BDBCommissioningNotification.Callback(Status=<BDBCommissioningStatus.InProgress: 1>, Mode=<BDBCommissioningMode.NwkSteering: 2>, RemainingModes=<BDBCommissioningMode.NwkFormation: 4>)
2021-04-07 12:47:56 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.StateChangeInd.Callback(State=<DeviceState.StartingAsCoordinator: 8>)
2021-04-07 12:47:57 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.StateChangeInd.Callback(State=<DeviceState.StartedAsCoordinator: 9>)
2021-04-07 12:47:57 DEBUG (MainThread) [zigpy_znp.api] Received command: AppConfig.BDBCommissioningNotification.Callback(Status=<BDBCommissioningStatus.Success: 0>, Mode=<BDBCommissioningMode.NwkSteering: 2>, RemainingModes=<BDBCommissioningMode.NONE: 0>)
2021-04-07 12:47:57 DEBUG (MainThread) [zigpy_znp.zigbee.application] Waiting for the NIB to be populated
2021-04-07 12:47:57 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.NIB: 33>)
2021-04-07 12:47:57 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=116)
2021-04-07 12:47:57 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.NIB: 33>, Offset=0)
2021-04-07 12:47:57 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x34\x05\x02\x00\x0F\x00\x00\x1E\x00\x00\x00\x01\x05\x01\x8F\x00\x07\x00\x02\x0D\x1E\x00\xFE\xFF\x00\x00\xFE\xFF\x00\x00\x00\x00\x00\x00\x00\x00\xFF\xFF\x00\x00\x00\x00\x00\x00\x0F\x0F\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x38\xA4\x81\x22\x00\x4B\x12\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\x00\x00\x0F\x05\x00\x01\x78\x0A\x01\x00\x00\x00\x00\x00\x00\x00')
2021-04-07 12:47:57 DEBUG (MainThread) [zigpy_znp.zigbee.application] Current NIB is NIB(SequenceNum=52, PassiveAckTimeout=5, MaxBroadcastRetries=2, MaxChildren=0, MaxDepth=15, MaxRouters=0, dummyNeighborTable=0, BroadcastDeliveryTime=30, ReportConstantCost=0, RouteDiscRetries=0, dummyRoutingTable=0, SecureAllFrames=1, SecurityLevel=5, SymLink=1, CapabilityFlags=143, PaddingByte0=b'\x00', TransactionPersistenceTime=7, nwkProtocolVersion=2, RouteDiscoveryTime=13, RouteExpiryTime=30, PaddingByte1=b'\x00', nwkDevAddress=0xFFFE, nwkLogicalChannel=0, PaddingByte2=b'\x00', nwkCoordAddress=0xFFFE, nwkCoordExtAddress=00:00:00:00:00:00:00:00, nwkPanId=65535, nwkState=<NwkState16.NWK_INIT: 0>, channelList=<Channels.NO_CHANNELS: 0>, beaconOrder=15, superFrameOrder=15, scanDuration=0, battLifeExt=0, allocatedRouterAddresses=0, allocatedEndDeviceAddresses=0, nodeDepth=0, extendedPANID=00:12:4b:00:22:81:a4:38, nwkKeyLoaded=<Bool.false: 0>, spare1=NwkKeyDesc(KeySeqNum=0, Key=[0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]), spare2=NwkKeyDesc(KeySeqNum=0, Key=[0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]), spare3=0, spare4=0, nwkLinkStatusPeriod=15, nwkRouterAgeLimit=5, nwkUseMultiCast=<Bool.false: 0>, nwkIsConcentrator=<Bool.true: 1>, nwkConcentratorDiscoveryTime=120, nwkConcentratorRadius=10, nwkAllFresh=1, PaddingByte3=b'\x00', nwkManagerAddr=0x0000, nwkTotalTransmissions=0, nwkUpdateId=0, PaddingByte4=b'\x00')
2021-04-07 12:47:58 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.NIB: 33>)
2021-04-07 12:47:58 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=116)
2021-04-07 12:47:58 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.NIB: 33>, Offset=0)
2021-04-07 12:47:58 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x34\x05\x02\x00\x0F\x00\x00\x1E\x00\x00\x00\x01\x05\x01\x8F\x00\x07\x00\x02\x0D\x1E\x00\xFE\xFF\x00\x00\xFE\xFF\x00\x00\x00\x00\x00\x00\x00\x00\xFF\xFF\x00\x00\x00\x00\x00\x00\x0F\x0F\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x38\xA4\x81\x22\x00\x4B\x12\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\x00\x00\x0F\x05\x00\x01\x78\x0A\x01\x00\x00\x00\x00\x00\x00\x00')
2021-04-07 12:47:58 DEBUG (MainThread) [zigpy_znp.zigbee.application] Current NIB is NIB(SequenceNum=52, PassiveAckTimeout=5, MaxBroadcastRetries=2, MaxChildren=0, MaxDepth=15, MaxRouters=0, dummyNeighborTable=0, BroadcastDeliveryTime=30, ReportConstantCost=0, RouteDiscRetries=0, dummyRoutingTable=0, SecureAllFrames=1, SecurityLevel=5, SymLink=1, CapabilityFlags=143, PaddingByte0=b'\x00', TransactionPersistenceTime=7, nwkProtocolVersion=2, RouteDiscoveryTime=13, RouteExpiryTime=30, PaddingByte1=b'\x00', nwkDevAddress=0xFFFE, nwkLogicalChannel=0, PaddingByte2=b'\x00', nwkCoordAddress=0xFFFE, nwkCoordExtAddress=00:00:00:00:00:00:00:00, nwkPanId=65535, nwkState=<NwkState16.NWK_INIT: 0>, channelList=<Channels.NO_CHANNELS: 0>, beaconOrder=15, superFrameOrder=15, scanDuration=0, battLifeExt=0, allocatedRouterAddresses=0, allocatedEndDeviceAddresses=0, nodeDepth=0, extendedPANID=00:12:4b:00:22:81:a4:38, nwkKeyLoaded=<Bool.false: 0>, spare1=NwkKeyDesc(KeySeqNum=0, Key=[0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]), spare2=NwkKeyDesc(KeySeqNum=0, Key=[0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]), spare3=0, spare4=0, nwkLinkStatusPeriod=15, nwkRouterAgeLimit=5, nwkUseMultiCast=<Bool.false: 0>, nwkIsConcentrator=<Bool.true: 1>, nwkConcentratorDiscoveryTime=120, nwkConcentratorRadius=10, nwkAllFresh=1, PaddingByte3=b'\x00', nwkManagerAddr=0x0000, nwkTotalTransmissions=0, nwkUpdateId=0, PaddingByte4=b'\x00')
2021-04-07 12:47:59 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.NIB: 33>)
2021-04-07 12:47:59 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=116)
2021-04-07 12:47:59 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.NIB: 33>, Offset=0)
2021-04-07 12:47:59 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x34\x05\x02\x00\x0F\x00\x00\x1E\x00\x00\x00\x01\x05\x01\x8F\x00\x07\x00\x02\x0D\x1E\x00\xFE\xFF\x00\x00\xFE\xFF\x00\x00\x00\x00\x00\x00\x00\x00\xFF\xFF\x00\x00\x00\x00\x00\x00\x0F\x0F\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x38\xA4\x81\x22\x00\x4B\x12\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\x00\x00\x0F\x05\x00\x01\x78\x0A\x01\x00\x00\x00\x00\x00\x00\x00')
2021-04-07 12:47:59 DEBUG (MainThread) [zigpy_znp.zigbee.application] Current NIB is NIB(SequenceNum=52, PassiveAckTimeout=5, MaxBroadcastRetries=2, MaxChildren=0, MaxDepth=15, MaxRouters=0, dummyNeighborTable=0, BroadcastDeliveryTime=30, ReportConstantCost=0, RouteDiscRetries=0, dummyRoutingTable=0, SecureAllFrames=1, SecurityLevel=5, SymLink=1, CapabilityFlags=143, PaddingByte0=b'\x00', TransactionPersistenceTime=7, nwkProtocolVersion=2, RouteDiscoveryTime=13, RouteExpiryTime=30, PaddingByte1=b'\x00', nwkDevAddress=0xFFFE, nwkLogicalChannel=0, PaddingByte2=b'\x00', nwkCoordAddress=0xFFFE, nwkCoordExtAddress=00:00:00:00:00:00:00:00, nwkPanId=65535, nwkState=<NwkState16.NWK_INIT: 0>, channelList=<Channels.NO_CHANNELS: 0>, beaconOrder=15, superFrameOrder=15, scanDuration=0, battLifeExt=0, allocatedRouterAddresses=0, allocatedEndDeviceAddresses=0, nodeDepth=0, extendedPANID=00:12:4b:00:22:81:a4:38, nwkKeyLoaded=<Bool.false: 0>, spare1=NwkKeyDesc(KeySeqNum=0, Key=[0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]), spare2=NwkKeyDesc(KeySeqNum=0, Key=[0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]), spare3=0, spare4=0, nwkLinkStatusPeriod=15, nwkRouterAgeLimit=5, nwkUseMultiCast=<Bool.false: 0>, nwkIsConcentrator=<Bool.true: 1>, nwkConcentratorDiscoveryTime=120, nwkConcentratorRadius=10, nwkAllFresh=1, PaddingByte3=b'\x00', nwkManagerAddr=0x0000, nwkTotalTransmissions=0, nwkUpdateId=0, PaddingByte4=b'\x00')
2021-04-07 12:48:00 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.NIB: 33>)
2021-04-07 12:48:00 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=116)
2021-04-07 12:48:00 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.NIB: 33>, Offset=0)
2021-04-07 12:48:00 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x34\x05\x02\x33\x0F\x33\x00\x1E\x00\x00\x00\x01\x05\x01\x8F\x00\x07\x00\x02\x0D\x1E\x00\x00\x00\x0F\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x01\x78\x08\x00\x00\x80\x00\x00\x0F\x0F\x04\x00\x01\x00\x00\x00\x01\x00\x00\x00\x00\x05\x9E\xB6\xFC\xF8\x90\x6E\xFF\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\x78\x0A\x01\x00\x00\x00\x00\x00\x00\x00')
2021-04-07 12:48:00 DEBUG (MainThread) [zigpy_znp.zigbee.application] Current NIB is NIB(SequenceNum=52, PassiveAckTimeout=5, MaxBroadcastRetries=2, MaxChildren=51, MaxDepth=15, MaxRouters=51, dummyNeighborTable=0, BroadcastDeliveryTime=30, ReportConstantCost=0, RouteDiscRetries=0, dummyRoutingTable=0, SecureAllFrames=1, SecurityLevel=5, SymLink=1, CapabilityFlags=143, PaddingByte0=b'\x00', TransactionPersistenceTime=7, nwkProtocolVersion=2, RouteDiscoveryTime=13, RouteExpiryTime=30, PaddingByte1=b'\x00', nwkDevAddress=0x0000, nwkLogicalChannel=15, PaddingByte2=b'\x00', nwkCoordAddress=0x0000, nwkCoordExtAddress=00:00:00:00:00:00:00:00, nwkPanId=30721, nwkState=<NwkState16.NWK_ROUTER: 8>, channelList=<Channels.CHANNEL_15: 32768>, beaconOrder=15, superFrameOrder=15, scanDuration=4, battLifeExt=0, allocatedRouterAddresses=1, allocatedEndDeviceAddresses=1, nodeDepth=0, extendedPANID=ff:6e:90:f8:fc:b6:9e:05, nwkKeyLoaded=<Bool.true: 1>, spare1=NwkKeyDesc(KeySeqNum=0, Key=[0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]), spare2=NwkKeyDesc(KeySeqNum=0, Key=[0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]), spare3=0, spare4=0, nwkLinkStatusPeriod=15, nwkRouterAgeLimit=5, nwkUseMultiCast=<Bool.false: 0>, nwkIsConcentrator=<Bool.true: 1>, nwkConcentratorDiscoveryTime=120, nwkConcentratorRadius=10, nwkAllFresh=1, PaddingByte3=b'\x00', nwkManagerAddr=0x0000, nwkTotalTransmissions=0, nwkUpdateId=0, PaddingByte4=b'\x00')
2021-04-07 12:48:00 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.HAS_CONFIGURED_ZSTACK3: 96>)
2021-04-07 12:48:00 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=0)
2021-04-07 12:48:00 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVItemInit.Req(Id=<OsalNvIds.HAS_CONFIGURED_ZSTACK3: 96>, ItemLen=1, Value=b'\x55')
2021-04-07 12:48:00 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVItemInit.Rsp(Status=<Status.NV_ITEM_UNINIT: 9>)
2021-04-07 12:48:00 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVWriteExt.Req(Id=<OsalNvIds.HAS_CONFIGURED_ZSTACK3: 96>, Offset=0, Value=b'\x55')
2021-04-07 12:48:00 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVWriteExt.Rsp(Status=<Status.SUCCESS: 0>)
2021-04-07 12:48:00 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.ResetReq.Req(Type=<ResetType.Soft: 1>)
2021-04-07 12:48:00 DEBUG (MainThread) [zigpy_znp.api] Request has no response, not waiting for one.
2021-04-07 12:48:03 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.ResetInd.Callback(Reason=<ResetReason.PowerUp: 0>, TransportRev=2, ProductId=1, MajorRel=2, MinorRel=7, MaintRel=1)
2021-04-07 12:48:03 DEBUG (MainThread) [zigpy_znp.api] Sending request: AppConfig.BDBStartCommissioning.Req(Mode=<BDBCommissioningMode.NwkFormation: 4>)
2021-04-07 12:48:05 DEBUG (MainThread) [zigpy_znp.api] Received command: AppConfig.BDBStartCommissioning.Rsp(Status=<Status.SUCCESS: 0>)
2021-04-07 12:48:05 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.StateChangeInd.Callback(State=<DeviceState.StartedAsCoordinator: 9>)
2021-04-07 12:48:05 DEBUG (MainThread) [zigpy_znp.api] Received command: AppConfig.BDBCommissioningNotification.Callback(Status=<BDBCommissioningStatus.NetworkRestored: 13>, Mode=<BDBCommissioningMode.NONE: 0>, RemainingModes=<BDBCommissioningMode.NwkFormation: 4>)
2021-04-07 12:48:06 DEBUG (MainThread) [zigpy_znp.api] Received command: AppConfig.BDBCommissioningNotification.Callback(Status=<BDBCommissioningStatus.FormationFailure: 8>, Mode=<BDBCommissioningMode.NwkSteering: 2>, RemainingModes=<BDBCommissioningMode.NONE: 0>)
2021-04-07 12:48:06 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.MgmtPermitJoinReq.Req(AddrMode=<AddrMode.NWK: 2>, Dst=0x0000, Duration=0, TCSignificance=1)
2021-04-07 12:48:06 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MgmtPermitJoinReq.Rsp(Status=<Status.SUCCESS: 0>)
2021-04-07 12:48:06 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MgmtPermitJoinRsp.Callback(Src=0x0000, Status=<Status.SUCCESS: 0>)
2021-04-07 12:48:06 DEBUG (MainThread) [zigpy_znp.zigbee.application] Intercepted a ZDO request: dst_addr=AddrModeAddress(mode=<AddrMode.Broadcast: 15>, address=0xFFFC), dst_ep=0, src_ep=0, cluster=54, sequence=1, options=TransmitOptions.NONE, radius=0, data=b'\x01\x00\x00'
2021-04-07 12:48:06 DEBUG (MainThread) [zigpy_znp.zigbee.application] Intercepted AP ZDO request 54({'PermitDuration': 0, 'TC_Significant': <Bool.false: 0>}) and replaced with ZDO.MgmtPermitJoinReq.Req(AddrMode=<AddrMode.Broadcast: 15>, Dst=0xFFFC, Duration=0, TCSignificance=0)
2021-04-07 12:48:06 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.MgmtPermitJoinReq.Req(AddrMode=<AddrMode.Broadcast: 15>, Dst=0xFFFC, Duration=0, TCSignificance=0)
2021-04-07 12:48:06 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MgmtPermitJoinReq.Rsp(Status=<Status.SUCCESS: 0>)
2021-04-07 12:48:06 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MgmtPermitJoinRsp.Callback(Src=0x0000, Status=<Status.SUCCESS: 0>)
2021-04-07 12:48:06 DEBUG (MainThread) [zigpy_znp.api] Sending request: Util.LEDControl.Req(LED=255, Mode=<LEDMode.OFF: 0>)
2021-04-07 12:48:06 DEBUG (MainThread) [zigpy_znp.api] Received command: RPCError.CommandNotRecognized.Rsp(ErrorCode=<ErrorCode.InvalidCommandId: 2>, RequestHeader=CommandHeader(id=0x0A, subsystem=Subsystem.UTIL, type=CommandType.SREQ))
2021-04-07 12:48:06 INFO (MainThread) [zigpy_znp.zigbee.application] This build of Z-Stack does not appear to support LED control
2021-04-07 12:48:06 DEBUG (MainThread) [zigpy_znp.api] Sending request: Util.GetDeviceInfo.Req()
2021-04-07 12:48:06 DEBUG (MainThread) [zigpy_znp.api] Received command: Util.GetDeviceInfo.Rsp(Status=<Status.SUCCESS: 0>, IEEE=00:12:4b:00:22:81:a4:38, NWK=0x0000, DeviceType=<DeviceTypeCapabilities.EndDevice|Router|Coordinator: 7>, DeviceState=<DeviceState.StartedAsCoordinator: 9>, AssociatedDevices=[])
2021-04-07 12:48:06 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.NodeDescReq.Req(DstAddr=0x0000, NWKAddrOfInterest=0x0000)
2021-04-07 12:48:06 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.NodeDescReq.Rsp(Status=<Status.SUCCESS: 0>)
2021-04-07 12:48:06 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.NodeDescRsp.Callback(Src=0x0000, Status=<Status.SUCCESS: 0>, NWK=0x0000, NodeDescriptor=NullableNodeDescriptor(byte1=0, byte2=64, mac_capability_flags=143, manufacturer_code=0, maximum_buffer_size=80, maximum_incoming_transfer_size=160, server_mask=11265, maximum_outgoing_transfer_size=160, descriptor_capability_field=0))
2021-04-07 12:48:06 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.Register.Req(Endpoint=1, ProfileId=260, DeviceId=1024, DeviceVersion=0, LatencyReq=<LatencyReq.NoLatencyReqs: 0>, InputClusters=[25], OutputClusters=[1280, 1282])
2021-04-07 12:48:06 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.Register.Rsp(Status=<Status.SUCCESS: 0>)
2021-04-07 12:48:06 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.Register.Req(Endpoint=2, ProfileId=49246, DeviceId=2080, DeviceVersion=0, LatencyReq=<LatencyReq.NoLatencyReqs: 0>, InputClusters=[], OutputClusters=[])
2021-04-07 12:48:06 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.Register.Rsp(Status=<Status.SUCCESS: 0>)
2021-04-07 12:48:06 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.NIB: 33>)
2021-04-07 12:48:06 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=116)
2021-04-07 12:48:06 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.NIB: 33>, Offset=0)
2021-04-07 12:48:06 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x34\x05\x02\x33\x0F\x33\x00\x1E\x00\x00\x00\x01\x05\x01\x8F\x00\x07\x00\x02\x0D\x1E\x00\x00\x00\x0F\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x01\x78\x08\x00\x00\x80\x00\x00\x0F\x0F\x04\x00\x01\x00\x00\x00\x01\x00\x00\x00\x00\x05\x9E\xB6\xFC\xF8\x90\x6E\xFF\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\x78\x0A\x01\x00\x00\x00\x00\x00\x00\x00')
2021-04-07 12:48:06 DEBUG (MainThread) [zigpy_znp.zigbee.application] Parsed NIB: NIB(SequenceNum=52, PassiveAckTimeout=5, MaxBroadcastRetries=2, MaxChildren=51, MaxDepth=15, MaxRouters=51, dummyNeighborTable=0, BroadcastDeliveryTime=30, ReportConstantCost=0, RouteDiscRetries=0, dummyRoutingTable=0, SecureAllFrames=1, SecurityLevel=5, SymLink=1, CapabilityFlags=143, PaddingByte0=b'\x00', TransactionPersistenceTime=7, nwkProtocolVersion=2, RouteDiscoveryTime=13, RouteExpiryTime=30, PaddingByte1=b'\x00', nwkDevAddress=0x0000, nwkLogicalChannel=15, PaddingByte2=b'\x00', nwkCoordAddress=0x0000, nwkCoordExtAddress=00:00:00:00:00:00:00:00, nwkPanId=30721, nwkState=<NwkState16.NWK_ROUTER: 8>, channelList=<Channels.CHANNEL_15: 32768>, beaconOrder=15, superFrameOrder=15, scanDuration=4, battLifeExt=0, allocatedRouterAddresses=1, allocatedEndDeviceAddresses=1, nodeDepth=0, extendedPANID=ff:6e:90:f8:fc:b6:9e:05, nwkKeyLoaded=<Bool.true: 1>, spare1=NwkKeyDesc(KeySeqNum=0, Key=[0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]), spare2=NwkKeyDesc(KeySeqNum=0, Key=[0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]), spare3=0, spare4=0, nwkLinkStatusPeriod=15, nwkRouterAgeLimit=5, nwkUseMultiCast=<Bool.false: 0>, nwkIsConcentrator=<Bool.true: 1>, nwkConcentratorDiscoveryTime=120, nwkConcentratorRadius=10, nwkAllFresh=1, PaddingByte3=b'\x00', nwkManagerAddr=0x0000, nwkTotalTransmissions=0, nwkUpdateId=0, PaddingByte4=b'\x00')
2021-04-07 12:48:06 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.NWKKEY: 130>)
2021-04-07 12:48:06 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=24)
2021-04-07 12:48:06 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.NWKKEY: 130>, Offset=0)
2021-04-07 12:48:06 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x00\x10\xF4\xFC\xAA\x40\x11\xB7\x45\xB5\xD9\x5B\x26\xAC\xAF\x19\x42\x00\x00\x00\x00\x00\x00\x00')
2021-04-07 12:48:06 DEBUG (MainThread) [zigpy_znp.zigbee.application] Parsed key info: NwkActiveKeyItems(Active=NwkKeyDesc(KeySeqNum=0, Key=[16, 244, 252, 170, 64, 17, 183, 69, 181, 217, 91, 38, 172, 175, 25, 66]), PaddingByte1=b'\x00', PaddingByte2=b'\x00', PaddingByte3=b'\x00', FrameCounter=0)
2021-04-07 12:48:06 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Version.Req()
2021-04-07 12:48:06 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.Version.Rsp(TransportRev=2, ProductId=1, MajorRel=2, MinorRel=7, MaintRel=1, CodeRevision=20210120, BootloaderBuildType=<BootloaderBuildType.NON_BOOTLOADER_BUILD: 0>, BootloaderRevision=None)
2021-04-07 12:48:06 INFO (MainThread) [zigpy_znp.zigbee.application] Network settings
2021-04-07 12:48:06 INFO (MainThread) [zigpy_znp.zigbee.application] Z-Stack version: 3.3
2021-04-07 12:48:06 INFO (MainThread) [zigpy_znp.zigbee.application] Z-Stack build id: 20210120
2021-04-07 12:48:06 INFO (MainThread) [zigpy_znp.zigbee.application] Max concurrent requests: 16
2021-04-07 12:48:06 INFO (MainThread) [zigpy_znp.zigbee.application] Channel: 15
2021-04-07 12:48:06 INFO (MainThread) [zigpy_znp.zigbee.application] PAN ID: 0x7801
2021-04-07 12:48:06 INFO (MainThread) [zigpy_znp.zigbee.application] Extended PAN ID: ff:6e:90:f8:fc:b6:9e:05
2021-04-07 12:48:06 DEBUG (MainThread) [zigpy_znp.zigbee.application] Network key: 10:f4:fc:aa:40:11:b7:45:b5:d9:5b:26:ac:af:19:42
2021-04-07 12:48:06 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event device_registry_updated[L]: action=create, device_id=9cb8b59d3e143b81c69a86b8da738cff>
2021-04-07 12:48:06 DEBUG (MainThread) [homeassistant.components.zha.core.gateway] [0x0000](Texas Instruments CC13X2/CC26X2, Z-Stack 3.30.00/3.40.00/4.10.00) restored as 'unavailable', last seen: not known
2021-04-07 12:48:06 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event device_registry_updated[L]: action=update, device_id=9cb8b59d3e143b81c69a86b8da738cff>
2021-04-07 12:48:06 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=zha, service=permit>
2021-04-07 12:48:06 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=zha, service=remove>
2021-04-07 12:48:06 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=zha, service=set_zigbee_cluster_attribute>
2021-04-07 12:48:06 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=zha, service=issue_zigbee_cluster_command>
2021-04-07 12:48:06 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=zha, service=issue_zigbee_group_command>
2021-04-07 12:48:06 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=zha, service=warning_device_squawk>
2021-04-07 12:48:06 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=zha, service=warning_device_warn>
2021-04-07 12:48:06 DEBUG (MainThread) [zigpy_znp.zigbee.application] Starting watchdog loop
2021-04-07 12:48:06 DEBUG (MainThread) [homeassistant.components.zha.core.gateway] Loading battery powered devices
2021-04-07 12:48:06 DEBUG (MainThread) [homeassistant.components.zha.core.gateway] Loading mains powered devices
2021-04-07 12:48:06 INFO (MainThread) [homeassistant.setup] Setting up device_tracker
2021-04-07 12:48:06 INFO (SyncWorker_5) [homeassistant.loader] Loaded climate from homeassistant.components.climate
2021-04-07 12:48:06 INFO (SyncWorker_6) [homeassistant.loader] Loaded number from homeassistant.components.number
2021-04-07 12:48:06 INFO (SyncWorker_2) [homeassistant.loader] Loaded lock from homeassistant.components.lock
2021-04-07 12:48:06 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x0000](CC13X2/CC26X2, Z-Stack 3.30.00/3.40.00/4.10.00): started initialization
2021-04-07 12:48:06 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0000:ZDO](CC13X2/CC26X2, Z-Stack 3.30.00/3.40.00/4.10.00): 'async_initialize' stage succeeded
2021-04-07 12:48:06 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=zha>
2021-04-07 12:48:06 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.zha
2021-04-07 12:48:06 INFO (MainThread) [homeassistant.components.cover] Setting up cover.zha
2021-04-07 12:48:06 INFO (MainThread) [homeassistant.components.fan] Setting up fan.zha
2021-04-07 12:48:06 INFO (MainThread) [homeassistant.components.light] Setting up light.zha
2021-04-07 12:48:06 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.zha
2021-04-07 12:48:06 INFO (MainThread) [homeassistant.components.switch] Setting up switch.zha
2021-04-07 12:48:06 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=device_tracker, service=see>
2021-04-07 12:48:06 INFO (MainThread) [homeassistant.setup] Setup of domain device_tracker took 0.0 seconds
2021-04-07 12:48:06 INFO (MainThread) [homeassistant.setup] Setting up climate
2021-04-07 12:48:06 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=climate, service=turn_on>
2021-04-07 12:48:06 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=climate, service=turn_off>
2021-04-07 12:48:06 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=climate, service=set_hvac_mode>
2021-04-07 12:48:06 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=climate, service=set_preset_mode>
2021-04-07 12:48:06 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=climate, service=set_aux_heat>
2021-04-07 12:48:06 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=climate, service=set_temperature>
2021-04-07 12:48:06 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=climate, service=set_humidity>
2021-04-07 12:48:06 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=climate, service=set_fan_mode>
2021-04-07 12:48:06 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=climate, service=set_swing_mode>
2021-04-07 12:48:06 INFO (MainThread) [homeassistant.setup] Setup of domain climate took 0.0 seconds
2021-04-07 12:48:06 INFO (MainThread) [homeassistant.setup] Setting up number
2021-04-07 12:48:06 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=number, service=set_value>
2021-04-07 12:48:06 INFO (MainThread) [homeassistant.setup] Setup of domain number took 0.0 seconds
2021-04-07 12:48:06 INFO (MainThread) [homeassistant.setup] Setting up lock
2021-04-07 12:48:06 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=lock, service=unlock>
2021-04-07 12:48:06 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=lock, service=lock>
2021-04-07 12:48:06 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=lock, service=open>
2021-04-07 12:48:06 INFO (MainThread) [homeassistant.setup] Setup of domain lock took 0.0 seconds
2021-04-07 12:48:06 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=device_tracker>
2021-04-07 12:48:06 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=climate>
2021-04-07 12:48:06 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=number>
2021-04-07 12:48:06 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=lock>
2021-04-07 12:48:06 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x0000](CC13X2/CC26X2, Z-Stack 3.30.00/3.40.00/4.10.00): power source: Mains
2021-04-07 12:48:06 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x0000](CC13X2/CC26X2, Z-Stack 3.30.00/3.40.00/4.10.00): completed initialization
2021-04-07 12:48:06 INFO (MainThread) [homeassistant.components.device_tracker] Setting up device_tracker.zha
2021-04-07 12:48:06 INFO (MainThread) [homeassistant.components.climate] Setting up climate.zha
2021-04-07 12:48:06 INFO (MainThread) [homeassistant.components.number] Setting up number.zha
2021-04-07 12:48:06 INFO (MainThread) [homeassistant.components.lock] Setting up lock.zha
2021-04-07 12:48:17 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event device_registry_updated[L]: action=update, device_id=9cb8b59d3e143b81c69a86b8da738cff>
2021-04-07 12:48:30 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sun.sun, old_state=<state sun.sun=above_horizon; next_dawn=2021-04-08T13:02:23+00:00, next_dusk=2021-04-08T03:18:19+00:00, next_midnight=2021-04-08T08:10:52+00:00, next_noon=2021-04-07T20:11:23+00:00, next_rising=2021-04-08T13:34:08+00:00, next_setting=2021-04-08T02:46:39+00:00, elevation=49.38, azimuth=169.91, rising=True, friendly_name=Sun @ 2021-04-07T12:04:30.309844-07:00>, new_state=<state sun.sun=above_horizon; next_dawn=2021-04-08T13:02:23+00:00, next_dusk=2021-04-08T03:18:19+00:00, next_midnight=2021-04-08T08:10:52+00:00, next_noon=2021-04-07T20:11:23+00:00, next_rising=2021-04-08T13:34:08+00:00, next_setting=2021-04-08T02:46:39+00:00, elevation=49.49, azimuth=171.42, rising=True, friendly_name=Sun @ 2021-04-07T12:04:30.309844-07:00>>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment