Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
glcos opened this issue May 22, 2021 · 7 comments · Fixed by #93
Closed

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

glcos opened this issue May 22, 2021 · 7 comments · Fixed by #93

Comments

@glcos
Copy link

glcos commented May 22, 2021

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

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

puddly commented May 22, 2021

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

glcos commented May 22, 2021

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

glcos commented Jun 2, 2021

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

@glcos
Copy link
Author

glcos commented Jun 8, 2021

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

puddly commented Jun 8, 2021

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

puddly commented Oct 30, 2021

Fixed by #93.

@puddly puddly closed this as completed Oct 30, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants