search

tube0013 / tube_gateways

Information and Documentation on Tube's Zigbee Gateways
264 stars 51 forks source link

Unable to configure Zigbee to PoE Coordinator in Home Assistant #110

Closed joeypiccola closed 1 year ago

joeypiccola commented 1 year ago

Home Assistant Version: 2022.10.4 (the one that runs as a container) Network: 10.0.3.0/24 (server VLAN)

Tubeszb Device: CC2652P2 Based Zigbee to PoE Coordinator 2022 Network: 192.168.9.0/24 (IoT VLAN) (device is using a reserved IP)

There's full routing between the two networks mentioned above, there are no restrictions.

Home Assistant (HA) discovers the Tubeszb device. However, when I attempt to configure it I get "Error" in the HA UI.

Discovery: image

Dialog when I click configure: image

Confirm serial port settings: image

Network formation: I have selected both "Keep radio network settings" and "Erase network settings and form a new network". image

Dialog once a network formation is selected: image

The Error: image

tube0013 commented 1 year ago

Can you please try to see if the device connects when on the same vlan as the server, then we can go from there to try and troubleshot the vlans.

joeypiccola commented 1 year ago

Unfortunately, still the same issue.

image image image image image

tube0013 commented 1 year ago

okay sorry for the troubles. can you enable debug logging for zigpy and zigpy-znp and then try again to get the logs and then post those:

https://www.home-assistant.io/integrations/zha/#debug-logging

joeypiccola commented 1 year ago

No worries, we'll figure it out. Logging enabled, filter applied -> "zigpy".

logger:
  default: info
  logs:
    zigpy: debug
    zigpy_znp: **debug**
2022-12-07 15:57:32.105 DEBUG (MainThread) [zigpy.appdb] Current database version is v10
2022-12-07 15:57:32.106 DEBUG (MainThread) [zigpy.appdb] Loading application state
2022-12-07 15:57:32.114 DEBUG (MainThread) [zigpy_znp.uart] Connecting to socket://10.0.3.51:6638 at 115200 baud
2022-12-07 15:57:32.116 DEBUG (MainThread) [zigpy_znp.uart] Opened socket://10.0.3.51:6638 serial port
2022-12-07 15:57:32.116 DEBUG (MainThread) [zigpy_znp.uart] Connected to socket://10.0.3.51:6638 at 115200 baud
2022-12-07 15:57:32.116 DEBUG (MainThread) [zigpy_znp.api] Toggling RTS/DTR pins to skip bootloader or reset chip
2022-12-07 15:57:32.571 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Ping.Req()
2022-12-07 15:57:32.632 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.Ping.Rsp(Capabilities=<MTCapabilities.APP_CNF|GP|UTIL|ZDO|AF|SYS: 1625>)
2022-12-07 15:57:32.633 DEBUG (MainThread) [zigpy_znp.api] Radio is alive: SYS.Ping.Rsp(Capabilities=<MTCapabilities.APP_CNF|GP|UTIL|ZDO|AF|SYS: 1625>)
2022-12-07 15:57:32.633 DEBUG (MainThread) [zigpy_znp.nvram] Detecting struct alignment
2022-12-07 15:57:32.633 DEBUG (MainThread) [zigpy_znp.api] Sending request: UTIL.AssocFindDevice.Req(Index=0)
2022-12-07 15:57:32.704 DEBUG (MainThread) [zigpy_znp.api] Received command: UTIL.AssocFindDevice.Rsp(Device=b'\xFE\xFF\x00\x20\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:57:32.706 DEBUG (MainThread) [zigpy_znp.nvram] Detected struct alignment: True
2022-12-07 15:57:32.706 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.TCLK_TABLE: 4>, SubId=0)
2022-12-07 15:57:32.777 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=20)
2022-12-07 15:57:32.778 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)
2022-12-07 15:57:32.850 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')
2022-12-07 15:57:32.851 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM[NvSysIds.ZSTACK][ExNvIds.TCLK_TABLE][0x0000] = b'\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xFF\x00\x00\x00'
2022-12-07 15:57:32.851 DEBUG (MainThread) [zigpy_znp.api] Detected Z-Stack 3.3
2022-12-07 15:57:32.851 DEBUG (MainThread) [zigpy_znp.api] Connected to socket://10.0.3.51:6638
2022-12-07 15:57:32.852 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.NIB: 33>)
2022-12-07 15:57:32.923 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=116)
2022-12-07 15:57:32.923 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.NIB: 33>, Offset=0)
2022-12-07 15:57:32.997 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x2B\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\xBD\x2D\x08\x00\x00\x80\x00\x00\x0F\x0F\x04\x00\x01\x00\x00\x00\x01\x00\x00\x00\x00\xBF\x9A\xFC\x3A\x91\xF1\x9A\x24\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\x64\x0A\x01\x00\x00\x00\x00\x00\x00\x00')
2022-12-07 15:57:32.999 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM["LEGACY"][0x0021] = NIB(SequenceNum=43, 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, TransactionPersistenceTime=7, nwkProtocolVersion=2, RouteDiscoveryTime=13, RouteExpiryTime=30, nwkDevAddress=0x0000, nwkLogicalChannel=15, nwkCoordAddress=0x0000, nwkCoordExtAddress=00:00:00:00:00:00:00:00, nwkPanId=11709, nwkState=<NwkState.NWK_ROUTER: 8>, channelList=<Channels.CHANNEL_15: 32768>, beaconOrder=15, superFrameOrder=15, scanDuration=4, battLifeExt=0, allocatedRouterAddresses=1, allocatedEndDeviceAddresses=1, nodeDepth=0, extendedPANID=24:9a:f1:91:3a:fc:9a:bf, 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=100, nwkConcentratorRadius=10, nwkAllFresh=1, nwkManagerAddr=0x0000, nwkTotalTransmissions=0, nwkUpdateId=0)
2022-12-07 15:57:32.999 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.BDBNODEISONANETWORK: 85>)
2022-12-07 15:57:33.069 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2022-12-07 15:57:33.070 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.BDBNODEISONANETWORK: 85>, Offset=0)
2022-12-07 15:57:33.142 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x01')
2022-12-07 15:57:33.142 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM["LEGACY"][0x0055] = 1
2022-12-07 15:57:33.143 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.EXTADDR: 1>)
2022-12-07 15:57:33.215 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=8)
2022-12-07 15:57:33.216 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.EXTADDR: 1>, Offset=0)
2022-12-07 15:57:33.288 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x14\xC3\x2E\x2A\x00\x4B\x12\x00')
2022-12-07 15:57:33.288 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM["LEGACY"][0x0001] = 00:12:4b:00:2a:2e:c3:14
2022-12-07 15:57:33.289 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.LOGICAL_TYPE: 135>)
2022-12-07 15:57:33.361 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2022-12-07 15:57:33.361 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.LOGICAL_TYPE: 135>, Offset=0)
2022-12-07 15:57:33.434 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x00')
2022-12-07 15:57:33.435 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM["LEGACY"][0x0087] = <DeviceLogicalType.Coordinator: 0>
2022-12-07 15:57:33.435 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.NWK_ACTIVE_KEY_INFO: 58>)
2022-12-07 15:57:33.507 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=17)
2022-12-07 15:57:33.509 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.NWK_ACTIVE_KEY_INFO: 58>, Offset=0)
2022-12-07 15:57:33.580 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x00\xA4\x1B\xB5\x0E\x7C\xDF\x22\x41\xB2\xC3\x1D\xE8\x18\x65\x79\xB6')
2022-12-07 15:57:33.581 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM["LEGACY"][0x003a] = NwkKeyDesc(KeySeqNum=0, Key=a4:1b:b5:0e:7c:df:22:41:b2:c3:1d:e8:18:65:79:b6)
2022-12-07 15:57:33.582 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.NWK_SEC_MATERIAL_TABLE: 7>, SubId=0)
2022-12-07 15:57:33.653 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:57:33.654 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)
2022-12-07 15:57:33.726 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVRead.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x00\x00\x00\x00\xBF\x9A\xFC\x3A\x91\xF1\x9A\x24')
2022-12-07 15:57:33.728 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM[NvSysIds.ZSTACK][ExNvIds.NWK_SEC_MATERIAL_TABLE][0x0000] = NwkSecMaterialDesc(FrameCounter=0, ExtendedPanID=24:9a:f1:91:3a:fc:9a:bf)
2022-12-07 15:57:33.729 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Version.Req()
2022-12-07 15:57:33.799 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.Version.Rsp(TransportRev=2, ProductId=1, MajorRel=2, MinorRel=7, MaintRel=1, CodeRevision=20220219, BootloaderBuildType=<BootloaderBuildType.NON_BOOTLOADER_BUILD: 0>, BootloaderRevision=None)
2022-12-07 15:57:33.800 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.TCLK_SEED: 257>)
2022-12-07 15:57:33.872 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=16)
2022-12-07 15:57:33.873 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.TCLK_SEED: 257>, Offset=0)
2022-12-07 15:57:33.945 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x3F\x46\x27\xF9\x6A\x70\xC4\xF5\xF2\xB1\x2C\xD4\x0A\xE0\xC4\x64')
2022-12-07 15:57:33.946 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM["LEGACY"][0x0101] = 3f:46:27:f9:6a:70:c4:f5:f2:b1:2c:d4:0a:e0:c4:64
2022-12-07 15:57:33.947 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.ResetReq.Req(Type=<ResetType.Soft: 1>)
2022-12-07 15:57:33.947 DEBUG (MainThread) [zigpy_znp.api] Request has no response, not waiting for one.
2022-12-07 15:57:33.948 DEBUG (MainThread) [zigpy_znp.uart] Closing serial port
2022-12-07 15:57:36.806 DEBUG (MainThread) [zigpy.appdb] Current database version is v10
2022-12-07 15:57:36.808 DEBUG (MainThread) [zigpy.appdb] Loading application state
2022-12-07 15:57:36.820 DEBUG (MainThread) [zigpy_znp.uart] Connecting to socket://10.0.3.51:6638 at 115200 baud
2022-12-07 15:57:36.823 DEBUG (MainThread) [zigpy_znp.uart] Opened socket://10.0.3.51:6638 serial port
2022-12-07 15:57:36.823 DEBUG (MainThread) [zigpy_znp.uart] Connected to socket://10.0.3.51:6638 at 115200 baud
2022-12-07 15:57:36.823 DEBUG (MainThread) [zigpy_znp.api] Toggling RTS/DTR pins to skip bootloader or reset chip
2022-12-07 15:57:37.276 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Ping.Req()
2022-12-07 15:57:37.330 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.Ping.Rsp(Capabilities=<MTCapabilities.APP_CNF|GP|UTIL|ZDO|AF|SYS: 1625>)
2022-12-07 15:57:37.331 DEBUG (MainThread) [zigpy_znp.api] Radio is alive: SYS.Ping.Rsp(Capabilities=<MTCapabilities.APP_CNF|GP|UTIL|ZDO|AF|SYS: 1625>)
2022-12-07 15:57:37.332 DEBUG (MainThread) [zigpy_znp.nvram] Detecting struct alignment
2022-12-07 15:57:37.332 DEBUG (MainThread) [zigpy_znp.api] Sending request: UTIL.AssocFindDevice.Req(Index=0)
2022-12-07 15:57:37.403 DEBUG (MainThread) [zigpy_znp.api] Received command: UTIL.AssocFindDevice.Rsp(Device=b'\xFE\xFF\x00\x20\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:57:37.404 DEBUG (MainThread) [zigpy_znp.nvram] Detected struct alignment: True
2022-12-07 15:57:37.404 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.TCLK_TABLE: 4>, SubId=0)
2022-12-07 15:57:37.476 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=20)
2022-12-07 15:57:37.477 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)
2022-12-07 15:57:37.550 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')
2022-12-07 15:57:37.550 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM[NvSysIds.ZSTACK][ExNvIds.TCLK_TABLE][0x0000] = b'\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xFF\x00\x00\x00'
2022-12-07 15:57:37.550 DEBUG (MainThread) [zigpy_znp.api] Detected Z-Stack 3.3
2022-12-07 15:57:37.550 DEBUG (MainThread) [zigpy_znp.api] Connected to socket://10.0.3.51:6638
2022-12-07 15:57:37.551 DEBUG (MainThread) [zigpy.application] Forming a new network
2022-12-07 15:57:37.551 DEBUG (MainThread) [zigpy.backups] Restoring backup NetworkBackup(backup_time=datetime.datetime(2022, 12, 7, 22, 57, 37, 551227, tzinfo=datetime.timezone.utc), network_info=NetworkInfo(extended_pan_id=e3:50:76:70:80:7a:81:e8, pan_id=55469, nwk_update_id=0, nwk_manager_id=0, channel=15, channel_mask=<Channels.CHANNEL_15: 32768>, security_level=5, network_key=Key(key=e0:26:a8:f2:a9:b4:d4:4a:54:61:f6:6e:46:c4:98:85, 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>))
2022-12-07 15:57:37.551 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.HAS_CONFIGURED_ZSTACK1: 3840>)
2022-12-07 15:57:37.622 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=0)
2022-12-07 15:57:37.622 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.HAS_CONFIGURED_ZSTACK3: 96>)
2022-12-07 15:57:37.695 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=0)
2022-12-07 15:57:37.696 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.ZIGPY_ZNP_MIGRATION_ID: 95>)
2022-12-07 15:57:37.768 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=0)
2022-12-07 15:57:37.768 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.BDBNODEISONANETWORK: 85>)
2022-12-07 15:57:37.841 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2022-12-07 15:57:37.841 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVDelete.Req(Id=<OsalNvIds.BDBNODEISONANETWORK: 85>, ItemLen=1)
2022-12-07 15:57:37.914 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVDelete.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:37.915 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.STARTUP_OPTION: 3>)
2022-12-07 15:57:37.987 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2022-12-07 15:57:37.987 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVWriteExt.Req(Id=<OsalNvIds.STARTUP_OPTION: 3>, Offset=0, Value=b'\x03')
2022-12-07 15:57:38.060 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVWriteExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:38.061 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.ResetReq.Req(Type=<ResetType.Soft: 1>)
2022-12-07 15:57:38.061 DEBUG (MainThread) [zigpy_znp.api] Request has no response, not waiting for one.
2022-12-07 15:57:40.510 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.ResetInd.Callback(Reason=<ResetReason.PowerUp: 0>, TransportRev=2, ProductId=1, MajorRel=2, MinorRel=7, MaintRel=1)
2022-12-07 15:57:40.511 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.PANID: 131>)
2022-12-07 15:57:40.576 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=2)
2022-12-07 15:57:40.576 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVWriteExt.Req(Id=<OsalNvIds.PANID: 131>, Offset=0, Value=b'\xFF\xFF')
2022-12-07 15:57:40.650 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVWriteExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:40.652 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.APS_USE_EXT_PANID: 71>)
2022-12-07 15:57:40.723 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=8)
2022-12-07 15:57:40.724 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVWriteExt.Req(Id=<OsalNvIds.APS_USE_EXT_PANID: 71>, Offset=0, Value=b'\x14\x1A\xF9\xAD\x3B\x77\x4C\xCD')
2022-12-07 15:57:40.796 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVWriteExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:40.797 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.PRECFGKEY: 98>)
2022-12-07 15:57:40.869 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=16)
2022-12-07 15:57:40.870 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVWriteExt.Req(Id=<OsalNvIds.PRECFGKEY: 98>, Offset=0, Value=b'\xF3\x42\x77\x97\x48\x03\x01\x59\x38\xB2\x7D\x7D\x8E\x5C\x0A\xC2')
2022-12-07 15:57:40.942 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVWriteExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:40.943 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.PRECFGKEYS_ENABLE: 99>)
2022-12-07 15:57:41.015 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2022-12-07 15:57:41.016 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVWriteExt.Req(Id=<OsalNvIds.PRECFGKEYS_ENABLE: 99>, Offset=0, Value=b'\x00')
2022-12-07 15:57:41.088 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVWriteExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:41.088 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.CHANLIST: 132>)
2022-12-07 15:57:41.161 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=4)
2022-12-07 15:57:41.162 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVWriteExt.Req(Id=<OsalNvIds.CHANLIST: 132>, Offset=0, Value=b'\x00\x80\x10\x02')
2022-12-07 15:57:41.234 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVWriteExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:41.236 DEBUG (MainThread) [zigpy_znp.api] Sending request: AppConfig.BDBSetChannel.Req(IsPrimary=<Bool.true: 1>, Channel=<Channels.CHANNEL_25|CHANNEL_20|CHANNEL_15: 34635776>)
2022-12-07 15:57:41.307 DEBUG (MainThread) [zigpy_znp.api] Received command: AppConfig.BDBSetChannel.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:41.308 DEBUG (MainThread) [zigpy_znp.api] Sending request: AppConfig.BDBSetChannel.Req(IsPrimary=<Bool.false: 0>, Channel=<Channels.NO_CHANNELS: 0>)
2022-12-07 15:57:41.380 DEBUG (MainThread) [zigpy_znp.api] Received command: AppConfig.BDBSetChannel.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:41.381 DEBUG (MainThread) [zigpy_znp.api] Forming temporary network
2022-12-07 15:57:41.382 DEBUG (MainThread) [zigpy_znp.api] Sending request: AppConfig.BDBStartCommissioning.Req(Mode=<BDBCommissioningMode.NwkFormation: 4>)
2022-12-07 15:57:44.437 DEBUG (MainThread) [zigpy_znp.api] Received command: AppConfig.BDBStartCommissioning.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:44.437 DEBUG (MainThread) [zigpy_znp.api] Received command: AppConfig.BDBCommissioningNotification.Callback(Status=<BDBCommissioningStatus.InProgress: 1>, Mode=<BDBCommissioningMode.NwkSteering: 2>, RemainingModes=<BDBCommissioningMode.NwkFormation: 4>)
2022-12-07 15:57:44.726 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.StateChangeInd.Callback(State=<DeviceState.StartingAsCoordinator: 8>)
2022-12-07 15:57:46.383 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.StateChangeInd.Callback(State=<DeviceState.StartedAsCoordinator: 9>)
2022-12-07 15:57:46.384 DEBUG (MainThread) [zigpy_znp.api] Received command: AppConfig.BDBCommissioningNotification.Callback(Status=<BDBCommissioningStatus.Success: 0>, Mode=<BDBCommissioningMode.NwkSteering: 2>, RemainingModes=<BDBCommissioningMode.NONE: 0>)
2022-12-07 15:57:46.385 DEBUG (MainThread) [zigpy_znp.api] Waiting for NIB to stabilize
2022-12-07 15:57:46.386 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.NIB: 33>)
2022-12-07 15:57:46.456 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=116)
2022-12-07 15:57:46.458 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.NIB: 33>, Offset=0)
2022-12-07 15:57:46.530 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x05\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\x14\xC3\x2E\x2A\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\x64\x0A\x01\x00\x00\x00\x00\x00\x00\x00')
2022-12-07 15:57:46.534 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM["LEGACY"][0x0021] = NIB(SequenceNum=5, 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, TransactionPersistenceTime=7, nwkProtocolVersion=2, RouteDiscoveryTime=13, RouteExpiryTime=30, nwkDevAddress=0xFFFE, nwkLogicalChannel=0, nwkCoordAddress=0xFFFE, nwkCoordExtAddress=00:00:00:00:00:00:00:00, nwkPanId=65535, nwkState=<NwkState.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:2a:2e:c3:14, nwkKeyLoaded=<Bool.false: 0>, 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=100, nwkConcentratorRadius=10, nwkAllFresh=1, nwkManagerAddr=0x0000, nwkTotalTransmissions=0, nwkUpdateId=0)
2022-12-07 15:57:46.534 DEBUG (MainThread) [zigpy_znp.api] Current NIB is NIB(SequenceNum=5, 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, TransactionPersistenceTime=7, nwkProtocolVersion=2, RouteDiscoveryTime=13, RouteExpiryTime=30, nwkDevAddress=0xFFFE, nwkLogicalChannel=0, nwkCoordAddress=0xFFFE, nwkCoordExtAddress=00:00:00:00:00:00:00:00, nwkPanId=65535, nwkState=<NwkState.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:2a:2e:c3:14, nwkKeyLoaded=<Bool.false: 0>, 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=100, nwkConcentratorRadius=10, nwkAllFresh=1, nwkManagerAddr=0x0000, nwkTotalTransmissions=0, nwkUpdateId=0)
2022-12-07 15:57:47.537 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.NIB: 33>)
2022-12-07 15:57:47.610 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=116)
2022-12-07 15:57:47.610 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.NIB: 33>, Offset=0)
2022-12-07 15:57:47.684 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x05\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\x14\xC3\x2E\x2A\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\x64\x0A\x01\x00\x00\x00\x00\x00\x00\x00')
2022-12-07 15:57:47.691 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM["LEGACY"][0x0021] = NIB(SequenceNum=5, 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, TransactionPersistenceTime=7, nwkProtocolVersion=2, RouteDiscoveryTime=13, RouteExpiryTime=30, nwkDevAddress=0xFFFE, nwkLogicalChannel=0, nwkCoordAddress=0xFFFE, nwkCoordExtAddress=00:00:00:00:00:00:00:00, nwkPanId=65535, nwkState=<NwkState.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:2a:2e:c3:14, nwkKeyLoaded=<Bool.false: 0>, 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=100, nwkConcentratorRadius=10, nwkAllFresh=1, nwkManagerAddr=0x0000, nwkTotalTransmissions=0, nwkUpdateId=0)
2022-12-07 15:57:47.692 DEBUG (MainThread) [zigpy_znp.api] Current NIB is NIB(SequenceNum=5, 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, TransactionPersistenceTime=7, nwkProtocolVersion=2, RouteDiscoveryTime=13, RouteExpiryTime=30, nwkDevAddress=0xFFFE, nwkLogicalChannel=0, nwkCoordAddress=0xFFFE, nwkCoordExtAddress=00:00:00:00:00:00:00:00, nwkPanId=65535, nwkState=<NwkState.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:2a:2e:c3:14, nwkKeyLoaded=<Bool.false: 0>, 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=100, nwkConcentratorRadius=10, nwkAllFresh=1, nwkManagerAddr=0x0000, nwkTotalTransmissions=0, nwkUpdateId=0)
2022-12-07 15:57:48.694 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.NIB: 33>)
2022-12-07 15:57:48.764 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=116)
2022-12-07 15:57:48.765 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.NIB: 33>, Offset=0)
2022-12-07 15:57:48.838 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x05\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\x14\xC3\x2E\x2A\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\x64\x0A\x01\x00\x00\x00\x00\x00\x00\x00')
2022-12-07 15:57:48.839 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM["LEGACY"][0x0021] = NIB(SequenceNum=5, 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, TransactionPersistenceTime=7, nwkProtocolVersion=2, RouteDiscoveryTime=13, RouteExpiryTime=30, nwkDevAddress=0xFFFE, nwkLogicalChannel=0, nwkCoordAddress=0xFFFE, nwkCoordExtAddress=00:00:00:00:00:00:00:00, nwkPanId=65535, nwkState=<NwkState.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:2a:2e:c3:14, nwkKeyLoaded=<Bool.false: 0>, 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=100, nwkConcentratorRadius=10, nwkAllFresh=1, nwkManagerAddr=0x0000, nwkTotalTransmissions=0, nwkUpdateId=0)
2022-12-07 15:57:48.839 DEBUG (MainThread) [zigpy_znp.api] Current NIB is NIB(SequenceNum=5, 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, TransactionPersistenceTime=7, nwkProtocolVersion=2, RouteDiscoveryTime=13, RouteExpiryTime=30, nwkDevAddress=0xFFFE, nwkLogicalChannel=0, nwkCoordAddress=0xFFFE, nwkCoordExtAddress=00:00:00:00:00:00:00:00, nwkPanId=65535, nwkState=<NwkState.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:2a:2e:c3:14, nwkKeyLoaded=<Bool.false: 0>, 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=100, nwkConcentratorRadius=10, nwkAllFresh=1, nwkManagerAddr=0x0000, nwkTotalTransmissions=0, nwkUpdateId=0)
2022-12-07 15:57:49.841 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.NIB: 33>)
2022-12-07 15:57:49.882 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=116)
2022-12-07 15:57:49.883 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.NIB: 33>, Offset=0)
2022-12-07 15:57:49.956 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x05\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\x77\x17\x08\x00\x00\x80\x10\x02\x0F\x0F\x04\x00\x01\x00\x00\x00\x01\x00\x00\x00\x00\x14\x1A\xF9\xAD\x3B\x77\x4C\xCD\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\x64\x0A\x01\x00\x00\x00\x00\x00\x00\x00')
2022-12-07 15:57:49.959 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM["LEGACY"][0x0021] = NIB(SequenceNum=5, 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, TransactionPersistenceTime=7, nwkProtocolVersion=2, RouteDiscoveryTime=13, RouteExpiryTime=30, nwkDevAddress=0x0000, nwkLogicalChannel=15, nwkCoordAddress=0x0000, nwkCoordExtAddress=00:00:00:00:00:00:00:00, nwkPanId=6007, nwkState=<NwkState.NWK_ROUTER: 8>, channelList=<Channels.CHANNEL_25|CHANNEL_20|CHANNEL_15: 34635776>, beaconOrder=15, superFrameOrder=15, scanDuration=4, battLifeExt=0, allocatedRouterAddresses=1, allocatedEndDeviceAddresses=1, nodeDepth=0, extendedPANID=cd:4c:77:3b:ad:f9:1a:14, 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=100, nwkConcentratorRadius=10, nwkAllFresh=1, nwkManagerAddr=0x0000, nwkTotalTransmissions=0, nwkUpdateId=0)
2022-12-07 15:57:49.960 DEBUG (MainThread) [zigpy_znp.api] Current NIB is NIB(SequenceNum=5, 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, TransactionPersistenceTime=7, nwkProtocolVersion=2, RouteDiscoveryTime=13, RouteExpiryTime=30, nwkDevAddress=0x0000, nwkLogicalChannel=15, nwkCoordAddress=0x0000, nwkCoordExtAddress=00:00:00:00:00:00:00:00, nwkPanId=6007, nwkState=<NwkState.NWK_ROUTER: 8>, channelList=<Channels.CHANNEL_25|CHANNEL_20|CHANNEL_15: 34635776>, beaconOrder=15, superFrameOrder=15, scanDuration=4, battLifeExt=0, allocatedRouterAddresses=1, allocatedEndDeviceAddresses=1, nodeDepth=0, extendedPANID=cd:4c:77:3b:ad:f9:1a:14, 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=100, nwkConcentratorRadius=10, nwkAllFresh=1, nwkManagerAddr=0x0000, nwkTotalTransmissions=0, nwkUpdateId=0)
2022-12-07 15:57:49.961 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.ResetReq.Req(Type=<ResetType.Soft: 1>)
2022-12-07 15:57:49.961 DEBUG (MainThread) [zigpy_znp.api] Request has no response, not waiting for one.
2022-12-07 15:57:52.758 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.ResetInd.Callback(Reason=<ResetReason.PowerUp: 0>, TransportRev=2, ProductId=1, MajorRel=2, MinorRel=7, MaintRel=1)
2022-12-07 15:57:52.758 DEBUG (MainThread) [zigpy_znp.api] Writing actual network settings
2022-12-07 15:57:52.759 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.NIB: 33>)
2022-12-07 15:57:52.832 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=116)
2022-12-07 15:57:52.832 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.NIB: 33>, Offset=0)
2022-12-07 15:57:52.906 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x05\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\x77\x17\x08\x00\x00\x80\x10\x02\x0F\x0F\x04\x00\x01\x00\x00\x00\x01\x00\x00\x00\x00\x14\x1A\xF9\xAD\x3B\x77\x4C\xCD\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\x64\x0A\x01\x00\x00\x00\x00\x00\x00\x00')
2022-12-07 15:57:52.909 DEBUG (MainThread) [zigpy_znp.nvram] Read NVRAM["LEGACY"][0x0021] = NIB(SequenceNum=5, 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, TransactionPersistenceTime=7, nwkProtocolVersion=2, RouteDiscoveryTime=13, RouteExpiryTime=30, nwkDevAddress=0x0000, nwkLogicalChannel=15, nwkCoordAddress=0x0000, nwkCoordExtAddress=00:00:00:00:00:00:00:00, nwkPanId=6007, nwkState=<NwkState.NWK_ROUTER: 8>, channelList=<Channels.CHANNEL_25|CHANNEL_20|CHANNEL_15: 34635776>, beaconOrder=15, superFrameOrder=15, scanDuration=4, battLifeExt=0, allocatedRouterAddresses=1, allocatedEndDeviceAddresses=1, nodeDepth=0, extendedPANID=cd:4c:77:3b:ad:f9:1a:14, 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=100, nwkConcentratorRadius=10, nwkAllFresh=1, nwkManagerAddr=0x0000, nwkTotalTransmissions=0, nwkUpdateId=0)
2022-12-07 15:57:52.911 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.NIB: 33>)
2022-12-07 15:57:52.978 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=116)
2022-12-07 15:57:52.978 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVWriteExt.Req(Id=<OsalNvIds.NIB: 33>, Offset=0, Value=b'\x05\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\xAD\xD8\x08\x00\x00\x80\x00\x00\x0F\x0F\x04\x00\x01\x00\x00\x00\x01\x00\x00\x00\x00\xE8\x81\x7A\x80\x70\x76\x50\xE3\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\x64\x0A\x01\x00\x00\x00\x00\x00\x00\x00')
2022-12-07 15:57:53.052 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVWriteExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:53.053 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.APS_USE_EXT_PANID: 71>)
2022-12-07 15:57:53.125 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=8)
2022-12-07 15:57:53.125 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVWriteExt.Req(Id=<OsalNvIds.APS_USE_EXT_PANID: 71>, Offset=0, Value=b'\xE8\x81\x7A\x80\x70\x76\x50\xE3')
2022-12-07 15:57:53.198 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVWriteExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:53.199 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.EXTENDED_PAN_ID: 45>)
2022-12-07 15:57:53.271 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=8)
2022-12-07 15:57:53.272 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVWriteExt.Req(Id=<OsalNvIds.EXTENDED_PAN_ID: 45>, Offset=0, Value=b'\xE8\x81\x7A\x80\x70\x76\x50\xE3')
2022-12-07 15:57:53.344 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVWriteExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:53.345 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.PRECFGKEY: 98>)
2022-12-07 15:57:53.417 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=16)
2022-12-07 15:57:53.418 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVWriteExt.Req(Id=<OsalNvIds.PRECFGKEY: 98>, Offset=0, Value=b'\xE0\x26\xA8\xF2\xA9\xB4\xD4\x4A\x54\x61\xF6\x6E\x46\xC4\x98\x85')
2022-12-07 15:57:53.490 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVWriteExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:53.490 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.CHANLIST: 132>)
2022-12-07 15:57:53.563 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=4)
2022-12-07 15:57:53.564 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVWriteExt.Req(Id=<OsalNvIds.CHANLIST: 132>, Offset=0, Value=b'\x00\x80\x00\x00')
2022-12-07 15:57:53.636 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVWriteExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:53.636 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.EXTADDR: 1>)
2022-12-07 15:57:53.709 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=8)
2022-12-07 15:57:53.709 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVDelete.Req(Id=<OsalNvIds.EXTADDR: 1>, ItemLen=8)
2022-12-07 15:57:53.782 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVDelete.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:53.783 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.LOGICAL_TYPE: 135>)
2022-12-07 15:57:53.855 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2022-12-07 15:57:53.855 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVWriteExt.Req(Id=<OsalNvIds.LOGICAL_TYPE: 135>, Offset=0, Value=b'\x00')
2022-12-07 15:57:53.928 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVWriteExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:53.928 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.NWK_ACTIVE_KEY_INFO: 58>)
2022-12-07 15:57:54.002 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=17)
2022-12-07 15:57:54.003 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVWriteExt.Req(Id=<OsalNvIds.NWK_ACTIVE_KEY_INFO: 58>, Offset=0, Value=b'\x00\xE0\x26\xA8\xF2\xA9\xB4\xD4\x4A\x54\x61\xF6\x6E\x46\xC4\x98\x85')
2022-12-07 15:57:54.074 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVWriteExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:54.075 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.NWK_ALTERN_KEY_INFO: 59>)
2022-12-07 15:57:54.147 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=17)
2022-12-07 15:57:54.148 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVWriteExt.Req(Id=<OsalNvIds.NWK_ALTERN_KEY_INFO: 59>, Offset=0, Value=b'\x00\xE0\x26\xA8\xF2\xA9\xB4\xD4\x4A\x54\x61\xF6\x6E\x46\xC4\x98\x85')
2022-12-07 15:57:54.220 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVWriteExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:54.221 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.TCLK_SEED: 257>)
2022-12-07 15:57:54.293 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=16)
2022-12-07 15:57:54.294 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVWriteExt.Req(Id=<OsalNvIds.TCLK_SEED: 257>, Offset=0, Value=b'\x90\x54\x4A\x48\x55\x65\x72\x06\xF4\xA7\x49\x61\xD0\xBA\xBD\xE7')
2022-12-07 15:57:54.366 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVWriteExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:54.368 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.NWK_SEC_MATERIAL_TABLE: 7>, SubId=0)
2022-12-07 15:57:54.439 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:57:54.440 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.NWK_SEC_MATERIAL_TABLE: 7>, SubId=0, Offset=0, Value=b'\x00\x00\x00\x00\xE8\x81\x7A\x80\x70\x76\x50\xE3')
2022-12-07 15:57:54.512 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:54.513 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.NWK_SEC_MATERIAL_TABLE: 7>, SubId=1)
2022-12-07 15:57:54.585 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:57:54.585 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.NWK_SEC_MATERIAL_TABLE: 7>, SubId=1, Offset=0, Value=b'\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00')
2022-12-07 15:57:54.659 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:54.659 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.NWK_SEC_MATERIAL_TABLE: 7>, SubId=2)
2022-12-07 15:57:54.732 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:57:54.734 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.NWK_SEC_MATERIAL_TABLE: 7>, SubId=2, Offset=0, Value=b'\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00')
2022-12-07 15:57:54.805 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:54.805 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.NWK_SEC_MATERIAL_TABLE: 7>, SubId=3)
2022-12-07 15:57:54.878 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:57:54.879 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.NWK_SEC_MATERIAL_TABLE: 7>, SubId=3, Offset=0, Value=b'\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00')
2022-12-07 15:57:54.951 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:54.952 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.NWK_SEC_MATERIAL_TABLE: 7>, SubId=4)
2022-12-07 15:57:55.024 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:57:55.024 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.NWK_SEC_MATERIAL_TABLE: 7>, SubId=4, Offset=0, Value=b'\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00')
2022-12-07 15:57:55.097 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:55.097 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.NWK_SEC_MATERIAL_TABLE: 7>, SubId=5)
2022-12-07 15:57:55.170 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=0)
2022-12-07 15:57:55.170 DEBUG (MainThread) [zigpy_znp.api] Writing children and keys
2022-12-07 15:57:55.171 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=0)
2022-12-07 15:57:55.243 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:57:55.243 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=0, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:57:55.316 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:55.316 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=1)
2022-12-07 15:57:55.389 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:57:55.390 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=1, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:57:55.462 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:55.463 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=2)
2022-12-07 15:57:55.535 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:57:55.535 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=2, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:57:55.608 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:55.609 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=3)
2022-12-07 15:57:55.681 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:57:55.682 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=3, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:57:55.754 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:55.755 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=4)
2022-12-07 15:57:55.827 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:57:55.828 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=4, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:57:55.900 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:55.902 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=5)
2022-12-07 15:57:55.973 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:57:55.974 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=5, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:57:56.046 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:56.047 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=6)
2022-12-07 15:57:56.119 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:57:56.120 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=6, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:57:56.192 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:56.193 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=7)
2022-12-07 15:57:56.265 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:57:56.266 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=7, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:57:56.338 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:56.340 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=8)
2022-12-07 15:57:56.411 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:57:56.413 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=8, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:57:56.484 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:56.486 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=9)
2022-12-07 15:57:56.557 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:57:56.558 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=9, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:57:56.630 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:56.632 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=10)
2022-12-07 15:57:56.703 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:57:56.704 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=10, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:57:56.776 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:56.777 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=11)
2022-12-07 15:57:56.849 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:57:56.850 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=11, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:57:56.922 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:56.922 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=12)
2022-12-07 15:57:56.995 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:57:56.995 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=12, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:57:57.068 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:57.068 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=13)
2022-12-07 15:57:57.141 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:57:57.142 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=13, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:57:57.214 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:57.216 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=14)
2022-12-07 15:57:57.287 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:57:57.288 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=14, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:57:57.360 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:57.362 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=15)
2022-12-07 15:57:57.433 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:57:57.434 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=15, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:57:57.507 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:57.508 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=16)
2022-12-07 15:57:57.580 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:57:57.581 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=16, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:57:57.653 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:57.654 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=17)
2022-12-07 15:57:57.726 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:57:57.727 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=17, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:57:57.799 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:57.800 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=18)
2022-12-07 15:57:57.872 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:57:57.874 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=18, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:57:57.945 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:57.946 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=19)
2022-12-07 15:57:58.018 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:57:58.019 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=19, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:57:58.091 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:58.092 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=20)
2022-12-07 15:57:58.164 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:57:58.166 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=20, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:57:58.237 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:58.238 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=21)
2022-12-07 15:57:58.311 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:57:58.312 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=21, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:57:58.383 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:58.384 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=22)
2022-12-07 15:57:58.456 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:57:58.457 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=22, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:57:58.529 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:58.531 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=23)
2022-12-07 15:57:58.602 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:57:58.603 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=23, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:57:58.675 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:58.677 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=24)
2022-12-07 15:57:58.748 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:57:58.749 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=24, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:57:58.821 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:58.823 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=25)
2022-12-07 15:57:58.894 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:57:58.895 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=25, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:57:58.967 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:58.968 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=26)
2022-12-07 15:57:59.040 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:57:59.042 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=26, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:57:59.113 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:59.114 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=27)
2022-12-07 15:57:59.186 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:57:59.188 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=27, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:57:59.259 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:59.260 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=28)
2022-12-07 15:57:59.332 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:57:59.334 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=28, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:57:59.405 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:59.406 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=29)
2022-12-07 15:57:59.478 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:57:59.479 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=29, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:57:59.551 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:59.552 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=30)
2022-12-07 15:57:59.624 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:57:59.625 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=30, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:57:59.698 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:59.699 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=31)
2022-12-07 15:57:59.771 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:57:59.771 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=31, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:57:59.844 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:59.845 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=32)
2022-12-07 15:57:59.917 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:57:59.918 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=32, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:57:59.990 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:57:59.990 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=33)
2022-12-07 15:58:00.063 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:00.063 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=33, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:00.136 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:00.137 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=34)
2022-12-07 15:58:00.210 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:00.210 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=34, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:00.282 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:00.283 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=35)
2022-12-07 15:58:00.356 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:00.356 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=35, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:00.429 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:00.429 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=36)
2022-12-07 15:58:00.502 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:00.503 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=36, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:00.567 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:00.568 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=37)
2022-12-07 15:58:00.640 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:00.641 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=37, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:00.714 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:00.715 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=38)
2022-12-07 15:58:00.787 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:00.788 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=38, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:00.860 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:00.862 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=39)
2022-12-07 15:58:00.933 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:00.933 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=39, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:01.007 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:01.009 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=40)
2022-12-07 15:58:01.081 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:01.081 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=40, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:01.154 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:01.155 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=41)
2022-12-07 15:58:01.227 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:01.227 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=41, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:01.300 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:01.301 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=42)
2022-12-07 15:58:01.373 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:01.373 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=42, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:01.446 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:01.447 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=43)
2022-12-07 15:58:01.519 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:01.520 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=43, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:01.592 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:01.593 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=44)
2022-12-07 15:58:01.665 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:01.666 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=44, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:01.738 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:01.739 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=45)
2022-12-07 15:58:01.811 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:01.812 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=45, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:01.884 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:01.885 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=46)
2022-12-07 15:58:01.957 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:01.958 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=46, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:02.030 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:02.031 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=47)
2022-12-07 15:58:02.103 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:02.104 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=47, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:02.176 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:02.177 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=48)
2022-12-07 15:58:02.249 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:02.249 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=48, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:02.322 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:02.323 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=49)
2022-12-07 15:58:02.395 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:02.395 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=49, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:02.468 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:02.469 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=50)
2022-12-07 15:58:02.541 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:02.542 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=50, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:02.614 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:02.615 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=51)
2022-12-07 15:58:02.687 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:02.688 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=51, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:02.760 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:02.761 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=52)
2022-12-07 15:58:02.833 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:02.834 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=52, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:02.978 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:02.980 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=53)
2022-12-07 15:58:03.051 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:03.052 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=53, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:03.124 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:03.125 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=54)
2022-12-07 15:58:03.197 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:03.198 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=54, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:03.270 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:03.272 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=55)
2022-12-07 15:58:03.343 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:03.344 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=55, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:03.416 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:03.418 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=56)
2022-12-07 15:58:03.489 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:03.490 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=56, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:03.562 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:03.564 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=57)
2022-12-07 15:58:03.636 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:03.638 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=57, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:03.709 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:03.711 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=58)
2022-12-07 15:58:03.782 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:03.782 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=58, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:03.855 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:03.856 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=59)
2022-12-07 15:58:03.929 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:03.931 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=59, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:04.002 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:04.003 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=60)
2022-12-07 15:58:04.075 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:04.076 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=60, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:04.148 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:04.148 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=61)
2022-12-07 15:58:04.221 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:04.221 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=61, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:04.294 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:04.294 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=62)
2022-12-07 15:58:04.367 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:04.367 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=62, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:04.440 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:04.440 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=63)
2022-12-07 15:58:04.513 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:04.514 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=63, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:04.586 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:04.587 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=64)
2022-12-07 15:58:04.659 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:04.660 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=64, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:04.732 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:04.733 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=65)
2022-12-07 15:58:04.805 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:04.806 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=65, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:04.878 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:04.879 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=66)
2022-12-07 15:58:04.951 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:04.952 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=66, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:05.024 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:05.025 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=67)
2022-12-07 15:58:05.097 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:05.098 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=67, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:05.170 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:05.170 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=68)
2022-12-07 15:58:05.243 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:05.243 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=68, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:05.316 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:05.316 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=69)
2022-12-07 15:58:05.389 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:05.389 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=69, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:05.462 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:05.462 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=70)
2022-12-07 15:58:05.535 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:05.535 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=70, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:05.608 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:05.609 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=71)
2022-12-07 15:58:05.681 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:05.681 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=71, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:05.754 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:05.755 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=72)
2022-12-07 15:58:05.827 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:05.827 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=72, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:05.900 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:05.903 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=73)
2022-12-07 15:58:05.973 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:05.974 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=73, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:06.046 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:06.047 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=74)
2022-12-07 15:58:06.119 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:06.120 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=74, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:06.192 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:06.193 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=75)
2022-12-07 15:58:06.265 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:06.266 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=75, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:06.338 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:06.339 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=76)
2022-12-07 15:58:06.411 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:06.413 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=76, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:06.484 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:06.484 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=77)
2022-12-07 15:58:06.557 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:06.559 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=77, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:06.630 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:06.631 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=78)
2022-12-07 15:58:06.703 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVLength.Rsp(Length=12)
2022-12-07 15:58:06.705 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVWrite.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=78, Offset=0, Value=b'\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-12-07 15:58:06.776 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.NVWrite.Rsp(Status=<Status.SUCCESS: 0>)
2022-12-07 15:58:06.778 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.ADDRMGR: 1>, SubId=79)
2022-12-07 15:58:06.800 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.ResetReq.Req(Type=<ResetType.Soft: 1>)
2022-12-07 15:58:06.800 DEBUG (MainThread) [zigpy_znp.api] Request has no response, not waiting for one.
2022-12-07 15:58:06.801 DEBUG (MainThread) [zigpy_znp.uart] Closing serial port
tube0013 commented 1 year ago

so all is going well, then the serial connections drops.

are you comfortable running some python command line tools?

if so can you try https://github.com/zigpy/zigpy-cli

I'd run a reset, followed by a form, and then an energy scan and see if those commands work.

zigpy radio znp socket://10.9.3.51:6638 reset
zigpy radio znp socket://10.9.3.51:6638 form
zigpy radio znp socket://10.9.3.51:6638 energy-scan
joeypiccola commented 1 year ago

Works.

~/Documents 
➜ zigpy radio znp socket://10.0.3.51:6638 reset

~/Documents took 5s 
➜ zigpy radio znp socket://10.0.3.51:6638 form 

~/Documents took 1m 31s 
➜ zigpy radio znp socket://10.0.3.51:6638 energy-scan
Channel energy (mean of 1 / 5):
------------------------------------------------
 + Lower energy is better
 + Active Zigbee networks on a channel may still cause congestion
 + TX on 26 in North America may be with lower power due to regulations
 + Zigbee channels 15, 20, 25 fall between WiFi channels 1, 6, 11
 + Some Zigbee devices only join networks on channels 15, 20, and 25
 + Current channel is enclosed in [square brackets]
------------------------------------------------
 -  11      35.69%  ###################################
 -  12       3.92%  ###
 -  13       2.75%  ##
 -  14       9.80%  #########
 - [15 ]    29.80%  #############################
 -  16      15.69%  ###############
 -  17      11.37%  ###########
 -  18      14.12%  ##############
 -  19      20.00%  ####################
 -  20      22.75%  ######################
 -  21      16.86%  ################
 -  22      48.24%  ################################################
 -  23      45.49%  #############################################
 -  24      31.37%  ###############################
 -  25       3.92%  ###
 -  26*     29.80%  #############################

Channel energy (mean of 2 / 5):
------------------------------------------------
 + Lower energy is better
 + Active Zigbee networks on a channel may still cause congestion
 + TX on 26 in North America may be with lower power due to regulations
 + Zigbee channels 15, 20, 25 fall between WiFi channels 1, 6, 11
 + Some Zigbee devices only join networks on channels 15, 20, and 25
 + Current channel is enclosed in [square brackets]
------------------------------------------------
 -  11      19.22%  ###################
 -  12       5.49%  #####
 -  13       2.75%  ##
 -  14      12.75%  ############
 - [15 ]    30.59%  ##############################
 -  16      16.27%  ################
 -  17       7.06%  #######
 -  18      19.02%  ###################
 -  19      19.22%  ###################
 -  20      21.37%  #####################
 -  21      24.12%  ########################
 -  22      48.24%  ################################################
 -  23      45.49%  #############################################
 -  24      18.43%  ##################
 -  25       2.55%  ##
 -  26*     19.02%  ###################

Channel energy (mean of 3 / 5):
------------------------------------------------
 + Lower energy is better
 + Active Zigbee networks on a channel may still cause congestion
 + TX on 26 in North America may be with lower power due to regulations
 + Zigbee channels 15, 20, 25 fall between WiFi channels 1, 6, 11
 + Some Zigbee devices only join networks on channels 15, 20, and 25
 + Current channel is enclosed in [square brackets]
------------------------------------------------
 -  11      13.73%  #############
 -  12       3.66%  ###
 -  13       3.14%  ###
 -  14      12.68%  ############
 - [15 ]    29.41%  #############################
 -  16      13.20%  #############
 -  17       8.50%  ########
 -  18      20.65%  ####################
 -  19      19.48%  ###################
 -  20      16.08%  ################
 -  21      21.31%  #####################
 -  22      49.28%  #################################################
 -  23      45.49%  #############################################
 -  24      13.59%  #############
 -  25       1.70%  #
 -  26*     22.61%  ######################

Channel energy (mean of 4 / 5):
------------------------------------------------
 + Lower energy is better
 + Active Zigbee networks on a channel may still cause congestion
 + TX on 26 in North America may be with lower power due to regulations
 + Zigbee channels 15, 20, 25 fall between WiFi channels 1, 6, 11
 + Some Zigbee devices only join networks on channels 15, 20, and 25
 + Current channel is enclosed in [square brackets]
------------------------------------------------
 -  11      10.59%  ##########
 -  12       4.51%  ####
 -  13       2.35%  ##
 -  14       9.51%  #########
 - [15 ]    26.67%  ##########################
 -  16      11.96%  ###########
 -  17       8.82%  ########
 -  18      21.47%  #####################
 -  19      18.14%  ##################
 -  20      17.35%  #################
 -  21      21.27%  #####################
 -  22      48.73%  ################################################
 -  23      45.49%  #############################################
 -  24      18.33%  ##################
 -  25       2.65%  ##
 -  26*     18.73%  ##################

Channel energy (mean of 5 / 5):
------------------------------------------------
 + Lower energy is better
 + Active Zigbee networks on a channel may still cause congestion
 + TX on 26 in North America may be with lower power due to regulations
 + Zigbee channels 15, 20, 25 fall between WiFi channels 1, 6, 11
 + Some Zigbee devices only join networks on channels 15, 20, and 25
 + Current channel is enclosed in [square brackets]
------------------------------------------------
 -  11       8.71%  ########
 -  12       5.02%  #####
 -  13       2.43%  ##
 -  14       8.71%  ########
 - [15 ]    25.02%  #########################
 -  16      12.71%  ############
 -  17       8.16%  ########
 -  18      21.96%  #####################
 -  19      18.51%  ##################
 -  20      17.88%  #################
 -  21      20.39%  ####################
 -  22      48.63%  ################################################
 -  23      45.18%  #############################################
 -  24      21.18%  #####################
 -  25       2.35%  ##
 -  26*     20.39%  ####################
 - ^C
Aborted!
tube0013 commented 1 year ago

oh - for the first 2, use the -vv switch for some feedback (it will look similar the ha logs)

zigpy -vv radio znp socket://10.9.3.51:6638 reset
zigpy -vv radio znp socket://10.9.3.51:6638 form
zigpy radio znp socket://10.9.3.51:6638 energy-scan
tube0013 commented 1 year ago

^ ignore this then.

tube0013 commented 1 year ago

Works.

let the scan run for a bit 10-20 minutes, it will run until stopped with control-c. goal is to just see if there are any disconnects in a short test.

joeypiccola commented 1 year ago

let the scan run for a bit 10-20 minutes

Understood, running now.

joeypiccola commented 1 year ago

Is it of concern that both of these integrations show up in HA? Should I ignore the ESPHome one, I have no use for it?

image

tube0013 commented 1 year ago

Nope. The ethernet/Serial Streamer runs on esphome, if you add it you will get a sensor showing serial connection status. the ZHA one is auto discovery for the ZHA.

joeypiccola commented 1 year ago

let the scan run for a bit 10-20 minutes, it will run until stopped with control-c. goal is to just see if there are any disconnects in a short test.

Ok, ran uninterrupted for 15 minutes. Thanks for the help.

tube0013 commented 1 year ago

okay. all this is good. as it shows device is working as expected.

you can kill the scan.

I saw in the log it was restoring a backup - is this the case?

joeypiccola commented 1 year ago

I saw in the log it was restoring a backup - is this the case?

Not to my knowledge, when setting it up the only setting I have selected have been "Keep radio network settings" and "Erase network settings and form a new network".

tube0013 commented 1 year ago

okay, well there is a networked now formed on the coordinator from the testing (the form command), so you should be able to add zha now and pick keep radio settings.

give that a try and hopefully the setup goes through

joeypiccola commented 1 year ago

Well, before I read your last comment I wanted to try the following.

My HA instance is accessed via a reverse proxy (specifically HAProxy). To remove any issues with that I accessed my HA instance via the direct URL (e.g. http://10.0.3.111:8123/). I went through the configure routine (selecting "Erase network settings and form a new network") and it worked.

I will need to move the coordinator back to the IoT VLAN. Later this evening I will remove the integration, move the coordinator back to the IoT VLAN, and attempt setup again via a direct URL to my HA instance.

I'm not sure why doing the configuration of the coordinator via my proxy address, https://ha.mydomain.com/, causes issues.

tube0013 commented 1 year ago

hmm. yeah.

so when you move it, all you need to do is do a migrate > re-configure current radio and then change the address.

joeypiccola commented 1 year ago

Moved to the new VLAN\IP address. Still works. Thank you for all the help.

tube0013 commented 1 year ago

Great. I wonder if it got into a funky state on the initial attempts and the testing- reset etc helped clear things out.

Sleashe commented 1 year ago

I confirm I had the same issue. Accessing HA from a reverse proxy ends to an issue when adding TubeZB via auto or manual integration. Accessing HA from IP resolved everything, no matter the VLAN.

I didn't take to read ZHA code, but I think TubeZB logic and HA are communicating their backlinks to each other when starting association process.

In my case, pfSense was not allowing IOT devices (Where TubeZB is) to access my reverse proxy instance. That's why integration was failing.

Aephir commented 1 year ago

Not to poke a dead horse, but I came upon this issue in my troubleshooting, so in case others have the same issue as me:

Nothing worked, regardless of VLAN, local IP vs. NGINX-served FQDN, and nothing found with zigpy-cli seemed out of the ordinary.

The only thing that made a difference was killing my deCONZ docker container and disabling the deCONZ integration in HA. Then after a HA restart, I could integrate the CC2652P2 PoE Coordinator with ZHA with absolutely no issues.