search

zigpy / zigpy-znp

TI CC2531, CC13x2, CC26x2 radio support for Zigpy and ZHA
GNU General Public License v3.0
148 stars 40 forks source link

CC2538 being seen as CC2531 and most of the time offline in Home Assistant #72

Closed glcos closed 3 years ago

glcos commented 3 years ago

CC2538 module is being seen as CC2531 in Home Assistant and is most of the time showed as offline even though is seems to work fine. This is what I see in Home Assistant log:

2021-05-22 21:15:46 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x0000](CC2531, Z-Stack 3.0.1/3.0.2): Attempting to checkin with device - missed checkins: 1
2021-05-22 21:15:46 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x0000](CC2531, Z-Stack 3.0.1/3.0.2): does not have a mandatory basic cluster
2021-05-22 21:17:04 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x0000](CC2531, Z-Stack 3.0.1/3.0.2): Attempting to checkin with device - missed checkins: 2
2021-05-22 21:17:04 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x0000](CC2531, Z-Stack 3.0.1/3.0.2): does not have a mandatory basic cluster

zigpy-znp version 0.5.1

MattWestb commented 3 years ago

ZHA/zigpy and the radio libs is not knowing the "real ID" of the device only the "family" used by the Zigbee stack protocol. Its the same for deCONZ is not knowing if its one RapBee I or one ConBee II that the system is "talking" with only that is using the protocol "deCONZ".

I think all radios is virtual devices and is not behaving as normal one and is only updating its online status with some hours interval so if looking in last seen they can being off line most of the time. I have reading that doing o re scan of network topography is making the last seen and is making it being flagged on line. Some user have setting the scan interval very short for going around the offline problem.

puddly commented 3 years ago

The name issue is cosmetic but I will see if I can find a way to distinguish the CC2538 from the CC2531 in the next release. Z-Stack doesn't actually provide any way to query device or really any stack information and I don't have a CC2538 to test with but if you want to help out, can you enable ZHA debug logging and post all of the lines containing zigpy_znp from your home-assistant.log file? Your randomly-generated network key will be in the log in a few places so you can redact it if you want.

As for the "offline" status, I noticed this when testing with a Silicon Labs coordinator as well. Seems like just a frontend glitch, as zigpy-znp would be logging tons of errors if the coordinator was ever "offline"". @dmulcahey, is there anything special the coordinator Device object needs to have other than a node descriptor for ZHA to always show it as online? Maybe set device.last_seen = time.time() after successful requests? Or give it that missing Basic cluster, which would allow ZHA to poll it periodically?

glcos commented 3 years ago

This is what I could capture from the log, hope it helps.

2021-05-22 22:49:11 DEBUG (MainThread) [zigpy_znp.uart] Connecting to /dev/ttyAMA0 at 115200 baud
2021-05-22 22:49:11 DEBUG (MainThread) [zigpy_znp.uart] Opened /dev/ttyAMA0 serial port
2021-05-22 22:49:11 DEBUG (MainThread) [zigpy_znp.uart] Toggling RTS/CTS to skip CC2652R bootloader
2021-05-22 22:49:12 DEBUG (MainThread) [zigpy_znp.uart] Connected to /dev/ttyAMA0 at 115200 baud
2021-05-22 22:49:12 DEBUG (MainThread) [zigpy_znp.api] Waiting 1s before sending anything
2021-05-22 22:49:13 DEBUG (MainThread) [zigpy_znp.api] Sending bootloader skip byte
2021-05-22 22:49:13 DEBUG (MainThread) [zigpy_znp.api] Waiting 1s or until a reset indication is received
2021-05-22 22:49:14 DEBUG (MainThread) [zigpy_znp.api] Testing connection to /dev/ttyAMA0
2021-05-22 22:49:14 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Ping.Req()
2021-05-22 22:49:14 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.Ping.Rsp(Capabilities=<MTCapabilities.CAP_APP_CNF|CAP_GP|CAP_APP|CAP_UTIL|CAP_SAPI|CAP_ZDO|CAP_AF|CAP_SYS: 1913>)
2021-05-22 22:49:14 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.TCLK_TABLE: 4>, SubId=0)
2021-05-22 22:49:14 DEBUG (MainThread) [zigpy_znp.api] Received command: RPCError.CommandNotRecognized.Rsp(ErrorCode=<ErrorCode.InvalidCommandId: 2>, RequestHeader=CommandHeader(id=0x32, subsystem=Subsystem.SYS, type=CommandType.SREQ))
2021-05-22 22:49:14 DEBUG (MainThread) [zigpy_znp.api] Detected Z-Stack 3.0
2021-05-22 22:49:14 DEBUG (MainThread) [zigpy_znp.api] Connected to /dev/ttyAMA0 at 115200 baud
2021-05-22 22:49:14 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.HAS_CONFIGURED_ZSTACK3: 96>)
2021-05-22 22:49:14 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2021-05-22 22:49:14 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.HAS_CONFIGURED_ZSTACK3: 96>, Offset=0)
2021-05-22 22:49:14 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x55')
2021-05-22 22:49:14 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.ResetReq.Req(Type=<ResetType.Soft: 1>)
2021-05-22 22:49:14 DEBUG (MainThread) [zigpy_znp.api] Request has no response, not waiting for one.
2021-05-22 22:49:15 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.ResetInd.Callback(Reason=<ResetReason.PowerUp: 0>, TransportRev=2, ProductId=2, MajorRel=2, MinorRel=7, MaintRel=2)
2021-05-22 22:49:15 INFO (MainThread) [zigpy_znp.zigbee.application] ZNP is already configured, not forming a new network
2021-05-22 22:49:15 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.LOGICAL_TYPE: 135>)
2021-05-22 22:49:15 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2021-05-22 22:49:15 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.LOGICAL_TYPE: 135>, Offset=0)
2021-05-22 22:49:15 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x00')
2021-05-22 22:49:15 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.CONCENTRATOR_ENABLE: 50>)
2021-05-22 22:49:15 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2021-05-22 22:49:15 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.CONCENTRATOR_ENABLE: 50>, Offset=0)
2021-05-22 22:49:15 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x01')
2021-05-22 22:49:15 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.CONCENTRATOR_DISCOVERY: 51>)
2021-05-22 22:49:15 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2021-05-22 22:49:15 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.CONCENTRATOR_DISCOVERY: 51>, Offset=0)
2021-05-22 22:49:15 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x78')
2021-05-22 22:49:15 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.CONCENTRATOR_RC: 54>)
2021-05-22 22:49:15 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2021-05-22 22:49:15 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.CONCENTRATOR_RC: 54>, Offset=0)
2021-05-22 22:49:15 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x01')
2021-05-22 22:49:15 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.SRC_RTG_EXPIRY_TIME: 56>)
2021-05-22 22:49:15 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2021-05-22 22:49:15 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.SRC_RTG_EXPIRY_TIME: 56>, Offset=0)
2021-05-22 22:49:15 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\xFF')
2021-05-22 22:49:15 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.NWK_CHILD_AGE_ENABLE: 62>)
2021-05-22 22:49:15 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2021-05-22 22:49:15 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.NWK_CHILD_AGE_ENABLE: 62>, Offset=0)
2021-05-22 22:49:15 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x00')
2021-05-22 22:49:15 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.BCAST_DELIVERY_TIME: 48>)
2021-05-22 22:49:15 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2021-05-22 22:49:15 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.BCAST_DELIVERY_TIME: 48>, Offset=0)
2021-05-22 22:49:15 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x1E')
2021-05-22 22:49:15 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.ZDO_DIRECT_CB: 143>)
2021-05-22 22:49:15 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2021-05-22 22:49:15 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.ZDO_DIRECT_CB: 143>, Offset=0)
2021-05-22 22:49:15 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x01')
2021-05-22 22:49:15 DEBUG (MainThread) [zigpy_znp.api] Sending request: AppConfig.BDBStartCommissioning.Req(Mode=<BDBCommissioningMode.NwkFormation: 4>)
2021-05-22 22:49:16 DEBUG (MainThread) [zigpy_znp.api] Received command: AppConfig.BDBStartCommissioning.Rsp(Status=<Status.SUCCESS: 0>)
2021-05-22 22:49:16 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.StateChangeInd.Callback(State=<DeviceState.StartedAsCoordinator: 9>)
2021-05-22 22:49:16 DEBUG (MainThread) [zigpy_znp.api] Received command: AppConfig.BDBCommissioningNotification.Callback(Status=<BDBCommissioningStatus.NetworkRestored: 13>, Mode=<BDBCommissioningMode.NONE: 0>, RemainingModes=<BDBCommissioningMode.NwkFormation: 4>)
2021-05-22 22:49:17 DEBUG (MainThread) [zigpy_znp.api] Received command: AppConfig.BDBCommissioningNotification.Callback(Status=<BDBCommissioningStatus.FormationFailure: 8>, Mode=<BDBCommissioningMode.NwkSteering: 2>, RemainingModes=<BDBCommissioningMode.NONE: 0>)
2021-05-22 22:49:17 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.MgmtPermitJoinReq.Req(AddrMode=<AddrMode.NWK: 2>, Dst=0x0000, Duration=0, TCSignificance=1)
2021-05-22 22:49:17 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MgmtPermitJoinReq.Rsp(Status=<Status.SUCCESS: 0>)
2021-05-22 22:49:17 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MgmtPermitJoinRsp.Callback(Src=0x0000, Status=<Status.SUCCESS: 0>)
2021-05-22 22:49:17 DEBUG (MainThread) [zigpy_znp.zigbee.application] Intercepted a ZDO request: dst_addr=AddrModeAddress(mode=<AddrMode.Broadcast: 15>, address=0xFFFC), dst_ep=0, src_ep=0, cluster=54, sequence=1, options=TransmitOptions.NONE, radius=0, data=b'\x01\x00\x00'
2021-05-22 22:49:17 DEBUG (MainThread) [zigpy_znp.zigbee.application] Intercepted AP ZDO request 54({'PermitDuration': 0, 'TC_Significant': <Bool.false: 0>}) and replaced with ZDO.MgmtPermitJoinReq.Req(AddrMode=<AddrMode.Broadcast: 15>, Dst=0xFFFC, Duration=0, TCSignificance=0)
2021-05-22 22:49:17 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.MgmtPermitJoinReq.Req(AddrMode=<AddrMode.Broadcast: 15>, Dst=0xFFFC, Duration=0, TCSignificance=0)
2021-05-22 22:49:17 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MgmtPermitJoinReq.Rsp(Status=<Status.SUCCESS: 0>)
2021-05-22 22:49:17 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MgmtPermitJoinRsp.Callback(Src=0x0000, Status=<Status.SUCCESS: 0>)
2021-05-22 22:49:17 DEBUG (MainThread) [zigpy_znp.api] Sending request: Util.LEDControl.Req(LED=255, Mode=<LEDMode.OFF: 0>)
2021-05-22 22:49:17 DEBUG (MainThread) [zigpy_znp.api] Received command: Util.LEDControl.Rsp(Status=<Status.SUCCESS: 0>)
2021-05-22 22:49:17 DEBUG (MainThread) [zigpy_znp.api] Sending request: Util.GetDeviceInfo.Req()
2021-05-22 22:49:17 DEBUG (MainThread) [zigpy_znp.api] Received command: Util.GetDeviceInfo.Rsp(Status=<Status.SUCCESS: 0>, IEEE=00:12:4b:00:04:1e:70:a0, NWK=0x0000, DeviceType=<DeviceTypeCapabilities.EndDevice|Router|Coordinator: 7>, DeviceState=<DeviceState.StartedAsCoordinator: 9>, AssociatedDevices=[0x3044])
2021-05-22 22:49:17 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.NodeDescReq.Req(DstAddr=0x0000, NWKAddrOfInterest=0x0000)
2021-05-22 22:49:17 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.NodeDescReq.Rsp(Status=<Status.SUCCESS: 0>)
2021-05-22 22:49:17 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.NodeDescRsp.Callback(Src=0x0000, Status=<Status.SUCCESS: 0>, NWK=0x0000, NodeDescriptor=NullableNodeDescriptor(byte1=0, byte2=64, mac_capability_flags=143, manufacturer_code=0, maximum_buffer_size=80, maximum_incoming_transfer_size=160, server_mask=1, maximum_outgoing_transfer_size=160, descriptor_capability_field=0, *allocate_address=True, *complex_descriptor_available=False, *is_alternate_pan_coordinator=True, *is_coordinator=True, *is_end_device=False, *is_full_function_device=True, *is_mains_powered=True, *is_receiver_on_when_idle=True, *is_router=False, *is_security_capable=False, *is_valid=True, *logical_type=<LogicalType.Coordinator: 0>, *user_descriptor_available=False))
2021-05-22 22:49:17 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.Register.Req(Endpoint=1, ProfileId=260, DeviceId=1024, DeviceVersion=0, LatencyReq=<LatencyReq.NoLatencyReqs: 0>, InputClusters=[25], OutputClusters=[1280, 1282])
2021-05-22 22:49:17 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.Register.Rsp(Status=<Status.SUCCESS: 0>)
2021-05-22 22:49:17 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.Register.Req(Endpoint=2, ProfileId=49246, DeviceId=2080, DeviceVersion=0, LatencyReq=<LatencyReq.NoLatencyReqs: 0>, InputClusters=[], OutputClusters=[])
2021-05-22 22:49:17 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.Register.Rsp(Status=<Status.SUCCESS: 0>)
2021-05-22 22:49:17 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.NIB: 33>)
2021-05-22 22:49:17 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=116)
2021-05-22 22:49:17 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.NIB: 33>, Offset=0)
2021-05-22 22:49:17 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x59\x05\x02\x51\x14\x51\x00\x64\x00\x00\x00\x01\x05\x01\x8F\x00\x07\x00\x02\x0D\x1E\x00\x00\x00\x0B\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x62\x1A\x08\x00\x00\x08\x00\x00\x0F\x0F\x04\x00\x01\x00\x00\x00\x01\x00\x00\x00\x00\xA0\x70\x1E\x04\x00\x4B\x12\x00\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x3C\x0C\x00\x01\x78\x0A\x01\x00\x00\x00\xB9\x01\x00\x00')
2021-05-22 22:49:17 DEBUG (MainThread) [zigpy_znp.zigbee.application] Parsed NIB: NIB(SequenceNum=89, PassiveAckTimeout=5, MaxBroadcastRetries=2, MaxChildren=81, MaxDepth=20, MaxRouters=81, dummyNeighborTable=0, BroadcastDeliveryTime=100, ReportConstantCost=0, RouteDiscRetries=0, dummyRoutingTable=0, SecureAllFrames=1, SecurityLevel=5, SymLink=1, CapabilityFlags=143, PaddingByte0=b'\x00', TransactionPersistenceTime=7, nwkProtocolVersion=2, RouteDiscoveryTime=13, RouteExpiryTime=30, PaddingByte1=b'\x00', nwkDevAddress=0x0000, nwkLogicalChannel=11, PaddingByte2=b'\x00', nwkCoordAddress=0x0000, nwkCoordExtAddress=00:00:00:00:00:00:00:00, nwkPanId=6754, nwkState=<NwkState16.NWK_ROUTER: 8>, channelList=<Channels.CHANNEL_11: 2048>, beaconOrder=15, superFrameOrder=15, scanDuration=4, battLifeExt=0, allocatedRouterAddresses=1, allocatedEndDeviceAddresses=1, nodeDepth=0, extendedPANID=00:12:4b:00:04:1e:70:a0, nwkKeyLoaded=<Bool.true: 1>, spare1=NwkKeyDesc(KeySeqNum=0, Key=[0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]), spare2=NwkKeyDesc(KeySeqNum=0, Key=[0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]), spare3=0, spare4=0, nwkLinkStatusPeriod=60, nwkRouterAgeLimit=12, nwkUseMultiCast=<Bool.false: 0>, nwkIsConcentrator=<Bool.true: 1>, nwkConcentratorDiscoveryTime=120, nwkConcentratorRadius=10, nwkAllFresh=1, PaddingByte3=b'\x00', nwkManagerAddr=0x0000, nwkTotalTransmissions=441, nwkUpdateId=0, PaddingByte4=b'\x00')
2021-05-22 22:49:17 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.NWKKEY: 130>)
2021-05-22 22:49:17 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=24)
2021-05-22 22:49:17 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.NWKKEY: 130>, Offset=0)
2021-05-22 22:49:17 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x00\x01\x03\x05\x07\x09\x0B\x0D\x0F\x00\x02\x04\x06\x08\x0A\x0C\x0D\x02\x00\x20\xD3\xDE\x00\x00')
2021-05-22 22:49:17 DEBUG (MainThread) [zigpy_znp.zigbee.application] Parsed key info: NwkActiveKeyItemsCC2531(Active=NwkKeyDesc(KeySeqNum=0, Key=[1, 3, 5, 7, 9, 11, 13, 15, 0, 2, 4, 6, 8, 10, 12, 13]), FrameCounter=3542089730)
2021-05-22 22:49:17 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Version.Req()
2021-05-22 22:49:17 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.Version.Rsp(TransportRev=2, ProductId=2, MajorRel=2, MinorRel=7, MaintRel=2, CodeRevision=20201010, BootloaderBuildType=<BootloaderBuildType.BUILT_AS_HEX: 2>, BootloaderRevision=4294967295)
2021-05-22 22:49:17 INFO (MainThread) [zigpy_znp.zigbee.application] Network settings
2021-05-22 22:49:17 INFO (MainThread) [zigpy_znp.zigbee.application]   Z-Stack version: 3.0
2021-05-22 22:49:17 INFO (MainThread) [zigpy_znp.zigbee.application]   Z-Stack build id: 20201010
2021-05-22 22:49:17 INFO (MainThread) [zigpy_znp.zigbee.application]   Max concurrent requests: 16
2021-05-22 22:49:17 INFO (MainThread) [zigpy_znp.zigbee.application]   Channel: 11
2021-05-22 22:49:17 INFO (MainThread) [zigpy_znp.zigbee.application]   PAN ID: 0x1a62
2021-05-22 22:49:17 INFO (MainThread) [zigpy_znp.zigbee.application]   Extended PAN ID: 00:12:4b:00:04:1e:70:a0
2021-05-22 22:49:17 DEBUG (MainThread) [zigpy_znp.zigbee.application]   Network key: 01:03:05:07:09:0b:0d:0f:00:02:04:06:08:0a:0c:0d
2021-05-22 22:49:17 DEBUG (MainThread) [zigpy_znp.zigbee.application] Starting watchdog loop
2021-05-22 22:49:17 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0xF18D), DstEndpoint=8, DstPanId=0x0000, SrcEndpoint=1, ClusterId=6, TSN=2, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=30, Data=b'\x00\x02\x00\x00\x00')
2021-05-22 22:49:17 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2021-05-22 22:49:17 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x8024), DstEndpoint=8, DstPanId=0x0000, SrcEndpoint=1, ClusterId=6, TSN=3, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=30, Data=b'\x00\x03\x00\x00\x00')
2021-05-22 22:49:18 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2021-05-22 22:49:18 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.SUCCESS: 0>, Endpoint=1, TSN=3)
2021-05-22 22:49:18 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.IncomingMsg.Callback(GroupId=0x0000, ClusterId=6, SrcAddr=0x8024, SrcEndpoint=8, DstEndpoint=1, WasBroadcast=<Bool.false: 0>, LQI=0, SecurityUse=<Bool.false: 0>, TimeStamp=13062, TSN=0, Data=b'\x18\x03\x01\x00\x00\x00\x10\x01', MacSrcAddr=0x8024, MsgResultRadius=29)
2021-05-22 22:49:18 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.NWK_NO_ROUTE: 205>, Endpoint=1, TSN=2)
2021-05-22 22:49:18 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.NWK_NO_ROUTE: 205>), retry attempt 1 of 5
2021-05-22 22:49:20 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0xF18D), DstEndpoint=8, DstPanId=0x0000, SrcEndpoint=1, ClusterId=6, TSN=2, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=30, Data=b'\x00\x02\x00\x00\x00')
2021-05-22 22:49:20 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2021-05-22 22:49:20 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.NWK_NO_ROUTE: 205>, Endpoint=1, TSN=2)
2021-05-22 22:49:20 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.NWK_NO_ROUTE: 205>), retry attempt 2 of 5
2021-05-22 22:49:20 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0xF18D), DstEndpoint=8, DstPanId=0x0000, SrcEndpoint=1, ClusterId=6, TSN=2, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=30, Data=b'\x00\x02\x00\x00\x00')
2021-05-22 22:49:21 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2021-05-22 22:49:21 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.NWK_NO_ROUTE: 205>, Endpoint=1, TSN=2)
2021-05-22 22:49:21 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.NWK_NO_ROUTE: 205>), retry attempt 3 of 5
2021-05-22 22:49:22 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0xF18D), DstEndpoint=8, DstPanId=0x0000, SrcEndpoint=1, ClusterId=6, TSN=2, Options=<TransmitOptions.ACK_REQUEST: 16>, Radius=30, Data=b'\x00\x02\x00\x00\x00')
2021-05-22 22:49:22 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2021-05-22 22:49:23 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.NWK_NO_ROUTE: 205>, Endpoint=1, TSN=2)
2021-05-22 22:49:23 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.NWK_NO_ROUTE: 205>), retry attempt 4 of 5
2021-05-22 22:49:23 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestSrcRtg.Req(DstAddr=0xF18D, DstEndpoint=8, SrcEndpoint=1, ClusterId=6, TSN=2, Options=<TransmitOptions.ACK_REQUEST: 16>, Radius=30, SourceRoute=[], Data=b'\x00\x02\x00\x00\x00')
2021-05-22 22:49:23 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestSrcRtg.Rsp(Status=<Status.SUCCESS: 0>)
2021-05-22 22:49:23 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=2)
2021-05-22 22:49:23 DEBUG (MainThread) [zigpy_znp.zigbee.application] Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 5 of 5
glcos commented 3 years ago

Upgraded application.py file to latest version and now the coordinator is showing CC2538, Great job! Can't wait for the latest release.

glcos commented 3 years ago

I've been monitoring my system for a while, it's working fine, however I still see this warning:

2021-06-08 07:52:53 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x0000](CC2538, Z-Stack 3.0.x (build 20201010)): Attempting to checkin with device - missed checkins: 1
2021-06-08 07:52:53 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x0000](CC2538, Z-Stack 3.0.x (build 20201010)): does not have a mandatory basic cluster
2021-06-08 07:54:08 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x0000](CC2538, Z-Stack 3.0.x (build 20201010)): Attempting to checkin with device - missed checkins: 2
2021-06-08 07:54:08 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x0000](CC2538, Z-Stack 3.0.x (build 20201010)): does not have a mandatory basic cluster

Could it be something related to the firmware I have flashed to the coordinator ?

puddly commented 3 years ago

This is related to the ZHA issue I mentioned earlier, where ZHA is treating the coordinator like a normal device and it attempts to poll it to make sure it's still alive after the coordinator doesn't "check in" for a while. I don't think this is a zigpy-znp problem but a ZHA problem. The coordinator should always show "online" in the UI (or that status should be removed for it).

puddly commented 3 years ago

Fixed by https://github.com/zigpy/zigpy-znp/pull/93.