[TC-MF-1.4] Node Behavior using BCM [DUT - Commissionee] First Controller : 12344321 Second Controller : 12345678 ***************** Step 1 ***************** TH_CR1 starts a commissioning process with DUT_CE connect -ble 3840 20202021 12344321 zcl NetworkCommissioning AddWiFiNetwork 12344321 0 0 ssid=str:WIFI_SSID credentials=str:WIFI_PASSWORD breadcrumb=0 timeoutMs=1000 zcl NetworkCommissioning EnableNetwork 12344321 0 0 networkID=str:WIFI_SSID breadcrumb=0 timeoutMs=1000 close-ble get-fabricid resolve 3907795957633267467 12344321 chip-device-ctrl > get-fabricid Get fabric ID complete Raw Fabric ID: 0x0000000000000000 (0) Compressed Fabric ID: 0x363b47b81570370b (3907795957633267467) chip-device-ctrl > resolve 3907795957633267467 12344321 [1634673754.574972][827276:827283] CHIP:DL: Avahi resolve found [1634673754.575175][827276:827283] CHIP:DIS: Node ID resolved for 0x0000000000BC5C01 to [192.168.1.111]:5540 [1634673754.575350][827276:827283] CHIP:CTL: SyncSetKeyValue on PairedDevicebc5c01 Node address has been updated [1634673754.576348][827276:827283] CHIP:CTL: OperationalDiscoveryComplete for device ID 12344321 [1634673754.576400][827276:827283] CHIP:CTL: Enabling CASE session establishment for the device [1634673754.576484][827276:827283] CHIP:CTL: SyncSetKeyValue on PairedDevicebc5c01 [1634673754.576524][827276:827283] CHIP:IN: Marking old secure session for device 0x0000000000BC5C01 as expired [1634673754.576600][827276:827283] CHIP:CTL: SyncSetKeyValue on PairedDevicebc5c01 [1634673754.576637][827276:827283] CHIP:CTL: SyncSetKeyValue on StartKeyID [1634673754.577642][827276:827283] CHIP:IN: Build plaintext message 0xd2dbcf8 to 0x0000000000000000 of type 48 and protocolId 0 on exchange 3343r with MessageCounter 1134922208. [1634673754.577719][827276:827283] CHIP:IN: Sending plaintext msg 0xd2dbcf8 to 0x0000000000000000 at utc time: 93740860 msec [1634673754.577755][827276:827283] CHIP:IN: Sending msg on generic transport [1634673754.577962][827276:827283] CHIP:SC: Sent SigmaR1 msg [1634673755.931574][827276:827283] CHIP:EM: Received message of type 0x31 with vendorId 0x0000 and protocolId 0x0000 on exchange 3343i [1634673755.931685][827276:827283] CHIP:EM: Rxd Ack; Removing MessageCounter:43A589E0 from Retrans Table [1634673755.931715][827276:827283] CHIP:EM: Removed CHIP MessageCounter:43A589E0 from RetransTable [1634673755.931769][827276:827283] CHIP:SC: Received SigmaR2 msg [1634673755.931823][827276:827283] CHIP:SC: Peer assigned session key ID 1 [1634673755.935710][827276:827283] CHIP:SC: Sending SigmaR3 [1634673755.936319][827276:827283] CHIP:EM: Piggybacking Ack for MessageCounter:B7FF56A7 on exchange: 3343i [1634673755.936395][827276:827283] CHIP:IN: Build plaintext message 0xd2dbcf8 to 0x0000000000000000 of type 50 and protocolId 0 on exchange 3343r with MessageCounter 1134922209. [1634673755.936443][827276:827283] CHIP:IN: Sending plaintext msg 0xd2dbcf8 to 0x0000000000000000 at utc time: 93742218 msec [1634673755.936473][827276:827283] CHIP:IN: Sending msg on generic transport [1634673755.936630][827276:827283] CHIP:SC: Sent SigmaR3 msg [1634673755.936676][827276:827283] CHIP:IN: New secure session created for device 0x0000000000BC5C01, key 1!! Commissioning complete Current address: 192.168.1.111:5540 [1634673755.937918][827276:827283] CHIP:CTL: Calling commissioning complete for device ID 12344321 ***************** Step 2a ***************** If (PICS_MF_BCM) TH_CR1 opens a commissioning window on DUT_CE using a commissioning timeout of PIXIT_COMM_WIN seconds using BCM zcl AdministratorCommissioning OpenBasicCommissioningWindow 12344321 0 0 commissioningTimeout=500 chip-device-ctrl > zcl AdministratorCommissioning OpenBasicCommissioningWindow 12344321 0 0 commissioningTimeout=500 [1634673763.422538][827276:827283] CHIP:DMG: ICR moving to [Initialize] [1634673763.422664][827276:827283] CHIP:DMG: ICR moving to [AddCommand] [1634673763.422938][827276:827283] CHIP:IN: Secure message was encrypted: Msg ID 2 [1634673763.423012][827276:827283] CHIP:IN: Build encrypted message 0xd2dbcf8 to 0x0000000000BC5C01 of type 8 and protocolId 1 on exchange 3345r with MessageCounter 2. [1634673763.423100][827276:827283] CHIP:IN: Sending encrypted msg 0xd2dbcf8 to 0x0000000000BC5C01 at utc time: 93749705 msec [1634673763.423163][827276:827283] CHIP:IN: Sending msg on generic transport [1634673763.423425][827276:827283] CHIP:DMG: ICR moving to [ Sending] [1634673764.086474][827276:827283] CHIP:EM: Received message of type 0x09 with vendorId 0x0000 and protocolId 0x0001 on exchange 3345i [1634673764.086655][827276:827283] CHIP:EM: Rxd Ack; Removing MessageCounter:00000002 from Retrans Table [1634673764.086723][827276:827283] CHIP:EM: Removed CHIP MessageCounter:00000002 from RetransTable [1634673764.086852][827276:827283] CHIP:DMG: InvokeCommand = [1634673764.086924][827276:827283] CHIP:DMG: { [1634673764.086981][827276:827283] CHIP:DMG: CommandList = [1634673764.087050][827276:827283] CHIP:DMG: [ [1634673764.087114][827276:827283] CHIP:DMG: CommandDataElement = [1634673764.087193][827276:827283] CHIP:DMG: { [1634673764.087261][827276:827283] CHIP:DMG: CommandPath = [1634673764.087341][827276:827283] CHIP:DMG: { [1634673764.087424][827276:827283] CHIP:DMG: EndpointId = 0x0, [1634673764.087516][827276:827283] CHIP:DMG: ClusterId = 0x3c, [1634673764.087602][827276:827283] CHIP:DMG: CommandId = 0x1, [1634673764.087688][827276:827283] CHIP:DMG: }, [1634673764.087781][827276:827283] CHIP:DMG: [1634673764.087848][827276:827283] CHIP:DMG: StatusElement = [1634673764.087926][827276:827283] CHIP:DMG: { [1634673764.088008][827276:827283] CHIP:DMG: GeneralCode = 0x0, [1634673764.088086][827276:827283] CHIP:DMG: ProtocolId = 0x1, [1634673764.088176][827276:827283] CHIP:DMG: protocolCode = 0x0, [1634673764.088256][827276:827283] CHIP:DMG: }, [1634673764.088333][827276:827283] CHIP:DMG: [1634673764.088397][827276:827283] CHIP:DMG: }, [1634673764.088475][827276:827283] CHIP:DMG: [1634673764.088537][827276:827283] CHIP:DMG: ], [1634673764.088613][827276:827283] CHIP:DMG: [1634673764.088670][827276:827283] CHIP:DMG: } SetCommandIndexStatus commandHandle=1 commandIndex=1 [1634673764.089398][827276:827283] CHIP:ZCL: DefaultResponse: [1634673764.089514][827276:827283] CHIP:ZCL: Transaction: 0xffffb7e75240 [1634673764.089576][827276:827283] CHIP:ZCL: status: EMBER_ZCL_STATUS_SUCCESS (0x00) [1634673764.089635][827276:827283] CHIP:ZCL: IMDefaultResponseCallback: Missing success callback [1634673764.089688][827276:827283] CHIP:ZCL: IMDefaultResponseCallback: Missing failure callback [1634673764.089885][827276:827283] CHIP:DMG: ICR moving to [Uninitiali] Received command status response: [1634673764.089972][827276:827283] CHIP:EM: Sending Standalone Ack for MessageCounter:00000002 [1634673764.090193][827276:827283] CHIP:IN: Secure message was encrypted: Msg ID 3 Container: ProtocolId = 1 ProtocolCode = 0 EndpointId = 0 ClusterId = 60 CommandId = 1 CommandIndex = 1 [1634673764.090268][827276:827283] CHIP:IN: Build encrypted message 0xffffa7ffdad0 to 0x0000000000BC5C01 of type 16 and protocolId 0 on exchange 3345r with MessageCounter 3. [1634673764.090639][827276:827283] CHIP:IN: Sending encrypted msg 0xffffa7ffdad0 to 0x0000000000BC5C01 at utc time: 93750373 msec [1634673764.090712][827276:827283] CHIP:IN: Sending msg on generic transport chip-device-ctrl > [1634673764.091222][827276:827283] CHIP:EM: Flushed pending ack for MessageCounter:00000002 ***************** Step 2b ***************** TH_CR1 writes and reads the Basic Information Cluster’s NodeLabel mandatory attribute of DUT_CE zclwrite Basic UserLabel 12344321 0 0 TE5New zclread Basic UserLabel 12344321 0 0 chip-device-ctrl > zclwrite Basic UserLabel 12344321 0 0 TE5New [1634673773.127799][827276:827283] CHIP:DMG: WriteClient moving to [Initialize] [1634673773.127937][827276:827283] CHIP:DMG: WriteClient moving to [AddAttribu] [1634673773.128232][827276:827283] CHIP:IN: Secure message was encrypted: Msg ID 4 [1634673773.128310][827276:827283] CHIP:IN: Build encrypted message 0xd2dbcf8 to 0x0000000000BC5C01 of type 6 and protocolId 1 on exchange 3346r with MessageCounter 4. [1634673773.128397][827276:827283] CHIP:IN: Sending encrypted msg 0xd2dbcf8 to 0x0000000000BC5C01 at utc time: 93759410 msec [1634673773.128462][827276:827283] CHIP:IN: Sending msg on generic transport [1634673773.128699][827276:827283] CHIP:DMG: WriteClient moving to [AwaitingRe] [1634673773.226984][827276:827283] CHIP:EM: Received message of type 0x07 with vendorId 0x0000 and protocolId 0x0001 on exchange 3346i [1634673773.227137][827276:827283] CHIP:EM: Rxd Ack; Removing MessageCounter:00000004 from Retrans Table [1634673773.227190][827276:827283] CHIP:EM: Removed CHIP MessageCounter:00000004 from RetransTable [1634673773.227292][827276:827283] CHIP:DMG: WriteResponse = [1634673773.227349][827276:827283] CHIP:DMG: { [1634673773.227391][827276:827283] CHIP:DMG: AttributeStatusList = [1634673773.227443][827276:827283] CHIP:DMG: [ [1634673773.227491][827276:827283] CHIP:DMG: AttributeStatusElement = [1634673773.227544][827276:827283] CHIP:DMG: { [1634673773.227595][827276:827283] CHIP:DMG: AttributePath = [1634673773.227672][827276:827283] CHIP:DMG: { [1634673773.227736][827276:827283] CHIP:DMG: FieldTag = 0x5, [1634673773.227961][827276:827283] CHIP:DMG: NodeId = 0xbc5c01, [1634673773.228040][827276:827283] CHIP:DMG: ClusterId = 0x28, [1634673773.228114][827276:827283] CHIP:DMG: EndpointId = 0x0, [1634673773.228182][827276:827283] CHIP:DMG: } [1634673773.228251][827276:827283] CHIP:DMG: [1634673773.228312][827276:827283] CHIP:DMG: StatusElement = [1634673773.228381][827276:827283] CHIP:DMG: { [1634673773.228438][827276:827283] CHIP:DMG: GeneralCode = 0x0, [1634673773.228510][827276:827283] CHIP:DMG: ProtocolId = 0x0, [1634673773.228581][827276:827283] CHIP:DMG: protocolCode = 0x0, [1634673773.228648][827276:827283] CHIP:DMG: }, [1634673773.228709][827276:827283] CHIP:DMG: [1634673773.228759][827276:827283] CHIP:DMG: }, [1634673773.228822][827276:827283] CHIP:DMG: [1634673773.228869][827276:827283] CHIP:DMG: ], [1634673773.228927][827276:827283] CHIP:DMG: [1634673773.228972][827276:827283] CHIP:DMG: } [1634673773.229644][827276:827283] CHIP:ZCL: WriteResponse: [1634673773.229688][827276:827283] CHIP:ZCL: status: EMBER_ZCL_STATUS_SUCCESS (0x00) [1634673773.229840][827276:827283] CHIP:DMG: WriteClient moving to [Uninitiali] AttributeWriteResult(path=AttributePath(nodeId=12344321, endpointId=0, clusterId=40, attributeId=5), status=0) [1634673773.229957][827276:827283] CHIP:EM: Sending Standalone Ack for MessageCounter:00000003 [1634673773.230220][827276:827283] CHIP:IN: Secure message was encrypted: Msg ID 5 [1634673773.230266][827276:827283] CHIP:IN: Build encrypted message 0xffffa7ffdad0 to 0x0000000000BC5C01 of type 16 and protocolId 0 on exchange 3346r with MessageCounter 5. [1634673773.230318][827276:827283] CHIP:IN: Sending encrypted msg 0xffffa7ffdad0 to 0x0000000000BC5C01 at utc time: 93759512 msec [1634673773.230346][827276:827283] CHIP:IN: Sending msg on generic transport chip-device-ctrl > [1634673773.230535][827276:827283] CHIP:EM: Flushed pending ack for MessageCounter:00000003 chip-device-ctrl > chip-device-ctrl > chip-device-ctrl > zclread Basic UserLabel 12344321 0 0 [1634673777.859251][827276:827283] CHIP:DMG: SendReadRequest: Client[0] [ INIT] [1634673777.859602][827276:827283] CHIP:IN: Secure message was encrypted: Msg ID 6 [1634673777.859682][827276:827283] CHIP:IN: Build encrypted message 0xd2dbcf8 to 0x0000000000BC5C01 of type 2 and protocolId 1 on exchange 3347r with MessageCounter 6. [1634673777.859768][827276:827283] CHIP:IN: Sending encrypted msg 0xd2dbcf8 to 0x0000000000BC5C01 at utc time: 93764142 msec [1634673777.859833][827276:827283] CHIP:IN: Sending msg on generic transport [1634673777.860080][827276:827283] CHIP:DMG: Client[0] moving to [AwaitingInitialReport] [1634673778.174340][827276:827283] CHIP:EM: Received message of type 0x05 with vendorId 0x0000 and protocolId 0x0001 on exchange 3347i [1634673778.174521][827276:827283] CHIP:EM: Rxd Ack; Removing MessageCounter:00000006 from Retrans Table [1634673778.174590][827276:827283] CHIP:EM: Removed CHIP MessageCounter:00000006 from RetransTable [1634673778.174716][827276:827283] CHIP:DMG: ReportData = [1634673778.174790][827276:827283] CHIP:DMG: { [1634673778.174847][827276:827283] CHIP:DMG: AttributeDataList = [1634673778.174916][827276:827283] CHIP:DMG: [ [1634673778.174978][827276:827283] CHIP:DMG: AttributeDataElement = [1634673778.175068][827276:827283] CHIP:DMG: { [1634673778.175136][827276:827283] CHIP:DMG: AttributePath = [1634673778.175217][827276:827283] CHIP:DMG: { [1634673778.175302][827276:827283] CHIP:DMG: NodeId = 0xbc5c01, [1634673778.175390][827276:827283] CHIP:DMG: EndpointId = 0x0, [1634673778.175477][827276:827283] CHIP:DMG: ClusterId = 0x28, [1634673778.175561][827276:827283] CHIP:DMG: FieldTag = 0x5, [1634673778.175642][827276:827283] CHIP:DMG: } [1634673778.175730][827276:827283] CHIP:DMG: [1634673778.175828][827276:827283] CHIP:DMG: Data = "TE5New", [1634673778.175916][827276:827283] CHIP:DMG: DataElementVersion = 0x0, [1634673778.175999][827276:827283] CHIP:DMG: }, [1634673778.176082][827276:827283] CHIP:DMG: [1634673778.176145][827276:827283] CHIP:DMG: ], [1634673778.176222][827276:827283] CHIP:DMG: [1634673778.176281][827276:827283] CHIP:DMG: } [1634673778.177936][827276:827283] CHIP:ZCL: ReadAttributesResponse: [1634673778.178028][827276:827283] CHIP:ZCL: ClusterId: 0x0000_0028 [1634673778.178102][827276:827283] CHIP:ZCL: attributeId: 0x0000_0005 [1634673778.178162][827276:827283] CHIP:ZCL: status: Success (0x0000) [1634673778.178221][827276:827283] CHIP:ZCL: attribute TLV Type: 0x0c [1634673778.178323][827276:827283] CHIP:ZCL: attributeValue: (span of length 6) 84 69 53 78 101 119 [1634673778.178927][827276:827283] CHIP:EM: Piggybacking Ack for MessageCounter:00000004 on exchange: 3347i [1634673778.179138][827276:827283] CHIP:IN: Secure message was encrypted: Msg ID 7 [1634673778.179214][827276:827283] CHIP:IN: Build encrypted message 0xd2dbcf8 to 0x0000000000BC5C01 of type 1 and protocolId 1 on exchange 3347r with MessageCounter 7. [1634673778.179306][827276:827283] CHIP:IN: Sending encrypted msg 0xd2dbcf8 to 0x0000000000BC5C01 at utc time: 93764461 msec [1634673778.179371][827276:827283] CHIP:IN: Sending msg on generic transport [1634673778.179670][827276:827283] CHIP:DMG: Client[0] moving to [UNINIT] AttributeReadResult(path=AttributePath(nodeId=12344321, endpointId=0, clusterId=40, attributeId=5), status=0, value='TE5New') chip-device-ctrl > chip-device-ctrl > [1634673778.246070][827276:827283] CHIP:EM: Received message of type 0x10 with vendorId 0x0000 and protocolId 0x0000 on exchange 3347i [1634673778.246241][827276:827283] CHIP:EM: Rxd Ack; Removing MessageCounter:00000007 from Retrans Table [1634673778.246306][827276:827283] CHIP:EM: Removed CHIP MessageCounter:00000007 from RetransTable ***************** Step 3 ***************** TH_CR2 starts a commissioning process with DUT_CE connect -ip 192.168.1.111 20202021 12345678 chip-device-ctrl > connect -ip 192.168.1.111 20202021 12345678 Device is assigned with nodeid = 12345678 [1634673790.802615][182635:182642] CHIP:SC: Assigned local session key ID 1 [1634673790.802887][182635:182642] CHIP:IN: Build plaintext message 0x394e5cf8 to 0x0000000000000000 of type 32 and protocolId 0 on exchange 43789r with MessageCounter 3489196626. [1634673790.802988][182635:182642] CHIP:IN: Sending plaintext msg 0x394e5cf8 to 0x0000000000000000 at utc time: 61894175 msec [1634673790.803053][182635:182642] CHIP:IN: Sending msg on generic transport [1634673790.803385][182635:182642] CHIP:SC: Sent PBKDF param request [1634673790.803554][182635:182642] CHIP:CTL: SyncSetKeyValue on StartKeyID [1634673791.436288][182635:182642] CHIP:EM: Received message of type 0x21 with vendorId 0x0000 and protocolId 0x0000 on exchange 43789i [1634673791.436457][182635:182642] CHIP:EM: Rxd Ack; Removing MessageCounter:CFF8EA52 from Retrans Table [1634673791.436523][182635:182642] CHIP:EM: Removed CHIP MessageCounter:CFF8EA52 from RetransTable [1634673791.436615][182635:182642] CHIP:SC: Received PBKDF param response [1634673791.436726][182635:182642] CHIP:SC: Peer assigned session ID 2 [1634673791.440045][182635:182642] CHIP:EM: Piggybacking Ack for MessageCounter:2CA5702C on exchange: 43789i [1634673791.440156][182635:182642] CHIP:IN: Build plaintext message 0x394e5cf8 to 0x0000000000000000 of type 34 and protocolId 0 on exchange 43789r with MessageCounter 3489196627. [1634673791.440248][182635:182642] CHIP:IN: Sending plaintext msg 0x394e5cf8 to 0x0000000000000000 at utc time: 61894812 msec [1634673791.440310][182635:182642] CHIP:IN: Sending msg on generic transport [1634673791.440581][182635:182642] CHIP:SC: Sent spake2p msg1 [1634673793.276018][182635:182642] CHIP:EM: Received message of type 0x23 with vendorId 0x0000 and protocolId 0x0000 on exchange 43789i [1634673793.276156][182635:182642] CHIP:EM: Rxd Ack; Removing MessageCounter:CFF8EA53 from Retrans Table [1634673793.276206][182635:182642] CHIP:EM: Removed CHIP MessageCounter:CFF8EA53 from RetransTable [1634673793.276278][182635:182642] CHIP:SC: Received spake2p msg2 [1634673793.278606][182635:182642] CHIP:EM: Piggybacking Ack for MessageCounter:2CA5702D on exchange: 43789i [1634673793.278837][182635:182642] CHIP:IN: Build plaintext message 0x394e5cf8 to 0x0000000000000000 of type 36 and protocolId 0 on exchange 43789r with MessageCounter 3489196628. [1634673793.278931][182635:182642] CHIP:IN: Sending plaintext msg 0x394e5cf8 to 0x0000000000000000 at utc time: 61896651 msec [1634673793.278980][182635:182642] CHIP:IN: Sending msg on generic transport [1634673793.279190][182635:182642] CHIP:SC: Sent spake2p msg3 [1634673793.328448][182635:182642] CHIP:EM: Received message of type 0x40 with vendorId 0x0000 and protocolId 0x0000 on exchange 43789i [1634673793.328548][182635:182642] CHIP:EM: Rxd Ack; Removing MessageCounter:CFF8EA54 from Retrans Table [1634673793.328575][182635:182642] CHIP:EM: Removed CHIP MessageCounter:CFF8EA54 from RetransTable [1634673793.328632][182635:182642] CHIP:IN: New secure session created for device 0x0000000000BC614E, key 2!! [1634673793.328721][182635:182642] CHIP:CTL: Remote device completed SPAKE2+ handshake [1634673793.328748][182635:182642] CHIP:CTL: Arming failsafe [1634673793.328840][182635:182642] CHIP:DMG: ICR moving to [Initialize] [1634673793.328884][182635:182642] CHIP:DMG: ICR moving to [AddCommand] [1634673793.329012][182635:182642] CHIP:IN: Secure message was encrypted: Msg ID 0 [1634673793.329053][182635:182642] CHIP:IN: Build encrypted message 0x394e5cf8 to 0x0000000000BC614E of type 8 and protocolId 1 on exchange 43790r with MessageCounter 0. [1634673793.329090][182635:182642] CHIP:IN: Sending encrypted msg 0x394e5cf8 to 0x0000000000BC614E at utc time: 61896701 msec [1634673793.329125][182635:182642] CHIP:IN: Sending msg on generic transport [1634673793.329245][182635:182642] CHIP:DMG: ICR moving to [ Sending] [1634673793.329281][182635:182642] CHIP:EM: Sending Standalone Ack for MessageCounter:2CA5702E [1634673793.329319][182635:182642] CHIP:IN: Build plaintext message 0xffff93ffdb10 to 0x0000000000000000 of type 16 and protocolId 0 on exchange 43789r with MessageCounter 3489196629. [1634673793.329363][182635:182642] CHIP:IN: Sending plaintext msg 0xffff93ffdb10 to 0x0000000000000000 at utc time: 61896701 msec [1634673793.329389][182635:182642] CHIP:IN: Sending msg on generic transport [1634673793.329469][182635:182642] CHIP:EM: Flushed pending ack for MessageCounter:2CA5702E [1634673793.405355][182635:182642] CHIP:EM: Received message of type 0x09 with vendorId 0x0000 and protocolId 0x0001 on exchange 43790i [1634673793.405664][182635:182642] CHIP:EM: Rxd Ack; Removing MessageCounter:00000000 from Retrans Table [1634673793.405731][182635:182642] CHIP:EM: Removed CHIP MessageCounter:00000000 from RetransTable [1634673793.405846][182635:182642] CHIP:DMG: InvokeCommand = [1634673793.405917][182635:182642] CHIP:DMG: { [1634673793.406005][182635:182642] CHIP:DMG: CommandList = [1634673793.406072][182635:182642] CHIP:DMG: [ [1634673793.406133][182635:182642] CHIP:DMG: CommandDataElement = [1634673793.406237][182635:182642] CHIP:DMG: { [1634673793.406303][182635:182642] CHIP:DMG: CommandPath = [1634673793.406386][182635:182642] CHIP:DMG: { [1634673793.406490][182635:182642] CHIP:DMG: EndpointId = 0x0, [1634673793.406579][182635:182642] CHIP:DMG: ClusterId = 0x30, [1634673793.406663][182635:182642] CHIP:DMG: CommandId = 0x0, [1634673793.406771][182635:182642] CHIP:DMG: }, [1634673793.406872][182635:182642] CHIP:DMG: [1634673793.406943][182635:182642] CHIP:DMG: StatusElement = [1634673793.407051][182635:182642] CHIP:DMG: { [1634673793.407138][182635:182642] CHIP:DMG: GeneralCode = 0x0, [1634673793.407244][182635:182642] CHIP:DMG: ProtocolId = 0x1, [1634673793.407322][182635:182642] CHIP:DMG: protocolCode = 0x0, [1634673793.407543][182635:182642] CHIP:DMG: }, [1634673793.407627][182635:182642] CHIP:DMG: [1634673793.407708][182635:182642] CHIP:DMG: }, [1634673793.407781][182635:182642] CHIP:DMG: [1634673793.407852][182635:182642] CHIP:DMG: ], [1634673793.407920][182635:182642] CHIP:DMG: [1634673793.407969][182635:182642] CHIP:DMG: } SetCommandIndexStatus commandHandle=1 commandIndex=1 [1634673793.408692][182635:182642] CHIP:ZCL: DefaultResponse: [1634673793.408749][182635:182642] CHIP:ZCL: Transaction: 0xffffa3ad6240 [1634673793.408795][182635:182642] CHIP:ZCL: status: EMBER_ZCL_STATUS_SUCCESS (0x00) [1634673793.408851][182635:182642] CHIP:CTL: Received success response 0x814 [1634673793.408921][182635:182642] CHIP:CTL: Setting Regulatory Config [1634673793.409015][182635:182642] CHIP:CTL: Unable to find regulatory location, defaulting to outdoor [1634673793.409073][182635:182642] CHIP:CTL: Unable to find country code, defaulting to WW [1634673793.409167][182635:182642] CHIP:DMG: ICR moving to [Initialize] [1634673793.409252][182635:182642] CHIP:DMG: ICR moving to [AddCommand] [1634673793.409496][182635:182642] CHIP:IN: Secure message was encrypted: Msg ID 1 [1634673793.409558][182635:182642] CHIP:IN: Build encrypted message 0x394e5cf8 to 0x0000000000BC614E of type 8 and protocolId 1 on exchange 43791r with MessageCounter 1. [1634673793.409632][182635:182642] CHIP:IN: Sending encrypted msg 0x394e5cf8 to 0x0000000000BC614E at utc time: 61896782 msec [1634673793.409686][182635:182642] CHIP:IN: Sending msg on generic transport [1634673793.409911][182635:182642] CHIP:DMG: ICR moving to [ Sending] [1634673793.410102][182635:182642] CHIP:DMG: ICR moving to [Uninitiali] [1634673793.410172][182635:182642] CHIP:EM: Sending Standalone Ack for MessageCounter:00000001 [1634673793.410309][182635:182642] CHIP:IN: Secure message was encrypted: Msg ID 2 [1634673793.410390][182635:182642] CHIP:IN: Build encrypted message 0xffff93ffdad0 to 0x0000000000BC614E of type 16 and protocolId 0 on exchange 43790r with MessageCounter 2. [1634673793.410463][182635:182642] CHIP:IN: Sending encrypted msg 0xffff93ffdad0 to 0x0000000000BC614E at utc time: 61896783 msec [1634673793.410516][182635:182642] CHIP:IN: Sending msg on generic transport [1634673793.410706][182635:182642] CHIP:EM: Flushed pending ack for MessageCounter:00000001 [1634673793.498625][182635:182642] CHIP:EM: Received message of type 0x09 with vendorId 0x0000 and protocolId 0x0001 on exchange 43791i [1634673793.498758][182635:182642] CHIP:EM: Rxd Ack; Removing MessageCounter:00000001 from Retrans Table [1634673793.498805][182635:182642] CHIP:EM: Removed CHIP MessageCounter:00000001 from RetransTable [1634673793.498897][182635:182642] CHIP:DMG: InvokeCommand = [1634673793.498950][182635:182642] CHIP:DMG: { [1634673793.498992][182635:182642] CHIP:DMG: CommandList = [1634673793.499041][182635:182642] CHIP:DMG: [ [1634673793.499087][182635:182642] CHIP:DMG: CommandDataElement = [1634673793.499178][182635:182642] CHIP:DMG: { [1634673793.499234][182635:182642] CHIP:DMG: CommandPath = [1634673793.499317][182635:182642] CHIP:DMG: { [1634673793.499385][182635:182642] CHIP:DMG: EndpointId = 0x0, [1634673793.499559][182635:182642] CHIP:DMG: ClusterId = 0x30, [1634673793.499628][182635:182642] CHIP:DMG: CommandId = 0x2, [1634673793.499710][182635:182642] CHIP:DMG: }, [1634673793.499783][182635:182642] CHIP:DMG: [1634673793.499836][182635:182642] CHIP:DMG: StatusElement = [1634673793.499918][182635:182642] CHIP:DMG: { [1634673793.499984][182635:182642] CHIP:DMG: GeneralCode = 0x0, [1634673793.500070][182635:182642] CHIP:DMG: ProtocolId = 0x1, [1634673793.500139][182635:182642] CHIP:DMG: protocolCode = 0x0, [1634673793.500215][182635:182642] CHIP:DMG: }, [1634673793.500282][182635:182642] CHIP:DMG: [1634673793.500356][182635:182642] CHIP:DMG: }, [1634673793.500422][182635:182642] CHIP:DMG: [1634673793.500467][182635:182642] CHIP:DMG: ], [1634673793.500544][182635:182642] CHIP:DMG: [1634673793.500586][182635:182642] CHIP:DMG: } SetCommandIndexStatus commandHandle=1 commandIndex=1 [1634673793.501141][182635:182642] CHIP:ZCL: DefaultResponse: [1634673793.501189][182635:182642] CHIP:ZCL: Transaction: 0xffffa3ad63a0 [1634673793.501230][182635:182642] CHIP:ZCL: status: EMBER_ZCL_STATUS_SUCCESS (0x00) [1634673793.501280][182635:182642] CHIP:CTL: Received success response 0x814 [1634673793.501360][182635:182642] CHIP:CTL: Exchanging certificates [1634673793.501400][182635:182642] CHIP:CTL: Sending OpCSR request to 0x3948c100 device [1634673793.501519][182635:182642] CHIP:DMG: ICR moving to [Initialize] [1634673793.501612][182635:182642] CHIP:DMG: ICR moving to [AddCommand] [1634673793.501834][182635:182642] CHIP:IN: Secure message was encrypted: Msg ID 3 [1634673793.501905][182635:182642] CHIP:IN: Build encrypted message 0x394e5cf8 to 0x0000000000BC614E of type 8 and protocolId 1 on exchange 43792r with MessageCounter 3. [1634673793.501970][182635:182642] CHIP:IN: Sending encrypted msg 0x394e5cf8 to 0x0000000000BC614E at utc time: 61896874 msec [1634673793.502017][182635:182642] CHIP:IN: Sending msg on generic transport [1634673793.502208][182635:182642] CHIP:DMG: ICR moving to [ Sending] [1634673793.502447][182635:182642] CHIP:CTL: Sent OpCSR request, waiting for the CSR [1634673793.502618][182635:182642] CHIP:DMG: ICR moving to [Uninitiali] [1634673793.502677][182635:182642] CHIP:EM: Sending Standalone Ack for MessageCounter:00000002 [1634673793.502808][182635:182642] CHIP:IN: Secure message was encrypted: Msg ID 4 [1634673793.502857][182635:182642] CHIP:IN: Build encrypted message 0xffff93ffdad0 to 0x0000000000BC614E of type 16 and protocolId 0 on exchange 43791r with MessageCounter 4. [1634673793.502942][182635:182642] CHIP:IN: Sending encrypted msg 0xffff93ffdad0 to 0x0000000000BC614E at utc time: 61896875 msec [1634673793.502989][182635:182642] CHIP:IN: Sending msg on generic transport [1634673793.503144][182635:182642] CHIP:EM: Flushed pending ack for MessageCounter:00000002 [1634673794.309597][182635:182642] CHIP:EM: Received message of type 0x09 with vendorId 0x0000 and protocolId 0x0001 on exchange 43792i [1634673794.309740][182635:182642] CHIP:EM: Rxd Ack; Removing MessageCounter:00000003 from Retrans Table [1634673794.309789][182635:182642] CHIP:EM: Removed CHIP MessageCounter:00000003 from RetransTable [1634673794.309885][182635:182642] CHIP:DMG: InvokeCommand = [1634673794.309937][182635:182642] CHIP:DMG: { [1634673794.309978][182635:182642] CHIP:DMG: CommandList = [1634673794.310028][182635:182642] CHIP:DMG: [ [1634673794.310074][182635:182642] CHIP:DMG: CommandDataElement = [1634673794.310157][182635:182642] CHIP:DMG: { [1634673794.310212][182635:182642] CHIP:DMG: CommandPath = [1634673794.310271][182635:182642] CHIP:DMG: { [1634673794.310348][182635:182642] CHIP:DMG: EndpointId = 0x0, [1634673794.310417][182635:182642] CHIP:DMG: ClusterId = 0x3e, [1634673794.310496][182635:182642] CHIP:DMG: CommandId = 0x5, [1634673794.310557][182635:182642] CHIP:DMG: }, [1634673794.310622][182635:182642] CHIP:DMG: [1634673794.310690][182635:182642] CHIP:DMG: CommandData = [1634673794.310750][182635:182642] CHIP:DMG: { [1634673794.310825][182635:182642] CHIP:DMG: 0x0 = [ [1634673794.310932][182635:182642] CHIP:DMG: 0x15, 0x30, 0x1, 0xcd, 0x30, 0x81, 0xca, 0x30, 0x70, 0x2, 0x1, 0x0, 0x30, 0xe, 0x31, 0xc, 0x30, 0xa, 0x6, 0x3, 0x55, 0x4, 0xa, 0xc, 0x3, 0x43, 0x53, 0x52, 0x30, 0x59, 0x30, 0x13, 0x6, 0x7, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x2, 0x1, 0x6, 0x8, 0x2a, 0x86, [1634673794.311019][182635:182642] CHIP:DMG: ] [1634673794.311082][182635:182642] CHIP:DMG: 0x1 = [ [1634673794.311161][182635:182642] CHIP:DMG: [1634673794.311224][182635:182642] CHIP:DMG: ] [1634673794.311283][182635:182642] CHIP:DMG: }, [1634673794.311337][182635:182642] CHIP:DMG: }, [1634673794.311465][182635:182642] CHIP:DMG: [1634673794.311516][182635:182642] CHIP:DMG: ], [1634673794.311573][182635:182642] CHIP:DMG: [1634673794.311632][182635:182642] CHIP:DMG: } [1634673794.311755][182635:182642] CHIP:ZCL: Received Cluster Command: Cluster=3e Command=5 Endpoint=0 [1634673794.311836][182635:182642] CHIP:ZCL: OpCSRResponse: [1634673794.311879][182635:182642] CHIP:ZCL: NOCSRElements: 254 [1634673794.311918][182635:182642] CHIP:ZCL: AttestationSignature: 0 [1634673794.311964][182635:182642] CHIP:CTL: Received certificate signing request from the device [1634673794.312006][182635:182642] CHIP:CTL: Getting certificate chain for the device from the issuer [1634673794.312046][182635:182642] CHIP:CTL: Verifying Certificate Signing Request [1634673794.313328][182635:182642] CHIP:CTL: Generating NOC [1634673794.313925][182635:182642] CHIP:CTL: Generating ICAC [1634673794.314599][182635:182642] CHIP:CTL: Providing certificate chain to the commissioner [1634673794.314660][182635:182642] CHIP:CTL: Received callback from the CA for NOC Chain generation. Status ../../src/controller/ExampleOperationalCredentialsIssuer.cpp:183: Success [1634673794.314871][182635:182642] CHIP:CTL: Sending root certificate to the device [1634673794.314967][182635:182642] CHIP:DMG: ICR moving to [Initialize] [1634673794.315058][182635:182642] CHIP:DMG: ICR moving to [AddCommand] [1634673794.315301][182635:182642] CHIP:IN: Secure message was encrypted: Msg ID 5 [1634673794.315355][182635:182642] CHIP:IN: Build encrypted message 0x394e5cf8 to 0x0000000000BC614E of type 8 and protocolId 1 on exchange 43793r with MessageCounter 5. [1634673794.315464][182635:182642] CHIP:IN: Sending encrypted msg 0x394e5cf8 to 0x0000000000BC614E at utc time: 61897688 msec [1634673794.315513][182635:182642] CHIP:IN: Sending msg on generic transport [1634673794.315727][182635:182642] CHIP:DMG: ICR moving to [ Sending] [1634673794.315782][182635:182642] CHIP:CTL: Sent root certificate to the device [1634673794.316222][182635:182642] CHIP:DMG: ICR moving to [Uninitiali] [1634673794.316279][182635:182642] CHIP:EM: Sending Standalone Ack for MessageCounter:00000003 [1634673794.316378][182635:182642] CHIP:IN: Secure message was encrypted: Msg ID 6 [1634673794.316415][182635:182642] CHIP:IN: Build encrypted message 0xffff93ffdad0 to 0x0000000000BC614E of type 16 and protocolId 0 on exchange 43792r with MessageCounter 6. [1634673794.316462][182635:182642] CHIP:IN: Sending encrypted msg 0xffff93ffdad0 to 0x0000000000BC614E at utc time: 61897689 msec [1634673794.316497][182635:182642] CHIP:IN: Sending msg on generic transport [1634673794.316641][182635:182642] CHIP:EM: Flushed pending ack for MessageCounter:00000003 [1634673794.405145][182635:182642] CHIP:EM: Received message of type 0x09 with vendorId 0x0000 and protocolId 0x0001 on exchange 43793i [1634673794.405258][182635:182642] CHIP:EM: Rxd Ack; Removing MessageCounter:00000005 from Retrans Table [1634673794.405291][182635:182642] CHIP:EM: Removed CHIP MessageCounter:00000005 from RetransTable [1634673794.405363][182635:182642] CHIP:DMG: InvokeCommand = [1634673794.405399][182635:182642] CHIP:DMG: { [1634673794.405426][182635:182642] CHIP:DMG: CommandList = [1634673794.405576][182635:182642] CHIP:DMG: [ [1634673794.405611][182635:182642] CHIP:DMG: CommandDataElement = [1634673794.405647][182635:182642] CHIP:DMG: { [1634673794.405680][182635:182642] CHIP:DMG: CommandPath = [1634673794.405737][182635:182642] CHIP:DMG: { [1634673794.405782][182635:182642] CHIP:DMG: EndpointId = 0x0, [1634673794.405837][182635:182642] CHIP:DMG: ClusterId = 0x3e, [1634673794.405883][182635:182642] CHIP:DMG: CommandId = 0xb, [1634673794.405935][182635:182642] CHIP:DMG: }, [1634673794.405982][182635:182642] CHIP:DMG: [1634673794.406017][182635:182642] CHIP:DMG: StatusElement = [1634673794.406069][182635:182642] CHIP:DMG: { [1634673794.406112][182635:182642] CHIP:DMG: GeneralCode = 0x0, [1634673794.406166][182635:182642] CHIP:DMG: ProtocolId = 0x1, [1634673794.406210][182635:182642] CHIP:DMG: protocolCode = 0x0, [1634673794.406266][182635:182642] CHIP:DMG: }, [1634673794.406311][182635:182642] CHIP:DMG: [1634673794.406346][182635:182642] CHIP:DMG: }, [1634673794.406400][182635:182642] CHIP:DMG: [1634673794.406430][182635:182642] CHIP:DMG: ], [1634673794.406481][182635:182642] CHIP:DMG: [1634673794.406510][182635:182642] CHIP:DMG: } SetCommandIndexStatus commandHandle=1 commandIndex=1 [1634673794.406958][182635:182642] CHIP:ZCL: DefaultResponse: [1634673794.407022][182635:182642] CHIP:ZCL: Transaction: 0xffffa3ad63a0 [1634673794.407076][182635:182642] CHIP:ZCL: status: EMBER_ZCL_STATUS_SUCCESS (0x00) [1634673794.407140][182635:182642] CHIP:CTL: Device confirmed that it has received the root certificate [1634673794.407197][182635:182642] CHIP:CTL: Sending operational certificate chain to the device [1634673794.407326][182635:182642] CHIP:DMG: ICR moving to [Initialize] [1634673794.407634][182635:182642] CHIP:DMG: ICR moving to [AddCommand] [1634673794.407979][182635:182642] CHIP:IN: Secure message was encrypted: Msg ID 7 [1634673794.408054][182635:182642] CHIP:IN: Build encrypted message 0x394e5cf8 to 0x0000000000BC614E of type 8 and protocolId 1 on exchange 43794r with MessageCounter 7. [1634673794.408138][182635:182642] CHIP:IN: Sending encrypted msg 0x394e5cf8 to 0x0000000000BC614E at utc time: 61897780 msec [1634673794.408225][182635:182642] CHIP:IN: Sending msg on generic transport [1634673794.408470][182635:182642] CHIP:DMG: ICR moving to [ Sending] [1634673794.408566][182635:182642] CHIP:CTL: Sent operational certificate to the device [1634673794.408777][182635:182642] CHIP:DMG: ICR moving to [Uninitiali] [1634673794.408855][182635:182642] CHIP:EM: Sending Standalone Ack for MessageCounter:00000004 [1634673794.408995][182635:182642] CHIP:IN: Secure message was encrypted: Msg ID 8 [1634673794.409085][182635:182642] CHIP:IN: Build encrypted message 0xffff93ffdad0 to 0x0000000000BC614E of type 16 and protocolId 0 on exchange 43793r with MessageCounter 8. [1634673794.409171][182635:182642] CHIP:IN: Sending encrypted msg 0xffff93ffdad0 to 0x0000000000BC614E at utc time: 61897781 msec [1634673794.409234][182635:182642] CHIP:IN: Sending msg on generic transport [1634673794.409446][182635:182642] CHIP:EM: Flushed pending ack for MessageCounter:00000004 [1634673796.734325][182635:182642] CHIP:EM: Received message of type 0x09 with vendorId 0x0000 and protocolId 0x0001 on exchange 43794i [1634673796.734511][182635:182642] CHIP:EM: Rxd Ack; Removing MessageCounter:00000007 from Retrans Table [1634673796.734584][182635:182642] CHIP:EM: Removed CHIP MessageCounter:00000007 from RetransTable [1634673796.734702][182635:182642] CHIP:DMG: InvokeCommand = [1634673796.734764][182635:182642] CHIP:DMG: { [1634673796.734810][182635:182642] CHIP:DMG: CommandList = [1634673796.734867][182635:182642] CHIP:DMG: [ [1634673796.734919][182635:182642] CHIP:DMG: CommandDataElement = [1634673796.734980][182635:182642] CHIP:DMG: { [1634673796.735036][182635:182642] CHIP:DMG: CommandPath = [1634673796.735099][182635:182642] CHIP:DMG: { [1634673796.735202][182635:182642] CHIP:DMG: EndpointId = 0x0, [1634673796.735298][182635:182642] CHIP:DMG: ClusterId = 0x3e, [1634673796.735387][182635:182642] CHIP:DMG: CommandId = 0x8, [1634673796.735585][182635:182642] CHIP:DMG: }, [1634673796.735719][182635:182642] CHIP:DMG: [1634673796.735831][182635:182642] CHIP:DMG: CommandData = [1634673796.735950][182635:182642] CHIP:DMG: { [1634673796.736073][182635:182642] CHIP:DMG: 0x0 = 0, [1634673796.736204][182635:182642] CHIP:DMG: 0x1 = 2, [1634673796.736331][182635:182642] CHIP:DMG: 0x2 = [ [1634673796.736415][182635:182642] CHIP:DMG: [1634673796.736504][182635:182642] CHIP:DMG: ] [1634673796.736582][182635:182642] CHIP:DMG: }, [1634673796.736664][182635:182642] CHIP:DMG: }, [1634673796.736750][182635:182642] CHIP:DMG: [1634673796.736812][182635:182642] CHIP:DMG: ], [1634673796.736888][182635:182642] CHIP:DMG: [1634673796.736945][182635:182642] CHIP:DMG: } [1634673796.737062][182635:182642] CHIP:ZCL: Received Cluster Command: Cluster=3e Command=8 Endpoint=0 [1634673796.737141][182635:182642] CHIP:ZCL: NOCResponse: [1634673796.737195][182635:182642] CHIP:ZCL: StatusCode: 0 [1634673796.737247][182635:182642] CHIP:ZCL: FabricIndex: 2 [1634673796.737299][182635:182642] CHIP:ZCL: DebugText: 0 [1634673796.737359][182635:182642] CHIP:CTL: Device returned status 0 on receiving the NOC [1634673796.737417][182635:182642] CHIP:CTL: Operational credentials provisioned on device 0x3948c100 [1634673796.737474][182635:182642] CHIP:CTL: Enabling Network [1634673796.737571][182635:182642] CHIP:DMG: ICR moving to [Initialize] [1634673796.737667][182635:182642] CHIP:DMG: ICR moving to [AddCommand] [1634673796.737915][182635:182642] CHIP:IN: Secure message was encrypted: Msg ID 9 [1634673796.737988][182635:182642] CHIP:IN: Build encrypted message 0x394e5cf8 to 0x0000000000BC614E of type 8 and protocolId 1 on exchange 43795r with MessageCounter 9. [1634673796.738072][182635:182642] CHIP:IN: Sending encrypted msg 0x394e5cf8 to 0x0000000000BC614E at utc time: 61900110 msec [1634673796.738135][182635:182642] CHIP:IN: Sending msg on generic transport [1634673796.738349][182635:182642] CHIP:DMG: ICR moving to [ Sending] [1634673796.738554][182635:182642] CHIP:DMG: ICR moving to [Uninitiali] [1634673796.738633][182635:182642] CHIP:EM: Sending Standalone Ack for MessageCounter:00000005 [1634673796.738767][182635:182642] CHIP:IN: Secure message was encrypted: Msg ID 10 [1634673796.738833][182635:182642] CHIP:IN: Build encrypted message 0xffff93ffdad0 to 0x0000000000BC614E of type 16 and protocolId 0 on exchange 43794r with MessageCounter 10. [1634673796.738916][182635:182642] CHIP:IN: Sending encrypted msg 0xffff93ffdad0 to 0x0000000000BC614E at utc time: 61900111 msec [1634673796.738978][182635:182642] CHIP:IN: Sending msg on generic transport [1634673796.739335][182635:182642] CHIP:EM: Flushed pending ack for MessageCounter:00000005 [1634673797.074920][182635:182642] CHIP:EM: Received message of type 0x09 with vendorId 0x0000 and protocolId 0x0001 on exchange 43795i [1634673797.075089][182635:182642] CHIP:EM: Rxd Ack; Removing MessageCounter:00000009 from Retrans Table [1634673797.075155][182635:182642] CHIP:EM: Removed CHIP MessageCounter:00000009 from RetransTable [1634673797.075276][182635:182642] CHIP:DMG: InvokeCommand = [1634673797.075346][182635:182642] CHIP:DMG: { [1634673797.075447][182635:182642] CHIP:DMG: CommandList = [1634673797.075534][182635:182642] CHIP:DMG: [ [1634673797.075597][182635:182642] CHIP:DMG: CommandDataElement = [1634673797.075675][182635:182642] CHIP:DMG: { [1634673797.075740][182635:182642] CHIP:DMG: CommandPath = [1634673797.075821][182635:182642] CHIP:DMG: { [1634673797.075904][182635:182642] CHIP:DMG: EndpointId = 0x0, [1634673797.075991][182635:182642] CHIP:DMG: ClusterId = 0x31, [1634673797.076076][182635:182642] CHIP:DMG: CommandId = 0xc, [1634673797.076163][182635:182642] CHIP:DMG: }, [1634673797.076255][182635:182642] CHIP:DMG: [1634673797.076328][182635:182642] CHIP:DMG: StatusElement = [1634673797.076415][182635:182642] CHIP:DMG: { [1634673797.076498][182635:182642] CHIP:DMG: GeneralCode = 0x0, [1634673797.076590][182635:182642] CHIP:DMG: ProtocolId = 0x1, [1634673797.076680][182635:182642] CHIP:DMG: protocolCode = 0x0, [1634673797.076766][182635:182642] CHIP:DMG: }, [1634673797.076850][182635:182642] CHIP:DMG: [1634673797.076920][182635:182642] CHIP:DMG: }, [1634673797.077005][182635:182642] CHIP:DMG: [1634673797.077066][182635:182642] CHIP:DMG: ], [1634673797.077143][182635:182642] CHIP:DMG: [1634673797.077201][182635:182642] CHIP:DMG: } SetCommandIndexStatus commandHandle=1 commandIndex=1 [1634673797.077839][182635:182642] CHIP:ZCL: DefaultResponse: [1634673797.077910][182635:182642] CHIP:ZCL: Transaction: 0xffffa3ad63a0 [1634673797.077965][182635:182642] CHIP:ZCL: status: EMBER_ZCL_STATUS_SUCCESS (0x00) [1634673797.078029][182635:182642] CHIP:CTL: Received success response 0x814 [1634673797.078114][182635:182642] CHIP:CTL: Finding node on operational network [1634673797.080553][182635:182642] CHIP:DMG: ICR moving to [Uninitiali] [1634673797.080669][182635:182642] CHIP:EM: Sending Standalone Ack for MessageCounter:00000006 [1634673797.080861][182635:182642] CHIP:IN: Secure message was encrypted: Msg ID 11 [1634673797.080934][182635:182642] CHIP:IN: Build encrypted message 0xffff93ffdad0 to 0x0000000000BC614E of type 16 and protocolId 0 on exchange 43795r with MessageCounter 11. [1634673797.081024][182635:182642] CHIP:IN: Sending encrypted msg 0xffff93ffdad0 to 0x0000000000BC614E at utc time: 61900453 msec [1634673797.081088][182635:182642] CHIP:IN: Sending msg on generic transport [1634673797.081298][182635:182642] CHIP:EM: Flushed pending ack for MessageCounter:00000006 [1634673797.082943][182635:182642] CHIP:DL: Avahi resolve found [1634673797.083114][182635:182642] CHIP:DIS: Node ID resolved for 0x0000000000BC614E to [192.168.1.111]:5540 [1634673797.083280][182635:182642] CHIP:CTL: SyncSetKeyValue on PairedDevicebc614e Node address has been updated [1634673797.083541][182635:182642] CHIP:CTL: OperationalDiscoveryComplete for device ID 12345678 [1634673797.083608][182635:182642] CHIP:CTL: Enabling CASE session establishment for the device [1634673797.083696][182635:182642] CHIP:CTL: SyncSetKeyValue on PairedDevicebc614e [1634673797.083731][182635:182642] CHIP:IN: Marking old secure session for device 0x0000000000BC614E as expired [1634673797.083800][182635:182642] CHIP:CTL: SyncSetKeyValue on PairedDevicebc614e [1634673797.083837][182635:182642] CHIP:CTL: SyncSetKeyValue on StartKeyID [1634673797.084599][182635:182642] CHIP:IN: Build plaintext message 0x394e5cf8 to 0x0000000000000000 of type 48 and protocolId 0 on exchange 43796r with MessageCounter 3489196630. [1634673797.084675][182635:182642] CHIP:IN: Sending plaintext msg 0x394e5cf8 to 0x0000000000000000 at utc time: 61900457 msec [1634673797.084711][182635:182642] CHIP:IN: Sending msg on generic transport [1634673797.084856][182635:182642] CHIP:SC: Sent SigmaR1 msg [1634673798.427616][182635:182642] CHIP:EM: Received message of type 0x31 with vendorId 0x0000 and protocolId 0x0000 on exchange 43796i [1634673798.427758][182635:182642] CHIP:EM: Rxd Ack; Removing MessageCounter:CFF8EA56 from Retrans Table [1634673798.427809][182635:182642] CHIP:EM: Removed CHIP MessageCounter:CFF8EA56 from RetransTable [1634673798.427887][182635:182642] CHIP:SC: Received SigmaR2 msg [1634673798.427959][182635:182642] CHIP:SC: Peer assigned session key ID 3 [1634673798.433750][182635:182642] CHIP:SC: Sending SigmaR3 [1634673798.434603][182635:182642] CHIP:EM: Piggybacking Ack for MessageCounter:2CA5702F on exchange: 43796i [1634673798.434703][182635:182642] CHIP:IN: Build plaintext message 0x394e5cf8 to 0x0000000000000000 of type 50 and protocolId 0 on exchange 43796r with MessageCounter 3489196631. [1634673798.434777][182635:182642] CHIP:IN: Sending plaintext msg 0x394e5cf8 to 0x0000000000000000 at utc time: 61901807 msec [1634673798.434825][182635:182642] CHIP:IN: Sending msg on generic transport [1634673798.435021][182635:182642] CHIP:SC: Sent SigmaR3 msg [1634673798.435088][182635:182642] CHIP:IN: New secure session created for device 0x0000000000BC614E, key 3!! [1634673798.435220][182635:182642] CHIP:CTL: Calling commissioning complete [1634673798.435295][182635:182642] CHIP:DMG: ICR moving to [Initialize] [1634673798.435354][182635:182642] CHIP:DMG: ICR moving to [AddCommand] [1634673798.435573][182635:182642] CHIP:IN: Secure message was encrypted: Msg ID 0 [1634673798.435620][182635:182642] CHIP:IN: Build encrypted message 0x394e5d10 to 0x0000000000BC614E of type 8 and protocolId 1 on exchange 43797r with MessageCounter 0. [1634673798.435661][182635:182642] CHIP:IN: Sending encrypted msg 0x394e5d10 to 0x0000000000BC614E at utc time: 61901808 msec [1634673798.435687][182635:182642] CHIP:IN: Sending msg on generic transport [1634673798.435807][182635:182642] CHIP:DMG: ICR moving to [ Sending] [1634673801.240079][182635:182642] CHIP:EM: Received message of type 0x10 with vendorId 0x0000 and protocolId 0x0000 on exchange 43796i [1634673801.240235][182635:182642] CHIP:EM: Rxd Ack; Removing MessageCounter:CFF8EA57 from Retrans Table [1634673801.240300][182635:182642] CHIP:EM: Removed CHIP MessageCounter:CFF8EA57 from RetransTable [1634673801.306186][182635:182642] CHIP:EM: Received message of type 0x09 with vendorId 0x0000 and protocolId 0x0001 on exchange 43797i [1634673801.306316][182635:182642] CHIP:EM: Rxd Ack; Removing MessageCounter:00000000 from Retrans Table [1634673801.306360][182635:182642] CHIP:EM: Removed CHIP MessageCounter:00000000 from RetransTable [1634673801.306448][182635:182642] CHIP:DMG: InvokeCommand = [1634673801.306495][182635:182642] CHIP:DMG: { [1634673801.306532][182635:182642] CHIP:DMG: CommandList = [1634673801.306588][182635:182642] CHIP:DMG: [ [1634673801.306630][182635:182642] CHIP:DMG: CommandDataElement = [1634673801.306682][182635:182642] CHIP:DMG: { [1634673801.306731][182635:182642] CHIP:DMG: CommandPath = [1634673801.306790][182635:182642] CHIP:DMG: { [1634673801.306846][182635:182642] CHIP:DMG: EndpointId = 0x0, [1634673801.306908][182635:182642] CHIP:DMG: ClusterId = 0x30, [1634673801.306969][182635:182642] CHIP:DMG: CommandId = 0x4, [1634673801.307026][182635:182642] CHIP:DMG: }, [1634673801.307088][182635:182642] CHIP:DMG: [1634673801.307137][182635:182642] CHIP:DMG: StatusElement = [1634673801.307195][182635:182642] CHIP:DMG: { [1634673801.307250][182635:182642] CHIP:DMG: GeneralCode = 0x0, [1634673801.307307][182635:182642] CHIP:DMG: ProtocolId = 0x1, [1634673801.307362][182635:182642] CHIP:DMG: protocolCode = 0x0, [1634673801.307520][182635:182642] CHIP:DMG: }, [1634673801.307596][182635:182642] CHIP:DMG: [1634673801.307650][182635:182642] CHIP:DMG: }, [1634673801.307714][182635:182642] CHIP:DMG: [1634673801.307760][182635:182642] CHIP:DMG: ], [1634673801.307819][182635:182642] CHIP:DMG: [1634673801.307861][182635:182642] CHIP:DMG: } SetCommandIndexStatus commandHandle=1 commandIndex=1 [1634673801.308376][182635:182642] CHIP:ZCL: DefaultResponse: [1634673801.308426][182635:182642] CHIP:ZCL: Transaction: 0xffffa3ad6240 [1634673801.308467][182635:182642] CHIP:ZCL: status: EMBER_ZCL_STATUS_SUCCESS (0x00) [1634673801.308517][182635:182642] CHIP:CTL: Received success response 0x814 [1634673801.308580][182635:182642] CHIP:CTL: Rendezvous cleanup [1634673801.308698][182635:182642] CHIP:CTL: SyncSetKeyValue on PairedDevicebc614e [1634673801.308772][182635:182642] CHIP:CTL: SyncSetKeyValue on ListPairedDevices0 [1634673801.308823][182635:182642] CHIP:CTL: SyncSetKeyValue on StartKeyID [1634673801.308887][182635:182642] CHIP:CTL: SyncSetKeyValue on PairedDevicebc614e Secure Session to Device Established Device temporary node id (**this does not match spec**): 12345678 [1634673801.309248][182635:182642] CHIP:DMG: ICR moving to [Uninitiali] [1634673801.309324][182635:182642] CHIP:EM: Sending Standalone Ack for MessageCounter:00000001 [1634673801.309466][182635:182642] CHIP:IN: chip-device-ctrl > Secure message was encrypted: Msg ID 1 [1634673801.309648][182635:182642] CHIP:IN: Build encrypted message 0xffff93ffdad0 to 0x0000000000BC614E of type 16 and protocolId 0 on exchange 43797r with MessageCounter 1. [1634673801.309722][182635:182642] CHIP:IN: Sending encrypted msg 0xffff93ffdad0 to 0x0000000000BC614E at utc time: 61904682 msec [1634673801.309771][182635:182642] CHIP:IN: Sending msg on generic transport [1634673801.309956][182635:182642] CHIP:EM: Flushed pending ack for MessageCounter:00000001 ***************** Step 4 ***************** TH_CR1 reads the list of Fabrics on DUT_CE zclread OperationalCredentials FabricsList 12344321 0 0 chip-device-ctrl > zclread OperationalCredentials FabricsList 12344321 0 0 [1634673813.491987][827276:827283] CHIP:DMG: SendReadRequest: Client[0] [ INIT] [1634673813.492259][827276:827283] CHIP:IN: Secure message was encrypted: Msg ID 8 [1634673813.492312][827276:827283] CHIP:IN: Build encrypted message 0xd2dbcf8 to 0x0000000000BC5C01 of type 2 and protocolId 1 on exchange 3348r with MessageCounter 8. [1634673813.492371][827276:827283] CHIP:IN: Sending encrypted msg 0xd2dbcf8 to 0x0000000000BC5C01 at utc time: 93799774 msec [1634673813.492416][827276:827283] CHIP:IN: Sending msg on generic transport [1634673813.492609][827276:827283] CHIP:DMG: Client[0] moving to [AwaitingInitialReport] [1634673813.798016][827276:827283] CHIP:EM: Received message of type 0x05 with vendorId 0x0000 and protocolId 0x0001 on exchange 3348i [1634673813.798192][827276:827283] CHIP:EM: Rxd Ack; Removing MessageCounter:00000008 from Retrans Table [1634673813.798259][827276:827283] CHIP:EM: Removed CHIP MessageCounter:00000008 from RetransTable [1634673813.798385][827276:827283] CHIP:DMG: ReportData = [1634673813.798458][827276:827283] CHIP:DMG: { [1634673813.798514][827276:827283] CHIP:DMG: AttributeDataList = [1634673813.798583][827276:827283] CHIP:DMG: [ [1634673813.798647][827276:827283] CHIP:DMG: AttributeDataElement = [1634673813.798730][827276:827283] CHIP:DMG: { [1634673813.798799][827276:827283] CHIP:DMG: AttributePath = [1634673813.798881][827276:827283] CHIP:DMG: { [1634673813.798972][827276:827283] CHIP:DMG: NodeId = 0xbc5c01, [1634673813.799066][827276:827283] CHIP:DMG: EndpointId = 0x0, [1634673813.799150][827276:827283] CHIP:DMG: ClusterId = 0x3e, [1634673813.799242][827276:827283] CHIP:DMG: FieldTag = 0x1, [1634673813.799327][827276:827283] CHIP:DMG: } [1634673813.799414][827276:827283] CHIP:DMG: [1634673813.799511][827276:827283] CHIP:DMG: Data = -- [1634673813.799598][827276:827283] CHIP:DMG: DataElementVersion = 0x0, [1634673813.799681][827276:827283] CHIP:DMG: }, [1634673813.799762][827276:827283] CHIP:DMG: [1634673813.799823][827276:827283] CHIP:DMG: ], [1634673813.799900][827276:827283] CHIP:DMG: [1634673813.799958][827276:827283] CHIP:DMG: } [1634673813.801095][827276:827283] CHIP:ZCL: ReadAttributesResponse: [1634673813.801182][827276:827283] CHIP:ZCL: ClusterId: 0x0000_003E [1634673813.801250][827276:827283] CHIP:ZCL: attributeId: 0x0000_0001 [1634673813.801306][827276:827283] CHIP:ZCL: status: Success (0x0000) [1634673813.801361][827276:827283] CHIP:ZCL: attribute TLV Type: 0x17 [1634673813.801456][827276:827283] CHIP:ZCL: attributeValue: List of length 2 [1634673813.801814][827276:827283] CHIP:EM: Piggybacking Ack for MessageCounter:00000006 on exchange: 3348i AttributeReadResult(path=AttributePath(nodeId=12344321, endpointId=0, clusterId=62, attributeId=1), status=0, value=[b'\x02\x00\x01A\x00\x041\xd0\xf2-q$\xb0u\'\x0c\xb8\xf1P\xea\x8f\xc8\xcc\x83\xdf\xa5q~^d\xf1\xc8{C\x1e\xaf\xe3\xec\x9a\xc7\x96\'H\x88\xe1\x95\x14\x91T\xbe\xfb\x03\xd4\x07.\xe2\x87%\xb5z"\x0f9,\x13\x1f\x12z\x95A\x10\xbc\x00\x00\x00\x00\x00\x00\x00\x00\x01\\\xbc\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\x00\x02A\x00\x04\xa4\xf6s\xd8U\xc5\xf8\xbb\xcaI\xe6-\xe2a\x0bya\x85\xcfF;\xe4\xa10\xc9\x97\xaf\x8f\x12\rZ>(\xe2f\x9c\x03\x13\xf8\xb3w\xd9\xc2\x94\xf6J\x8b@H\x80\xb73N\r(\xc1\x97\xe6)\x1d\xd5X\xf7\xa1\x80p\x00\x00\x00\x00\x00\x00\x00\x00Na\xbc\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\x00']) [1634673813.802013][827276:827283] CHIP:IN: Secure message was encrypted: Msg ID 9 [1634673813.802093][827276:827283] CHIP:IN: Build encrypted message 0xd2dbcf8 to 0x0000000000BC5C01 of type 1 and protocolId 1 on exchange 3348r with MessageCounter 9. [1634673813.802183][827276:827283] CHIP:IN: Sending encrypted msg 0xd2dbcf8 to 0x0000000000BC5C01 at utc time: 93800084 msec [1634673813.802249][827276:827283] CHIP:IN: Sending msg on generic transport chip-device-ctrl > [1634673813.802545][827276:827283] CHIP:DMG: Client[0] moving to [UNINIT] [1634673813.873260][827276:827283] CHIP:EM: Received message of type 0x10 with vendorId 0x0000 and protocolId 0x0000 on exchange 3348i [1634673813.873366][827276:827283] CHIP:EM: Rxd Ack; Removing MessageCounter:00000009 from Retrans Table [1634673813.873405][827276:827283] CHIP:EM: Removed CHIP MessageCounter:00000009 from RetransTable ***************** Step 5 ***************** TH_CR2 reads the list of Fabrics on DUT_CE zclread OperationalCredentials FabricsList 12345678 0 0 chip-device-ctrl > zclread OperationalCredentials FabricsList 12345678 0 0 [1634673857.834872][182635:182642] CHIP:IN: Build plaintext message 0x394e5cf8 to 0x0000000000000000 of type 48 and protocolId 0 on exchange 43798r with MessageCounter 3489196632. [1634673857.834980][182635:182642] CHIP:IN: Sending plaintext msg 0x394e5cf8 to 0x0000000000000000 at utc time: 61961207 msec [1634673857.835031][182635:182642] CHIP:IN: Sending msg on generic transport [1634673857.835281][182635:182642] CHIP:SC: Sent SigmaR1 msg [1634673857.835365][182635:182642] CHIP:DMG: SendReadRequest: Client[0] [ INIT] [1634673857.835670][182635:182642] CHIP:IN: Secure message was encrypted: Msg ID 2 [1634673857.835725][182635:182642] CHIP:IN: Build encrypted message 0x394e5d10 to 0x0000000000BC614E of type 2 and protocolId 1 on exchange 43799r with MessageCounter 2. [1634673857.835808][182635:182642] CHIP:IN: Sending encrypted msg 0x394e5d10 to 0x0000000000BC614E at utc time: 61961208 msec [1634673857.835857][182635:182642] CHIP:IN: Sending msg on generic transport [1634673857.836037][182635:182642] CHIP:DMG: Client[0] moving to [AwaitingInitialReport] [1634673859.254304][182635:182642] CHIP:EM: Received message of type 0x31 with vendorId 0x0000 and protocolId 0x0000 on exchange 43798i [1634673859.254465][182635:182642] CHIP:EM: Rxd Ack; Removing MessageCounter:CFF8EA58 from Retrans Table [1634673859.254530][182635:182642] CHIP:EM: Removed CHIP MessageCounter:CFF8EA58 from RetransTable [1634673859.254639][182635:182642] CHIP:SC: Received SigmaR2 msg [1634673859.254732][182635:182642] CHIP:SC: Peer assigned session key ID 5 [1634673859.262665][182635:182642] CHIP:SC: Sending SigmaR3 [1634673859.263645][182635:182642] CHIP:EM: Piggybacking Ack for MessageCounter:2CA57031 on exchange: 43798i [1634673859.263775][182635:182642] CHIP:IN: Build plaintext message 0x394e5cf8 to 0x0000000000000000 of type 50 and protocolId 0 on exchange 43798r with MessageCounter 3489196633. [1634673859.263872][182635:182642] CHIP:IN: Sending plaintext msg 0x394e5cf8 to 0x0000000000000000 at utc time: 61962636 msec [1634673859.263935][182635:182642] CHIP:IN: Sending msg on generic transport [1634673859.264223][182635:182642] CHIP:SC: Sent SigmaR3 msg [1634673859.264482][182635:182642] CHIP:IN: New secure session created for device 0x0000000000BC614E, key 5!! [1634673861.521206][182635:182642] CHIP:EM: Received message of type 0x10 with vendorId 0x0000 and protocolId 0x0000 on exchange 43798i [1634673861.521345][182635:182642] CHIP:EM: Rxd Ack; Removing MessageCounter:CFF8EA59 from Retrans Table [1634673861.521394][182635:182642] CHIP:EM: Removed CHIP MessageCounter:CFF8EA59 from RetransTable [1634673862.809544][182635:182642] CHIP:IN: Sending encrypted msg 0x394e5d10 to 0x0000000000BC614E at utc time: 61966182 msec [1634673862.809652][182635:182642] CHIP:IN: Sending msg on generic transport [1634673862.809941][182635:182642] CHIP:EM: Retransmit MessageCounter:00000002 Send Cnt 1 [1634673863.065468][182635:182642] CHIP:IN: Sending encrypted msg 0x394e5d10 to 0x0000000000BC614E at utc time: 61966438 msec [1634673863.065535][182635:182642] CHIP:IN: Sending msg on generic transport [1634673863.065727][182635:182642] CHIP:EM: Retransmit MessageCounter:00000002 Send Cnt 2 [1634673863.321235][182635:182642] CHIP:IN: Sending encrypted msg 0x394e5d10 to 0x0000000000BC614E at utc time: 61966693 msec [1634673863.321294][182635:182642] CHIP:IN: Sending msg on generic transport [1634673863.321464][182635:182642] CHIP:EM: Retransmit MessageCounter:00000002 Send Cnt 3 [1634673863.576941][182635:182642] CHIP:EM: Failed to Send CHIP MessageCounter:00000002 sendCount: 3 max retries: 3 [1634673869.836741][182635:182642] CHIP:DMG: Time out! failed to receive report data from Exchange: 43799i [1634673869.836820][182635:182642] CHIP:ZCL: ReadAttributesResponse: [1634673869.836859][182635:182642] CHIP:ZCL: ClusterId: 0x0000_0000 [1634673869.836908][182635:182642] CHIP:ZCL: attributeId: 0x0000_0000 [1634673869.836952][182635:182642] CHIP:ZCL: status: Failure (0x0001) [1634673869.837127][182635:182642] CHIP:DMG: Client[0] moving to [UNINIT] An exception occurred during reading ZCL attribute: CHIP Error 0x00000001: Sending blocked ***************** Step 6 ***************** Verify DUT_CE is now discoverable over DNS-SD with two operational service records (_matter._tcp SRV records) whose compressed Fabric ID and Node ID in the instance name match the commissioning state to date. avahi-browse -rt _matter._tcp ubuntu@matter-te-6:~$ avahi-browse -rt _matter._tcp + eth0 IPv6 941BC0799407C614-0000000000BC614E _matter._tcp local + eth0 IPv6 363B47B81570370B-0000000000BC5C01 _matter._tcp local + eth0 IPv4 941BC0799407C614-0000000000BC614E _matter._tcp local + eth0 IPv4 363B47B81570370B-0000000000BC5C01 _matter._tcp local = eth0 IPv6 941BC0799407C614-0000000000BC614E _matter._tcp local hostname = [A402A0A44DD4.local] address = [192.168.1.111] port = [5540] txt = ["T=1" "CRA=300" "CRI=5000"] = eth0 IPv6 363B47B81570370B-0000000000BC5C01 _matter._tcp local hostname = [A402A0A44DD4.local] address = [192.168.1.111] port = [5540] txt = ["T=1" "CRA=300" "CRI=5000"] = eth0 IPv4 941BC0799407C614-0000000000BC614E _matter._tcp local hostname = [A402A0A44DD4.local] address = [192.168.1.111] port = [5540] txt = ["T=1" "CRA=300" "CRI=5000"] = eth0 IPv4 363B47B81570370B-0000000000BC5C01 _matter._tcp local hostname = [A402A0A44DD4.local] address = [192.168.1.111] port = [5540] txt = ["T=1" "CRA=300" "CRI=5000"] ***************** Step 7 ***************** TH_CR1 writes and reads the Basic Information Cluster’s NodeLabel mandatory attribute of DUT_CE zclwrite Basic UserLabel 12344321 0 0 TE5New zclread Basic UserLabel 12344321 0 0 chip-device-ctrl > zclwrite Basic UserLabel 12344321 0 0 TE5New [1634673904.076442][827276:827283] CHIP:DMG: WriteClient moving to [Initialize] [1634673904.076568][827276:827283] CHIP:DMG: WriteClient moving to [AddAttribu] [1634673904.076831][827276:827283] CHIP:IN: Secure message was encrypted: Msg ID 10 [1634673904.076897][827276:827283] CHIP:IN: Build encrypted message 0xd2dbcf8 to 0x0000000000BC5C01 of type 6 and protocolId 1 on exchange 3349r with MessageCounter 10. [1634673904.076973][827276:827283] CHIP:IN: Sending encrypted msg 0xd2dbcf8 to 0x0000000000BC5C01 at utc time: 93890359 msec [1634673904.077031][827276:827283] CHIP:IN: Sending msg on generic transport [1634673904.077253][827276:827283] CHIP:DMG: WriteClient moving to [AwaitingRe] [1634673909.051891][827276:827283] CHIP:IN: Sending encrypted msg 0xd2dbcf8 to 0x0000000000BC5C01 at utc time: 93895334 msec [1634673909.052001][827276:827283] CHIP:IN: Sending msg on generic transport [1634673909.052261][827276:827283] CHIP:EM: Retransmit MessageCounter:0000000A Send Cnt 1 [1634673909.304879][827276:827283] CHIP:IN: Sending encrypted msg 0xd2dbcf8 to 0x0000000000BC5C01 at utc time: 93895587 msec [1634673909.304985][827276:827283] CHIP:IN: Sending msg on generic transport [1634673909.305251][827276:827283] CHIP:EM: Retransmit MessageCounter:0000000A Send Cnt 2 [1634673909.560839][827276:827283] CHIP:IN: Sending encrypted msg 0xd2dbcf8 to 0x0000000000BC5C01 at utc time: 93895843 msec [1634673909.560952][827276:827283] CHIP:IN: Sending msg on generic transport [1634673909.561214][827276:827283] CHIP:EM: Retransmit MessageCounter:0000000A Send Cnt 3 [1634673909.816741][827276:827283] CHIP:EM: Failed to Send CHIP MessageCounter:0000000A sendCount: 3 max retries: 3 [1634673916.077538][827276:827283] CHIP:DMG: Time out! failed to receive write response from Exchange: 3349i [1634673916.077627][827276:827283] CHIP:ZCL: WriteResponse: [1634673916.077672][827276:827283] CHIP:ZCL: status: EMBER_ZCL_STATUS_FAILURE (0x01) [1634673916.077874][827276:827283] CHIP:DMG: WriteClient moving to [Uninitiali] AttributeWriteResult(path=AttributePath(nodeId=12344321, endpointId=0, clusterId=40, attributeId=5), status=0) chip-device-ctrl > zclread Basic UserLabel 12344321 0 0 [1634673916.086802][827276:827283] CHIP:DMG: SendReadRequest: Client[0] [ INIT] [1634673916.087145][827276:827283] CHIP:IN: Secure message was encrypted: Msg ID 11 [1634673916.087223][827276:827283] CHIP:IN: Build encrypted message 0xd2dbcf8 to 0x0000000000BC5C01 of type 2 and protocolId 1 on exchange 3350r with MessageCounter 11. [1634673916.087345][827276:827283] CHIP:IN: Sending encrypted msg 0xd2dbcf8 to 0x0000000000BC5C01 at utc time: 93902369 msec [1634673916.087414][827276:827283] CHIP:IN: Sending msg on generic transport [1634673916.087712][827276:827283] CHIP:DMG: Client[0] moving to [AwaitingInitialReport] [1634673921.080508][827276:827283] CHIP:IN: Sending encrypted msg 0xd2dbcf8 to 0x0000000000BC5C01 at utc time: 93907363 msec [1634673921.080595][827276:827283] CHIP:IN: Sending msg on generic transport [1634673921.080845][827276:827283] CHIP:EM: Retransmit MessageCounter:0000000B Send Cnt 1 [1634673921.336373][827276:827283] CHIP:IN: Sending encrypted msg 0xd2dbcf8 to 0x0000000000BC5C01 at utc time: 93907618 msec [1634673921.336459][827276:827283] CHIP:IN: Sending msg on generic transport [1634673921.336703][827276:827283] CHIP:EM: Retransmit MessageCounter:0000000B Send Cnt 2 [1634673921.592294][827276:827283] CHIP:IN: Sending encrypted msg 0xd2dbcf8 to 0x0000000000BC5C01 at utc time: 93907874 msec [1634673921.592405][827276:827283] CHIP:IN: Sending msg on generic transport [1634673921.592689][827276:827283] CHIP:EM: Retransmit MessageCounter:0000000B Send Cnt 3 [1634673921.848252][827276:827283] CHIP:EM: Failed to Send CHIP MessageCounter:0000000B sendCount: 3 max retries: 3 [1634673928.089418][827276:827283] CHIP:DMG: Time out! failed to receive report data from Exchange: 3350i [1634673928.089571][827276:827283] CHIP:ZCL: ReadAttributesResponse: [1634673928.089630][827276:827283] CHIP:ZCL: ClusterId: 0x0000_0000 [1634673928.089695][827276:827283] CHIP:ZCL: attributeId: 0x0000_0000 [1634673928.089752][827276:827283] CHIP:ZCL: status: Failure (0x0001) [1634673928.089949][827276:827283] CHIP:DMG: Client[0] moving to [UNINIT] An exception occurred during reading ZCL attribute: CHIP Error 0x00000001: Sending blocked ***************** Step 8 ***************** TH_CR2 writes and reads the Basic Information Cluster’s NodeLabel mandatory attribute of DUT_CE zclwrite Basic UserLabel 12345678 0 0 TE5 zclread Basic UserLabel 12345678 0 0 chip-device-ctrl > zclwrite Basic UserLabel 12345678 0 0 TE5 [1634673990.635823][182635:182642] CHIP:DMG: WriteClient moving to [Initialize] [1634673990.635944][182635:182642] CHIP:DMG: WriteClient moving to [AddAttribu] [1634673990.636195][182635:182642] CHIP:IN: Secure message was encrypted: Msg ID 0 [1634673990.636258][182635:182642] CHIP:IN: Build encrypted message 0x394e5cf8 to 0x0000000000BC614E of type 6 and protocolId 1 on exchange 43800r with MessageCounter 0. [1634673990.636334][182635:182642] CHIP:IN: Sending encrypted msg 0x394e5cf8 to 0x0000000000BC614E at utc time: 62094008 msec [1634673990.636389][182635:182642] CHIP:IN: Sending msg on generic transport [1634673990.636656][182635:182642] CHIP:DMG: WriteClient moving to [AwaitingRe] [1634673995.609541][182635:182642] CHIP:IN: Sending encrypted msg 0x394e5cf8 to 0x0000000000BC614E at utc time: 62098982 msec [1634673995.609603][182635:182642] CHIP:IN: Sending msg on generic transport [1634673995.609780][182635:182642] CHIP:EM: Retransmit MessageCounter:00000000 Send Cnt 1 [1634673995.865301][182635:182642] CHIP:IN: Sending encrypted msg 0x394e5cf8 to 0x0000000000BC614E at utc time: 62099237 msec [1634673995.865409][182635:182642] CHIP:IN: Sending msg on generic transport [1634673995.865689][182635:182642] CHIP:EM: Retransmit MessageCounter:00000000 Send Cnt 2 [1634673996.121346][182635:182642] CHIP:IN: Sending encrypted msg 0x394e5cf8 to 0x0000000000BC614E at utc time: 62099493 msec [1634673996.121428][182635:182642] CHIP:IN: Sending msg on generic transport [1634673996.121646][182635:182642] CHIP:EM: Retransmit MessageCounter:00000000 Send Cnt 3 [1634673996.377136][182635:182642] CHIP:EM: Failed to Send CHIP MessageCounter:00000000 sendCount: 3 max retries: 3 [1634674002.638713][182635:182642] CHIP:DMG: Time out! failed to receive write response from Exchange: 43800i [1634674002.638810][182635:182642] CHIP:ZCL: WriteResponse: [1634674002.638862][182635:182642] CHIP:ZCL: status: EMBER_ZCL_STATUS_FAILURE (0x01) [1634674002.639114][182635:182642] CHIP:DMG: WriteClient moving to [Uninitiali] DUT log for abort CHIP:IN: CASE Session established. Setting up the secure channel. CHIP:IN: Marking old secure session for device 0x00000000000022B8 as expired CHIP:IN: New secure session created for device 0x00000000000022B8, key 3!! CHIP:IN: CASE secure channel is available now. CHIP:IN: CASE Server enabling CASE session setups CHIP:EM: Sending Standalone Ack for MessageCounter:CFF8EA59 CHIP:IN: Build plaintext message 0x8022118 to 0x0000000000000000 of type 16 and protocolId 0 on exchange 43798i with MessageCounter 749039666. CHIP:IN: Sending plaintext msg 0x8022118 to 0x0000000000000000 at utc time: ld msec CHIP:IN: Sending msg on generic transport CHIP:EM: Flushed pending ack for MessageCounter:CFF8EA59 CHIP:DL: Long dispatch time: 2250 ms, for event type 4 CHIP:DMG: Cluster 3e, Field 1 is dirty CHIP:DMG: Received Cluster Command: Cluster=0x0000_003E NodeId=0x0000000000BC614E Endpoint=0 AttributeId=1 ListIndex=0 CHIP:DMG: Sending report...